Re: a verbose option for autovacuum

On Tue, Feb 2, 2021 at 9:59 AM Tommy Li <tommy(at)coffeemeetsbagel(dot)com> wrote:
>
> Hi Masahiko
>
> > If we set
> > it per-table basis, it’s useful when the user already knows which
> > tables are likely to take a long time for autovacuum
>
> I would assume that's the default case, most apps I've seen are designed around a small
> number of large tables that take up most of the maintenance effort
>
> > Regarding when to log, we can have autovacuum emit index vacuum log
> > after each lazy_vacuum/cleanup_index() end like VACUUM VERBOSE does,
> > but I’m not sure how it could work together with
> > log_autovacuum_min_duration.
>
> I do like having this rolled into the existing configuration. This might be an absurd idea, but
> what if the autovacuum process accumulates the per-index vacuum information until that
> threshold is reached, and then spits out the logs all at once? And after the min duration is
> passed, it just logs the rest of the index vacuum information as they occur. That way the
> information is more likely to be available to investigate an abnormally long running vacuum
> while it's still happening.

Since index vacuum can be executed more than once within an
autovacuum, we need to keep all of them. It's not impossible.

As the second idea, I think showing index vacuum statistics (i.g.,
what lazy_cleanup_index shows) together with the current autovacuum
logs might be a good start. The autovacuum log becomes like follows:

* HEAD
LOG: automatic vacuum of table "postgres.public.test": index scans: 1
pages: 0 removed, 443 remain, 0 skipped due to pins, 0 skipped frozen
tuples: 1000 removed, 99000 remain, 0 are dead but not yet removable,
oldest xmin: 545
buffer usage: 2234 hits, 4 misses, 4 dirtied
avg read rate: 0.504 MB/s, avg write rate: 0.504 MB/s
system usage: CPU: user: 0.03 s, system: 0.00 s, elapsed: 0.06 s
WAL usage: 2162 records, 4 full page images, 159047 bytes

* Proposed idea
LOG: automatic vacuum of table "postgres.public.test": index scans: 1
pages: 0 removed, 443 remain, 0 skipped due to pins, 0 skipped frozen
tuples: 1000 removed, 99000 remain, 0 are dead but not yet removable,
oldest xmin: 545
indexes: "postgres.public.test_idx1" 276 pages, 0 newly deleted, 0
currently deleted, 0 reusable.
"postgres.public.test_idx2" 300 pages, 10 newly deleted, 0 currently
deleted, 3 reusable.
"postgres.public.test_idx2" 310 pages, 4 newly deleted, 0 currently
deleted, 0 reusable.
buffer usage: 2234 hits, 4 misses, 4 dirtied
avg read rate: 0.504 MB/s, avg write rate: 0.504 MB/s
system usage: CPU: user: 0.03 s, system: 0.00 s, elapsed: 0.06 s
WAL usage: 2162 records, 4 full page images, 159047 bytes

It still lacks some of what VACUUM VERBOSE shows (e.g., each index
vacuum execution time etc) but it would be enough information to know
the index page statistics. Probably we can output those by default
without adding a new parameter controlling that.

Regards,

--
Masahiko Sawada
EDB: https://www.enterprisedb.com/