Thread: Instrumented pages/tuples frozen in autovacuum's server log out (and VACUUM VERBOSE)

Attached is another autovacuum (and VACUUM VERBOSE) instrumentation
patch. This one adds instrumentation about freezing to the report
autovacuum makes to the server log. Specifically, it makes the output
look like this:

regression=#  vacuum (freeze,verbose) foo;
INFO:  aggressively vacuuming "regression.public.foo"
INFO:  finished vacuuming "regression.public.foo": index scans: 0
pages: 0 removed, 45 remain, 45 scanned (100.00% of total)
tuples: 0 removed, 10000 remain, 0 are dead but not yet removable
removable cutoff: 751, which was 0 XIDs old when operation ended
new relfrozenxid: 751, which is 2 XIDs ahead of previous value
XIDs processed: 45 pages from table (100.00% of total) had 10000 tuples frozen
index scan not needed: 0 pages from table (0.00% of total) had 0 dead
item identifiers removed
I/O timings: read: 0.023 ms, write: 0.000 ms
avg read rate: 2.829 MB/s, avg write rate: 5.658 MB/s
buffer usage: 95 hits, 2 misses, 4 dirtied
WAL usage: 91 records, 1 full page images, 133380 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
VACUUM

Notice the new line about freezing, which we always output -- it's the
line that begins with "XIDs processed", that appears about half way
down. The new line is deliberately placed after the existing "new
relfrozenxid" line and before the existing line about dead item
identifiers. This placement of the new instrumentation seems logical
to me; freezing is related to relfrozenxid (obviously), but doesn't
need to be shoehorned into the prominent early line that reports on
tuples removed/remain[ing].

Like its neighboring "dead item identifier" line, this new line shows
the number of items/tuples affected, and the number of heap pages
affected -- with heap pages shown both as an absolute number and as a
percentage of rel_pages (in parentheses). The main cost associated
with freezing is the WAL overhead, so emphasizing pages here seems
like the way to go -- pages are more interesting than tuples. This
format also makes it relatively easy to get a sense of the *relative*
costs of the overhead of each distinct class/category of maintenance
performed.

-- 
Peter Geoghegan

On Wed, Aug 31, 2022 at 7:49 PM Jeff Janes <jeff.janes@gmail.com> wrote:
> I like this addition, but I would also like to see how many pages got newly set to all frozen by the vacuum.

I'd say that that's independent work. Though I'm happy to discuss it now.

It would be fairly straightforward to show something about the VM
itself, but it's not entirely clear what aspects of the VM should be
emphasized. Are we reporting on the state of the table, or work
performed by VACUUM? You said you were interested in the latter
already, but why prefer that over a summary of the contents of the VM
at the end of the VACUUM? Are you concerned about the cost of setting
pages all-visible? Do you have an interest in how VACUUM manages to
set VM pages over time? Something else?

We already call visibilitymap_count() at the end of every VACUUM,
which scans the authoritative VM to produce a more-or-less consistent
summary of the VM at that point in time. This information is then used
to update pg_class.relallvisible (we don't do anything with the
all-frozen number at all). Why not show that information in
VERBOSE/autovacuum's log message? Does it really matter *when* a page
became all-visible/all-frozen/unset?

> Also, isn't all of vacuuming about XID processing?  I think "frozen:" would be a more suitable line prefix.

That also works for me. I have no strong feelings here.

-- 
Peter Geoghegan

On Wed, Aug 31, 2022 at 7:49 PM Jeff Janes <jeff.janes@gmail.com> wrote:
> I think "frozen:" would be a more suitable line prefix.

Attached revision does it that way.

Barring any objections I will commit this patch within the next few days.

Thanks
-- 
Peter Geoghegan

On Mon, Sep 5, 2022 at 12:43 PM Peter Geoghegan <pg@bowt.ie> wrote:
> Barring any objections I will commit this patch within the next few days.

Pushed this just now.

Thanks
-- 
Peter Geoghegan