MIME-Version: 1.0
From: Pavel Stehule <pavel.stehule@gmail.com>
Date: Mon, 27 Apr 2026 09:02:16 +0200
Message-ID: 
 <CAFj8pRAHj6c8DMCH6wJz1Q0YOb47oE+Wfy1KbZKqQ4s92Nk24g@mail.gmail.com>
Subject: proposal: refactoring vacuum verbose output
To: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Content-Type: multipart/alternative; boundary="00000000000006ad8b06506bb497"
Archived-At: 
 <https://www.postgresql.org/message-id/CAFj8pRAHj6c8DMCH6wJz1Q0YOb47oE%2BWfy1KbZKqQ4s92Nk24g%40mail.gmail.com>
Precedence: bulk

--00000000000006ad8b06506bb497
Content-Type: text/plain; charset="UTF-8"

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

--00000000000006ad8b06506bb497
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div>Hi</div><div><br></div><div>I am working on a patch t=
hat tries to colourize some lines from VACUUM VERBOSE output.</div><div><br=
></div><div>The main problem is inconsistent output from VACUUM, ANALYZE, R=
EINDEX and REPACK.</div><div><br></div><div>Can we introduce some new error=
 levels, and new error fields that allows to write these reports more reada=
ble:</div><div><br></div><div>Current output from REINDEX VERBOSE</div><div=
><br></div><div>(2026-04-24 21:30:41) postgres=3D# reindex (verbose) table =
pg_class;<br>INFO: =C2=A0index &quot;pg_class_oid_index&quot; was reindexed=
<br>DETAIL: =C2=A0CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s<br>INF=
O: =C2=A0index &quot;pg_class_relname_nsp_index&quot; was reindexed<br>DETA=
IL: =C2=A0CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s<br>INFO: =C2=
=A0index &quot;pg_class_tblspc_relfilenode_index&quot; was reindexed<br>DET=
AIL: =C2=A0CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s<br>REINDEX=C2=
=A0</div><div><br></div><div>Current output from VACUUM VERBOSE</div><div><=
br></div><div>(2026-04-24 21:30:49) postgres=3D# vacuum verbose pg_proc;<br=
>INFO: =C2=A0vacuuming &quot;postgres.pg_catalog.pg_proc&quot;<br>INFO: =C2=
=A0finished vacuuming &quot;postgres.pg_catalog.pg_proc&quot;: index scans:=
 0<br>pages: 0 removed, 101 remain, 1 scanned (0.99% of total), 0 eagerly s=
canned<br>tuples: 0 removed, 3437 remain, 0 are dead but not yet removable<=
br>removable cutoff: 702, which was 0 XIDs old when operation ended<br>new =
relfrozenxid: 702, which is 1 XIDs ahead of previous value<br>frozen: 0 pag=
es from table (0.00% of total) had 0 tuples frozen<br>visibility map: 0 pag=
es set all-visible, 0 pages set all-frozen (0 were all-visible)<br>index sc=
an not needed: 0 pages from table (0.00% of total) had 0 dead item identifi=
ers removed<br>avg read rate: 0.000 MB/s, avg write rate: 12.440 MB/s<br>bu=
ffer usage: 22 hits, 0 reads, 1 dirtied<br>WAL usage: 1 records, 1 full pag=
e images, 5871 bytes, 5752 full page image bytes, 0 buffers full<br>memory =
usage: dead item storage 0.02 MB accumulated across 0 resets (limit 64.00 M=
B each)<br>system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s=
<br>INFO: =C2=A0vacuuming &quot;postgres.pg_toast.pg_toast_1255&quot;<br>IN=
FO: =C2=A0finished vacuuming &quot;postgres.pg_toast.pg_toast_1255&quot;: i=
ndex scans: 0<br>pages: 0 removed, 2 remain, 2 scanned (100.00% of total), =
0 eagerly scanned<br>tuples: 0 removed, 7 remain, 0 are dead but not yet re=
movable<br>removable cutoff: 702, which was 0 XIDs old when operation ended=
<br>new relfrozenxid: 702, which is 1 XIDs ahead of previous value<br>froze=
n: 0 pages from table (0.00% of total) had 0 tuples frozen<br>visibility ma=
p: 0 pages set all-visible, 0 pages set all-frozen (0 were all-visible)<br>=
index scan not needed: 0 pages from table (0.00% of total) had 0 dead item =
identifiers removed<br>avg read rate: 0.000 MB/s, avg write rate: 16.482 MB=
/s<br>buffer usage: 43 hits, 0 reads, 1 dirtied<br>WAL usage: 1 records, 1 =
full page images, 4255 bytes, 4136 full page image bytes, 0 buffers full<br=
>memory usage: dead item storage 0.02 MB accumulated across 0 resets (limit=
 64.00 MB each)<br>system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed=
: 0.00 s<br>VACUUM</div><div><br></div><div>My proposal is introduction new=
 three levels of INFO - INFO1, INFO2, and INFO3</div><div><br></div><div>IN=
