From 2fa535dd84d93b61bfac40380e1d616bfef2ea44 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy Date: Sun, 27 Sep 2026 02:55:24 +0000 Subject: [PATCH v1] Include parallel workers in the I/O timings reported by VACUUM. Commit 5cd72cc0c5 made the buffer usage in the VACUUM VERBOSE and autovacuum log lines come from the pgBufferUsage delta, which includes what the parallel vacuum workers did, but left the I/O timings on the leader's own pgStatBlockReadTime and pgStatBlockWriteTime counters, which nothing folds the workers' time into. The log therefore counts the blocks the workers read and dirtied without the time they spent on them, understating the I/O time by the parallel share and making the time per block that anyone computes from the log too low. Take the timings from the same BufferUsage delta as the block counts. A worker accumulates its buffer usage, timings included, into its own pgBufferUsage, and the leader folds that into its own with InstrAccumParallelQuery() once the workers are done with an index phase. Summing the shared and the local fields leaves the numbers for a temporary table as they were, since pgStatBlockReadTime counted local blocks too. The leader's own share also stops coming out slightly low. pgStatBlockReadTime and pgStatBlockWriteTime are fed whole microseconds per I/O, so they dropped the sub-microsecond remainder of every read and write, around half a microsecond each, while the BufferUsage fields keep the full instr_time. This is an inconsistency in what the log reports rather than a bug, so it is not back-patched. Oversight in commit 5cd72cc0c5. Reported-by: Claude Code Author: Bharath Rupireddy Discussion: https://postgr.es/m/<> --- src/backend/access/heap/vacuumlazy.c | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 997d84a77b3..63efa11d4c3 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -636,8 +636,6 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, new_rel_allfrozen; PGRUsage ru0; TimestampTz starttime = 0; - PgStat_Counter startreadtime = 0, - startwritetime = 0; WalUsage startwalusage = pgWalUsage; BufferUsage startbufferusage = pgBufferUsage; ErrorContextCallback errcallback; @@ -648,14 +646,7 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, instrument = (verbose || (AmAutoVacuumWorkerProcess() && params->log_vacuum_min_duration >= 0)); if (instrument) - { pg_rusage_init(&ru0); - if (track_io_timing) - { - startreadtime = pgStatBlockReadTime; - startwritetime = pgStatBlockWriteTime; - } - } /* Used for instrumentation and stats report */ starttime = GetCurrentTimestamp(); @@ -1176,8 +1167,17 @@ heap_vacuum_rel(Relation rel, const VacuumParams *params, } if (track_io_timing) { - double read_ms = (double) (pgStatBlockReadTime - startreadtime) / 1000; - double write_ms = (double) (pgStatBlockWriteTime - startwritetime) / 1000; + /* + * Take the timings from the same buffer usage delta as the + * block counts, so that the parallel workers are included in + * both. + */ + double read_ms = + INSTR_TIME_GET_MILLISEC(bufferusage.shared_blk_read_time) + + INSTR_TIME_GET_MILLISEC(bufferusage.local_blk_read_time); + double write_ms = + INSTR_TIME_GET_MILLISEC(bufferusage.shared_blk_write_time) + + INSTR_TIME_GET_MILLISEC(bufferusage.local_blk_write_time); appendStringInfo(&buf, _("I/O timings: read: %.3f ms, write: %.3f ms\n"), read_ms, write_ms); -- 2.47.3