Horton

Thread

Commits

  1. Add writeback to pg_stat_io

  2. Update parameter name context to wb_context

  3. Use BUFFER_USAGE_LIMIT to reduce needed test table size

  1. pg_stat_io not tracking smgrwriteback() is confusing

    Andres Freund <andres@anarazel.de> — 2023-04-19T17:23:26Z

    Hi,

I noticed that the numbers in pg_stat_io dont't quite add up to what I
expected in write heavy workloads. Particularly for checkpointer, the numbers
for "write" in log_checkpoints output are larger than what is visible in
pg_stat_io.

That partially is because log_checkpoints' "write" covers way too many things,
but there's an issue with pg_stat_io as well:

Checkpoints, and some other sources of writes, will often end up doing a lot
of smgrwriteback() calls - which pg_stat_io doesn't track. Nor do any
pre-existing forms of IO statistics.

It seems pretty clear that we should track writeback as well. I wonder if it's
worth doing so for 16? It'd give a more complete picture that way. The
counter-argument I see is that we didn't track the time for it in existing
stats either, and that nobody complained - but I suspect that's mostly because
nobody knew to look.

Greetings,

Andres Freund

  2. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Jonathan S. Katz <jkatz@postgresql.org> — 2023-04-22T19:25:11Z

    On 4/19/23 1:23 PM, Andres Freund wrote:
> Hi,
> 
> I noticed that the numbers in pg_stat_io dont't quite add up to what I
> expected in write heavy workloads. Particularly for checkpointer, the numbers
> for "write" in log_checkpoints output are larger than what is visible in
> pg_stat_io.
> 
> That partially is because log_checkpoints' "write" covers way too many things,
> but there's an issue with pg_stat_io as well:
> 
> Checkpoints, and some other sources of writes, will often end up doing a lot
> of smgrwriteback() calls - which pg_stat_io doesn't track. Nor do any
> pre-existing forms of IO statistics.
> 
> It seems pretty clear that we should track writeback as well. I wonder if it's
> worth doing so for 16? It'd give a more complete picture that way. The
> counter-argument I see is that we didn't track the time for it in existing
> stats either, and that nobody complained - but I suspect that's mostly because
> nobody knew to look.

[RMT hat]

