Re: Unifying VACUUM VERBOSE and log_autovacuum_min_duration output

On Fri, Nov 26, 2021 at 12:37 PM Peter Geoghegan <pg(at)bowt(dot)ie> wrote:
> My preferred approach to this is simple: redefine VACUUM VERBOSE to
> not show incremental output, which seems rather unhelpful anyway. This
> does mean that VACUUM VERBOSE won't show certain information that
> might occasionally be useful to hackers.

Attached is a WIP patch doing this.

One thing that's still unclear is what the new elevel should be for
the ereport messages that used to be either LOG (for VACUUM VERBOSE)
or DEBUG2 (for everything else) -- what should I change them to now?
For now I've done taken the obvious approach of making everything
DEBUG2. There is of course no reason why some messages can't be DEBUG1
instead. Some of them do seem more interesting than others (though
still not particularly interesting overall).

Here is an example of VACUUM VERBOSE on HEAD:

pg(at)regression=# vacuum VERBOSE foo;
INFO: vacuuming "public.foo"
INFO: table "public.foo": found 0 removable, 54 nonremovable row
versions in 1 out of 45 pages
DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 770
Skipped 0 pages due to buffer pins, 0 frozen pages.
CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
VACUUM

Here's what a VACUUM VERBOSE against the same table looks like with
the patch applied:

pg(at)regression=# vacuum VERBOSE foo;
INFO: vacuuming "regression.public.foo"
INFO: finished vacuuming "regression.public.foo": index scans: 0
pages: 0 removed, 45 remain, 0 skipped due to pins, 0 skipped frozen
tuples: 0 removed, 7042 remain, 0 are dead but not yet removable,
oldest xmin: 770
index scan not needed: 0 pages from table (0.00% of total) had 0 dead
item identifiers removed
I/O timings: read: 0.065 ms, write: 0.000 ms
avg read rate: 147.406 MB/s, avg write rate: 14.741 MB/s
buffer usage: 22 hits, 10 misses, 1 dirtied
WAL usage: 1 records, 1 full page images, 1401 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
VACUUM

It's easy to produce examples where the patch is somewhat more verbose
than HEAD (that's what you see here). It's also easy to produce
examples where HEAD is *significantly* more verbose than the patch.
Especially when VERBOSE shows many lines of getrusage() output (patch
only ever shows one of those, at the end). Another factor is index
vacuuming. With the patch, you'll only see one extra line per index,
versus several lines on HEAD.

I cannot find clear guidelines on multiline INFO messages lines -- all
I'm really doing here is selectively making the LOG output from
log_autovacuum_min_duration into INFO output for VACUUM VERBOSE
(actually there are 2 INFO messages per heap relation processed). It
would be nice if there was a clear message style precedent that I
could point to for this.

--
Peter Geoghegan