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.