(sorry for slow reply on this, I've been out for a few days).

It does sound generally helpful to track writeback to ensure anyone 
building around pg_stat_io can see tthe more granular picture. How big 
of an effort is this? Do you think this helps to complete the feature 
for v16?

Thanks,

Jonathan

  3. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Amit Kapila <amit.kapila16@gmail.com> — 2023-04-24T05:22:15Z

    On Sun, Apr 23, 2023 at 12:55 AM Jonathan S. Katz <jkatz@postgresql.org> wrote:
>
> On 4/19/23 1:23 PM, Andres Freund wrote:
> > Hi,
> >
> > I noticed that the numbers in pg_stat_io dont't quite add up to what I
> > expected in write heavy workloads. Particularly for checkpointer, the numbers
> > for "write" in log_checkpoints output are larger than what is visible in
> > pg_stat_io.
> >
> > That partially is because log_checkpoints' "write" covers way too many things,
> > but there's an issue with pg_stat_io as well:
> >
> > Checkpoints, and some other sources of writes, will often end up doing a lot
> > of smgrwriteback() calls - which pg_stat_io doesn't track. Nor do any
> > pre-existing forms of IO statistics.
> >
> > It seems pretty clear that we should track writeback as well.

Agreed. +1.

> > I wonder if it's
> > worth doing so for 16? It'd give a more complete picture that way. The
> > counter-argument I see is that we didn't track the time for it in existing
> > stats either, and that nobody complained - but I suspect that's mostly because
> > nobody knew to look.
>
> [RMT hat]
>
> (sorry for slow reply on this, I've been out for a few days).
>
> It does sound generally helpful to track writeback to ensure anyone
> building around pg_stat_io can see tthe more granular picture. How big
> of an effort is this?
>

Right, I think this is the key factor to decide whether we can get
this in PG16 or not. If this is just adding a new column and a few
existing stats update calls then it should be okay to get in but if
this requires some more complex work then we can probably update the
docs.

-- 
With Regards,
Amit Kapila.

  4. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Melanie Plageman <melanieplageman@gmail.com> — 2023-04-24T20:39:36Z

    On Wed, Apr 19, 2023 at 10:23:26AM -0700, Andres Freund wrote:
> Hi,
> 
> I noticed that the numbers in pg_stat_io dont't quite add up to what I
> expected in write heavy workloads. Particularly for checkpointer, the numbers
> for "write" in log_checkpoints output are larger than what is visible in
> pg_stat_io.
> 
> That partially is because log_checkpoints' "write" covers way too many things,
> but there's an issue with pg_stat_io as well:
> 
> Checkpoints, and some other sources of writes, will often end up doing a lot
> of smgrwriteback() calls - which pg_stat_io doesn't track. Nor do any
> pre-existing forms of IO statistics.
> 
> It seems pretty clear that we should track writeback as well. I wonder if it's
> worth doing so for 16? It'd give a more complete picture that way. The
> counter-argument I see is that we didn't track the time for it in existing
> stats either, and that nobody complained - but I suspect that's mostly because
> nobody knew to look.

Not complaining about making pg_stat_io more accurate, but what exactly
would we be tracking for smgrwriteback()? I assume you are talking about
IO timing. AFAICT, on Linux, it does sync_file_range() with
SYNC_FILE_RANGE_WRITE, which is asynchronous. Wouldn't we just be
tracking the system call overhead time?

- Melanie

  5. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Andres Freund <andres@anarazel.de> — 2023-04-24T21:14:32Z

    Hi,

On 2023-04-24 16:39:36 -0400, Melanie Plageman wrote:
> On Wed, Apr 19, 2023 at 10:23:26AM -0700, Andres Freund wrote:
> > Hi,
> > 
> > I noticed that the numbers in pg_stat_io dont't quite add up to what I
> > expected in write heavy workloads. Particularly for checkpointer, the numbers
> > for "write" in log_checkpoints output are larger than what is visible in
> > pg_stat_io.
> > 
> > That partially is because log_checkpoints' "write" covers way too many things,
> > but there's an issue with pg_stat_io as well:
> > 
> > Checkpoints, and some other sources of writes, will often end up doing a lot
> > of smgrwriteback() calls - which pg_stat_io doesn't track. Nor do any
> > pre-existing forms of IO statistics.
> > 
> > It seems pretty clear that we should track writeback as well. I wonder if it's
> > worth doing so for 16? It'd give a more complete picture that way. The
> > counter-argument I see is that we didn't track the time for it in existing
> > stats either, and that nobody complained - but I suspect that's mostly because
> > nobody knew to look.
> 
> Not complaining about making pg_stat_io more accurate, but what exactly
> would we be tracking for smgrwriteback()? I assume you are talking about
> IO timing. AFAICT, on Linux, it does sync_file_range() with
> SYNC_FILE_RANGE_WRITE, which is asynchronous. Wouldn't we just be
> tracking the system call overhead time?

It starts blocking once "enough" IO is in flight. For things like an immediate
checkpoint, that can happen fairly quickly, unless you have a very fast IO
subsystem. So often it'll not matter whether we track smgrwriteback(), but
when it matter, it can matter a lot.

As an example, I inited' a pgbench w/ scale 1000, on a decent but not great
NVMe SSD. Created dirty data with:

  c=96;/srv/dev/build/m-opt/src/bin/pgbench/pgbench --random-seed=0 -n -M prepared -c$c -j$c -T30 -P1
and then measured the checkpoint:
  perf trace -s -p $pid_of_checkpointer psql -x -c "SELECT pg_stat_reset_shared('io')" -c "checkpoint"

 postgres (367444), 1891280 events, 100.0%

   syscall            calls  errors  total       min       avg       max       stddev
                                     (msec)    (msec)    (msec)    (msec)        (%)
   --------------- --------  ------ -------- --------- --------- ---------     ------
   sync_file_range   359176      0  4560.670     0.002     0.013   238.955     10.36%
   pwrite64          582964      0  2874.634     0.003     0.005     0.156      0.06%
   fsync                242      0   251.631     0.001     1.040    42.166     18.81%
   openat               317     65     2.171     0.002     0.007     0.068      5.69%
   rename                69      0     1.973     0.012     0.029     0.084      5.81%
   fdatasync              1      0     1.543     1.543     1.543     1.543      0.00%
   unlink               150    137     1.278     0.002     0.009     0.062     10.69%
   close                250      0     0.694     0.001     0.003     0.007      3.14%
   newfstatat           140     68     0.667     0.001     0.005     0.022      7.26%
   write                  5      0     0.067     0.005     0.013     0.025     24.55%
   lseek                 14      0     0.050     0.001     0.004     0.018     33.87%
   getdents64             8      0     0.047     0.002     0.006     0.022     39.51%
   kill                   3      0     0.029     0.008     0.010     0.011     10.18%
   epoll_wait             2      1     0.006     0.000     0.003     0.006    100.00%
   read                   1      0     0.004     0.004     0.004     0.004      0.00%

Log output:

2023-04-24 14:11:59.234 PDT [367444][checkpointer][:0][] LOG:  checkpoint starting: immediate force wait
2023-04-24 14:12:09.236 PDT [367444][checkpointer][:0][] LOG:  checkpoint complete: wrote 595974 buffers (28.4%); 0 WAL file(s) added, 0 removed, 68 recycled; write=9.740 s, sync=0.057 s, total=10.002 s; sync files=27, longest=0.043 s, average=0.003 s; distance=4467386 kB, estimate=4467386 kB; lsn=6/E5D33F98, redo lsn=6/E5D33F28


# SELECT writes, write_time, fsyncs, fsync_time FROM pg_stat_io WHERE backend_type = 'checkpointer';
┌────────┬────────────────────┬────────┬────────────┐
│ writes │     write_time     │ fsyncs │ fsync_time │
├────────┼────────────────────┼────────┼────────────┤
│ 595914 │ 4002.1730000000002 │     24 │     46.359 │
└────────┴────────────────────┴────────┴────────────┘


Greetings,

Andres Freund

  6. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Melanie Plageman <melanieplageman@gmail.com> — 2023-04-24T21:37:48Z

    On Mon, Apr 24, 2023 at 02:14:32PM -0700, Andres Freund wrote:
> Hi,
> 
> On 2023-04-24 16:39:36 -0400, Melanie Plageman wrote:
> > On Wed, Apr 19, 2023 at 10:23:26AM -0700, Andres Freund wrote:
> > > Hi,
> > > 
> > > I noticed that the numbers in pg_stat_io dont't quite add up to what I
> > > expected in write heavy workloads. Particularly for checkpointer, the numbers
> > > for "write" in log_checkpoints output are larger than what is visible in
> > > pg_stat_io.
> > > 
> > > That partially is because log_checkpoints' "write" covers way too many things,
> > > but there's an issue with pg_stat_io as well:
> > > 
> > > Checkpoints, and some other sources of writes, will often end up doing a lot
> > > of smgrwriteback() calls - which pg_stat_io doesn't track. Nor do any
> > > pre-existing forms of IO statistics.
> > > 
> > > It seems pretty clear that we should track writeback as well. I wonder if it's
> > > worth doing so for 16? It'd give a more complete picture that way. The
> > > counter-argument I see is that we didn't track the time for it in existing
> > > stats either, and that nobody complained - but I suspect that's mostly because
> > > nobody knew to look.
> > 
> > Not complaining about making pg_stat_io more accurate, but what exactly
> > would we be tracking for smgrwriteback()? I assume you are talking about
> > IO timing. AFAICT, on Linux, it does sync_file_range() with
> > SYNC_FILE_RANGE_WRITE, which is asynchronous. Wouldn't we just be
> > tracking the system call overhead time?
> 
> It starts blocking once "enough" IO is in flight. For things like an immediate
> checkpoint, that can happen fairly quickly, unless you have a very fast IO
> subsystem. So often it'll not matter whether we track smgrwriteback(), but
> when it matter, it can matter a lot.

I see. So, it sounds like this is most likely to happen for checkpointer
and not likely to happen for other backends who call
ScheduleBufferTagForWriteback(). Also, it seems like this (given the
current code) is only reachable for permanent relations (i.e. not for IO
object temp relation). If other backend types than checkpointer may call
smgrwriteback(), we likely have to consider the IO context. I would
imagine that we want to smgrwriteback() timing to writes/write time for
the relevant IO context and backend type.

- Melanie

  7. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Andres Freund <andres@anarazel.de> — 2023-04-24T22:13:00Z

    Hi,

On 2023-04-24 17:37:48 -0400, Melanie Plageman wrote:
> On Mon, Apr 24, 2023 at 02:14:32PM -0700, Andres Freund wrote:
> > It starts blocking once "enough" IO is in flight. For things like an immediate
> > checkpoint, that can happen fairly quickly, unless you have a very fast IO
> > subsystem. So often it'll not matter whether we track smgrwriteback(), but
> > when it matter, it can matter a lot.
> 
> I see. So, it sounds like this is most likely to happen for checkpointer
> and not likely to happen for other backends who call
> ScheduleBufferTagForWriteback().

It's more likely, but once the IO subsystem is busy, it'll also happen for
other users ScheduleBufferTagForWriteback().


> Also, it seems like this (given the current code) is only reachable for
> permanent relations (i.e. not for IO object temp relation). If other backend
> types than checkpointer may call smgrwriteback(), we likely have to consider
> the IO context.

I think we should take it into account - it'd e.g. interesting to see a COPY
is bottlenecked on smgrwriteback() rather than just writing the data.


> I would imagine that we want to smgrwriteback() timing to writes/write time
> for the relevant IO context and backend type.

Yes.

Greetings,

Andres Freund

  8. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Andres Freund <andres@anarazel.de> — 2023-04-24T22:14:20Z

    Hi,

On 2023-04-24 10:52:15 +0530, Amit Kapila wrote:
> On Sun, Apr 23, 2023 at 12:55 AM Jonathan S. Katz <jkatz@postgresql.org> wrote:
> > > I wonder if it's
> > > worth doing so for 16? It'd give a more complete picture that way. The
> > > counter-argument I see is that we didn't track the time for it in existing
> > > stats either, and that nobody complained - but I suspect that's mostly because
> > > nobody knew to look.
> >
> > [RMT hat]
> >
> > (sorry for slow reply on this, I've been out for a few days).
> >
> > It does sound generally helpful to track writeback to ensure anyone
> > building around pg_stat_io can see tthe more granular picture. How big
> > of an effort is this?
> >
> 
> Right, I think this is the key factor to decide whether we can get
> this in PG16 or not. If this is just adding a new column and a few
> existing stats update calls then it should be okay to get in but if
> this requires some more complex work then we can probably update the
> docs.

I suspect it should really just be adding a few stats calls. The only possible
complication that I can see is that we might need to pass a bit more context
down in a place or two.

Greetings,

Andres Freund

  9. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Melanie Plageman <melanieplageman@gmail.com> — 2023-04-24T22:36:24Z

    On Mon, Apr 24, 2023 at 6:13 PM Andres Freund <andres@anarazel.de> wrote:

> Hi,
>
> On 2023-04-24 17:37:48 -0400, Melanie Plageman wrote:
> > On Mon, Apr 24, 2023 at 02:14:32PM -0700, Andres Freund wrote:
> > > It starts blocking once "enough" IO is in flight. For things like an
> immediate
> > > checkpoint, that can happen fairly quickly, unless you have a very
> fast IO
> > > subsystem. So often it'll not matter whether we track smgrwriteback(),
> but
> > > when it matter, it can matter a lot.
> >
> > I see. So, it sounds like this is most likely to happen for checkpointer
> > and not likely to happen for other backends who call
> > ScheduleBufferTagForWriteback().
>
> It's more likely, but once the IO subsystem is busy, it'll also happen for
> other users ScheduleBufferTagForWriteback().
>
>
> > Also, it seems like this (given the current code) is only reachable for
> > permanent relations (i.e. not for IO object temp relation). If other
> backend
> > types than checkpointer may call smgrwriteback(), we likely have to
> consider
> > the IO context.
>
> I think we should take it into account - it'd e.g. interesting to see a
> COPY
> is bottlenecked on smgrwriteback() rather than just writing the data.
>

With the quick and dirty attached patch and using your example but with a
pgbench -T200 on my rather fast local NVMe SSD, you can still see quite
a difference.
This is with a stats reset before the checkpoint.

unpatched:

    backend_type     |    object     |  context  |  writes | write_time |
 fsyncs | fsync_time
---------------------+---------------+-----------+---------+------------+---------+------------
 background writer   | relation      | normal    |     443 |      1.408 |
    0 |          0
 checkpointer        | relation      | normal    |  187804 |    396.829 |
   47 |    254.226

patched:

    backend_type     |    object     |  context  |  writes |     write_time
    | fsyncs | fsync_time
---------------------+---------------+-----------+---------+--------------------+--------+------------
 background writer   | relation      | normal    |     917 |
4.4670000000000005 |      0 |          0
 checkpointer        | relation      | normal    |  375798 |
 977.354 |     48 |    202.514

I did compare client backend stats before and after pgbench and it made
basically no difference. I'll do a COPY example like you mentioned.

Patch needs cleanup/comments and a bit more work, but I could do with
a sanity check review on the approach.

- Melanie

  10. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Andres Freund <andres@anarazel.de> — 2023-04-24T22:56:54Z

    Hi,

On 2023-04-24 18:36:24 -0400, Melanie Plageman wrote:
> On Mon, Apr 24, 2023 at 6:13 PM Andres Freund <andres@anarazel.de> wrote:
> > > Also, it seems like this (given the current code) is only reachable for
> > > permanent relations (i.e. not for IO object temp relation). If other
> > backend
> > > types than checkpointer may call smgrwriteback(), we likely have to
> > consider
> > > the IO context.
> >
> > I think we should take it into account - it'd e.g. interesting to see a
> > COPY
> > is bottlenecked on smgrwriteback() rather than just writing the data.
> >
> 
> With the quick and dirty attached patch and using your example but with a
> pgbench -T200 on my rather fast local NVMe SSD, you can still see quite
> a difference.

Quite a difference between what?

What scale of pgbench did you use?

-T200 is likely not a good idea, because a timed checkpoint might "interfere",
unless you use a non-default checkpoint_timeout. A timed checkpoint won't show
the issue as easily, because checkpointer spend most of the time sleeping.


> This is with a stats reset before the checkpoint.
> 
> unpatched:
> 
>     backend_type     |    object     |  context  |  writes | write_time |
>  fsyncs | fsync_time
> ---------------------+---------------+-----------+---------+------------+---------+------------
>  background writer   | relation      | normal    |     443 |      1.408 |
>     0 |          0
>  checkpointer        | relation      | normal    |  187804 |    396.829 |
>    47 |    254.226
> 
> patched:
> 
>     backend_type     |    object     |  context  |  writes |     write_time
>     | fsyncs | fsync_time
> ---------------------+---------------+-----------+---------+--------------------+--------+------------
>  background writer   | relation      | normal    |     917 |
> 4.4670000000000005 |      0 |          0
>  checkpointer        | relation      | normal    |  375798 |
>  977.354 |     48 |    202.514
> 
> I did compare client backend stats before and after pgbench and it made
> basically no difference. I'll do a COPY example like you mentioned.


> Patch needs cleanup/comments and a bit more work, but I could do with
> a sanity check review on the approach.

I was thinking we'd track writeback separately from the write, rather than
attributing the writeback to "write".  Otherwise it looks good, based on a
quick skim.

Greetings,

Andres Freund

  11. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Melanie Plageman <melanieplageman@gmail.com> — 2023-04-24T23:02:47Z

    On Mon, Apr 24, 2023 at 03:56:54PM -0700, Andres Freund wrote:
> Hi,
> 
> On 2023-04-24 18:36:24 -0400, Melanie Plageman wrote:
> > On Mon, Apr 24, 2023 at 6:13 PM Andres Freund <andres@anarazel.de> wrote:
> > > > Also, it seems like this (given the current code) is only reachable for
> > > > permanent relations (i.e. not for IO object temp relation). If other
> > > backend
> > > > types than checkpointer may call smgrwriteback(), we likely have to
> > > consider
> > > > the IO context.
> > >
> > > I think we should take it into account - it'd e.g. interesting to see a
> > > COPY
> > > is bottlenecked on smgrwriteback() rather than just writing the data.
> > >
> > 
> > With the quick and dirty attached patch and using your example but with a
> > pgbench -T200 on my rather fast local NVMe SSD, you can still see quite
> > a difference.
> 
> Quite a difference between what?

With and without the patch. Meaning: clearly tracking writeback is a good idea.

> 
> What scale of pgbench did you use?

1000, as you did

> 
> -T200 is likely not a good idea, because a timed checkpoint might "interfere",
> unless you use a non-default checkpoint_timeout. A timed checkpoint won't show
> the issue as easily, because checkpointer spend most of the time sleeping.

Ah, I see. I did not use a non-default checkpoint timeout.

> > Patch needs cleanup/comments and a bit more work, but I could do with
> > a sanity check review on the approach.
> 
> I was thinking we'd track writeback separately from the write, rather than
> attributing the writeback to "write".  Otherwise it looks good, based on a
> quick skim.

Like you want a separate IOOp IOOP_WRITEBACK? Interesting. Okay.

- Melanie

  12. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Jonathan S. Katz <jkatz@postgresql.org> — 2023-04-24T23:20:30Z

    
On 4/24/23 6:14 PM, Andres Freund wrote:
> Hi,
> 
> On 2023-04-24 10:52:15 +0530, Amit Kapila wrote:
>> On Sun, Apr 23, 2023 at 12:55 AM Jonathan S. Katz <jkatz@postgresql.org> wrote:
>>>> I wonder if it's
>>>> worth doing so for 16? It'd give a more complete picture that way. The
>>>> counter-argument I see is that we didn't track the time for it in existing
>>>> stats either, and that nobody complained - but I suspect that's mostly because
>>>> nobody knew to look.
>>>
>>> [RMT hat]
>>>
>>> (sorry for slow reply on this, I've been out for a few days).
>>>
>>> It does sound generally helpful to track writeback to ensure anyone
>>> building around pg_stat_io can see tthe more granular picture. How big
>>> of an effort is this?
>>>
>>
>> Right, I think this is the key factor to decide whether we can get
>> this in PG16 or not. If this is just adding a new column and a few
>> existing stats update calls then it should be okay to get in but if
>> this requires some more complex work then we can probably update the
>> docs.
> 
> I suspect it should really just be adding a few stats calls. The only possible
> complication that I can see is that we might need to pass a bit more context
> down in a place or two.

OK. So far it sounds reasonable to include. I think we should add this 
as an open item. I don't know if we need to set a deadline just yet, but 
we should try to keep go/nogo to earlier in the beta cycle.

Thanks,

Jonathan

  13. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Melanie Plageman <melanieplageman@gmail.com> — 2023-04-25T01:29:48Z

    On Mon, Apr 24, 2023 at 7:02 PM Melanie Plageman <melanieplageman@gmail.com>
wrote:

> On Mon, Apr 24, 2023 at 03:56:54PM -0700, Andres Freund wrote:
> >
> > I was thinking we'd track writeback separately from the write, rather
> than
> > attributing the writeback to "write".  Otherwise it looks good, based on
> a
> > quick skim.
>
> Like you want a separate IOOp IOOP_WRITEBACK? Interesting. Okay.
>


Okay, attached v2 does this (adds IOOP_WRITEBACK).

With my patch applied and the same pgbench setup as you (for -T30):

After pgbench:

    backend_type     |    object     |  context  |  writes  | write_time |
writebacks | writeback_time |  fsyncs | fsync_time |
---------------------+---------------+-----------+----------+------------+------------+----------------+---------+------------+
 background writer   | relation      | normal    |     5581 |     23.416 |
      5568 |          32.33 |       0 |          0 |
 checkpointer        | relation      | normal    |    89116 |    295.576 |
     89106 |          416.5 |      84 |   5242.764 |


and then after a stats reset followed by an explicit checkpoint:


    backend_type     |    object     |  context  |  writes |     write_time
    | writebacks | writeback_time |  fsyncs | fsync_time |
---------------------+---------------+-----------+---------+--------------------+------------+----------------+---------+------------+
 checkpointer        | relation      | normal    |  229807 |
457.43600000000004 |     229817 |         532.84 |      52 |    378.652 |


I've yet to cook up a client backend test case (e.g. with COPY). I've taken
that as a todo.

I have a few outstanding questions:

1) Does it make sense for writebacks to count the number of blocks for
which writeback was requested or the number of calls to smgrwriteback() or
the number of actual syscalls made? We don't actually know from outside
of mdwriteback() how many FileWriteback() calls we will make.

2) I'm a little nervous about not including IOObject in the writeback
context. Technically, there is nothing stopping local buffer code from
calling IssuePendingWritebacks(). Right now, local buffer code doesn't
do ScheduleBufferTagForWriteback(). But it doesn't seem quite right to
hardcode in IOOBJECT_RELATION when there is nothing wrong with
requesting writeback of local buffers (AFAIK). What do you think?

3) Should any restrictions be added to pgstat_tracks_io_object() or
pgstat_tracks_io_op()? I couldn't think of any backend types or IO
contexts which would not do writeback as a rule. Also, though we don't
do writeback for temp tables now, it isn't nonsensical to do so. In
this version, I didn't add any restrictions.

Docs need work. I added a placeholder for the new columns. I'll update it
once we decide what writebacks should actually count. And, I don't think
we can do any kind of ongoing test.

- Melanie

  14. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Melanie Plageman <melanieplageman@gmail.com> — 2023-04-26T21:08:14Z

    On Mon, Apr 24, 2023 at 9:29 PM Melanie Plageman
<melanieplageman@gmail.com> wrote:
> I've yet to cook up a client backend test case (e.g. with COPY). I've taken
> that as a todo.

It was trivial to see client backend writebacks in almost any scenario
once I set backend_flush_after. I wonder if it is worth mentioning the
various "*flush_after" gucs in the docs?

> I have a few outstanding questions:
>
> 1) Does it make sense for writebacks to count the number of blocks for
> which writeback was requested or the number of calls to smgrwriteback() or
> the number of actual syscalls made? We don't actually know from outside
> of mdwriteback() how many FileWriteback() calls we will make.