FO1 can be used for starting, finishing=C2=A0processing of primary object l=
ike tables</div><div>INFO2 can be used for starting, finishing processing o=
f depending objects like toast tables or partitions</div><div>INFO3 can be =
used for starting, finishing processing of nested objects like indexes</div=
><div><br></div><div>We can introduce new error field RESOURCES</div><div><=
br></div><div>After change new=C2=A0 verbose output can looks like:</div><d=
iv><br></div><div>(2026-04-24 21:30:41) postgres=3D# reindex (verbose) tabl=
e pg_class;<br>INFO3: =C2=A0index &quot;pg_class_oid_index&quot; was reinde=
xed<br>RESOURCES: =C2=A0CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s<=
br>INFO3: =C2=A0index &quot;pg_class_relname_nsp_index&quot; was reindexed<=
br>RESOURCES: =C2=A0CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s<br>I=
NFO3: =C2=A0index &quot;pg_class_tblspc_relfilenode_index&quot; was reindex=
ed<br>RESOURCES: =C2=A0CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s<b=
r>REINDEX=C2=A0<br></div><div><br></div><div><div>(2026-04-24 21:30:49) pos=
tgres=3D# vacuum verbose pg_proc;</div><div><b>INFO1: =C2=A0vacuuming &quot=
;postgres.pg_catalog.pg_proc&quot;<br>INFO1: =C2=A0finished vacuuming &quot=
;postgres.pg_catalog.pg_proc&quot;</b></div><div>DETAIL: index scans: 0,</d=
iv><div>pages: 0 removed, 101 remain, 1 scanned (0.99% of total), 0 eagerly=
 scanned<br>tuples: 0 removed, 3437 remain, 0 are dead but not yet removabl=
e<br>removable cutoff: 702, which was 0 XIDs old when operation ended<br>ne=
w relfrozenxid: 702, which is 1 XIDs ahead of previous value<br>frozen: 0 p=
ages from table (0.00% of total) had 0 tuples frozen<br>visibility map: 0 p=
ages set all-visible, 0 pages set all-frozen (0 were all-visible)<br>index =
scan not needed: 0 pages from table (0.00% of total) had 0 dead item identi=
fiers removed<br>RESOURCES: avg read rate: 0.000 MB/s, avg write rate: 12.4=
40 MB/s,<br>buffer usage: 22 hits, 0 reads, 1 dirtied<br>WAL usage: 1 recor=
ds, 1 full page images, 5871 bytes, 5752 full page image bytes, 0 buffers f=
ull<br>memory usage: dead item storage 0.02 MB accumulated across 0 resets =
(limit 64.00 MB each)<br>system usage: CPU: user: 0.00 s, system: 0.00 s, e=
lapsed: 0.00 s<br><b>INFO2: =C2=A0vacuuming &quot;postgres.pg_toast.pg_toas=
t_</b><b>1255&quot;<br>INFO2: =C2=A0finished vacuuming &quot;postgres.pg_to=
ast.pg_toast_</b><b>1255&quot;</b></div><div>DETAIL: index scans: 0<br>page=
s: 0 removed, 2 remain, 2 scanned (100.00% of total), 0 eagerly scanned<br>=
tuples: 0 removed, 7 remain, 0 are dead but not yet removable<br>removable =
cutoff: 702, which was 0 XIDs old when operation ended<br>new relfrozenxid:=
 702, which is 1 XIDs ahead of previous value<br>frozen: 0 pages from table=
 (0.00% of total) had 0 tuples frozen<br>visibility map: 0 pages set all-vi=
sible, 0 pages set all-frozen (0 were all-visible)<br>index scan not needed=
: 0 pages from table (0.00% of total) had 0 dead item identifiers removed<b=
r>RESOURCES: avg read rate: 0.000 MB/s, avg write rate: 16.482 MB/s<br>buff=
er usage: 43 hits, 0 reads, 1 dirtied<br>WAL usage: 1 records, 1 full page =
images, 4255 bytes, 4136 full page image bytes, 0 buffers full<br>memory us=
age: dead item storage 0.02 MB accumulated across 0 resets (limit 64.00 MB =
each)<br>system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s<b=
r>VACUUM</div><br></div><div>There is a problem about the leveling of INFO,=
 because the perspective of VACUUM and REINDEX is shifted.</div><div><br></=
div><div>With proposed design we can highlight lines INFO1..INFO3 or we can=
 hide DETAIL or RESOURCES fields.<br><br></div><div>Maybe we can introduce =
a new error field DETAIL_CRITICAL. When I use VACUUM VERBOSE - I watch prim=
ary field `0 are dead but not yet removable`. Can be nice if this informati=
on is separated.</div><div><br></div><div>Another possible error field can =
be &quot;hint&quot; with query to progress stat view</div><div><br></div><d=
iv>INFO1: vacuuming &quot;postgres.pg_catalog.pg_proc&quot;</div><div>PROGR=
ESS_QUERY: SELECT * FROM pg_stat_progress_vacuum WHERE pid =3D xxx ...</div=
><div><br></div><div>or maybe in more parseable form</div><div>STATEMENTINF=
O: cmdtag &quot;VACUUM&quot;: progress_tab=3Dpg_stat_progress_vacuum&quot;:=
 pid=3D111</div><div><br></div><div>Another idea - introduce a new error fi=
eld dedicated for holding information for client in parseable format. This =
field should be processed by a client and should not be displayed to the us=
er. And should not be stored in a log.</div><div><br></div><div>INFO1: vacu=
uming &quot;postgres.....</div><div>CLIENTINFO: {&quot;cmdtag&quot;:&quot;V=
ACUUM&quot;, &quot;pid&quot;: 112, &quot;progres_view&quot;:&quot;pg_stat_p=
rogress_vacuum&quot;, ...</div><div><br></div><div>All new fields and error=
 levels require protocol enhancement.</div><div><br></div><div>What do you =
think about this proposal?</div><div><br></div><div>Regards</div><div><br><=
/div><div>Pavel</div><div><br></div></div>

--00000000000006ad8b06506bb497--