Hi,
On 2022-04-14 12:26:20 -0400, Tom Lane wrote:
> Andres Freund <and...@anarazel.de> writes:
> > Thanks! Can you repro the problem manually on wrasse, perhaps even
> > outside the buildfarm script?
Ah, cool.
> I'm working on that right now, actually...
>
> > I wonder if we should make VACUUM log the VERBOSE output at DEBUG1
> > unconditionally. This is like the third bug where we needed that
> > information, and it's practically impossible to include in regression
> > output. Then we'd know what the xid horizon is, whether pages were
> > skipped, etc.
>
> Right at the moment it seems like we also need visibility into what
> CREATE INDEX is doing.
> I'm not sure I'd buy into permanent changes here (at least not ones made
> in haste), but temporarily adding more logging seems perfectly reasonable.
I think it might be worth leaving in, but let's debate that separately?
I'm thinking of something like the attached.
Greetings,
Andres Freund
diff --git i/src/backend/access/heap/vacuumlazy.c w/src/backend/access/heap/vacuumlazy.c
index 788db569b2d..eaee473754d 100644
--- i/src/backend/access/heap/vacuumlazy.c
+++ w/src/backend/access/heap/vacuumlazy.c
@@ -186,6 +186,7 @@ typedef struct LVRelState
OffsetNumber offnum; /* used only for heap operations */
VacErrPhase phase;
bool verbose; /* VACUUM VERBOSE? */
+ int elevel;
/*
* dead_items stores TIDs whose index tuples are deleted by index
@@ -330,8 +331,24 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
WalUsage walusage_start = pgWalUsage;
ErrorContextCallback errcallback;
char **indnames = NULL;
+ int elevel;
+
+ if (params->options & VACOPT_VERBOSE)
+ {
+ verbose = true;
+ elevel = INFO;
+ }
+ else if (message_level_is_interesting(DEBUG1))
+ {
+ verbose = true;
+ elevel = DEBUG1;
+ }
+ else
+ {
+ verbose = false;
+ elevel = DEBUG5;
+ }
- verbose = (params->options & VACOPT_VERBOSE) != 0;
instrument = (verbose || (IsAutoVacuumWorkerProcess() &&
params->log_min_duration >= 0));
if (instrument)
@@ -392,20 +409,20 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
vacrel->indname = NULL;
vacrel->phase = VACUUM_ERRCB_PHASE_UNKNOWN;
vacrel->verbose = verbose;
+ vacrel->elevel = elevel;
errcallback.callback = vacuum_error_callback;
errcallback.arg = vacrel;
errcallback.previous = error_context_stack;
error_context_stack = &errcallback;
- if (verbose)
+ if (verbose && !IsAutoVacuumWorkerProcess())
{
- Assert(!IsAutoVacuumWorkerProcess());
if (aggressive)
- ereport(INFO,
+ ereport(elevel,
(errmsg("aggressively vacuuming \"%s.%s.%s\"",
get_database_name(MyDatabaseId),
vacrel->relnamespace, vacrel->relname)));
else
- ereport(INFO,
+ ereport(elevel,
(errmsg("vacuuming \"%s.%s.%s\"",
get_database_name(MyDatabaseId),
vacrel->relnamespace, vacrel->relname)));
@@ -788,7 +805,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
(unsigned long long) walusage.wal_bytes);
appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
- ereport(verbose ? INFO : LOG,
+ ereport(elevel,
(errmsg_internal("%s", buf.data)));
pfree(buf.data);
}
@@ -2944,7 +2961,7 @@ lazy_truncate_heap(LVRelState *vacrel)
vacrel->removed_pages += orig_rel_pages - new_rel_pages;
vacrel->rel_pages = new_rel_pages;
- ereport(vacrel->verbose ? INFO : DEBUG2,
+ ereport(vacrel->elevel,
(errmsg("table \"%s\": truncated %u to %u pages",
vacrel->relname,
orig_rel_pages, new_rel_pages)));
@@ -3006,7 +3023,7 @@ count_nondeletable_pages(LVRelState *vacrel, bool *lock_waiter_detected)
{
if (LockHasWaitersRelation(vacrel->rel, AccessExclusiveLock))
{
- ereport(vacrel->verbose ? INFO : DEBUG2,
+ ereport(vacrel->elevel,
(errmsg("table \"%s\": suspending truncate due to conflicting lock request",
vacrel->relname)));
