proposal: refactoring vacuum verbose output - Mailing list pgsql-hackers

From Pavel Stehule
Subject proposal: refactoring vacuum verbose output
Date
Msg-id CAFj8pRAHj6c8DMCH6wJz1Q0YOb47oE+Wfy1KbZKqQ4s92Nk24g@mail.gmail.com
Whole thread
List pgsql-hackers
Hi

I am working on a patch that tries to colourize some lines from VACUUM VERBOSE output.

The main problem is inconsistent output from VACUUM, ANALYZE, REINDEX and REPACK.

Can we introduce some new error levels, and new error fields that allows to write these reports more readable:

Current output from REINDEX VERBOSE

(2026-04-24 21:30:41) postgres=# reindex (verbose) table pg_class;
INFO:  index "pg_class_oid_index" was reindexed
DETAIL:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
INFO:  index "pg_class_relname_nsp_index" was reindexed
DETAIL:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
INFO:  index "pg_class_tblspc_relfilenode_index" was reindexed
DETAIL:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
REINDEX 

Current output from VACUUM VERBOSE

(2026-04-24 21:30:49) postgres=# vacuum verbose pg_proc;
INFO:  vacuuming "postgres.pg_catalog.pg_proc"
INFO:  finished vacuuming "postgres.pg_catalog.pg_proc": index scans: 0
pages: 0 removed, 101 remain, 1 scanned (0.99% of total), 0 eagerly scanned
tuples: 0 removed, 3437 remain, 0 are dead but not yet removable
removable cutoff: 702, which was 0 XIDs old when operation ended
new relfrozenxid: 702, which is 1 XIDs ahead of previous value
frozen: 0 pages from table (0.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 (0.00% of total) had 0 dead item identifiers removed
avg read rate: 0.000 MB/s, avg write rate: 12.440 MB/s
buffer usage: 22 hits, 0 reads, 1 dirtied
WAL usage: 1 records, 1 full page images, 5871 bytes, 5752 full page image bytes, 0 buffers full
memory usage: dead item storage 0.02 MB accumulated across 0 resets (limit 64.00 MB each)
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
INFO:  vacuuming "postgres.pg_toast.pg_toast_1255"
INFO:  finished vacuuming "postgres.pg_toast.pg_toast_1255": index scans: 0
pages: 0 removed, 2 remain, 2 scanned (100.00% of total), 0 eagerly scanned
tuples: 0 removed, 7 remain, 0 are dead but not yet removable
removable cutoff: 702, which was 0 XIDs old when operation ended
new relfrozenxid: 702, which is 1 XIDs ahead of previous value
frozen: 0 pages from table (0.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 (0.00% of total) had 0 dead item identifiers removed
avg read rate: 0.000 MB/s, avg write rate: 16.482 MB/s
buffer usage: 43 hits, 0 reads, 1 dirtied
WAL usage: 1 records, 1 full page images, 4255 bytes, 4136 full page image bytes, 0 buffers full
memory usage: dead item storage 0.02 MB accumulated across 0 resets (limit 64.00 MB each)
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
VACUUM

My proposal is introduction new three levels of INFO - INFO1, INFO2, and INFO3

INFO1 can be used for starting, finishing processing of primary object like tables
INFO2 can be used for starting, finishing processing of depending objects like toast tables or partitions
INFO3 can be used for starting, finishing processing of nested objects like indexes

We can introduce new error field RESOURCES

After change new  verbose output can looks like:

(2026-04-24 21:30:41) postgres=# reindex (verbose) table pg_class;
INFO3:  index "pg_class_oid_index" was reindexed
RESOURCES:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
INFO3:  index "pg_class_relname_nsp_index" was reindexed
RESOURCES:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
INFO3:  index "pg_class_tblspc_relfilenode_index" was reindexed
RESOURCES:  CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
REINDEX 

(2026-04-24 21:30:49) postgres=# vacuum verbose pg_proc;
INFO1:  vacuuming "postgres.pg_catalog.pg_proc"
INFO1:  finished vacuuming "postgres.pg_catalog.pg_proc"
DETAIL: index scans: 0,
pages: 0 removed, 101 remain, 1 scanned (0.99% of total), 0 eagerly scanned
tuples: 0 removed, 3437 remain, 0 are dead but not yet removable
removable cutoff: 702, which was 0 XIDs old when operation ended
new relfrozenxid: 702, which is 1 XIDs ahead of previous value
frozen: 0 pages from table (0.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 (0.00% of total) had 0 dead item identifiers removed
RESOURCES: avg read rate: 0.000 MB/s, avg write rate: 12.440 MB/s,
buffer usage: 22 hits, 0 reads, 1 dirtied
WAL usage: 1 records, 1 full page images, 5871 bytes, 5752 full page image bytes, 0 buffers full
memory usage: dead item storage 0.02 MB accumulated across 0 resets (limit 64.00 MB each)
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
INFO2:  vacuuming "postgres.pg_toast.pg_toast_1255"
INFO2:  finished vacuuming "postgres.pg_toast.pg_toast_
1255"
DETAIL: index scans: 0
pages: 0 removed, 2 remain, 2 scanned (100.00% of total), 0 eagerly scanned
tuples: 0 removed, 7 remain, 0 are dead but not yet removable
removable cutoff: 702, which was 0 XIDs old when operation ended
new relfrozenxid: 702, which is 1 XIDs ahead of previous value
frozen: 0 pages from table (0.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 (0.00% of total) had 0 dead item identifiers removed
RESOURCES: avg read rate: 0.000 MB/s, avg write rate: 16.482 MB/s
buffer usage: 43 hits, 0 reads, 1 dirtied
WAL usage: 1 records, 1 full page images, 4255 bytes, 4136 full page image bytes, 0 buffers full
memory usage: dead item storage 0.02 MB accumulated across 0 resets (limit 64.00 MB each)
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
VACUUM

There is a problem about the leveling of INFO, because the perspective of VACUUM and REINDEX is shifted.

With proposed design we can highlight lines INFO1..INFO3 or we can hide DETAIL or RESOURCES fields.

Maybe we can introduce a new error field DETAIL_CRITICAL. When I use VACUUM VERBOSE - I watch primary field `0 are dead but not yet removable`. Can be nice if this information is separated.

Another possible error field can be "hint" with query to progress stat view

INFO1: vacuuming "postgres.pg_catalog.pg_proc"
PROGRESS_QUERY: SELECT * FROM pg_stat_progress_vacuum WHERE pid = xxx ...

or maybe in more parseable form
STATEMENTINFO: cmdtag "VACUUM": progress_tab=pg_stat_progress_vacuum": pid=111

Another idea - introduce a new error field dedicated for holding information for client in parseable format. This field should be processed by a client and should not be displayed to the user. And should not be stored in a log.

INFO1: vacuuming "postgres.....
CLIENTINFO: {"cmdtag":"VACUUM", "pid": 112, "progres_view":"pg_stat_progress_vacuum", ...

All new fields and error levels require protocol enhancement.

What do you think about this proposal?

Regards

Pavel

pgsql-hackers by date:

Previous
From: vignesh C
Date:
Subject: Re: StringInfo fixes, v19 edition. Plus a few oddities
Next
From: shveta malik
Date:
Subject: Re: Parallel Apply