So, in the attached v3, I've kept the first method: writebacks are the
number of blocks which the backend has requested writeback of. I'd like
it to be clear in the docs exactly what writebacks are (so that people
know not to add them together with writes or something like that). I
made an effort but could use further docs review.

> 2) I'm a little nervous about not including IOObject in the writeback
> context. Technically, there is nothing stopping local buffer code from
> calling IssuePendingWritebacks(). Right now, local buffer code doesn't
> do ScheduleBufferTagForWriteback(). But it doesn't seem quite right to
> hardcode in IOOBJECT_RELATION when there is nothing wrong with
> requesting writeback of local buffers (AFAIK). What do you think?

I've gone ahead and added IOObject to the WritebackContext.

- Melanie

  15. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2023-04-27T02:22:23Z

    At Wed, 26 Apr 2023 17:08:14 -0400, Melanie Plageman <melanieplageman@gmail.com> wrote in 
> On Mon, Apr 24, 2023 at 9:29 PM Melanie Plageman
> <melanieplageman@gmail.com> wrote:
> > I've yet to cook up a client backend test case (e.g. with COPY). I've taken
> > that as a todo.
> 
> It was trivial to see client backend writebacks in almost any scenario
> once I set backend_flush_after. I wonder if it is worth mentioning the
> various "*flush_after" gucs in the docs?
> 
> > I have a few outstanding questions:
> >
> > 1) Does it make sense for writebacks to count the number of blocks for
> > which writeback was requested or the number of calls to smgrwriteback() or
> > the number of actual syscalls made? We don't actually know from outside
> > of mdwriteback() how many FileWriteback() calls we will make.
> 
> So, in the attached v3, I've kept the first method: writebacks are the
> number of blocks which the backend has requested writeback of. I'd like
> it to be clear in the docs exactly what writebacks are (so that people
> know not to add them together with writes or something like that). I
> made an effort but could use further docs review.

