Hi,
AI review identified an inconsistency in parallel vacuum (5cd72cc0c5).
I checked it myself and it is there on HEAD and on every branch since
PG15. Patch attached, [2] has the reproducer. I don't think
back-patching is necessary as it's not a bug, only what the log
reports.
5cd72cc0c5 made the buffer usage in the VACUUM VERBOSE and autovacuum
log lines come from the pgBufferUsage delta, which includes what the
parallel workers did, but left the I/O timings on the leader's own
pgStatBlockReadTime and pgStatBlockWriteTime, which nothing folds the
workers' time into. So the same log line counts the blocks the workers
read and dirtied without the time they spent on them, and the time per
block computed from it comes out too low. [1] shows it before and
after.
The fix takes the timings from the same buffer usage 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 an index phase is done. The shared
and the local fields are summed, so a temporary table keeps the
numbers it had, pgStatBlockReadTime having counted local blocks too.
It also stops the leader's own share from coming out slightly low,
pgStatBlockReadTime and pgStatBlockWriteTime being fed whole
microseconds per I/O while the BufferUsage fields keep the full
instr_time.
[1] The same vacuum with two workers, before and after the patch.
Before:
I/O timings: read: 179.511 ms, write: 149.717 ms
After:
I/O timings: read: 236.303 ms, write: 215.114 ms
The difference in write time is what the workers spent, which
pg_stat_io accounts to them and the log left out. Read time also moves
around on its own with the OS page cache.
[2] With track_io_timing = on, shared_buffers = 1MB and autovacuum = off:
CREATE TABLE t (a int, b int, c int) WITH (autovacuum_enabled = off);
INSERT INTO t SELECT i, i, i FROM generate_series(1, 2000000) i;
CREATE INDEX t_a_idx ON t (a);
CREATE INDEX t_b_idx ON t (b);
CREATE INDEX t_c_idx ON t (c);
DELETE FROM t WHERE a % 4 = 0;
Restart the server so that nothing is left in shared buffers, then:
SELECT pg_stat_reset_shared('io');
Run the vacuum in a session of its own, so that the client backend row below is
the leader and nothing else:
VACUUM (VERBOSE, PARALLEL 2) t;
Then from another session:
SELECT backend_type, context, round(read_time::numeric, 3) AS read_ms,
round(write_time::numeric, 3) AS write_ms, reads, writes
FROM pg_stat_io WHERE read_time > 0 OR write_time > 0
ORDER BY 1, 2;
--
Bharath Rupireddy
Amazon Web Services: https://aws.amazon.com
From 2fa535dd84d93b61bfac40380e1d616bfef2ea44 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <[email protected]>
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 <[email protected]>
Discussion: https://postgr.es/m/<<message-id>>
---
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
