| From: | Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com> |
|---|---|
| To: | PostgreSQL Hackers <pgsql-hackers(at)lists(dot)postgresql(dot)org> |
| Subject: | proposal: refactoring vacuum verbose output |
| Date: | 2026-04-27 07:02:16 |
| Message-ID: | CAFj8pRAHj6c8DMCH6wJz1Q0YOb47oE+Wfy1KbZKqQ4s92Nk24g@mail.gmail.com |
| Views: | Whole Thread | Raw Message | Download mbox | Resend email |
| Thread: | |
| Lists: | 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
| From | Date | Subject | |
|---|---|---|---|
| Next Message | shveta malik | 2026-04-27 07:07:52 | Re: Parallel Apply |
| Previous Message | vignesh C | 2026-04-27 06:44:36 | Re: StringInfo fixes, v19 edition. Plus a few oddities |