+        Number of units of size <varname>op_bytes</varname> which the backend
+        requested the kernel write out to permanent storage.

I just want to mention that it is not necessarily the same as the
number of system calls, but I'm not sure what others think about that.

+        Time spent in writeback operations in milliseconds (if
+        <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero). This
+        does not necessarily count the time spent by the kernel writing the
+        data out. The backend will initiate write-out of the dirty pages and
+        wait only if the request queue is full.

The last sentence looks like it's taken from the sync_file_range() man
page, but I think it's a bit too detailed. We could just say, "The
time usually only includes the time it takes to queue write-out
requests.", bit I'm not sure wh...

> > 2) I'm a little nervous about not including IOObject in the writeback
> > context. Technically, there is nothing stopping local buffer code from
> > calling IssuePendingWritebacks(). Right now, local buffer code doesn't
> > do ScheduleBufferTagForWriteback(). But it doesn't seem quite right to
> > hardcode in IOOBJECT_RELATION when there is nothing wrong with
> > requesting writeback of local buffers (AFAIK). What do you think?
> 
> I've gone ahead and added IOObject to the WritebackContext.

The smgropen call in IssuePendingWritebacks below clearly shows that
the function only deals with shared buffers.

>		/* and finally tell the kernel to write the data to storage */
>		reln = smgropen(currlocator, InvalidBackendId);
>		smgrwriteback(reln, BufTagGetForkNum(&tag), tag.blockNum, nblocks);

The callback-related code fully depends on callers following its
expectation. So we can rewrite the following comment added to
InitBufferPoll with a more confident tone.

