From dcc2a682ff00a462908674df907275bb141c4e8e Mon Sep 17 00:00:00 2001 From: Andrey Rachitskiy 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 Reported-by: Justin Pryzby 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 object is not wal, or if is enabled and object is wal, - otherwise zero) + otherwise zero). This may include time spent waiting for a read + started by another backend; in that case + reads can still be zero, especially in + per-backend IO statistics. 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