1
0
mirror of https://github.com/postgres/postgres.git synced 2026-10-23 13:29:09 +03:00

Fix parallel vacuum I/O timing reporting.

Commit 5cd72cc0c5 made the VACUUM VERBOSE and autovacuum logs report
buffer usage from the pgBufferUsage delta, which includes the parallel
workers' usage, but left the I/O timings on the leader's
pgStatBlockReadTime and pgStatBlockWriteTime. So the log counted the
blocks the workers read and dirtied but not the time they spent on
them.

Fix this by taking the I/O timings from the same BufferUsage delta.
This also removes a small error in the leader's own timings, since
pgStatBlock{Read,Write}Time accumulate whole microseconds per I/O.

Although 5cd72cc0c5 was backpatched to v15, BufferUsage on v16 doesn't
track the I/O time of temporary relations, so the same fix there would
drop that time from the log. We don't think a reporting issue is worth
v16-specific code, nor worth leaving v16 unfixed between v15 and v17,
so backpatch to v17 only.

Found by Bharath using AI assisted review with Claude.

Reported-by: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Author: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Reviewed-by: Sami Imseih <samimseih.pg@gmail.com>
Reviewed-by: Chao Li <li.evan.chao@gmail.com>
Reviewed-by: Masahiko Sawada <sawada.mshk@gmail.com>
Reviewed-by: Shihao Zhong <zhong950419@gmail.com>
Discussion: https://postgr.es/m/CALj2ACXrqaHrYmGdpAoGKXtiY9Xw4o1dxSC+EELxn47GDO6HAQ@mail.gmail.com
Backpatch-through: 17
This commit is contained in:
Masahiko Sawada
2026-10-08 11:26:17 -07:00
parent 87e4176816
commit 35c508af52

View File

@@ -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);