Hi, On Mon, Sep 28, 2026 at 11:09 PM Masahiko Sawada <[email protected]> wrote: > > Yes, I think we should treat it the same way as 5cd72cc0c5. > > We need to note that in 16 BufferUsage doesn't have > local_blk_{read|write}_time, and pgstat_count_io_op_time() adds the > I/O time of temp relations only to pgStatBlockReadTime and > pgStatBlockWRiteTime, not to BufferUsage.blk_{read|write}_time. So > taking the timings from BufferUsage would drop the time spent on temp > relations from the log. In 15, blk_{read|write}_time and > pgStatBlock{Read|Write}TIme cover the same I/O, so the fix would be > straightforward, but I don't think it's worth leaving 16 unfixed in > between, or adding 16-specific code for a reporting issue. So I'm > inclined to backpatch it to 17. Thoughts?
Agreed. +1 to keeping the version diff minimal as far back as possible with less invasive changes, so back-patching it to PG17 makes sense to me. Please find the attached v2 patch. I did not add the ANALYZE change suggested upthread, because ANALYZE has no parallel workers and so does not have the inconsistency reported in this thread. It might still be worth doing for consistency with VACUUM. -- Bharath Rupireddy Amazon Web Services: https://aws.amazon.com
From 2a8ad0d1896a4955f950c0128aeec6fcfa505359 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy <[email protected]> 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 <[email protected]> Author: Bharath Rupireddy <[email protected]> Reviewed-by: Sami Imseih <[email protected]> Reviewed-by: Chao Li <[email protected]> Reviewed-by: Masahiko Sawada <[email protected]> Reviewed-by: Shihao Zhong <[email protected]> Discussion: CALj2ACXrqaHrYmGdpAoGKXtiY9Xw4o1dxSC+EELxn47GDO6HAQ@mail.gmail.com">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 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
From ce60d1d179139cb1213b1ca640c9f491b6da62b1 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy <[email protected]> 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 <[email protected]> Author: Bharath Rupireddy <[email protected]> Reviewed-by: Sami Imseih <[email protected]> Reviewed-by: Chao Li <[email protected]> Reviewed-by: Masahiko Sawada <[email protected]> Reviewed-by: Shihao Zhong <[email protected]> Discussion: CALj2ACXrqaHrYmGdpAoGKXtiY9Xw4o1dxSC+EELxn47GDO6HAQ@mail.gmail.com">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
From c16f988ce456e9d8043a25df8de1195f6fddf716 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy <[email protected]> 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 <[email protected]> Author: Bharath Rupireddy <[email protected]> Reviewed-by: Sami Imseih <[email protected]> Reviewed-by: Chao Li <[email protected]> Reviewed-by: Masahiko Sawada <[email protected]> Reviewed-by: Shihao Zhong <[email protected]> Discussion: CALj2ACXrqaHrYmGdpAoGKXtiY9Xw4o1dxSC+EELxn47GDO6HAQ@mail.gmail.com">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 989fb491e55..e359e45dcd4 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -627,8 +627,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, new_rel_allfrozen; PGRUsage ru0; TimestampTz starttime = 0; - PgStat_Counter startreadtime = 0, - startwritetime = 0; WalUsage startwalusage = pgWalUsage; BufferUsage startbufferusage = pgBufferUsage; ErrorContextCallback errcallback; @@ -638,14 +636,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, instrument = (verbose || (AmAutoVacuumWorkerProcess() && params->log_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(); @@ -1115,8 +1106,17 @@ heap_vacuum_rel(Relation rel, 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
From 0916d905801d38c47b35ca988dbfbd7e2b0b32be Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy <[email protected]> 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 <[email protected]> Author: Bharath Rupireddy <[email protected]> Reviewed-by: Sami Imseih <[email protected]> Reviewed-by: Chao Li <[email protected]> Reviewed-by: Masahiko Sawada <[email protected]> Reviewed-by: Shihao Zhong <[email protected]> Discussion: CALj2ACXrqaHrYmGdpAoGKXtiY9Xw4o1dxSC+EELxn47GDO6HAQ@mail.gmail.com">https://postgr.es/m/CALj2ACXrqaHrYmGdpAoGKXtiY9Xw4o1dxSC+EELxn47GDO6HAQ@mail.gmail.com Backpatch-through: 17 --- src/backend/access/heap/vacuumlazy.c | 20 +++++++++++--------- 1 file changed, 11 insertions(+), 9 deletions(-) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index cb28830064a..086d17b088a 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -306,8 +306,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, new_rel_allvisible; PGRUsage ru0; TimestampTz starttime = 0; - PgStat_Counter startreadtime = 0, - startwritetime = 0; WalUsage startwalusage = pgWalUsage; BufferUsage startbufferusage = pgBufferUsage; ErrorContextCallback errcallback; @@ -320,11 +318,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, { pg_rusage_init(&ru0); starttime = GetCurrentTimestamp(); - if (track_io_timing) - { - startreadtime = pgStatBlockReadTime; - startwritetime = pgStatBlockWriteTime; - } } pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, @@ -732,8 +725,17 @@ heap_vacuum_rel(Relation rel, 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