+	 * Initialize per-backend file flush context. IOObject is initialized to
+	 * IOOBJECT_RELATION and IOContext to IOCONTEXT_NORMAL since these are the
+	 * most likely targets for writeback. The backend can overwrite these as
+	 * appropriate.

Or I actually think we might not even need to pass around the io_*
parameters and could just pass immediate values to the
pgstat_count_io_op_time call. If we ever start using shared buffers
for thing other than relation files (for example SLRU?), we'll have to
consider the target individually for each buffer block. That being
said, I'm fine with how it is either.

Regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  16. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Melanie Plageman <melanieplageman@gmail.com> — 2023-04-27T15:36:49Z

    Thanks for the review!

On Wed, Apr 26, 2023 at 10:22 PM Kyotaro Horiguchi
<horikyota.ntt@gmail.com> wrote:
>
> At Wed, 26 Apr 2023 17:08:14 -0400, Melanie Plageman <melanieplageman@gmail.com> wrote in
> > On Mon, Apr 24, 2023 at 9:29 PM Melanie Plageman
> > <melanieplageman@gmail.com> wrote:
> > > I've yet to cook up a client backend test case (e.g. with COPY). I've taken
> > > that as a todo.
> >
> > It was trivial to see client backend writebacks in almost any scenario
> > once I set backend_flush_after. I wonder if it is worth mentioning the
> > various "*flush_after" gucs in the docs?
> >
> > > I have a few outstanding questions:
> > >
> > > 1) Does it make sense for writebacks to count the number of blocks for
> > > which writeback was requested or the number of calls to smgrwriteback() or
> > > the number of actual syscalls made? We don't actually know from outside
> > > of mdwriteback() how many FileWriteback() calls we will make.
> >
> > So, in the attached v3, I've kept the first method: writebacks are the
> > number of blocks which the backend has requested writeback of. I'd like
> > it to be clear in the docs exactly what writebacks are (so that people
> > know not to add them together with writes or something like that). I
> > made an effort but could use further docs review.
>
> +        Number of units of size <varname>op_bytes</varname> which the backend
> +        requested the kernel write out to permanent storage.
>
> I just want to mention that it is not necessarily the same as the
> number of system calls, but I'm not sure what others think about that.

My thinking is that some other IO operations, for example, extends,
count the number of blocks extended and not the number of syscalls.

> +        Time spent in writeback operations in milliseconds (if
> +        <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero). This
> +        does not necessarily count the time spent by the kernel writing the
> +        data out. The backend will initiate write-out of the dirty pages and
> +        wait only if the request queue is full.
>
> The last sentence looks like it's taken from the sync_file_range() man
> page, but I think it's a bit too detailed. We could just say, "The
> time usually only includes the time it takes to queue write-out
> requests.", bit I'm not sure wh...

Ah, yes, I indeed took heavy inspiration from the sync_file_range()
man page :) I've modified this comment in the attached v4. I didn't want
to say "usually" since I imagine it is quite workload and configuration
dependent.

> > > 2) I'm a little nervous about not including IOObject in the writeback
> > > context. Technically, there is nothing stopping local buffer code from
> > > calling IssuePendingWritebacks(). Right now, local buffer code doesn't
> > > do ScheduleBufferTagForWriteback(). But it doesn't seem quite right to
> > > hardcode in IOOBJECT_RELATION when there is nothing wrong with
> > > requesting writeback of local buffers (AFAIK). What do you think?
> >
> > I've gone ahead and added IOObject to the WritebackContext.
>
> The smgropen call in IssuePendingWritebacks below clearly shows that
> the function only deals with shared buffers.
>
> >               /* and finally tell the kernel to write the data to storage */
> >               reln = smgropen(currlocator, InvalidBackendId);
> >               smgrwriteback(reln, BufTagGetForkNum(&tag), tag.blockNum, nblocks);

Yes, as it is currently, IssuePendingWritebacks() is only used for shared
buffers. My rationale for including IOObject is that localbuf.c calls
smgr* functions and there isn't anything stopping it from calling
smgrwriteback() or using WritebackContexts (AFAICT).

> The callback-related code fully depends on callers following its
> expectation. So we can rewrite the following comment added to
> InitBufferPoll with a more confident tone.
>
> +        * Initialize per-backend file flush context. IOObject is initialized to
> +        * IOOBJECT_RELATION and IOContext to IOCONTEXT_NORMAL since these are the
> +        * most likely targets for writeback. The backend can overwrite these as
> +        * appropriate.

I have updated this comment to be more confident and specific.

> Or I actually think we might not even need to pass around the io_*
> parameters and could just pass immediate values to the
> pgstat_count_io_op_time call. If we ever start using shared buffers
> for thing other than relation files (for example SLRU?), we'll have to
> consider the target individually for each buffer block. That being
> said, I'm fine with how it is either.

In IssuePendingWritebacks() we don't actually know which IOContext we
are issuing writebacks for when we call pgstat_count_io_op_time() (we do
issue pending writebacks for other IOContexts than IOCONTEXT_NORMAL). I
agree IOObject is not strictly necessary right now. I've kept IOObject a
member of WritebackContext for the reasons I mention above, however, I
am open to removing it if it adds confusion.

- Melanie

  17. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Jonathan S. Katz <jkatz@postgresql.org> — 2023-05-03T15:36:10Z

    On 4/27/23 11:36 AM, Melanie Plageman wrote:
