Re: Unifying VACUUM VERBOSE and log_autovacuum_min_duration output

Hi,

On 2021-11-29 18:51:37 -0800, Peter Geoghegan wrote:
> 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.

I think some actually ended up being omitted compared to the previous
state. E.g. "aggressively vacuuming ...", but I think others as well.

> It's easy to produce examples where the patch is somewhat more verbose
> than HEAD (that's what you see here).

We could make verbose a more complicated parameter if that turns out to be a
problem. E.g. controlling whether resource usage is included.

> 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).

That's not really equivalent though? It does seem somewhat useful to be able
to distinguish the cost of heap and index processing?

> 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).

Using multiple messages has the clear drawback of including context/statement
multiple times... But if part of the point is to be able to analyze what's
currently happening there's not really an alternative. However that need
probably is lessened now that we have pg_stat_progress_vacuum.

> @@ -702,12 +705,13 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
> vacrel->new_dead_tuples);
> pgstat_progress_end_command();
>
> - /* and log the action if appropriate */
> - if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
> + /* Output instrumentation where appropriate */
> + if (verbose ||
> + (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0))
> {
> TimestampTz endtime = GetCurrentTimestamp();
>
> - if (params->log_min_duration == 0 ||
> + if (verbose || params->log_min_duration == 0 ||
> TimestampDifferenceExceeds(starttime, endtime,
> params->log_min_duration))
> {

This is quite the nest of conditions by now. Any chance of cleaning that up?

> @@ -3209,7 +3144,7 @@ lazy_truncate_heap(LVRelState *vacrel)
> * We failed to establish the lock in the specified number of
> * retries. This means we give up truncating.
> */
> - ereport(elevel,
> + ereport(DEBUG2,
> (errmsg("\"%s\": stopping truncate due to conflicting lock request",
> vacrel->relname)));
> return;

> @@ -3279,12 +3214,10 @@ lazy_truncate_heap(LVRelState *vacrel)
> vacrel->pages_removed += orig_rel_pages - new_rel_pages;
> vacrel->rel_pages = new_rel_pages;
>
> - ereport(elevel,
> + ereport(DEBUG2,
> (errmsg("table \"%s\": truncated %u to %u pages",
> vacrel->relname,
> - orig_rel_pages, new_rel_pages),
> - errdetail_internal("%s",
> - pg_rusage_show(&ru0))));
> + orig_rel_pages, new_rel_pages)));
> orig_rel_pages = new_rel_pages;
> } while (new_rel_pages > vacrel->nonempty_pages && lock_waiter_detected);
> }

These imo are useful. Perhaps we could just make them part of some log
message that autovac logging includes as well?

Greetings,

Andres Freund