Parallel vacuum: I/O timings in the log leave out the parallel workers
Hackorum builds and tests every patch posted to the lists, not only commitfest submissions. This is Hackorum's own CI rather than the PostgreSQL project's, and it is still under testing - please report anything that looks wrong.
This thread has been committed, so CI has stopped here. Anything below is the last result it produced.
You can run a PostgreSQL built from this patch straight from Docker, with no checkout and no build:
docker run --rm -p 5432:5432 ghcr.io/hackorum-dev/postgres-patch:t253962psql -h localhost -U postgresBuilt from patchset v6 (message #6), October 08, 2026 at 04:41 AM.
Every patchset is also pushed to a branch of our PostgreSQL fork, so you can check out the same tree CI built. Without a PostgreSQL checkout:
git clone --branch t253962_6 https://github.com/hackorum-dev/postgres.gitIn a checkout you already have, add the fork once:
git remote add hackorum https://github.com/hackorum-dev/postgres.gitthen, for this patchset and every later one:
git fetch hackorum t253962_6 && git checkout t253962_6Patchset v6 (message #6) is on t253962_6
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]With track_io_timing = on, shared_buffers = 1MB and autovacuum = off: 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]The same vacuum with two workers, before and after the patch. 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
Hi Bharath,
This looks good to me, and I wonder if we should do the same
for ANALYZE. It does the same exact thing. Although we don't
have parallel analyze now, if we ever get that we will need to
fix it there also, so let's just do it now.
--
Sami Imseih
Amazon Web Services (AWS)
On Sep 28, 2026, at 08:15, Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote:
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
<v1-0001-Include-parallel-workers-in-the-I-O-timings-repor.patch>
Switching to pgBufferUsage looks correct to me. 5cd72cc0c5 switched the hit, read, and dirtied counts to pgBufferUsage, but seems to have missed the read and write timings. Since that fix was back-patched through v15, should this fix be back-patched through v15 as well?
Best regards,
--
Chao Li (Evan)
HighGo Software Co., Ltd.
https://www.highgo.com/
On Mon, Sep 28, 2026 at 7:45 PM Chao Li <li.evan.chao@gmail.com> wrote:
On Sep 28, 2026, at 08:15, Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote:
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
<v1-0001-Include-parallel-workers-in-the-I-O-timings-repor.patch>Switching to pgBufferUsage looks correct to me. 5cd72cc0c5 switched the hit, read, and dirtied counts to pgBufferUsage, but seems to have missed the read and write timings. Since that fix was back-patched through v15, should this fix be back-patched through v15 as well?
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?
Regards,
--
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com
So I'm inclined to backpatch it to 17. Thoughts?
+1 for 17. From 17 on, pgstat_count_io_op_time() feeds pgStatBlockReadTime
and the BufferUsage fields from the same io_time for the same objects, so
without workers the log only changes by the rounding. 16 is different, as
you said.
I ran Bharath's reproducer and compared the log line with pg_stat_io for the
same VACUUM. On master the log said
I/O timings: read: 200.596 ms, write: 200.286 ms
while pg_stat_io had
read ms write ms
leader 213.442 213.006
workers 61.415 127.415
So the workers are missing, and the log is short even of the leader's own
time, which is the microsecond rounding Bharath mentioned.
With the patch the log matched leader plus workers within 0.3 ms.
Thanks,
Shihao
Hi,
On Mon, Sep 28, 2026 at 11:09 PM Masahiko Sawada <sawada.mshk@gmail.com> 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
Attachments:
t253962_6v2-0001-Fix-parallel-vacuum-I-O-timing-reporting.patchapplication/x-patch; name=v2-0001-Fix-parallel-vacuum-I-O-timing-reporting.patchDownload+11-12
nocfbot-v2-0001-PG19-Fix-parallel-vacuum-I-O-timing-reporting.patchapplication/x-patch; name=nocfbot-v2-0001-PG19-Fix-parallel-vacuum-I-O-timing-reporting.patchDownload+11-12
nocfbot-v2-0001-PG18-Fix-parallel-vacuum-I-O-timing-reporting.patchapplication/x-patch; name=nocfbot-v2-0001-PG18-Fix-parallel-vacuum-I-O-timing-reporting.patchDownload+11-12
nocfbot-v2-0001-PG17-Fix-parallel-vacuum-I-O-timing-reporting.patchapplication/x-patch; name=nocfbot-v2-0001-PG17-Fix-parallel-vacuum-I-O-timing-reporting.patchDownload+11-10
On Wed, Sep 30, 2026 at 9:18 PM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
Hi,
On Mon, Sep 28, 2026 at 11:09 PM Masahiko Sawada <sawada.mshk@gmail.com> 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.
Thank you for updating the patches! They look good to me.
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.
+1
I'm going to push them tomorrow, barring objections.
Regards,
--
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com
On Wed, Oct 7, 2026 at 1:41 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
On Wed, Sep 30, 2026 at 9:18 PM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:Hi,
On Mon, Sep 28, 2026 at 11:09 PM Masahiko Sawada <sawada.mshk@gmail.com> 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.Thank you for updating the patches! They look good to me.
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.+1
I'm going to push them tomorrow, barring objections.
Pushed.
Regards,
--
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com