Re: Logging pg_autovacuum

tgl(at)sss(dot)pgh(dot)pa(dot)us (Tom Lane) writes:

> "Larry Rosenman" <lrosenman(at)pervasive(dot)com> writes:
>> I'd like to see a more concrete definition of what we
>> want Autovacuum to output and at what levels.
>
> I would argue that what people typically want is
>
> (0) nothing
>
> (1) per-database log messages
>
> or
>
> (2) per-table log messages (including per-database)
>
> The first problem is that (2) is only available at DEBUG2 or below,
> which is not good because that also clutters the log with a whole
> lot of implementer-level debugging info.
>
> The second problem is that we don't really want to use the global
> log_min_messages setting to determine this, because that constrains
> your decision about how much chatter you want from ordinary
> backends.
>
> I suggest that maybe the cleanest solution is to not use log level
> at all for this, but to invent a separate "autovacuum_verbosity"
> setting that controls how many messages autovac tries to log, using
> the above scale. Anything it does try to log can just come out at
> LOG message setting.

At "level 2," it seems to me that it would be quite useful to have
some way of getting at the verbose output of VACUUM.

Consider when I vacuum a table, thus:

/* cbbrowne(at)[local]/dba2 performance=*/ vacuum verbose analyze days;
INFO: vacuuming "public.days"
INFO: "days": found 0 removable, 1893 nonremovable row versions in 9 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 0 unused item pointers.
0 pages are entirely empty.
CPU 0.00s/0.00u sec elapsed 0.03 sec.
INFO: analyzing "public.days"
INFO: "days": 9 pages, 1893 rows sampled, 1893 estimated total rows
VACUUM

The only thing that PostgreSQL will log generally about this is, if
the query runs for a while, that I requested "vacuum verbose analyze
days;", and that this took 4284ms to run.

It would be really nice if we could have some way of logging the
details, namely of numbers of row versions removed/nonremovable, and
of pages affected.

If we could regularly log that sort of information, that could be very
useful in figuring out some "more nearly optimal" schedule for
vacuuming.

One of our people wrote a Perl script that will take verbose VACUUM
output and essentially parses it so as to be able to generate a bunch
of SQL queries to try to collect how much time was spent, and what
sorts of changes got accomplished.

At present, getting anything out of that mandates that every VACUUM
request have stdout tied to this Perl script, which I'm not overly
keen on, for any number of reasons, notably:

- Any vacuums run separately aren't monitored at all

- Parsing not-forcibly-stable-across-versions file formats with Perl
is a fragile thing

- Ideally, this would be nice to get into the PG "engine," somewhere,
whether as part of standard logging, or as part of how pg_autovacuum
works...

Having some ability to collect statistics about "we recovered 42 pages
from table foo at 12:45" would seem useful both from an immediate
temporal perspective where it could suggest whether specific tables
were being vacuumed too (seldom|often), and from a more
global/analytic perspective of perhaps suggesting better kinds of
vacuuming policies. (In much the same way that I'd like to have some
way of moving towards an analytically better value for
default_statistics_target than 10...)

If people are interested, I could provide a copy of the "analyze
VACUUM stats" script...
--
(reverse (concatenate 'string "gro.mca" "@" "enworbbc"))
http://www.ntlug.org/~cbbrowne/sgml.html
"I would rather spend 10 hours reading someone else's source code than
10 minutes listening to Musak waiting for technical support which
isn't." -- Dr. Greg Wettstein, Roger Maris Cancer Center