pg_stat_io not tracking smgrwriteback() is confusing
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
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
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.
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
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
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
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
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
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 otherbackend
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
Attachments:
v1-0001-Add-writeback-to-pg_stat_io-writes.patchtext/x-patch; charset=US-ASCII; name=v1-0001-Add-writeback-to-pg_stat_io-writes.patchDownload+16-7
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 otherbackend
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.226patched:
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.514I 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
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 otherbackend
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
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
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
Attachments:
v2-0001-Add-writeback-to-pg_stat_io.patchtext/x-patch; charset=US-ASCII; name=v2-0001-Add-writeback-to-pg_stat_io.patchDownload+55-12
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
Attachments:
v3-0001-Add-writeback-to-pg_stat_io.patchtext/x-patch; charset=US-ASCII; name=v3-0001-Add-writeback-to-pg_stat_io.patchDownload+85-18
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
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
Attachments:
v4-0001-Add-writeback-to-pg_stat_io.patchtext/x-patch; charset=US-ASCII; name=v4-0001-Add-writeback-to-pg_stat_io.patchDownload+85-18
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
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_io28e626bde00 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
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
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