On 14th of February 2025, Nathan Bossart committed patch:
Add delay time to VACUUM/ANALYZE (VERBOSE) and autovacuum logs. Commit bb8dff9995 added this information to the pg_stat_progress_vacuum and pg_stat_progress_analyze system views. This commit adds the same information to the output of VACUUM and ANALYZE with the VERBOSE option and to the autovacuum logs. Suggested-by: Masahiro Ikeda <ikedamsh@oss.nttdata.com> Author: Bertrand Drouvot <bertranddrouvot.pg@gmail.com> Discussion: https://postgr.es/m/ZmaXmWDL829fzAVX%40ip-10-97-1-34.eu-west-3.compute.internal
Just couple of days ago I wrote that now we will have delay information in view showing progress of vacuums, where I wrote:
Kinda makes me wish this value was also logged (at the end of vacuum) to pg logs…
and now – we got it!
Ran two tests, similar setup (though size of table was only 10% of previously used), and then, in first case ran vacuum manually:
=$ vacuum verbose test_it;INFO: vacuuming "depesz.public.test_it"INFO: finished vacuuming "depesz.public.test_it": index scans: 1
pages: 0 removed, 12736 remain, 12736 scanned (100.00% of total), 0 eagerly scanned
tuples: 750324 removed, 249676 remain, 0 are dead but not yet removable
removable cutoff: 2159, which was 0 XIDs old when operation ended
frozen: 0 pages from table (0.00% of total) had 0 tuples frozen
visibility map: 12706 pages set all-visible, 799 pages set all-frozen (0 were all-visible)
index scan needed: 12698 pages from table (99.70% of total) had 750324 dead item identifiers removed
index "test_it_pkey": pages: 2745 in total, 0 newly deleted, 0 currently deleted, 0 reusable
delay time: 2493.787 ms
I/O timings: read: 8.274 ms, write: 11.363 ms
avg read rate: 7.771 MB/s, avg write rate: 7.760 MB/s
buffer usage: 38215 hits, 2752 reads, 2748 dirtied
WAL usage: 40843 records, 7 full page images, 6766991 bytes, 0 buffers full
system usage: CPU: user: 0.17 s, system: 0.02 s, elapsed: 2.76 s
INFO: vacuuming "depesz.pg_toast.pg_toast_798487"INFO: finished vacuuming "depesz.pg_toast.pg_toast_798487": index scans: 0
pages: 0 removed, 0 remain, 0 scanned (100.00% of total), 0 eagerly scanned
tuples: 0 removed, 0 remain, 0 are dead but not yet removable
removable cutoff: 2159, which was 0 XIDs old when operation ended
new relfrozenxid: 2159, which is 3 XIDs ahead of previous value
frozen: 0 pages from table (100.00% of total) had 0 tuples frozen
visibility map: 0 pages set all-visible, 0 pages set all-frozen (0 were all-visible)
index scan not needed: 0 pages from table (100.00% of total) had 0 dead item identifiers removed
delay time: 5.580 ms
I/O timings: read: 0.031 ms, write: 0.000 ms
avg read rate: 1.351 MB/s, avg write rate: 0.000 MB/s
buffer usage: 25 hits, 1 reads, 0 dirtied
WAL usage: 1 records, 0 full page images, 254 bytes, 0 buffers full
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
VACUUM
Please check line 26 above – delay time: 5.580ms 🙂
Then I redid the setup, and left it so autovacuum will pick it.
To make sure that I will get it logged, made sure to have log_autovacuum_min_duration set to 0. After some time, in logs, I got this:
2025-02-19 12:32:04.690 CET @ 379450 LOG: automatic vacuum of table "depesz.public.test_it": index scans: 1
pages: 0 removed, 115008 remain, 115008 scanned (100.00% of total), 0 eagerly scanned
tuples: 7500218 removed, 2499782 remain, 0 are dead but not yet removable
removable cutoff: 2175, which was 0 XIDs old when operation ended
frozen: 114185 pages from table (99.28% of total) had 2499726 tuples frozen
visibility map: 114976 pages set all-visible, 114962 pages set all-frozen (0 were all-visible)
index scan needed: 114962 pages from table (99.96% of total) had 7500218 dead item identifiers removed
index "test_it_pkey": pages: 27422 in total, 0 newly deleted, 0 currently deleted, 0 reusable
delay time: 57002.466 ms
I/O timings: read: 384.980 ms, write: 1032.635 ms
avg read rate: 27.745 MB/s, avg write rate: 30.244 MB/s
buffer usage: 146632 hits, 225888 reads, 246238 dirtied
WAL usage: 487219 records, 223217 full page images, 1224286719 bytes, 11605 buffers full
system usage: CPU: user: 3.74 s, system: 2.41 s, elapsed: 63.60 s
This time, line 9: delay time: 57002.466 ms.
This is absolutely awesome. Thanks a lot to everyone involved.