> Thanks for the review!
> 
> On Wed, Apr 26, 2023 at 10:22 PM Kyotaro Horiguchi
> <horikyota.ntt@gmail.com> wrote:
>>
>> At Wed, 26 Apr 2023 17:08:14 -0400, Melanie Plageman <melanieplageman@gmail.com> wrote in
>>> On Mon, Apr 24, 2023 at 9:29 PM Melanie Plageman
>>> <melanieplageman@gmail.com> wrote:
>>>> I've yet to cook up a client backend test case (e.g. with COPY). I've taken
>>>> that as a todo.
>>>
>>> It was trivial to see client backend writebacks in almost any scenario
>>> once I set backend_flush_after. I wonder if it is worth mentioning the
>>> various "*flush_after" gucs in the docs?
>>>
>>>> I have a few outstanding questions:
>>>>
>>>> 1) Does it make sense for writebacks to count the number of blocks for
>>>> which writeback was requested or the number of calls to smgrwriteback() or
>>>> the number of actual syscalls made? We don't actually know from outside
>>>> of mdwriteback() how many FileWriteback() calls we will make.
>>>
>>> So, in the attached v3, I've kept the first method: writebacks are the
>>> number of blocks which the backend has requested writeback of. I'd like
>>> it to be clear in the docs exactly what writebacks are (so that people
>>> know not to add them together with writes or something like that). I
>>> made an effort but could use further docs review.
>>
>> +        Number of units of size <varname>op_bytes</varname> which the backend
>> +        requested the kernel write out to permanent storage.
>>
>> I just want to mention that it is not necessarily the same as the
>> number of system calls, but I'm not sure what others think about that.
> 
> My thinking is that some other IO operations, for example, extends,
> count the number of blocks extended and not the number of syscalls.
> 
>> +        Time spent in writeback operations in milliseconds (if
>> +        <xref linkend="guc-track-io-timing"/> is enabled, otherwise zero). This
>> +        does not necessarily count the time spent by the kernel writing the
>> +        data out. The backend will initiate write-out of the dirty pages and
>> +        wait only if the request queue is full.
>>
>> The last sentence looks like it's taken from the sync_file_range() man
>> page, but I think it's a bit too detailed. We could just say, "The
>> time usually only includes the time it takes to queue write-out
>> requests.", bit I'm not sure wh...
> 
> Ah, yes, I indeed took heavy inspiration from the sync_file_range()
> man page :) I've modified this comment in the attached v4. I didn't want
> to say "usually" since I imagine it is quite workload and configuration
> dependent.
> 
>>>> 2) I'm a little nervous about not including IOObject in the writeback
>>>> context. Technically, there is nothing stopping local buffer code from
>>>> calling IssuePendingWritebacks(). Right now, local buffer code doesn't
>>>> do ScheduleBufferTagForWriteback(). But it doesn't seem quite right to
>>>> hardcode in IOOBJECT_RELATION when there is nothing wrong with
>>>> requesting writeback of local buffers (AFAIK). What do you think?
>>>
>>> I've gone ahead and added IOObject to the WritebackContext.
>>
>> The smgropen call in IssuePendingWritebacks below clearly shows that
>> the function only deals with shared buffers.
>>
>>>                /* and finally tell the kernel to write the data to storage */
>>>                reln = smgropen(currlocator, InvalidBackendId);
>>>                smgrwriteback(reln, BufTagGetForkNum(&tag), tag.blockNum, nblocks);
> 
> Yes, as it is currently, IssuePendingWritebacks() is only used for shared
> buffers. My rationale for including IOObject is that localbuf.c calls
> smgr* functions and there isn't anything stopping it from calling
> smgrwriteback() or using WritebackContexts (AFAICT).
> 
>> The callback-related code fully depends on callers following its
>> expectation. So we can rewrite the following comment added to
>> InitBufferPoll with a more confident tone.
>>
>> +        * Initialize per-backend file flush context. IOObject is initialized to
>> +        * IOOBJECT_RELATION and IOContext to IOCONTEXT_NORMAL since these are the
>> +        * most likely targets for writeback. The backend can overwrite these as
>> +        * appropriate.
> 
> I have updated this comment to be more confident and specific.
> 
>> Or I actually think we might not even need to pass around the io_*
>> parameters and could just pass immediate values to the
>> pgstat_count_io_op_time call. If we ever start using shared buffers
>> for thing other than relation files (for example SLRU?), we'll have to
>> consider the target individually for each buffer block. That being
>> said, I'm fine with how it is either.
> 
> In IssuePendingWritebacks() we don't actually know which IOContext we
> are issuing writebacks for when we call pgstat_count_io_op_time() (we do
> issue pending writebacks for other IOContexts than IOCONTEXT_NORMAL). I
> agree IOObject is not strictly necessary right now. I've kept IOObject a
> member of WritebackContext for the reasons I mention above, however, I
> am open to removing it if it adds confusion.

[RMT hat]

Horiguchi-san: do the changes that Melanie made address your feedback?

It'd be good if we can get this into Beta 1 if everyone is comfortable 
with the patch.

Thanks,

Jonathan

  18. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Andres Freund <andres@anarazel.de> — 2023-05-04T16:44:02Z

    Hi,

On 2023-04-27 11:36:49 -0400, Melanie Plageman wrote:
> > >               /* and finally tell the kernel to write the data to storage */
> > >               reln = smgropen(currlocator, InvalidBackendId);
> > >               smgrwriteback(reln, BufTagGetForkNum(&tag), tag.blockNum, nblocks);
> 
> Yes, as it is currently, IssuePendingWritebacks() is only used for shared
> buffers. My rationale for including IOObject is that localbuf.c calls
> smgr* functions and there isn't anything stopping it from calling
> smgrwriteback() or using WritebackContexts (AFAICT).

I think it's extremely unlikely that we'll ever do that, because it's very
common to have temp tables that are bigger than temp_buffers. We basically
hope that the kernel can do good caching for us there.


> > Or I actually think we might not even need to pass around the io_*
> > parameters and could just pass immediate values to the
> > pgstat_count_io_op_time call. If we ever start using shared buffers
> > for thing other than relation files (for example SLRU?), we'll have to
> > consider the target individually for each buffer block. That being
> > said, I'm fine with how it is either.
> 
> In IssuePendingWritebacks() we don't actually know which IOContext we
> are issuing writebacks for when we call pgstat_count_io_op_time() (we do
> issue pending writebacks for other IOContexts than IOCONTEXT_NORMAL). I
> agree IOObject is not strictly necessary right now. I've kept IOObject a
> member of WritebackContext for the reasons I mention above, however, I
> am open to removing it if it adds confusion.

I don't think it's really worth adding struct members for potential future
safety. We can just add them later if we end up needing them.


> From 7cdd6fc78ed82180a705ab9667714f80d08c5f7d Mon Sep 17 00:00:00 2001
> From: Melanie Plageman <melanieplageman@gmail.com>
> Date: Mon, 24 Apr 2023 18:21:54 -0400
> Subject: [PATCH v4] Add writeback to pg_stat_io
> 
> 28e626bde00 added the notion of IOOps but neglected to include
> writeback. With the addition of IO timing to pg_stat_io in ac8d53dae5,
> the omission of writeback caused some confusion. Checkpointer write
> timing in pg_stat_io often differed greatly from the write timing
> written to the log. To fix this, add IOOp IOOP_WRITEBACK and track
> writebacks and writeback timing in pg_stat_io.

For the future: It'd be good to note that catversion needs to be increased.

Off-topic: I've been wondering about computing a "catversion hash" based on
all the files going into initdb. At least to have some tooling to detect
missing catversion increases...


> index 99f7f95c39..27b6f1a0a0 100644
> --- a/doc/src/sgml/monitoring.sgml
> +++ b/doc/src/sgml/monitoring.sgml
> @@ -3867,6 +3867,32 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i
>        </entry>
>       </row>
>  
> +     <row>
> +      <entry role="catalog_table_entry">
> +       <para role="column_definition">
> +        <structfield>writebacks</structfield> <type>bigint</type>
> +       </para>
> +       <para>
> +        Number of units of size <varname>op_bytes</varname> which the backend
> +        requested the kernel write out to permanent storage.
> +       </para>
> +      </entry>
> +     </row>

I think the reference to "backend" here is somewhat misplaced - it could be
checkpointer or bgwriter as well. We don't reference the backend in other
comparable columns of pgsio either...


> diff --git a/src/backend/storage/buffer/buf_init.c b/src/backend/storage/buffer/buf_init.c
> index 0057443f0c..a7182fe95a 100644
> --- a/src/backend/storage/buffer/buf_init.c
> +++ b/src/backend/storage/buffer/buf_init.c
> @@ -145,9 +145,15 @@ InitBufferPool(void)
>  	/* Init other shared buffer-management stuff */
>  	StrategyInitialize(!foundDescs);
>  
> -	/* Initialize per-backend file flush context */
> -	WritebackContextInit(&BackendWritebackContext,
> -						 &backend_flush_after);
> +	/*
> +	 * Initialize per-backend file flush context. IOContext is initialized to
> +	 * IOCONTEXT_NORMAL because this is the most common context. IOObject is
> +	 * initialized to IOOBJECT_RELATION because writeback is currently only
> +	 * requested for permanent relations in shared buffers. The backend can
> +	 * overwrite these as appropriate.
> +	 */
> +	WritebackContextInit(&BackendWritebackContext, IOOBJECT_RELATION,
> +						 IOCONTEXT_NORMAL, &backend_flush_after);
>  }
>

This seems somewhat icky.


