From ce60d1d179139cb1213b1ca640c9f491b6da62b1 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy Date: Wed, 30 Sep 2026 05:35:19 +0000 Subject: [PATCH v2] Fix parallel vacuum I/O timing reporting. The I/O timings in the VACUUM VERBOSE and autovacuum log lines account for only the work the leader did. When a vacuum uses parallel workers on the indexes, the same log line counts the blocks the workers read and dirtied, but not the time they spent on them, so the reported I/O time falls short by the workers' share and the time per block anyone computes from the log comes out too low. Fix this by reporting the timings from the same buffer usage the block counts already come from, which the workers accumulate their own share into once they are done with an index phase. This also makes the leader's own time slightly more accurate, the counters used so far having been fed whole microseconds per I/O. Oversight in commit 5cd72cc0c5. Found by Bharath using AI assisted review with Claude. Backpatch to PG17, the oldest branch whose buffer usage also carries the I/O time of temporary relations. On PG16 it does not, and fixing it there would mean adding branch specific code to keep that time from going missing from the log, which is avoided for a reporting issue. Reported-by: Bharath Rupireddy Author: Bharath Rupireddy Reviewed-by: Sami Imseih Reviewed-by: Chao Li Reviewed-by: Masahiko Sawada Reviewed-by: Shihao Zhong Discussion: https://postgr.es/m/CALj2ACXrqaHrYmGdpAoGKXtiY9Xw4o1dxSC+EELxn47GDO6HAQ@mail.gmail.com Backpatch-through: 17 --- 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 ed7301c69ec..53e3a1ab0b9 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(); @@ -1177,8 +1168,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