I tried implementing the approach Andres suggested, so that we keep recording the foreign-IO wait time rather than dropping it.
The patch: - adds pgstat_count_io_time() for timing-only updates (no operation count). - switches WaitReadBuffers() to use pgstat_count_io_time(). - keeps pgstat_count_io_op_time() for counted operations, with Assert(cnt > 0). - stops requiring a non-zero count whenever time is non-zero. - briefly documents that per-backend IO stats may then show read_time without matching reads. --- Regards, Rachitskiy Andrey вт, 21 июл. 2026 г. в 20:03, Andres Freund <[email protected]>: > Hi, > > On 2026-07-16 15:59:12 -0400, Melanie Plageman wrote: > > Thanks, Justin, for the report > > > > On Thu, Jul 16, 2026 at 11:03 AM Andrey Rachitskiy <[email protected]> > wrote: > > > > > > With track_io_timing=on, foreign IO wait time is currently recorded: > when WaitReadBuffers() waits on foreign_io, it calls > pgstat_count_io_op_time() with cnt=0. So we do write non-zero IOOP_READ > time into this backend's pending pg_stat_io stats, without incrementing the > read count in this backend. > > > > > > Thus, this fix introduces a real change: it disables recording foreign > IO wait time in pg_stat_io statistics for the backend that is performing > the wait. > > > > > > What we lose is only that wait time. The initiating backend still > records the read count and its own IO time, and the waiting backend still > records a buffer hit once the IO completes. > > > > Yea, so, I don't think we can just not record the wait time for > > foreign IOs. > > Agreed. > > > > For asynchronous reads, read time in pg_stat_io is almost entirely wait > > time. > > Right. And for some workloads a decent percentage of the waits can be due > to > foreign IOs (often started by ourselves). That's particularly true once > index > readahead goes in. > > > > That's also why it doesn't make sense to have a separate IOOP_WAIT -- > unless > > we start measuring and displaying read latency (how long the actual reads > > took) in pg_stat_io and then you could separate that from wait time. > > My main problem with IOOP_WAIT would be that it would conflate waiting for > different IO operations. Read, write, fsync latencies can be wildly > different... > > > > My first thought is that we should relax the restriction in > > pgstat_bktype_io_stats_valid() that requires non-zero counts if time > > is non-zero. > > I think that may be the way. There's other places where that assertion > causes > us to track less well than we otherwise could: > > /* > * We must get an IO handle before StartBufferIO(), as > pgaio_io_acquire() > * might block, which we don't want after setting IO_IN_PROGRESS. > If we > * don't need to do the IO, we'll release the handle. > * > * If we need to wait for IO before we can get a handle, submit > * already-staged IO first, so that other backends don't need to > wait. > * There wouldn't be a deadlock risk, as pgaio_io_acquire() just > needs to > * wait for already submitted IO, which doesn't require additional > locks, > * but it could still cause undesirable waits. > * > * A secondary benefit is that this would allow us to measure the > time in > * pgaio_io_acquire() without causing undue timer overhead in the > common, > * non-blocking, case. However, currently the pgstats > infrastructure > * doesn't really allow that, as it a) asserts that an operation > can't > * have time without operations b) doesn't have an API to report > * "accumulated" time. > */ > > The a) in the last paragraph in particular. > > > > But that seems silly: 1) we lose lots of validation for cases where this > > would be bogus > > But how likely is that actually going to be a problem? > > Perhaps we should add a separate function that explicitly just counts > timing > (no operation count), and only allow that one to work with a 0 operations > count? > > > > and 2) anyone looking at the view that seems non-zero IO time and 0 count > > will be very confused > > But I don't think you would really see that - normally the IO count will > have > been increemented by another operation. > > > > and 3) it makes any math dividing read time by read operations > meaningless > > (though I don't know how meaningful that is now). > > Hm. The fix for that is to write read_time / NULLIF(reads, 0). But it's > somewhat annoying to have to know to do that, as it will be quite rare to > encounter cases where just the wait time, but no operation count will have > been reported. At least for pg_stat_io, I guess pg_stat_get_backend_io() > will > make it a bit more common. > > But I just don't really see an alternative. > > > > If read time is truly just wait time > > It's not always that way. For a fast IO subsystem with a deep enough queue > most of the time will actually be in the submission path (since that's > where > you trigger interrupts and do kernel work like identifying the disk block > the > requested data is on etc). > > > > we could just pass pg_stat_count_io_op_time() a count of 1 for foreign > IO in > > WaitReadBuffers(). In 19, we should likely either do this or do as Andrey > > suggested and not count the wait time for foreign IOs. > > > > For master, I'd like to do something more satisfying, but I'm not sure > what. > > I think medium term we might need to redesign where the pg_stat_io > accounting > happens. Not primarily because of this, but because there's at the moment > sources of waits that are not properly accounted. > > Consider e.g. this: > - io_max_concurrency=32 > - some read stream starts 32 reads > - another part of the query tries to do a single AIO write > - that needs to do a blocking pgaio_io_acquire(), as there are no unused > handles > - as part of that, pgaio_io_acquire() will wait on the oldest in-flight > IO, > which was a read > > Today the wait time for that (as explained in the comment above) is > unattributed. If we were to account it were the comment suggests, we'd > attribute it to the *write*, even though the waiting is actually unrelated > to > the write itself, its waiting for some old read to finish. > > The same thing could happen with reads that fall into different contexts, > e.g. we could end up attributing waits triggered by relation/bulkread to > relation/normal, just because the bulkread filled up the queue. > > > Now, some fuzziness here is fundamental. Having N IOs in the queue before > an > additional IO X will increase the latency of X. If we only wait for X, not > for > any of the earlier IOs, the latency of those other IOs will be attributed > to X > to some degree. But I feel the case of waiting for specific earlier IOs to > complete is different, as that's not an indirect increase in latency due to > deeper queues, it's directly waiting for other IO operations - and those > other > IO operations might be much higher latency ones (the most extreme case is > probably io_max_concurrency fsyncs queued when trying to start a small > read). > > > So a larger refactoring could be to add something like > pgstat_io_set_stats_target(), which would then allow the pgstat reporting > to > happen within the AIO subsystem. > > > > It did get me thinking that there is 0 way for the user (or developer) > > to know about foreign IOs. Maybe that's okay...? > > I think it may be OK, we historically have not exposed having to wait in > StartBufferIO() when the buffer is undergoing IO in another backend either. > > It's not entirely clear what the alternative is either. One relatively easy > thing we could do is to have more separated out wait events. E.g.: > > 1) a direct wait for IO started by the current backend > > 2) a direct wait for an IO started by another backend > > 3) a wait for an IO started by the current backend, but as part of > acquiring > an IO handle. > > 4) a wait as part of pgaio_closing_fd() > > 5) a wait as part of pgaio_shutdown() > > With possible subdivisions for 1), to separate out "foreign" IOs that have > been started by the current backend from plain waits on the IO itself. But > that's a bit of a weird division, because for the AIO subsystem there's > zero > difference between those cases. > > > It's not entirely trivial to introduce that separation, because > pgaio_io_wait() already has different wait events, because you may need to > wait for the IO to actually complete (WAIT_EVENT_AIO_IO_URING_EXECUTION) or > you may need to wait for another backend to execute the IO completion > (WAIT_EVENT_AIO_IO_COMPLETION). > > Which is not helped by WAIT_EVENT_AIO_IO_COMPLETION covering different > things > for different IO methods. For io_uring it will just be used when the kernel > has executed the IO, but the callback hasn't yet been executed, whereas for > sync/worker modes, it'll be used for the entire IO duration. > > Greetings, > > Andres Freund >
From dcc2a682ff00a462908674df907275bb141c4e8e Mon Sep 17 00:00:00 2001 From: Andrey Rachitskiy <[email protected]> Date: Tue, 21 Jul 2026 21:42:56 +0500 Subject: [PATCH] Allow pg_stat_io timing without a matching operation count With track_io_timing=on, WaitReadBuffers() records wait time for in-progress reads by calling pgstat_count_io_op_time() with a zero operation count. For IOs started by this backend that is fine, because AsyncReadBuffers() already incremented the count. For foreign IOs the count lives in another backend, so this backend can end up with non-zero read_time and zero reads. That tripped pgstat_bktype_io_stats_valid() under cassert. Keep recording that wait time, but do it via pgstat_count_io_time() so timing can be reported without a local operation count. Use that from WaitReadBuffers(), require a non-zero count in pgstat_count_io_op_time(), and relax validation accordingly. Briefly note the resulting per-backend IO stats shape in the docs. Author: Andrey Rachitskiy <[email protected]> Reported-by: Justin Pryzby <[email protected]> Discussion: https://postgr.es/m/ak5lccE4qiQpOBHn@pryzbyj2023 --- doc/src/sgml/monitoring.sgml | 5 +- src/backend/storage/buffer/bufmgr.c | 9 +- src/backend/utils/activity/pgstat_io.c | 118 +++++++++++++++---------- src/include/pgstat.h | 2 + 4 files changed, 83 insertions(+), 51 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index d1a20d001e9..074a821a68e 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -3052,7 +3052,10 @@ description | Waiting for a newly initialized WAL file to reach durable storage <varname>object</varname> is not <literal>wal</literal>, or if <xref linkend="guc-track-wal-io-timing"/> is enabled and <varname>object</varname> is <literal>wal</literal>, - otherwise zero) + otherwise zero). This may include time spent waiting for a read + started by another backend; in that case + <structfield>reads</structfield> can still be zero, especially in + per-backend IO statistics. </para> </entry> </row> diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c index 3908529872a..65b4e1410ac 100644 --- a/src/backend/storage/buffer/bufmgr.c +++ b/src/backend/storage/buffer/bufmgr.c @@ -1829,11 +1829,12 @@ WaitReadBuffers(ReadBuffersOperation *operation) needed_wait = true; /* - * The IO operation itself was already counted earlier, in - * AsyncReadBuffers(), this just accounts for the wait time. + * Only the wait time belongs here. The read itself was + * already counted in AsyncReadBuffers() -- by us, or by + * another backend if this is a foreign IO. */ - pgstat_count_io_op_time(io_object, io_context, IOOP_READ, - io_start, 0, 0); + pgstat_count_io_time(io_object, io_context, IOOP_READ, + io_start); } else { diff --git a/src/backend/utils/activity/pgstat_io.c b/src/backend/utils/activity/pgstat_io.c index 4f7a39aaa0e..c2dbfc04e13 100644 --- a/src/backend/utils/activity/pgstat_io.c +++ b/src/backend/utils/activity/pgstat_io.c @@ -25,9 +25,11 @@ static bool have_iostats = false; /* * Check that stats have not been counted for any combination of IOObject, - * IOContext, and IOOp which are not tracked for the passed-in BackendType. If - * stats are tracked for this combination and IO times are non-zero, counts - * should be non-zero. + * IOContext, and IOOp which are not tracked for the passed-in BackendType. + * + * Non-zero time with a zero operation count is allowed: a backend may wait + * on a foreign IO and record only the wait time, while another backend + * counted the read. See pgstat_count_io_time(). * * The passed-in PgStat_BktypeIO must contain stats from the BackendType * specified by the second parameter. Caller is responsible for locking the @@ -43,19 +45,16 @@ pgstat_bktype_io_stats_valid(PgStat_BktypeIO *backend_io, { for (int io_op = 0; io_op < IOOP_NUM_TYPES; io_op++) { - /* we do track it */ if (pgstat_tracks_io_op(bktype, io_object, io_context, io_op)) - { - /* ensure that if IO times are non-zero, counts are > 0 */ - if (backend_io->times[io_object][io_context][io_op] != 0 && - backend_io->counts[io_object][io_context][io_op] <= 0) - return false; - continue; - } - /* we don't track it, and it is not 0 */ - if (backend_io->counts[io_object][io_context][io_op] != 0) + /* + * Nothing should be recorded for combinations we don't track. + * Check times as well as counts, since timing can be reported + * on its own via pgstat_count_io_time(). + */ + if (backend_io->counts[io_object][io_context][io_op] != 0 || + backend_io->times[io_object][io_context][io_op] != 0) return false; } } @@ -98,8 +97,8 @@ pgstat_prepare_io_time(bool track_io_guc) { /* * There is no need to set io_start when an IO timing GUC is disabled. - * Initialize it to zero to avoid compiler warnings and to let - * pgstat_count_io_op_time() know that timings should be ignored. + * Initialize it to zero to avoid compiler warnings and to let the + * pgstat_count_io_*time() helpers know that timings should be ignored. */ INSTR_TIME_SET_ZERO(io_start); } @@ -108,7 +107,12 @@ pgstat_prepare_io_time(bool track_io_guc) } /* - * Like pgstat_count_io_op() except it also accumulates time. + * Add IO timing without bumping the operation count or bytes. + * + * Useful when the IO was already counted elsewhere -- for example + * WaitReadBuffers() waiting on a read that AsyncReadBuffers() (possibly in + * another backend) has already counted. If you are both doing and counting + * the IO, call pgstat_count_io_op_time() instead. * * The calls related to pgstat_count_buffer_*() are for pgstat_database. As * pg_stat_database only counts block read and write times, these are done for @@ -119,44 +123,66 @@ pgstat_prepare_io_time(bool track_io_guc) * activity of temporary blocks, so these are ignored here. */ void -pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, - instr_time start_time, uint32 cnt, uint64 bytes) +pgstat_count_io_time(IOObject io_object, IOContext io_context, IOOp io_op, + instr_time start_time) { - if (!INSTR_TIME_IS_ZERO(start_time)) - { - instr_time io_time; + instr_time io_time; + + Assert((unsigned int) io_object < IOOBJECT_NUM_TYPES); + Assert((unsigned int) io_context < IOCONTEXT_NUM_TYPES); + Assert((unsigned int) io_op < IOOP_NUM_TYPES); + Assert(pgstat_tracks_io_op(MyBackendType, io_object, io_context, io_op)); - INSTR_TIME_SET_CURRENT(io_time); - INSTR_TIME_SUBTRACT(io_time, start_time); + /* timing disabled (see pgstat_prepare_io_time()) */ + if (INSTR_TIME_IS_ZERO(start_time)) + return; - if (io_object != IOOBJECT_WAL) + INSTR_TIME_SET_CURRENT(io_time); + INSTR_TIME_SUBTRACT(io_time, start_time); + + if (io_object != IOOBJECT_WAL) + { + if (io_op == IOOP_WRITE || io_op == IOOP_EXTEND) { - if (io_op == IOOP_WRITE || io_op == IOOP_EXTEND) - { - pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time)); - if (io_object == IOOBJECT_RELATION) - INSTR_TIME_ADD(pgBufferUsage.shared_blk_write_time, io_time); - else if (io_object == IOOBJECT_TEMP_RELATION) - INSTR_TIME_ADD(pgBufferUsage.local_blk_write_time, io_time); - } - else if (io_op == IOOP_READ) - { - pgstat_count_buffer_read_time(INSTR_TIME_GET_MICROSEC(io_time)); - if (io_object == IOOBJECT_RELATION) - INSTR_TIME_ADD(pgBufferUsage.shared_blk_read_time, io_time); - else if (io_object == IOOBJECT_TEMP_RELATION) - INSTR_TIME_ADD(pgBufferUsage.local_blk_read_time, io_time); - } + pgstat_count_buffer_write_time(INSTR_TIME_GET_MICROSEC(io_time)); + if (io_object == IOOBJECT_RELATION) + INSTR_TIME_ADD(pgBufferUsage.shared_blk_write_time, io_time); + else if (io_object == IOOBJECT_TEMP_RELATION) + INSTR_TIME_ADD(pgBufferUsage.local_blk_write_time, io_time); } + else if (io_op == IOOP_READ) + { + pgstat_count_buffer_read_time(INSTR_TIME_GET_MICROSEC(io_time)); + if (io_object == IOOBJECT_RELATION) + INSTR_TIME_ADD(pgBufferUsage.shared_blk_read_time, io_time); + else if (io_object == IOOBJECT_TEMP_RELATION) + INSTR_TIME_ADD(pgBufferUsage.local_blk_read_time, io_time); + } + } - INSTR_TIME_ADD(PendingIOStats.pending_times[io_object][io_context][io_op], - io_time); + INSTR_TIME_ADD(PendingIOStats.pending_times[io_object][io_context][io_op], + io_time); - /* Add the per-backend count */ - pgstat_count_backend_io_op_time(io_object, io_context, io_op, - io_time); - } + pgstat_count_backend_io_op_time(io_object, io_context, io_op, io_time); + + have_iostats = true; + pgstat_report_fixed = true; +} + +/* + * Like pgstat_count_io_op(), but also accumulate time. + * + * cnt must be greater than zero. To report timing alone (no new operation), + * use pgstat_count_io_time(). + */ +void +pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, + instr_time start_time, uint32 cnt, uint64 bytes) +{ + /* timing-only updates belong in pgstat_count_io_time() */ + Assert(cnt > 0); + pgstat_count_io_time(io_object, io_context, io_op, start_time); pgstat_count_io_op(io_object, io_context, io_op, cnt, bytes); } diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 58a44857f13..c5627a9af22 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -629,6 +629,8 @@ extern bool pgstat_bktype_io_stats_valid(PgStat_BktypeIO *backend_io, extern void pgstat_count_io_op(IOObject io_object, IOContext io_context, IOOp io_op, uint32 cnt, uint64 bytes); extern instr_time pgstat_prepare_io_time(bool track_io_guc); +extern void pgstat_count_io_time(IOObject io_object, IOContext io_context, + IOOp io_op, instr_time start_time); extern void pgstat_count_io_op_time(IOObject io_object, IOContext io_context, IOOp io_op, instr_time start_time, uint32 cnt, uint64 bytes); -- 2.53.0