>  /*
> diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
> index 1fa689052e..116910cdfe 100644
> --- a/src/backend/storage/buffer/bufmgr.c
> +++ b/src/backend/storage/buffer/bufmgr.c
> @@ -1685,6 +1685,8 @@ again:
>  		FlushBuffer(buf_hdr, NULL, IOOBJECT_RELATION, io_context);
>  		LWLockRelease(content_lock);
>  
> +		BackendWritebackContext.io_object = IOOBJECT_RELATION;
> +		BackendWritebackContext.io_context = io_context;
>  		ScheduleBufferTagForWriteback(&BackendWritebackContext,
>  									  &buf_hdr->tag);
>  	}

What about passing the io_context to ScheduleBufferTagForWriteback instead?


> --- a/src/test/regress/sql/stats.sql
> +++ b/src/test/regress/sql/stats.sql

Hm. Could we add a test for this? While it's not implemented everywhere, we
still issue the smgrwriteback() afaics. The default for the _flush_after GUCs
changes, but backend_flush_after is USERSET, so we could just change it for a
single command.

Greetings,

Andres Freund

  19. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Andres Freund <andres@anarazel.de> — 2023-05-04T16:46:54Z

    Hi,

On 2023-05-03 11:36:10 -0400, Jonathan S. Katz wrote:
> It'd be good if we can get this into Beta 1 if everyone is comfortable with
> the patch.

I think we need one more iteration, then I think it can be committed. The
changes are docs phrasing and polishing the API a bit, which shouldn't be too
hard.  I'll try to look more tomorrow.

Greetings,

Andres Freund

  20. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Andres Freund <andres@anarazel.de> — 2023-05-04T16:57:38Z

    Hi,

On 2023-04-24 21:29:48 -0400, Melanie Plageman wrote:
> 1) Does it make sense for writebacks to count the number of blocks for
> which writeback was requested or the number of calls to smgrwriteback() or
> the number of actual syscalls made? We don't actually know from outside
> of mdwriteback() how many FileWriteback() calls we will make.

The number of blocks is the right thing IMO. The rest is just some
micro-optimization.


> 2) I'm a little nervous about not including IOObject in the writeback
> context. Technically, there is nothing stopping local buffer code from
> calling IssuePendingWritebacks(). Right now, local buffer code doesn't
> do ScheduleBufferTagForWriteback(). But it doesn't seem quite right to
> hardcode in IOOBJECT_RELATION when there is nothing wrong with
> requesting writeback of local buffers (AFAIK). What do you think?

I think it'd be wrong on performance grounds ;). We could add an assertion to
ScheduleBufferTagForWriteback(), I guess, to document that fact?


> 3) Should any restrictions be added to pgstat_tracks_io_object() or
> pgstat_tracks_io_op()? I couldn't think of any backend types or IO
> contexts which would not do writeback as a rule. Also, though we don't
> do writeback for temp tables now, it isn't nonsensical to do so. In
> this version, I didn't add any restrictions.

I think the temp table restriction could be encoded for now, I don't forsee
that changing anytime soon.

About other restrictions: Anything that triggers catalog access can trigger
buffers to be written back. Checkpointer and bgwriter don't do catalog access,
but have explicit writeback calls. WAL receiver, WAL writer, syslogger and
archiver are excluded on a backend type basis.  I think the startup process
will use the normal backend logic, and thus also trigger writebacks?

Greetings,

Andres Freund

  21. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Jonathan S. Katz <jkatz@postgresql.org> — 2023-05-04T19:41:57Z

    On 5/4/23 12:46 PM, Andres Freund wrote:
> Hi,
> 
> On 2023-05-03 11:36:10 -0400, Jonathan S. Katz wrote:
>> It'd be good if we can get this into Beta 1 if everyone is comfortable with
>> the patch.
> 
> I think we need one more iteration, then I think it can be committed. The
> changes are docs phrasing and polishing the API a bit, which shouldn't be too
> hard.  I'll try to look more tomorrow.

[RMT hat, personal opinion]

Great to hear. From my skim of the patch, I had thought the conclusion 
would be something similar, but did want to hear from you & Melanie on that.

Thanks,

Jonathan

  22. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Melanie Plageman <melanieplageman@gmail.com> — 2023-05-06T17:30:39Z

    v5 attached.

On Thu, May 4, 2023 at 12:44 PM Andres Freund <andres@anarazel.de> wrote:
> On 2023-04-27 11:36:49 -0400, Melanie Plageman wrote:
> > > >               /* and finally tell the kernel to write the data to storage */
> > > >               reln = smgropen(currlocator, InvalidBackendId);
> > > >               smgrwriteback(reln, BufTagGetForkNum(&tag), tag.blockNum, nblocks);
> >
> > Yes, as it is currently, IssuePendingWritebacks() is only used for shared
> > buffers. My rationale for including IOObject is that localbuf.c calls
> > smgr* functions and there isn't anything stopping it from calling
> > smgrwriteback() or using WritebackContexts (AFAICT).
>
> I think it's extremely unlikely that we'll ever do that, because it's very
> common to have temp tables that are bigger than temp_buffers. We basically
> hope that the kernel can do good caching for us there.
>
>
> > > Or I actually think we might not even need to pass around the io_*
> > > parameters and could just pass immediate values to the
> > > pgstat_count_io_op_time call. If we ever start using shared buffers
> > > for thing other than relation files (for example SLRU?), we'll have to
> > > consider the target individually for each buffer block. That being
> > > said, I'm fine with how it is either.
> >
> > In IssuePendingWritebacks() we don't actually know which IOContext we
> > are issuing writebacks for when we call pgstat_count_io_op_time() (we do
> > issue pending writebacks for other IOContexts than IOCONTEXT_NORMAL). I
> > agree IOObject is not strictly necessary right now. I've kept IOObject a
> > member of WritebackContext for the reasons I mention above, however, I
> > am open to removing it if it adds confusion.
>
> I don't think it's really worth adding struct members for potential future
> safety. We can just add them later if we end up needing them.

I've removed both members of WritebackContext and hard-coded
IOOBJECT_RELATION in the call to pgstat_count_io_op_time().

> > From 7cdd6fc78ed82180a705ab9667714f80d08c5f7d Mon Sep 17 00:00:00 2001
> > From: Melanie Plageman <melanieplageman@gmail.com>
> > Date: Mon, 24 Apr 2023 18:21:54 -0400
> > Subject: [PATCH v4] Add writeback to pg_stat_io
> >
> > 28e626bde00 added the notion of IOOps but neglected to include
> > writeback. With the addition of IO timing to pg_stat_io in ac8d53dae5,
> > the omission of writeback caused some confusion. Checkpointer write
> > timing in pg_stat_io often differed greatly from the write timing
> > written to the log. To fix this, add IOOp IOOP_WRITEBACK and track
> > writebacks and writeback timing in pg_stat_io.
>
> For the future: It'd be good to note that catversion needs to be increased.

Noted. I've added it to the commit message since I did a new version
anyway.

> > index 99f7f95c39..27b6f1a0a0 100644
> > --- a/doc/src/sgml/monitoring.sgml
> > +++ b/doc/src/sgml/monitoring.sgml
> > @@ -3867,6 +3867,32 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i
> >        </entry>
> >       </row>
> >
> > +     <row>
> > +      <entry role="catalog_table_entry">
> > +       <para role="column_definition">
> > +        <structfield>writebacks</structfield> <type>bigint</type>
> > +       </para>
> > +       <para>
> > +        Number of units of size <varname>op_bytes</varname> which the backend
> > +        requested the kernel write out to permanent storage.
> > +       </para>
> > +      </entry>
> > +     </row>
>
> I think the reference to "backend" here is somewhat misplaced - it could be
> checkpointer or bgwriter as well. We don't reference the backend in other
> comparable columns of pgsio either...

So, I tried to come up with something that doesn't make reference to
any "requester" of the writeback and the best I could do was:

"Number of units of size op_bytes requested that the kernel write out."

This is awfully awkward sounding.

"backend_type" is the name of the column in pg_stat_io. Client backends
are always referred to as such in the pg_stat_io documentation. Thus, I
think it is reasonable to use the word "backend" and assume people
understand it could be any type of backend.

However, since the existing docs for pg_stat_bgwriter use "backend" to
mean "client backend", and I see a few uses of the word "process" in the
stats docs, I've changed my use of the word "backend" to "process".

> > diff --git a/src/backend/storage/buffer/buf_init.c b/src/backend/storage/buffer/buf_init.c
> > index 0057443f0c..a7182fe95a 100644
> > --- a/src/backend/storage/buffer/buf_init.c
> > +++ b/src/backend/storage/buffer/buf_init.c
> > @@ -145,9 +145,15 @@ InitBufferPool(void)
> >       /* Init other shared buffer-management stuff */
> >       StrategyInitialize(!foundDescs);
> >
> > -     /* Initialize per-backend file flush context */
> > -     WritebackContextInit(&BackendWritebackContext,
> > -                                              &backend_flush_after);
> > +     /*
> > +      * Initialize per-backend file flush context. IOContext is initialized to
> > +      * IOCONTEXT_NORMAL because this is the most common context. IOObject is
> > +      * initialized to IOOBJECT_RELATION because writeback is currently only
> > +      * requested for permanent relations in shared buffers. The backend can
> > +      * overwrite these as appropriate.
> > +      */
> > +     WritebackContextInit(&BackendWritebackContext, IOOBJECT_RELATION,
> > +                                              IOCONTEXT_NORMAL, &backend_flush_after);
> >  }
> >
>
> This seems somewhat icky.

I've removed both IOObject and IOContext from WritebackContext.

> >  /*
> > diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
> > index 1fa689052e..116910cdfe 100644
> > --- a/src/backend/storage/buffer/bufmgr.c
> > +++ b/src/backend/storage/buffer/bufmgr.c
> > @@ -1685,6 +1685,8 @@ again:
> >               FlushBuffer(buf_hdr, NULL, IOOBJECT_RELATION, io_context);
> >               LWLockRelease(content_lock);
> >
> > +             BackendWritebackContext.io_object = IOOBJECT_RELATION;
> > +             BackendWritebackContext.io_context = io_context;
> >               ScheduleBufferTagForWriteback(&BackendWritebackContext,
> >                                                                         &buf_hdr->tag);
> >       }
>
> What about passing the io_context to ScheduleBufferTagForWriteback instead?

I assume we don't want to include the time spent in
sort_pending_writebacks(), so I've added io_context as a parameter to
ScheduleBufferTagForWriteback and threaded it through
IssuePendingWritebacks() as well.

Because WritebackContext was just called "context" as a function
parameter to these functions and that was easy to confuse with
"io_context", I've changed the name of the WritebackContext function
parameter to "wb_context". I separated this rename into its own commit so
that the diff for the commit adding writeback is more clear. I assume
the committer will squash those commits.

> > --- a/src/test/regress/sql/stats.sql
> > +++ b/src/test/regress/sql/stats.sql
>
> Hm. Could we add a test for this? While it's not implemented everywhere, we
> still issue the smgrwriteback() afaics. The default for the _flush_after GUCs
> changes, but backend_flush_after is USERSET, so we could just change it for a
> single command.

I couldn't come up with a way to write a test for this.
GetVictimBuffer() is only called when flushing a dirty buffer. I tried
adding backend_flush_after = 1 and sum(writebacks) to the test for
reuses with vacuum strategy, but there were never more writebacks (in
any context) after doing the full table rewrite with VACUUM. I presume
this is because checkpointer or bgwriter is writing out the dirty
buffers before our client backend gets to reusing them. And, since
bgwriter/checkpointer_flush_after are not USERSET, I don't think we can
guarantee this will cause writeback operations. Just anecdotally, I
increased size of the table to exceed checkpoint_flush_after on my
Postgres instance and I could get the test to cause writeback, but that
doesn't work for a portable test. This was the same reason we couldn't
test writes for VACUUM strategy.

I did notice while working on this that, with the addition of the VACUUM
parameter BUFFER_USAGE_LIMIT, we could decrease the size of the table in
the vacuum strategy reuses test. Not sure if this is legit to commit now
since it isn't required for the writeback patch set, but I included a
patch for it in this patchset.

On Thu, May 4, 2023 at 12:57 PM Andres Freund <andres@anarazel.de> wrote:
> On 2023-04-24 21:29:48 -0400, Melanie Plageman wrote:
>
> > 2) I'm a little nervous about not including IOObject in the writeback
> > context. Technically, there is nothing stopping local buffer code from
> > calling IssuePendingWritebacks(). Right now, local buffer code doesn't
> > do ScheduleBufferTagForWriteback(). But it doesn't seem quite right to
> > hardcode in IOOBJECT_RELATION when there is nothing wrong with
> > requesting writeback of local buffers (AFAIK). What do you think?
>
> I think it'd be wrong on performance grounds ;). We could add an assertion to
> ScheduleBufferTagForWriteback(), I guess, to document that fact?

Now that it doesn't have access to IOObject, no need. I've added
comments elsewhere.

> > 3) Should any restrictions be added to pgstat_tracks_io_object() or
> > pgstat_tracks_io_op()? I couldn't think of any backend types or IO
> > contexts which would not do writeback as a rule. Also, though we don't
> > do writeback for temp tables now, it isn't nonsensical to do so. In
> > this version, I didn't add any restrictions.
>
> I think the temp table restriction could be encoded for now, I don't forsee
> that changing anytime soon.

I've done that in the attached v5.

- Melanie

  23. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Jonathan S. Katz <jkatz@postgresql.org> — 2023-05-16T14:30:27Z

    On 5/6/23 1:30 PM, Melanie Plageman wrote:

> I've done that in the attached v5.

[RMT hat]

RMT nudge on this thread, as we're approaching the Beta 1 cutoff. From 
the above discussion, it sounds like it's pretty close to being ready.

Thanks,

Jonathan

  24. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Andres Freund <andres@anarazel.de> — 2023-05-17T19:19:24Z

    Hi,

On 2023-05-16 10:30:27 -0400, Jonathan S. Katz wrote:
> On 5/6/23 1:30 PM, Melanie Plageman wrote:
> 
> > I've done that in the attached v5.
> 
> [RMT hat]
> 
> RMT nudge on this thread, as we're approaching the Beta 1 cutoff. From the
> above discussion, it sounds like it's pretty close to being ready.

Thanks for the nudge. I just pushed the changes, with some very minor changes
(a newline, slight changes in commit messages).

I'll go and mark the item as closed.

Greetings,

Andres Freund

  25. Re: pg_stat_io not tracking smgrwriteback() is confusing

    Jonathan S. Katz <jkatz@postgresql.org> — 2023-05-17T19:21:25Z

    On 5/17/23 3:19 PM, Andres Freund wrote:
> Hi,
> 
> On 2023-05-16 10:30:27 -0400, Jonathan S. Katz wrote:
>> On 5/6/23 1:30 PM, Melanie Plageman wrote:
>>
>>> I've done that in the attached v5.
>>
>> [RMT hat]
>>
>> RMT nudge on this thread, as we're approaching the Beta 1 cutoff. From the
>> above discussion, it sounds like it's pretty close to being ready.
> 
> Thanks for the nudge. I just pushed the changes, with some very minor changes
> (a newline, slight changes in commit messages).
> 
> I'll go and mark the item as closed.

Nice! Thank you,

Jonathan