Unifying VACUUM VERBOSE and log_autovacuum_min_duration output
I think that it's worth unifying VACUUM VERBOSE and
log_autovacuum_min_duration output, to remove the redundancy, and to
provide more useful VACUUM VERBOSE output.
Both variants already output approximately the same things. But, each
variant reports on certain details that the other variant lacks. I
find the extra information provided by log_autovacuum_min_duration far
more useful than the extra details provided by VACUUM VERBOSE. This is
probably because we've focussed on improving the former over the
latter, probably because autovacuum is much more interesting than
VACUUM on average, in practice, to users.
Unifying everything cannot be approached mechanically, so doing this
requires real buy-in. It's a bit tricky because VACUUM VERBOSE is
supposed to show real time information about what just finished, as a
kind of rudimentary progress indicator, while log_autovacuum_*
summarizes the whole entire VACUUM operation. This difference is most
notable when there are multiple index vacuuming passes ("index
scans"), or when we truncate the heap relation.
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. For example, there is
detailed information about how rel truncation happened in the VERBOSE
output, and detailed information about how many index tuples were
deleted by each round of index vacuuming, for each individual index.
We can keep this extra information as DEBUG2 messages, as in the
current !VERBOSE case (or perhaps make some of them DEBUG1). I don't
think that we need to keep the getrusage() stuff at all, though.
I think that this would significantly improve VACUUM VERBOSE output,
especially for users, but also for hackers. Here are my reasons, in
detail:
* We have pg_stat_progress_vacuum these days.
* VACUUM VERBOSE doesn't provide much of the most useful
instrumentation that we have available in log_autovacuum_min_duration,
and yet produces output that is ludicrously, unmanageably verbose --
lots of pg_rusage_show() information for each and every step, which
just isn't useful.
* I really miss the extra stuff that log_autovacuum_min_duration
provides when I run VACUUM VERBOSE, though.
* In practice having multiple rounds of index vacuuming is quite rare
these days. And when it does happen it's interesting because it
happened at all -- I don't really care about the breakdown beyond
that. If I ever do care about the very fine details, I can easily set
client_min_messages to DEBUG2 on that one occasion.
* The fact that VACUUM VERBOSE will no longer report on
IndexBulkDeleteResult.num_index_tuples and
IndexBulkDeleteResult.tuples_removed seems like no great loss to me --
the fact that the number might be higher or lower for an index
typically means very little these days, with the improvements made to
index tuple deletion.
VERBOSE will still report on IndexBulkDeleteResult.pages_*, which is
what really matters. VERBOSE will also report on LP_DEAD-in-heap items
removed (or not removed) directly, which is a generic upper bound on
tuples_removed, that applies to all indexes.
* The detailed lazy_truncate_heap() instrumentation output by VACUUM
VERBOSE just isn't useful outside of debugging scenarios -- it just
isn't actionable to users (users only really care about how much
smaller the table became through truncation). The low level details
could easily be output as DEBUG1 (not DEBUG2) instead.
Thoughts?
--
Peter Geoghegan
On Fri, Nov 26, 2021 at 12:37:32PM -0800, Peter Geoghegan wrote:
My preferred approach to this is simple: redefine VACUUM VERBOSE to
not show incremental output, which seems rather unhelpful anyway.
I don't think that we need to keep the getrusage() stuff at all, though.
+1
* VACUUM VERBOSE doesn't provide much of the most useful
instrumentation that we have available in log_autovacuum_min_duration,
and yet produces output that is ludicrously, unmanageably verbose --
lots of pg_rusage_show() information for each and every step, which
just isn't useful.
Not only not useful/unhelpful, but confusing.
It's what I complained about here.
/messages/by-id/20191220171132.GB30414@telsasoft.com
I see that lazy_scan_heap() still has a shadow variable buf...
--
Justin
On Fri, Nov 26, 2021 at 12:37 PM Peter Geoghegan <pg@bowt.ie> wrote:
Unifying everything cannot be approached mechanically, so doing this
requires real buy-in. It's a bit tricky because VACUUM VERBOSE is
supposed to show real time information about what just finished, as a
kind of rudimentary progress indicator, while log_autovacuum_*
summarizes the whole entire VACUUM operation. This difference is most
notable when there are multiple index vacuuming passes ("index
scans"), or when we truncate the heap relation.
I based these remarks on one sentence about VERBOSE that appears in vacuum.sgml:
"When VERBOSE is specified, VACUUM emits progress messages to indicate
which table is currently being processed. Various statistics about the
tables are printed as well."
There is a very similar sentence in analyze.sgml. It seems that I
overinterpreted the word "progress" before. I now believe that VACUUM
VERBOSE wasn't ever really intended to indicate the progress of one
particular vacuumlazy.c-wise operation targeting one particular heap
relation with storage. The VERBOSE option gives some necessary
table-level structure to an unqualified "VACUUM VERBOSE" -- same as
an unqualified "ANALYZE VERBOSE". The progress is explicitly table
granularity progress. Nothing more.
I definitely need to preserve that aspect of VERBOSE output --
obviously the output must still make it perfectly clear which
particular table a given run of information relates to, especially
with unqualified "VACUUM VERBOSE". Fortunately, that'll be easy. In
fact, my proposal will improve things here, because now there will
only be a single extra INFO line per table (so one INFO line for the
table name, another with newlines for the instrumentation itself).
This matches the current behavior with an unqualified "ANALYZE
VERBOSE".
--
Peter Geoghegan
On Fri, Nov 26, 2021 at 1:57 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
* VACUUM VERBOSE doesn't provide much of the most useful
instrumentation that we have available in log_autovacuum_min_duration,
and yet produces output that is ludicrously, unmanageably verbose --
lots of pg_rusage_show() information for each and every step, which
just isn't useful.Not only not useful/unhelpful, but confusing.
Also makes testing harder.
It's what I complained about here.
/messages/by-id/20191220171132.GB30414@telsasoft.comI see that lazy_scan_heap() still has a shadow variable buf...
I noticed that myself. That function has had many accretions of code,
over decades. I often notice things that seem like they once made
sense (e.g., before we had HOT), but don't anymore.
I hope to be able to pay down more technical debt in this area for Postgres 15.
--
Peter Geoghegan
On Fri, Nov 26, 2021 at 12:37 PM Peter Geoghegan <pg@bowt.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@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@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
Attachments:
v1-0001-Unify-VACUUM-VERBOSE-and-log_autovacuum_min_durat.patchapplication/octet-stream; name=v1-0001-Unify-VACUUM-VERBOSE-and-log_autovacuum_min_durat.patchDownload
From 231413b144972592c99aa608e69e6c18c57fcfab Mon Sep 17 00:00:00 2001
From: Peter Geoghegan <pg@bowt.ie>
Date: Sun, 21 Nov 2021 21:48:33 -0800
Subject: [PATCH v1] Unify VACUUM VERBOSE and log_autovacuum_min_duration.
Author: Peter Geoghegan <pg@bowt.ie>
Discussion: https://postgr.es/m/CAH2-WzmW4Me7_qR4X4ka7pxP-jGmn7=Npma_-Z-9Y1eD0MQRLw@mail.gmail.com
---
src/include/commands/vacuum.h | 6 +-
src/backend/access/heap/vacuumlazy.c | 248 ++++++++++-----------------
src/backend/commands/vacuum.c | 2 +-
3 files changed, 93 insertions(+), 163 deletions(-)
diff --git a/src/include/commands/vacuum.h b/src/include/commands/vacuum.h
index 4cfd52eaf..d1e804f47 100644
--- a/src/include/commands/vacuum.h
+++ b/src/include/commands/vacuum.h
@@ -177,7 +177,7 @@ typedef struct VacAttrStats
/* flag bits for VacuumParams->options */
#define VACOPT_VACUUM 0x01 /* do VACUUM */
#define VACOPT_ANALYZE 0x02 /* do ANALYZE */
-#define VACOPT_VERBOSE 0x04 /* print progress info */
+#define VACOPT_VERBOSE 0x04 /* output instrumentation */
#define VACOPT_FREEZE 0x08 /* FREEZE option */
#define VACOPT_FULL 0x10 /* FULL (non-concurrent) vacuum */
#define VACOPT_SKIP_LOCKED 0x20 /* skip if cannot get lock */
@@ -217,8 +217,8 @@ typedef struct VacuumParams
* whole table */
bool is_wraparound; /* force a for-wraparound vacuum */
int log_min_duration; /* minimum execution threshold in ms at
- * which verbose logs are activated, -1
- * to use default */
+ * which verbose output is logged, -1 to
+ * use default */
VacOptValue index_cleanup; /* Do index vacuum and cleanup */
VacOptValue truncate; /* Truncate empty pages at the end */
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 6a2fa2ba0..e98d4bb44 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -179,7 +179,6 @@ typedef struct LVShared
* the lazy vacuum.
*/
Oid relid;
- int elevel;
/*
* An indication for vacuum workers to perform either index vacuum or
@@ -312,7 +311,7 @@ typedef struct LVRelState
/* Error reporting state */
char *relnamespace;
char *relname;
- char *indname;
+ char *indname; /* Current index name */
BlockNumber blkno; /* used only for heap operations */
OffsetNumber offnum; /* used only for heap operations */
VacErrPhase phase;
@@ -372,9 +371,6 @@ typedef struct LVSavedErrInfo
VacErrPhase phase;
} LVSavedErrInfo;
-/* elevel controls whole VACUUM's verbosity */
-static int elevel = -1;
-
/* non-export function prototypes */
static void lazy_scan_heap(LVRelState *vacrel, VacuumParams *params,
@@ -457,6 +453,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
BufferAccessStrategy bstrategy)
{
LVRelState *vacrel;
+ bool verbose,
+ instrument;
PGRUsage ru0;
TimestampTz starttime = 0;
WalUsage walusage_start = pgWalUsage;
@@ -482,8 +480,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
TransactionId FreezeLimit;
MultiXactId MultiXactCutoff;
- /* measure elapsed time iff autovacuum logging requires it */
- if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+ verbose = (params->options & VACOPT_VERBOSE) != 0;
+ instrument = (verbose || (IsAutoVacuumWorkerProcess() &&
+ params->log_min_duration >= 0));
+ if (instrument)
{
pg_rusage_init(&ru0);
starttime = GetCurrentTimestamp();
@@ -494,11 +494,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
}
}
- if (params->options & VACOPT_VERBOSE)
- elevel = INFO;
- else
- elevel = DEBUG2;
-
pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM,
RelationGetRelid(rel));
@@ -523,14 +518,56 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
if (params->options & VACOPT_DISABLE_PAGE_SKIPPING)
aggressive = true;
+ /*
+ * Setup error traceback support for ereport(). The idea is to set up an
+ * error context callback to display additional information on any error
+ * during a vacuum. During different phases of vacuum, we update the
+ * state so that the error context callback always display current
+ * information. Copy the names of relations into local memory now, too.
+ * It isn't always safe to assume that we can get the name of each rel.
+ * It's convenient for code in lazy_scan_heap to always use these temp
+ * copies.
+ *
+ * Note that the index vacuum and heap vacuum phases may be called
+ * multiple times in the middle of the heap scan phase. So the old phase
+ * information is restored at the end of those phases.
+ */
vacrel = (LVRelState *) palloc0(sizeof(LVRelState));
+ vacrel->relnamespace = get_namespace_name(RelationGetNamespace(rel));
+ vacrel->relname = pstrdup(RelationGetRelationName(rel));
+ vacrel->indname = NULL;
+ vacrel->phase = VACUUM_ERRCB_PHASE_UNKNOWN;
+ errcallback.callback = vacuum_error_callback;
+ errcallback.arg = vacrel;
+ errcallback.previous = error_context_stack;
+ error_context_stack = &errcallback;
+ if (verbose)
+ {
+ /* VACUUM VERBOSE initial INFO message, before we start real work */
+ Assert(!IsAutoVacuumWorkerProcess());
+ if (aggressive)
+ ereport(INFO,
+ (errmsg("aggressively vacuuming \"%s.%s.%s\"",
+ get_database_name(MyDatabaseId),
+ vacrel->relnamespace, vacrel->relname)));
+ else
+ ereport(INFO,
+ (errmsg("vacuuming \"%s.%s.%s\"",
+ get_database_name(MyDatabaseId),
+ vacrel->relnamespace, vacrel->relname)));
+ }
/* Set up high level stuff about rel */
vacrel->rel = rel;
vac_open_indexes(vacrel->rel, RowExclusiveLock, &vacrel->nindexes,
&vacrel->indrels);
- vacrel->failsafe_active = false;
- vacrel->consider_bypass_optimization = true;
+ if (instrument && vacrel->nindexes > 0)
+ {
+ /* Couldn't copy index names earlier, so do that now instead */
+ indnames = palloc(sizeof(char *) * vacrel->nindexes);
+ for (int i = 0; i < vacrel->nindexes; i++)
+ indnames[i] = pstrdup(RelationGetRelationName(vacrel->indrels[i]));
+ }
/*
* The index_cleanup param either disables index vacuuming and cleanup or
@@ -544,6 +581,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
Assert(params->index_cleanup != VACOPTVALUE_UNSPECIFIED);
Assert(params->truncate != VACOPTVALUE_UNSPECIFIED &&
params->truncate != VACOPTVALUE_AUTO);
+ vacrel->failsafe_active = false;
+ vacrel->consider_bypass_optimization = true;
vacrel->do_index_vacuuming = true;
vacrel->do_index_cleanup = true;
vacrel->do_rel_truncate = (params->truncate != VACOPTVALUE_DISABLED);
@@ -574,37 +613,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
vacrel->FreezeLimit = FreezeLimit;
vacrel->MultiXactCutoff = MultiXactCutoff;
- vacrel->relnamespace = get_namespace_name(RelationGetNamespace(rel));
- vacrel->relname = pstrdup(RelationGetRelationName(rel));
- vacrel->indname = NULL;
- vacrel->phase = VACUUM_ERRCB_PHASE_UNKNOWN;
-
- /* Save index names iff autovacuum logging requires it */
- if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0 &&
- vacrel->nindexes > 0)
- {
- indnames = palloc(sizeof(char *) * vacrel->nindexes);
- for (int i = 0; i < vacrel->nindexes; i++)
- indnames[i] =
- pstrdup(RelationGetRelationName(vacrel->indrels[i]));
- }
-
- /*
- * Setup error traceback support for ereport(). The idea is to set up an
- * error context callback to display additional information on any error
- * during a vacuum. During different phases of vacuum (heap scan, heap
- * vacuum, index vacuum, index clean up, heap truncate), we update the
- * error context callback to display appropriate information.
- *
- * Note that the index vacuum and heap vacuum phases may be called
- * multiple times in the middle of the heap scan phase. So the old phase
- * information is restored at the end of those phases.
- */
- errcallback.callback = vacuum_error_callback;
- errcallback.arg = vacrel;
- errcallback.previous = error_context_stack;
- error_context_stack = &errcallback;
-
/*
* Call lazy_scan_heap to perform all required heap pruning, index
* vacuuming, and heap vacuuming (plus related processing)
@@ -635,11 +643,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
*/
if (should_attempt_truncation(vacrel))
{
- /*
- * Update error traceback information. This is the last phase during
- * which we add context information to errors, so we don't need to
- * revert to the previous phase.
- */
update_vacuum_error_info(vacrel, NULL, VACUUM_ERRCB_PHASE_TRUNCATE,
vacrel->nonempty_pages,
InvalidOffsetNumber);
@@ -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))
{
@@ -730,12 +734,17 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
(secs + usecs / 1000000.0);
}
- /*
- * This is pretty messy, but we split it up so that we can skip
- * emitting individual parts of the message when not applicable.
- */
initStringInfo(&buf);
- if (params->is_wraparound)
+ if (verbose)
+ {
+ /*
+ * Aggressiveness already reported earlier, in dedicated
+ * VACUUM VERBOSE ereport
+ */
+ Assert(!params->is_wraparound);
+ msgfmt = _("finished vacuuming \"%s.%s.%s\": index scans: %d\n");
+ }
+ else if (params->is_wraparound)
{
/*
* While it's possible for a VACUUM to be both is_wraparound
@@ -834,19 +843,19 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
(unsigned long long) walusage.wal_bytes);
appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
- ereport(LOG,
+ ereport(verbose ? INFO : LOG,
(errmsg_internal("%s", buf.data)));
pfree(buf.data);
}
}
- /* Cleanup index statistics and index names */
+ /* Cleanup index statistics and names */
for (int i = 0; i < vacrel->nindexes; i++)
{
if (vacrel->indstats[i])
pfree(vacrel->indstats[i]);
- if (indnames && indnames[i])
+ if (instrument)
pfree(indnames[i]);
}
}
@@ -896,10 +905,8 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
next_unskippable_block,
next_failsafe_block,
next_fsm_block_to_vacuum;
- PGRUsage ru0;
Buffer vmbuffer = InvalidBuffer;
bool skipping_blocks;
- StringInfoData buf;
const int initprog_index[] = {
PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -908,19 +915,6 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
int64 initprog_val[3];
GlobalVisState *vistest;
- pg_rusage_init(&ru0);
-
- if (aggressive)
- ereport(elevel,
- (errmsg("aggressively vacuuming \"%s.%s\"",
- vacrel->relnamespace,
- vacrel->relname)));
- else
- ereport(elevel,
- (errmsg("vacuuming \"%s.%s\"",
- vacrel->relnamespace,
- vacrel->relname)));
-
nblocks = RelationGetNumberOfBlocks(vacrel->rel);
next_unskippable_block = 0;
next_failsafe_block = 0;
@@ -1613,49 +1607,15 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
/*
* When the table has no indexes (i.e. in the one-pass strategy case),
- * make log report that lazy_vacuum_heap_rel would've made had there been
- * indexes. (As in the two-pass strategy case, only make this report when
- * there were LP_DEAD line pointers vacuumed in lazy_vacuum_heap_page.)
+ * produce debug output that lazy_vacuum_heap_rel would've made had there
+ * been indexes. (As in the two-pass strategy case, only do so when there
+ * were LP_DEAD line pointers vacuumed in lazy_vacuum_heap_page.)
*/
if (vacrel->nindexes == 0 && vacrel->lpdead_item_pages > 0)
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("table \"%s\": removed %lld dead item identifiers in %u pages",
vacrel->relname, (long long) vacrel->lpdead_items,
vacrel->lpdead_item_pages)));
-
- /*
- * Make a log report summarizing pruning and freezing.
- *
- * The autovacuum specific logging in heap_vacuum_rel summarizes an entire
- * VACUUM operation, whereas each VACUUM VERBOSE log report generally
- * summarizes a single round of index/heap vacuuming (or rel truncation).
- * It wouldn't make sense to report on pruning or freezing while following
- * that convention, though. You can think of this log report as a summary
- * of our first pass over the heap.
- */
- initStringInfo(&buf);
- appendStringInfo(&buf,
- _("%lld dead row versions cannot be removed yet, oldest xmin: %u\n"),
- (long long) vacrel->new_dead_tuples, vacrel->OldestXmin);
- appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
- "Skipped %u pages due to buffer pins, ",
- vacrel->pinskipped_pages),
- vacrel->pinskipped_pages);
- appendStringInfo(&buf, ngettext("%u frozen page.\n",
- "%u frozen pages.\n",
- vacrel->frozenskipped_pages),
- vacrel->frozenskipped_pages);
- appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
-
- ereport(elevel,
- (errmsg("table \"%s.%s\": found %lld removable, %lld nonremovable row versions in %u out of %u pages",
- vacrel->relnamespace,
- vacrel->relname,
- (long long) vacrel->tuples_deleted,
- (long long) vacrel->num_tuples, vacrel->scanned_pages,
- nblocks),
- errdetail_internal("%s", buf.data)));
- pfree(buf.data);
}
/*
@@ -2147,11 +2107,6 @@ lazy_vacuum(LVRelState *vacrel)
* calls.)
*/
vacrel->do_index_vacuuming = false;
- ereport(elevel,
- (errmsg("table \"%s\": index scan bypassed: %u pages from table (%.2f%% of total) have %lld dead item identifiers",
- vacrel->relname, vacrel->lpdead_item_pages,
- 100.0 * vacrel->lpdead_item_pages / vacrel->rel_pages,
- (long long) vacrel->lpdead_items)));
}
else if (lazy_vacuum_all_indexes(vacrel))
{
@@ -2294,7 +2249,6 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
{
int index;
BlockNumber vacuumed_pages;
- PGRUsage ru0;
Buffer vmbuffer = InvalidBuffer;
LVSavedErrInfo saved_err_info;
@@ -2311,7 +2265,6 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
VACUUM_ERRCB_PHASE_VACUUM_HEAP,
InvalidBlockNumber, InvalidOffsetNumber);
- pg_rusage_init(&ru0);
vacuumed_pages = 0;
index = 0;
@@ -2358,10 +2311,9 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
(index == vacrel->lpdead_items &&
vacuumed_pages == vacrel->lpdead_item_pages));
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("table \"%s\": removed %lld dead item identifiers in %u pages",
- vacrel->relname, (long long) index, vacuumed_pages),
- errdetail_internal("%s", pg_rusage_show(&ru0))));
+ vacrel->relname, (long long) index, vacuumed_pages)));
/* Revert to the previous phase information for error traceback */
restore_vacuum_error_info(vacrel, &saved_err_info);
@@ -2736,13 +2688,13 @@ do_parallel_vacuum_or_cleanup(LVRelState *vacrel, int nworkers)
}
if (lps->lvshared->for_cleanup)
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg(ngettext("launched %d parallel vacuum worker for index cleanup (planned: %d)",
"launched %d parallel vacuum workers for index cleanup (planned: %d)",
lps->pcxt->nworkers_launched),
lps->pcxt->nworkers_launched, nworkers)));
else
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg(ngettext("launched %d parallel vacuum worker for index vacuuming (planned: %d)",
"launched %d parallel vacuum workers for index vacuuming (planned: %d)",
lps->pcxt->nworkers_launched),
@@ -3009,16 +2961,12 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat,
double reltuples, LVRelState *vacrel)
{
IndexVacuumInfo ivinfo;
- PGRUsage ru0;
LVSavedErrInfo saved_err_info;
- pg_rusage_init(&ru0);
-
ivinfo.index = indrel;
ivinfo.analyze_only = false;
ivinfo.report_progress = false;
ivinfo.estimated_count = true;
- ivinfo.message_level = elevel;
ivinfo.num_heap_tuples = reltuples;
ivinfo.strategy = vacrel->bstrategy;
@@ -3038,10 +2986,9 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat,
istat = index_bulk_delete(&ivinfo, istat, lazy_tid_reaped,
(void *) vacrel->dead_items);
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("scanned index \"%s\" to remove %d row versions",
- vacrel->indname, vacrel->dead_items->num_items),
- errdetail_internal("%s", pg_rusage_show(&ru0))));
+ vacrel->indname, vacrel->dead_items->num_items)));
/* Revert to the previous phase information for error traceback */
restore_vacuum_error_info(vacrel, &saved_err_info);
@@ -3066,16 +3013,12 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat,
LVRelState *vacrel)
{
IndexVacuumInfo ivinfo;
- PGRUsage ru0;
LVSavedErrInfo saved_err_info;
- pg_rusage_init(&ru0);
-
ivinfo.index = indrel;
ivinfo.analyze_only = false;
ivinfo.report_progress = false;
ivinfo.estimated_count = estimated_count;
- ivinfo.message_level = elevel;
ivinfo.num_heap_tuples = reltuples;
ivinfo.strategy = vacrel->bstrategy;
@@ -3095,21 +3038,17 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat,
istat = index_vacuum_cleanup(&ivinfo, istat);
if (istat)
- {
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("index \"%s\" now contains %.0f row versions in %u pages",
RelationGetRelationName(indrel),
istat->num_index_tuples,
istat->num_pages),
errdetail("%.0f index row versions were removed.\n"
"%u index pages were newly deleted.\n"
- "%u index pages are currently deleted, of which %u are currently reusable.\n"
- "%s.",
+ "%u index pages are currently deleted, of which %u are currently reusable.\n",
istat->tuples_removed,
istat->pages_newly_deleted,
- istat->pages_deleted, istat->pages_free,
- pg_rusage_show(&ru0))));
- }
+ istat->pages_deleted, istat->pages_free)));
/* Revert to the previous phase information for error traceback */
restore_vacuum_error_info(vacrel, &saved_err_info);
@@ -3178,10 +3117,6 @@ lazy_truncate_heap(LVRelState *vacrel)
*/
do
{
- PGRUsage ru0;
-
- pg_rusage_init(&ru0);
-
/*
* We need full exclusive lock on the relation in order to do
* truncation. If we can't get it, give up rather than waiting --- we
@@ -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);
}
@@ -3343,7 +3276,7 @@ count_nondeletable_pages(LVRelState *vacrel, bool *lock_waiter_detected)
{
if (LockHasWaitersRelation(vacrel->rel, AccessExclusiveLock))
{
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("table \"%s\": suspending truncate due to conflicting lock request",
vacrel->relname)));
@@ -3977,7 +3910,6 @@ begin_parallel_vacuum(LVRelState *vacrel, int nrequested)
shared = (LVShared *) shm_toc_allocate(pcxt->toc, est_shared_len);
MemSet(shared, 0, est_shared_len);
shared->relid = RelationGetRelid(vacrel->rel);
- shared->elevel = elevel;
shared->maintenance_work_mem_worker =
(nindexes_mwm > 0) ?
maintenance_work_mem / Min(parallel_workers, nindexes_mwm) :
@@ -4188,12 +4120,10 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc)
lvshared = (LVShared *) shm_toc_lookup(toc, PARALLEL_VACUUM_KEY_SHARED,
false);
- elevel = lvshared->elevel;
-
if (lvshared->for_cleanup)
- elog(DEBUG1, "starting parallel vacuum worker for cleanup");
+ elog(DEBUG2, "starting parallel vacuum worker for cleanup");
else
- elog(DEBUG1, "starting parallel vacuum worker for bulk delete");
+ elog(DEBUG2, "starting parallel vacuum worker for bulk delete");
/* Set debug_query_string for individual workers */
sharedquery = shm_toc_lookup(toc, PARALLEL_VACUUM_KEY_QUERY_TEXT, true);
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index 5c4bc15b4..47d8ab733 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -261,7 +261,7 @@ ExecVacuum(ParseState *pstate, VacuumStmt *vacstmt, bool isTopLevel)
/* user-invoked vacuum is never "for wraparound" */
params.is_wraparound = false;
- /* user-invoked vacuum never uses this parameter */
+ /* user-invoked vacuum uses VACOPT_VERBOSE instead of log_min_duration */
params.log_min_duration = -1;
/* Now go through the common routine */
--
2.30.2
I think the 2nd chunk here could say "if (instrument)" like the first:
@@ -482,8 +480,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
TransactionId FreezeLimit;
MultiXactId MultiXactCutoff;- /* measure elapsed time iff autovacuum logging requires it */ - if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0) + verbose = (params->options & VACOPT_VERBOSE) != 0; + instrument = (verbose || (IsAutoVacuumWorkerProcess() && + params->log_min_duration >= 0)); + if (instrument)
...
@@ -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) - if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0) + /* Output instrumentation where appropriate */ + if (verbose || + (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0))
Autovacuum's format doesn't show the number of scanned pages ; it shows how
many pages were skipped due to frozen bit, but not how many were skipped due to
the all visible bit:
INFO: table "public.foo": found 0 removable, 54 nonremovable row versions in 1 out of 45 pages
...
INFO: finished vacuuming "regression.public.foo": index scans: 0
pages: 0 removed, 45 remain, 0 skipped due to pins, 0 skipped frozen
If the format of autovacuum output were to change, maybe it's an opportunity to
show some of the stuff Jeff mentioned:
|Also, I'd appreciate a report on how many hint-bits were set, and how many
|pages were marked all-visible and/or frozen
--
Justin
On Mon, Nov 29, 2021 at 8:19 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
I think the 2nd chunk here could say "if (instrument)" like the first:
I agree that that would be clearer.
Autovacuum's format doesn't show the number of scanned pages ; it shows how
many pages were skipped due to frozen bit, but not how many were skipped due to
the all visible bit:
That's a weird historical accident. I had planned on fixing that as
part of ongoing refactoring work [1]/messages/by-id/CAH2-Wznp=c=Opj8Z7RMR3G=ec3_JfGYMN_YvmCEjoPCHzWbx0g@mail.gmail.com -- Peter Geoghegan.
The short explanation for why it works that way goes like this: while
it makes zero practical sense (who wants to see how many frozen pages
we skipped, without also seeing merely all-visible pages skipped?), it
does make some sense when your starting point is the code itself.
If the format of autovacuum output were to change, maybe it's an opportunity to
show some of the stuff Jeff mentioned:
You must be referencing the thread again, from your earlier message --
you must mean Jeff Janes here.
Jeff said something about the number of all-visible pages accessed
(i.e. not skipped over) being implicit. For what it's worth, that
isn't true in the general case -- there simply is no reliable way to
see the total number of pages that were skipped using the VM, as of
right now.
|Also, I'd appreciate a report on how many hint-bits were set, and how many
|pages were marked all-visible and/or frozen
I will probably also add the latter in the Postgres 15 cycle.
Hint-bits-set is much harder, and not likely to happen soon.
[1]: /messages/by-id/CAH2-Wznp=c=Opj8Z7RMR3G=ec3_JfGYMN_YvmCEjoPCHzWbx0g@mail.gmail.com -- Peter Geoghegan
--
Peter Geoghegan
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
On Fri, Dec 10, 2021 at 8:30 PM Andres Freund <andres@anarazel.de> wrote:
I think some actually ended up being omitted compared to the previous
state. E.g. "aggressively vacuuming ...", but I think others as well.
The "aggressive-ness" is reported by a distinct ereport() with the
patch, so you'll still see that information. You'll still be able to
see when each VACUUM begins and ends, which matters in database level
"VACUUM" command (a VACUUM that doesn't specify any relation, and so
vacuums everything). VACUUM VERBOSE should still work as a progress
indicator at the whole-VACUUM-operation level (when there will be more
than a single operation per command), but it won't indicate the
progress of any individual VACUUM operation anymore. That's the
trade-off.
To me the most notable loss of VERBOSE information is the number of
index tuples deleted in each index. But even that isn't so useful,
since you can already see the number of LP_DEAD items, which is a more
interesting number (that applies equally to all indexes, and the table
itself).
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.
That's true, but I don't think that it's going to be a problem. I'd
rather avoid it if possible. If we need to place some of the stuff
that's currently only shown by VERBOSE to be shown by the autovacuum
log output too, then that's fine.
You said something about showing the number of workers launched in the
autovacuum log output (also the new VERBOSE output). That could make
sense. But there could be a different number of workers for cleanup
and for vacuuming. Should I show both together, or just the high
watermark? I think that it needs to be okay to suppress the output in
the common case where parallelism isn't used (e.g., in every
autovacuum).
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've personally never used VACUUM VERBOSE like that. I agree that it
could be useful, but I would argue that it's not worth it. I'd just
use the DEBUG1 version, or more likely use my own custom
microbenchmark.
This is quite the nest of conditions by now. Any chance of cleaning that up?
Yes, I can simplify that code a little.
@@ -3279,12 +3214,10 @@ lazy_truncate_heap(LVRelState *vacrel)
These imo are useful. Perhaps we could just make them part of some log
message that autovac logging includes as well?
I would argue that it already does -- because you see pages removed
(which is heap pages truncation). We do lose the details with the
patch, of course -- you'll no longer see the progress of truncation,
which works incrementally. But as I said, that's the general trade-off
that the patch makes.
If you can't truncate the table due to a conflicting lock request,
then that might just have been for the last round of truncation. And
so reporting that aspect in the whole-autovacuum log output (or in the
new format VACUUM VERBOSE output) seems like it could be misleading.
I went as far as removing the getrusage stuff for the ereport()
messages that get demoted to DEBUG2. What do you think of that aspect?
I could add some the getrusage output back where that makes sense. I
don't have very strong feelings about that.
--
Peter Geoghegan
On 2021-12-11 09:52:29 -0800, Peter Geoghegan wrote:
On Fri, Dec 10, 2021 at 8:30 PM Andres Freund <andres@anarazel.de> wrote:
I think some actually ended up being omitted compared to the previous
state. E.g. "aggressively vacuuming ...", but I think others as well.The "aggressive-ness" is reported by a distinct ereport() with the
patch, so you'll still see that information.
But the ereport is inside an if (verbose), no?
On Sat, Dec 11, 2021 at 12:24 PM Andres Freund <andres@anarazel.de> wrote:
But the ereport is inside an if (verbose), no?
Yes -- in order to report aggressiveness in VACUUM VERBOSE. But the
autovacuum case still reports verbose-ness, in the same way as it
always has -- in that same LOG entry. We don't want to repeat
ourselves in the VERBOSE case, which will have already indicated its
verboseness in the up-front ereport().
In other words, every distinct case reports on its aggressiveness
exactly once per call into lazyvacuum.c. In roughly the same way as it
works on HEAD.
--
Peter Geoghegan
On Sat, Dec 11, 2021 at 1:13 PM Peter Geoghegan <pg@bowt.ie> wrote:
Yes -- in order to report aggressiveness in VACUUM VERBOSE. But the
autovacuum case still reports verbose-ness, in the same way as it
always has -- in that same LOG entry. We don't want to repeat
ourselves in the VERBOSE case, which will have already indicated its
verboseness in the up-front ereport().
Sorry, I meant "indicated its aggressiveness in the up-front ereport()".
--
Peter Geoghegan
Hi,
On 2021-12-11 13:13:56 -0800, Peter Geoghegan wrote:
On Sat, Dec 11, 2021 at 12:24 PM Andres Freund <andres@anarazel.de> wrote:
But the ereport is inside an if (verbose), no?
Yes -- in order to report aggressiveness in VACUUM VERBOSE. But the
autovacuum case still reports verbose-ness, in the same way as it
always has -- in that same LOG entry. We don't want to repeat
ourselves in the VERBOSE case, which will have already indicated its
verboseness in the up-front ereport().
I feel one, or both, must be missing something here. My point was that you
said upthread that the patch doesn't change DEBUG2/non-verbose logging for
most messages. But the fact that those messages are only emitted inside and if
(verbose) seems to contradict that?
Greetings,
Andres Freund
On Sat, Dec 11, 2021 at 2:52 PM Andres Freund <andres@anarazel.de> wrote:
I feel one, or both, must be missing something here. My point was that you
said upthread that the patch doesn't change DEBUG2/non-verbose logging for
most messages. But the fact that those messages are only emitted inside and if
(verbose) seems to contradict that?
That is technically true, but it's not true in any practical sense.
Yes, there are 2 distinct ereports() per vacuumlazy.c call for VACUUM
VERBOSE (i.e. 2 per relation processed by the command). Yes, only the
second one is actually "shared" with log_autovacuum_* (the first one
is just shows that we're processing a new relation, with the
aggressiveness). But that's not very significant.
The only reason that I did it that way is because there is an
expectation that plain "VACUUM VERBOSE" (i.e. no target relation
specified) will work as a rudimentary progress indicator at the heap
rel granularity -- the VACUUM VERBOSE docs pretty much say so. As I
pointed out before, the docs for VERBOSE that appear in vacuum.sgml
say:
"When VERBOSE is specified, VACUUM emits progress messages to indicate
which table is currently being processed. Various statistics about the
tables are printed as well."
Having 2 ereports (not just 1) isn't essential, but it seems useful
because it makes the new VACUUM VERBOSE continue to work like this.
But without any of the downsides that go with seeing way too much
detail, moment to moment.
--
Peter Geoghegan
On Mon, Nov 29, 2021 at 6:51 PM Peter Geoghegan <pg@bowt.ie> wrote:
Attached is a WIP patch doing this.
This has bitrot, so I attach v2, mostly just to keep the CFTester
status green. The only real change is one minor simplification to how
we set everything up, inside heap_vacuum_rel().
--
Peter Geoghegan
Attachments:
v2-0001-Unify-VACUUM-VERBOSE-and-log_autovacuum_min_durat.patchapplication/octet-stream; name=v2-0001-Unify-VACUUM-VERBOSE-and-log_autovacuum_min_durat.patchDownload
From 2e3947da159b8a2f9657fd8c1a5a1f366f83ba85 Mon Sep 17 00:00:00 2001
From: Peter Geoghegan <pg@bowt.ie>
Date: Sun, 21 Nov 2021 21:48:33 -0800
Subject: [PATCH v2] Unify VACUUM VERBOSE and log_autovacuum_min_duration.
Author: Peter Geoghegan <pg@bowt.ie>
Discussion: https://postgr.es/m/CAH2-WzmW4Me7_qR4X4ka7pxP-jGmn7=Npma_-Z-9Y1eD0MQRLw@mail.gmail.com
---
src/include/commands/vacuum.h | 6 +-
src/backend/access/heap/vacuumlazy.c | 240 ++++++++++-----------------
src/backend/commands/vacuum.c | 2 +-
3 files changed, 88 insertions(+), 160 deletions(-)
diff --git a/src/include/commands/vacuum.h b/src/include/commands/vacuum.h
index 4cfd52eaf..d1e804f47 100644
--- a/src/include/commands/vacuum.h
+++ b/src/include/commands/vacuum.h
@@ -177,7 +177,7 @@ typedef struct VacAttrStats
/* flag bits for VacuumParams->options */
#define VACOPT_VACUUM 0x01 /* do VACUUM */
#define VACOPT_ANALYZE 0x02 /* do ANALYZE */
-#define VACOPT_VERBOSE 0x04 /* print progress info */
+#define VACOPT_VERBOSE 0x04 /* output instrumentation */
#define VACOPT_FREEZE 0x08 /* FREEZE option */
#define VACOPT_FULL 0x10 /* FULL (non-concurrent) vacuum */
#define VACOPT_SKIP_LOCKED 0x20 /* skip if cannot get lock */
@@ -217,8 +217,8 @@ typedef struct VacuumParams
* whole table */
bool is_wraparound; /* force a for-wraparound vacuum */
int log_min_duration; /* minimum execution threshold in ms at
- * which verbose logs are activated, -1
- * to use default */
+ * which verbose output is logged, -1 to
+ * use default */
VacOptValue index_cleanup; /* Do index vacuum and cleanup */
VacOptValue truncate; /* Truncate empty pages at the end */
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index db6becfed..754f373d3 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -180,7 +180,6 @@ typedef struct LVShared
* the lazy vacuum.
*/
Oid relid;
- int elevel;
/*
* Fields for both index vacuum and cleanup.
@@ -333,7 +332,7 @@ typedef struct LVRelState
/* Error reporting state */
char *relnamespace;
char *relname;
- char *indname;
+ char *indname; /* Current index name */
BlockNumber blkno; /* used only for heap operations */
OffsetNumber offnum; /* used only for heap operations */
VacErrPhase phase;
@@ -393,9 +392,6 @@ typedef struct LVSavedErrInfo
VacErrPhase phase;
} LVSavedErrInfo;
-/* elevel controls whole VACUUM's verbosity */
-static int elevel = -1;
-
/* non-export function prototypes */
static void lazy_scan_heap(LVRelState *vacrel, VacuumParams *params,
@@ -472,6 +468,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
BufferAccessStrategy bstrategy)
{
LVRelState *vacrel;
+ bool verbose,
+ instrument;
PGRUsage ru0;
TimestampTz starttime = 0;
WalUsage walusage_start = pgWalUsage;
@@ -497,8 +495,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
TransactionId FreezeLimit;
MultiXactId MultiXactCutoff;
- /* measure elapsed time iff autovacuum logging requires it */
- if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+ verbose = (params->options & VACOPT_VERBOSE) != 0;
+ instrument = (verbose || (IsAutoVacuumWorkerProcess() &&
+ params->log_min_duration >= 0));
+ if (instrument)
{
pg_rusage_init(&ru0);
starttime = GetCurrentTimestamp();
@@ -509,11 +509,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
}
}
- if (params->options & VACOPT_VERBOSE)
- elevel = INFO;
- else
- elevel = DEBUG2;
-
pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM,
RelationGetRelid(rel));
@@ -538,14 +533,56 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
if (params->options & VACOPT_DISABLE_PAGE_SKIPPING)
aggressive = true;
+ /*
+ * Setup error traceback support for ereport(). The idea is to set up an
+ * error context callback to display additional information on any error
+ * during a vacuum. During different phases of vacuum, we update the
+ * state so that the error context callback always display current
+ * information. Copy the names of relations into local memory now, too.
+ * It isn't always safe to assume that we can get the name of each rel.
+ * It's convenient for code in lazy_scan_heap to always use these temp
+ * copies.
+ *
+ * Note that the index vacuum and heap vacuum phases may be called
+ * multiple times in the middle of the heap scan phase. So the old phase
+ * information is restored at the end of those phases.
+ */
vacrel = (LVRelState *) palloc0(sizeof(LVRelState));
+ vacrel->relnamespace = get_namespace_name(RelationGetNamespace(rel));
+ vacrel->relname = pstrdup(RelationGetRelationName(rel));
+ vacrel->indname = NULL;
+ vacrel->phase = VACUUM_ERRCB_PHASE_UNKNOWN;
+ errcallback.callback = vacuum_error_callback;
+ errcallback.arg = vacrel;
+ errcallback.previous = error_context_stack;
+ error_context_stack = &errcallback;
+ if (verbose)
+ {
+ /* VACUUM VERBOSE initial INFO message, before we start real work */
+ Assert(!IsAutoVacuumWorkerProcess());
+ if (aggressive)
+ ereport(INFO,
+ (errmsg("aggressively vacuuming \"%s.%s.%s\"",
+ get_database_name(MyDatabaseId),
+ vacrel->relnamespace, vacrel->relname)));
+ else
+ ereport(INFO,
+ (errmsg("vacuuming \"%s.%s.%s\"",
+ get_database_name(MyDatabaseId),
+ vacrel->relnamespace, vacrel->relname)));
+ }
/* Set up high level stuff about rel */
vacrel->rel = rel;
vac_open_indexes(vacrel->rel, RowExclusiveLock, &vacrel->nindexes,
&vacrel->indrels);
- vacrel->failsafe_active = false;
- vacrel->consider_bypass_optimization = true;
+ if (instrument && vacrel->nindexes > 0)
+ {
+ /* Couldn't copy index names earlier, so do that now instead */
+ indnames = palloc(sizeof(char *) * vacrel->nindexes);
+ for (int i = 0; i < vacrel->nindexes; i++)
+ indnames[i] = pstrdup(RelationGetRelationName(vacrel->indrels[i]));
+ }
/*
* The index_cleanup param either disables index vacuuming and cleanup or
@@ -559,6 +596,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
Assert(params->index_cleanup != VACOPTVALUE_UNSPECIFIED);
Assert(params->truncate != VACOPTVALUE_UNSPECIFIED &&
params->truncate != VACOPTVALUE_AUTO);
+ vacrel->failsafe_active = false;
+ vacrel->consider_bypass_optimization = true;
vacrel->do_index_vacuuming = true;
vacrel->do_index_cleanup = true;
vacrel->do_rel_truncate = (params->truncate != VACOPTVALUE_DISABLED);
@@ -589,37 +628,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
vacrel->FreezeLimit = FreezeLimit;
vacrel->MultiXactCutoff = MultiXactCutoff;
- vacrel->relnamespace = get_namespace_name(RelationGetNamespace(rel));
- vacrel->relname = pstrdup(RelationGetRelationName(rel));
- vacrel->indname = NULL;
- vacrel->phase = VACUUM_ERRCB_PHASE_UNKNOWN;
-
- /* Save index names iff autovacuum logging requires it */
- if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0 &&
- vacrel->nindexes > 0)
- {
- indnames = palloc(sizeof(char *) * vacrel->nindexes);
- for (int i = 0; i < vacrel->nindexes; i++)
- indnames[i] =
- pstrdup(RelationGetRelationName(vacrel->indrels[i]));
- }
-
- /*
- * Setup error traceback support for ereport(). The idea is to set up an
- * error context callback to display additional information on any error
- * during a vacuum. During different phases of vacuum (heap scan, heap
- * vacuum, index vacuum, index clean up, heap truncate), we update the
- * error context callback to display appropriate information.
- *
- * Note that the index vacuum and heap vacuum phases may be called
- * multiple times in the middle of the heap scan phase. So the old phase
- * information is restored at the end of those phases.
- */
- errcallback.callback = vacuum_error_callback;
- errcallback.arg = vacrel;
- errcallback.previous = error_context_stack;
- error_context_stack = &errcallback;
-
/*
* Call lazy_scan_heap to perform all required heap pruning, index
* vacuuming, and heap vacuuming (plus related processing)
@@ -650,11 +658,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
*/
if (should_attempt_truncation(vacrel))
{
- /*
- * Update error traceback information. This is the last phase during
- * which we add context information to errors, so we don't need to
- * revert to the previous phase.
- */
update_vacuum_error_info(vacrel, NULL, VACUUM_ERRCB_PHASE_TRUNCATE,
vacrel->nonempty_pages,
InvalidOffsetNumber);
@@ -717,12 +720,11 @@ 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)
+ if (instrument)
{
TimestampTz endtime = GetCurrentTimestamp();
- if (params->log_min_duration == 0 ||
+ if (verbose || params->log_min_duration == 0 ||
TimestampDifferenceExceeds(starttime, endtime,
params->log_min_duration))
{
@@ -745,12 +747,17 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
(secs + usecs / 1000000.0);
}
- /*
- * This is pretty messy, but we split it up so that we can skip
- * emitting individual parts of the message when not applicable.
- */
initStringInfo(&buf);
- if (params->is_wraparound)
+ if (verbose)
+ {
+ /*
+ * Aggressiveness already reported earlier, in dedicated
+ * VACUUM VERBOSE ereport
+ */
+ Assert(!params->is_wraparound);
+ msgfmt = _("finished vacuuming \"%s.%s.%s\": index scans: %d\n");
+ }
+ else if (params->is_wraparound)
{
/*
* While it's possible for a VACUUM to be both is_wraparound
@@ -849,7 +856,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
(unsigned long long) walusage.wal_bytes);
appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
- ereport(LOG,
+ ereport(verbose ? INFO : LOG,
(errmsg_internal("%s", buf.data)));
pfree(buf.data);
}
@@ -861,7 +868,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
if (vacrel->indstats[i])
pfree(vacrel->indstats[i]);
- if (indnames && indnames[i])
+ if (instrument)
pfree(indnames[i]);
}
}
@@ -911,10 +918,8 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
next_unskippable_block,
next_failsafe_block,
next_fsm_block_to_vacuum;
- PGRUsage ru0;
Buffer vmbuffer = InvalidBuffer;
bool skipping_blocks;
- StringInfoData buf;
const int initprog_index[] = {
PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -923,19 +928,6 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
int64 initprog_val[3];
GlobalVisState *vistest;
- pg_rusage_init(&ru0);
-
- if (aggressive)
- ereport(elevel,
- (errmsg("aggressively vacuuming \"%s.%s\"",
- vacrel->relnamespace,
- vacrel->relname)));
- else
- ereport(elevel,
- (errmsg("vacuuming \"%s.%s\"",
- vacrel->relnamespace,
- vacrel->relname)));
-
nblocks = RelationGetNumberOfBlocks(vacrel->rel);
next_unskippable_block = 0;
next_failsafe_block = 0;
@@ -1628,49 +1620,15 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
/*
* When the table has no indexes (i.e. in the one-pass strategy case),
- * make log report that lazy_vacuum_heap_rel would've made had there been
- * indexes. (As in the two-pass strategy case, only make this report when
- * there were LP_DEAD line pointers vacuumed in lazy_vacuum_heap_page.)
+ * produce debug output that lazy_vacuum_heap_rel would've made had there
+ * been indexes. (As in the two-pass strategy case, only do so when there
+ * were LP_DEAD line pointers vacuumed in lazy_vacuum_heap_page.)
*/
if (vacrel->nindexes == 0 && vacrel->lpdead_item_pages > 0)
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("table \"%s\": removed %lld dead item identifiers in %u pages",
vacrel->relname, (long long) vacrel->lpdead_items,
vacrel->lpdead_item_pages)));
-
- /*
- * Make a log report summarizing pruning and freezing.
- *
- * The autovacuum specific logging in heap_vacuum_rel summarizes an entire
- * VACUUM operation, whereas each VACUUM VERBOSE log report generally
- * summarizes a single round of index/heap vacuuming (or rel truncation).
- * It wouldn't make sense to report on pruning or freezing while following
- * that convention, though. You can think of this log report as a summary
- * of our first pass over the heap.
- */
- initStringInfo(&buf);
- appendStringInfo(&buf,
- _("%lld dead row versions cannot be removed yet, oldest xmin: %u\n"),
- (long long) vacrel->new_dead_tuples, vacrel->OldestXmin);
- appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
- "Skipped %u pages due to buffer pins, ",
- vacrel->pinskipped_pages),
- vacrel->pinskipped_pages);
- appendStringInfo(&buf, ngettext("%u frozen page.\n",
- "%u frozen pages.\n",
- vacrel->frozenskipped_pages),
- vacrel->frozenskipped_pages);
- appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
-
- ereport(elevel,
- (errmsg("table \"%s.%s\": found %lld removable, %lld nonremovable row versions in %u out of %u pages",
- vacrel->relnamespace,
- vacrel->relname,
- (long long) vacrel->tuples_deleted,
- (long long) vacrel->num_tuples, vacrel->scanned_pages,
- nblocks),
- errdetail_internal("%s", buf.data)));
- pfree(buf.data);
}
/*
@@ -2162,11 +2120,6 @@ lazy_vacuum(LVRelState *vacrel)
* calls.)
*/
vacrel->do_index_vacuuming = false;
- ereport(elevel,
- (errmsg("table \"%s\": index scan bypassed: %u pages from table (%.2f%% of total) have %lld dead item identifiers",
- vacrel->relname, vacrel->lpdead_item_pages,
- 100.0 * vacrel->lpdead_item_pages / vacrel->rel_pages,
- (long long) vacrel->lpdead_items)));
}
else if (lazy_vacuum_all_indexes(vacrel))
{
@@ -2309,7 +2262,6 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
{
int index;
BlockNumber vacuumed_pages;
- PGRUsage ru0;
Buffer vmbuffer = InvalidBuffer;
LVSavedErrInfo saved_err_info;
@@ -2326,7 +2278,6 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
VACUUM_ERRCB_PHASE_VACUUM_HEAP,
InvalidBlockNumber, InvalidOffsetNumber);
- pg_rusage_init(&ru0);
vacuumed_pages = 0;
index = 0;
@@ -2373,10 +2324,9 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
(index == vacrel->lpdead_items &&
vacuumed_pages == vacrel->lpdead_item_pages));
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("table \"%s\": removed %lld dead item identifiers in %u pages",
- vacrel->relname, (long long) index, vacuumed_pages),
- errdetail_internal("%s", pg_rusage_show(&ru0))));
+ vacrel->relname, (long long) index, vacuumed_pages)));
/* Revert to the previous phase information for error traceback */
restore_vacuum_error_info(vacrel, &saved_err_info);
@@ -2744,13 +2694,13 @@ parallel_vacuum_process_all_indexes(LVRelState *vacrel, bool vacuum)
}
if (vacuum)
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(ngettext("launched %d parallel vacuum worker for index vacuuming (planned: %d)",
"launched %d parallel vacuum workers for index vacuuming (planned: %d)",
lps->pcxt->nworkers_launched),
lps->pcxt->nworkers_launched, nworkers)));
else
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(ngettext("launched %d parallel vacuum worker for index cleanup (planned: %d)",
"launched %d parallel vacuum workers for index cleanup (planned: %d)",
lps->pcxt->nworkers_launched),
@@ -3019,16 +2969,12 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat,
double reltuples, LVRelState *vacrel)
{
IndexVacuumInfo ivinfo;
- PGRUsage ru0;
LVSavedErrInfo saved_err_info;
- pg_rusage_init(&ru0);
-
ivinfo.index = indrel;
ivinfo.analyze_only = false;
ivinfo.report_progress = false;
ivinfo.estimated_count = true;
- ivinfo.message_level = elevel;
ivinfo.num_heap_tuples = reltuples;
ivinfo.strategy = vacrel->bstrategy;
@@ -3048,10 +2994,9 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat,
istat = index_bulk_delete(&ivinfo, istat, lazy_tid_reaped,
(void *) vacrel->dead_items);
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("scanned index \"%s\" to remove %d row versions",
- vacrel->indname, vacrel->dead_items->num_items),
- errdetail_internal("%s", pg_rusage_show(&ru0))));
+ vacrel->indname, vacrel->dead_items->num_items)));
/* Revert to the previous phase information for error traceback */
restore_vacuum_error_info(vacrel, &saved_err_info);
@@ -3076,16 +3021,12 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat,
LVRelState *vacrel)
{
IndexVacuumInfo ivinfo;
- PGRUsage ru0;
LVSavedErrInfo saved_err_info;
- pg_rusage_init(&ru0);
-
ivinfo.index = indrel;
ivinfo.analyze_only = false;
ivinfo.report_progress = false;
ivinfo.estimated_count = estimated_count;
- ivinfo.message_level = elevel;
ivinfo.num_heap_tuples = reltuples;
ivinfo.strategy = vacrel->bstrategy;
@@ -3105,21 +3046,17 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat,
istat = index_vacuum_cleanup(&ivinfo, istat);
if (istat)
- {
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("index \"%s\" now contains %.0f row versions in %u pages",
RelationGetRelationName(indrel),
istat->num_index_tuples,
istat->num_pages),
errdetail("%.0f index row versions were removed.\n"
"%u index pages were newly deleted.\n"
- "%u index pages are currently deleted, of which %u are currently reusable.\n"
- "%s.",
+ "%u index pages are currently deleted, of which %u are currently reusable.\n",
istat->tuples_removed,
istat->pages_newly_deleted,
- istat->pages_deleted, istat->pages_free,
- pg_rusage_show(&ru0))));
- }
+ istat->pages_deleted, istat->pages_free)));
/* Revert to the previous phase information for error traceback */
restore_vacuum_error_info(vacrel, &saved_err_info);
@@ -3188,10 +3125,6 @@ lazy_truncate_heap(LVRelState *vacrel)
*/
do
{
- PGRUsage ru0;
-
- pg_rusage_init(&ru0);
-
/*
* We need full exclusive lock on the relation in order to do
* truncation. If we can't get it, give up rather than waiting --- we
@@ -3219,7 +3152,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;
@@ -3289,12 +3222,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);
}
@@ -3353,7 +3284,7 @@ count_nondeletable_pages(LVRelState *vacrel, bool *lock_waiter_detected)
{
if (LockHasWaitersRelation(vacrel->rel, AccessExclusiveLock))
{
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("table \"%s\": suspending truncate due to conflicting lock request",
vacrel->relname)));
@@ -3997,7 +3928,6 @@ parallel_vacuum_begin(LVRelState *vacrel, int nrequested)
shared = (LVShared *) shm_toc_allocate(pcxt->toc, est_shared_len);
MemSet(shared, 0, est_shared_len);
shared->relid = RelationGetRelid(vacrel->rel);
- shared->elevel = elevel;
shared->maintenance_work_mem_worker =
(nindexes_mwm > 0) ?
maintenance_work_mem / Min(parallel_workers, nindexes_mwm) :
@@ -4154,8 +4084,6 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc)
lvshared = (LVShared *) shm_toc_lookup(toc, PARALLEL_VACUUM_KEY_SHARED,
false);
- elevel = lvshared->elevel;
-
elog(DEBUG1, "starting parallel vacuum worker");
/* Set debug_query_string for individual workers */
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index 5c4bc15b4..47d8ab733 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -261,7 +261,7 @@ ExecVacuum(ParseState *pstate, VacuumStmt *vacstmt, bool isTopLevel)
/* user-invoked vacuum is never "for wraparound" */
params.is_wraparound = false;
- /* user-invoked vacuum never uses this parameter */
+ /* user-invoked vacuum uses VACOPT_VERBOSE instead of log_min_duration */
params.log_min_duration = -1;
/* Now go through the common routine */
--
2.30.2
I haven't read the patch yet. But some thoughts based on the posted output:
1) At first I was quite skeptical about losing the progress reporting.
I've often found it quite useful. But looking at the examples I'm
convinced.
Or rather I think a better way to look at it is that the progress
output for the operator should be separated from the metrics logged.
As an operator what I want to see is some progress indicator
""starting table scan", "overflow at x% of table scanned, starting
index scan", "processing index 1" "index 2"... so I can have some idea
of how much longer the vacuum will take and see whether I need to
raise maintenance_work_mem and by how much. I don't need to see all
the metrics while it's running.
2) I don't much like the format. I want to be able to parse the output
with awk or mtail or even just grep for relevant lines. Things like
"index scan not needed" make it hard to parse since you don't know
what it will look like if they are needed. I would have expected
something like "index scans: 0" which is actually already there up
above. I'm not clear how this line is meant to be read. Is it just
explaining *why* the index scan was skipped? It would just be missing
entirely if it wasn't skipped?
Fwiw, having it be parsable is why I wouldn't want it to be multiple
ereports. That would mean it could get interleaved with other errors
from other backends. That would be a disaster.
On Tue, Dec 21, 2021 at 2:39 AM Peter Geoghegan <pg@bowt.ie> wrote:
On Mon, Nov 29, 2021 at 6:51 PM Peter Geoghegan <pg@bowt.ie> wrote:
Attached is a WIP patch doing this.
This has bitrot, so I attach v2, mostly just to keep the CFTester
status green. The only real change is one minor simplification to how
we set everything up, inside heap_vacuum_rel().
I've looked at the patch and here are comments:
@@ -3076,16 +3021,12 @@ lazy_cleanup_one_index(Relation indrel,
IndexBulkDeleteResult *istat,
LVRelState *vacrel)
{
IndexVacuumInfo ivinfo;
- PGRUsage ru0;
LVSavedErrInfo saved_err_info;
- pg_rusage_init(&ru0);
-
ivinfo.index = indrel;
ivinfo.analyze_only = false;
ivinfo.report_progress = false;
ivinfo.estimated_count = estimated_count;
- ivinfo.message_level = elevel;
I think we should set message_level. Otherwise, index AM will set an
invalid log level, although any index AM in core seems not to use it.
---
- /*
- * Update error traceback information. This is the
last phase during
- * which we add context information to errors, so we
don't need to
- * revert to the previous phase.
- */
Why is this comment removed? ISTM this comment is still valid.
Regards,
--
Masahiko Sawada
EDB: https://www.enterprisedb.com/
On Tue, Dec 21, 2021 at 9:46 PM Greg Stark <stark@mit.edu> wrote:
Or rather I think a better way to look at it is that the progress
output for the operator should be separated from the metrics logged.
As an operator what I want to see is some progress indicator
""starting table scan", "overflow at x% of table scanned, starting
index scan", "processing index 1" "index 2"... so I can have some idea
of how much longer the vacuum will take and see whether I need to
raise maintenance_work_mem and by how much. I don't need to see all
the metrics while it's running.
We have the pg_stat_progress_vacuum view for that these days, of
course. Which has the advantage of working with autovacuum and
manually-run VACUUMs in exactly the same way. I am generally opposed
to any difference between autovacuum and manual VACUUM that isn't
clearly necessary. For example, ANALYZE behaves very differently in a
VACUUM ANALYZE run on a table with a GIN index in autovacuum -- that
seems awful to me.
2) I don't much like the format. I want to be able to parse the output
with awk or mtail or even just grep for relevant lines. Things like
"index scan not needed" make it hard to parse since you don't know
what it will look like if they are needed. I would have expected
something like "index scans: 0" which is actually already there up
above. I'm not clear how this line is meant to be read. Is it just
explaining *why* the index scan was skipped? It would just be missing
entirely if it wasn't skipped?
No, a line that looks very much like the "index scan not needed" line
will always be there. IOW there will reliably be a line that explains
whether or not any index scan took place, and why (or why not).
Whereas there won't ever be a line in VACUUM VERBOSE (as currently
implemented) that tells you about something that might have been
expected to happen, but didn't actually happen.
The same thing cannot be said for every line of the log output,
though. For example, the line about I/O timings only appears with
track_io_timing=on.
I have changed things here quite a bit in the last year. I do try to
stick to the "always show line" convention, if only for the benefit of
humans. If the line doesn't generalize to every situation, then I tend
to doubt that it merits appearing in the summary in the first place.
Fwiw, having it be parsable is why I wouldn't want it to be multiple
ereports. That would mean it could get interleaved with other errors
from other backends. That would be a disaster.
That does seem relevant, but honestly I haven't made that a goal here.
Part of the problem has been with what we've actually shown. Postgres
14 was the first version to separately report on the number of LP_DEAD
line pointers in the table (or left behind in the table when we didn't
do index vacuuming). Prior to 14 we only reported dead tuples. These
seemed to be assumed to be roughly equivalent in the past, but
actually they're totally different things, with many practical
consequences:
/messages/by-id/CAH2-WzkkGT2Gt4XauS5eQOQi4mVvL5X49hBTtWccC8DEqeNfKA@mail.gmail.com
This means that we only just started showing one particular metric
that is of fundamental importance in this log output (and VACUUM
VERBOSE). We also used to show things that had very little relevance,
with slightly different (confusingly similar) metrics shown in each
variant of the instrumentation (a problem that I'm trying to
permanently avoid by unifying everything). While things have improved
a lot here recently, I don't think that things have fully settled yet
-- the output will probably change quite a bit more in Postgres 15.
That makes me a little hesitant to promise very much about making the
output parseable or stable.
That said, I don't want to make it needlessly difficult. That should be avoided.
--
Peter Geoghegan
On Tue, Dec 21, 2021 at 11:57 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
I've looked at the patch and here are comments:
Thanks!
The patch bitrot again, so attached is a rebased version, v3.
I think we should set message_level. Otherwise, index AM will set an
invalid log level, although any index AM in core seems not to use it.
Fixed.
---
- /*
- * Update error traceback information. This is the
last phase during
- * which we add context information to errors, so we
don't need to
- * revert to the previous phase.
- */Why is this comment removed? ISTM this comment is still valid.
We don't "revert to the previous phase" here, which is always
VACUUM_ERRCB_PHASE_SCAN_HEAP in practice, per the comment -- but that
doesn't seem significant. It's not just unnecessary to do so, as the
comment claims -- it actually seems *wrong*. That is, it would be
wrong to go back to VACUUM_ERRCB_PHASE_SCAN_HEAP here, since we're
completely finished scanning the heap at this point.
There is still perhaps a small danger that somebody will forget to add
a new VACUUM_ERRCB_PHASE_* for some new kind of work that happens
after this point, at the very last moment. But that would be equally
true if the new kind of work took place earlier, inside
lazy_scan_heap(). And so the last call to update_vacuum_error_info()
isn't special compared to any other update_vacuum_error_info() call
(or any other call that doesn't set a saved_err_info).
--
Peter Geoghegan
Attachments:
v3-0001-Unify-VACUUM-VERBOSE-and-log_autovacuum_min_durat.patchapplication/octet-stream; name=v3-0001-Unify-VACUUM-VERBOSE-and-log_autovacuum_min_durat.patchDownload
From d2a123562ef35b33c0355ce869576d77ebbc7f36 Mon Sep 17 00:00:00 2001
From: Peter Geoghegan <pg@bowt.ie>
Date: Sun, 21 Nov 2021 21:48:33 -0800
Subject: [PATCH v3] Unify VACUUM VERBOSE and log_autovacuum_min_duration.
Author: Peter Geoghegan <pg@bowt.ie>
Discussion: https://postgr.es/m/CAH2-WzmW4Me7_qR4X4ka7pxP-jGmn7=Npma_-Z-9Y1eD0MQRLw@mail.gmail.com
---
src/include/commands/vacuum.h | 6 +-
src/backend/access/heap/vacuumlazy.c | 215 ++++++++++-----------------
src/backend/commands/vacuum.c | 2 +-
3 files changed, 84 insertions(+), 139 deletions(-)
diff --git a/src/include/commands/vacuum.h b/src/include/commands/vacuum.h
index 5a36049be..85a84178e 100644
--- a/src/include/commands/vacuum.h
+++ b/src/include/commands/vacuum.h
@@ -182,7 +182,7 @@ typedef struct VacAttrStats
/* flag bits for VacuumParams->options */
#define VACOPT_VACUUM 0x01 /* do VACUUM */
#define VACOPT_ANALYZE 0x02 /* do ANALYZE */
-#define VACOPT_VERBOSE 0x04 /* print progress info */
+#define VACOPT_VERBOSE 0x04 /* output instrumentation */
#define VACOPT_FREEZE 0x08 /* FREEZE option */
#define VACOPT_FULL 0x10 /* FULL (non-concurrent) vacuum */
#define VACOPT_SKIP_LOCKED 0x20 /* skip if cannot get lock */
@@ -222,8 +222,8 @@ typedef struct VacuumParams
* whole table */
bool is_wraparound; /* force a for-wraparound vacuum */
int log_min_duration; /* minimum execution threshold in ms at
- * which verbose logs are activated, -1
- * to use default */
+ * which verbose output is logged, -1 to
+ * use default */
VacOptValue index_cleanup; /* Do index vacuum and cleanup */
VacOptValue truncate; /* Truncate empty pages at the end */
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index cd603e6aa..70d0fdec4 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -171,7 +171,7 @@ typedef struct LVRelState
/* Error reporting state */
char *relnamespace;
char *relname;
- char *indname;
+ char *indname; /* Current index name */
BlockNumber blkno; /* used only for heap operations */
OffsetNumber offnum; /* used only for heap operations */
VacErrPhase phase;
@@ -237,9 +237,6 @@ typedef struct LVSavedErrInfo
VacErrPhase phase;
} LVSavedErrInfo;
-/* elevel controls whole VACUUM's verbosity */
-static int elevel = -1;
-
/* non-export function prototypes */
static void lazy_scan_heap(LVRelState *vacrel, VacuumParams *params,
@@ -299,6 +296,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
BufferAccessStrategy bstrategy)
{
LVRelState *vacrel;
+ bool verbose,
+ instrument;
PGRUsage ru0;
TimestampTz starttime = 0;
WalUsage walusage_start = pgWalUsage;
@@ -324,8 +323,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
TransactionId FreezeLimit;
MultiXactId MultiXactCutoff;
- /* measure elapsed time iff autovacuum logging requires it */
- if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0)
+ verbose = (params->options & VACOPT_VERBOSE) != 0;
+ instrument = (verbose || (IsAutoVacuumWorkerProcess() &&
+ params->log_min_duration >= 0));
+ if (instrument)
{
pg_rusage_init(&ru0);
starttime = GetCurrentTimestamp();
@@ -336,11 +337,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
}
}
- if (params->options & VACOPT_VERBOSE)
- elevel = INFO;
- else
- elevel = DEBUG2;
-
pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM,
RelationGetRelid(rel));
@@ -365,14 +361,56 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
if (params->options & VACOPT_DISABLE_PAGE_SKIPPING)
aggressive = true;
+ /*
+ * Setup error traceback support for ereport(). The idea is to set up an
+ * error context callback to display additional information on any error
+ * during a vacuum. During different phases of vacuum, we update the
+ * state so that the error context callback always display current
+ * information. Copy the names of relations into local memory now, too.
+ * It isn't always safe to assume that we can get the name of each rel.
+ * It's convenient for code in lazy_scan_heap to always use these temp
+ * copies.
+ *
+ * Note that the index vacuum and heap vacuum phases may be called
+ * multiple times in the middle of the heap scan phase. So the old phase
+ * information is restored at the end of those phases.
+ */
vacrel = (LVRelState *) palloc0(sizeof(LVRelState));
+ vacrel->relnamespace = get_namespace_name(RelationGetNamespace(rel));
+ vacrel->relname = pstrdup(RelationGetRelationName(rel));
+ vacrel->indname = NULL;
+ vacrel->phase = VACUUM_ERRCB_PHASE_UNKNOWN;
+ errcallback.callback = vacuum_error_callback;
+ errcallback.arg = vacrel;
+ errcallback.previous = error_context_stack;
+ error_context_stack = &errcallback;
+ if (verbose)
+ {
+ /* VACUUM VERBOSE initial INFO message, before we start real work */
+ Assert(!IsAutoVacuumWorkerProcess());
+ if (aggressive)
+ ereport(INFO,
+ (errmsg("aggressively vacuuming \"%s.%s.%s\"",
+ get_database_name(MyDatabaseId),
+ vacrel->relnamespace, vacrel->relname)));
+ else
+ ereport(INFO,
+ (errmsg("vacuuming \"%s.%s.%s\"",
+ get_database_name(MyDatabaseId),
+ vacrel->relnamespace, vacrel->relname)));
+ }
/* Set up high level stuff about rel */
vacrel->rel = rel;
vac_open_indexes(vacrel->rel, RowExclusiveLock, &vacrel->nindexes,
&vacrel->indrels);
- vacrel->failsafe_active = false;
- vacrel->consider_bypass_optimization = true;
+ if (instrument && vacrel->nindexes > 0)
+ {
+ /* Couldn't copy index names earlier, so do that now instead */
+ indnames = palloc(sizeof(char *) * vacrel->nindexes);
+ for (int i = 0; i < vacrel->nindexes; i++)
+ indnames[i] = pstrdup(RelationGetRelationName(vacrel->indrels[i]));
+ }
/*
* The index_cleanup param either disables index vacuuming and cleanup or
@@ -386,6 +424,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
Assert(params->index_cleanup != VACOPTVALUE_UNSPECIFIED);
Assert(params->truncate != VACOPTVALUE_UNSPECIFIED &&
params->truncate != VACOPTVALUE_AUTO);
+ vacrel->failsafe_active = false;
+ vacrel->consider_bypass_optimization = true;
vacrel->do_index_vacuuming = true;
vacrel->do_index_cleanup = true;
vacrel->do_rel_truncate = (params->truncate != VACOPTVALUE_DISABLED);
@@ -416,37 +456,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
vacrel->FreezeLimit = FreezeLimit;
vacrel->MultiXactCutoff = MultiXactCutoff;
- vacrel->relnamespace = get_namespace_name(RelationGetNamespace(rel));
- vacrel->relname = pstrdup(RelationGetRelationName(rel));
- vacrel->indname = NULL;
- vacrel->phase = VACUUM_ERRCB_PHASE_UNKNOWN;
-
- /* Save index names iff autovacuum logging requires it */
- if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0 &&
- vacrel->nindexes > 0)
- {
- indnames = palloc(sizeof(char *) * vacrel->nindexes);
- for (int i = 0; i < vacrel->nindexes; i++)
- indnames[i] =
- pstrdup(RelationGetRelationName(vacrel->indrels[i]));
- }
-
- /*
- * Setup error traceback support for ereport(). The idea is to set up an
- * error context callback to display additional information on any error
- * during a vacuum. During different phases of vacuum (heap scan, heap
- * vacuum, index vacuum, index clean up, heap truncate), we update the
- * error context callback to display appropriate information.
- *
- * Note that the index vacuum and heap vacuum phases may be called
- * multiple times in the middle of the heap scan phase. So the old phase
- * information is restored at the end of those phases.
- */
- errcallback.callback = vacuum_error_callback;
- errcallback.arg = vacrel;
- errcallback.previous = error_context_stack;
- error_context_stack = &errcallback;
-
/*
* Call lazy_scan_heap to perform all required heap pruning, index
* vacuuming, and heap vacuuming (plus related processing)
@@ -477,11 +486,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
*/
if (should_attempt_truncation(vacrel))
{
- /*
- * Update error traceback information. This is the last phase during
- * which we add context information to errors, so we don't need to
- * revert to the previous phase.
- */
update_vacuum_error_info(vacrel, NULL, VACUUM_ERRCB_PHASE_TRUNCATE,
vacrel->nonempty_pages,
InvalidOffsetNumber);
@@ -544,12 +548,11 @@ 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)
+ if (instrument)
{
TimestampTz endtime = GetCurrentTimestamp();
- if (params->log_min_duration == 0 ||
+ if (verbose || params->log_min_duration == 0 ||
TimestampDifferenceExceeds(starttime, endtime,
params->log_min_duration))
{
@@ -572,12 +575,17 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
(secs + usecs / 1000000.0);
}
- /*
- * This is pretty messy, but we split it up so that we can skip
- * emitting individual parts of the message when not applicable.
- */
initStringInfo(&buf);
- if (params->is_wraparound)
+ if (verbose)
+ {
+ /*
+ * Aggressiveness already reported earlier, in dedicated
+ * VACUUM VERBOSE ereport
+ */
+ Assert(!params->is_wraparound);
+ msgfmt = _("finished vacuuming \"%s.%s.%s\": index scans: %d\n");
+ }
+ else if (params->is_wraparound)
{
/*
* While it's possible for a VACUUM to be both is_wraparound
@@ -676,7 +684,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
(unsigned long long) walusage.wal_bytes);
appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0));
- ereport(LOG,
+ ereport(verbose ? INFO : LOG,
(errmsg_internal("%s", buf.data)));
pfree(buf.data);
}
@@ -688,7 +696,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params,
if (vacrel->indstats[i])
pfree(vacrel->indstats[i]);
- if (indnames && indnames[i])
+ if (instrument)
pfree(indnames[i]);
}
}
@@ -738,10 +746,8 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
next_unskippable_block,
next_failsafe_block,
next_fsm_block_to_vacuum;
- PGRUsage ru0;
Buffer vmbuffer = InvalidBuffer;
bool skipping_blocks;
- StringInfoData buf;
const int initprog_index[] = {
PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -750,19 +756,6 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
int64 initprog_val[3];
GlobalVisState *vistest;
- pg_rusage_init(&ru0);
-
- if (aggressive)
- ereport(elevel,
- (errmsg("aggressively vacuuming \"%s.%s\"",
- vacrel->relnamespace,
- vacrel->relname)));
- else
- ereport(elevel,
- (errmsg("vacuuming \"%s.%s\"",
- vacrel->relnamespace,
- vacrel->relname)));
-
nblocks = RelationGetNumberOfBlocks(vacrel->rel);
next_unskippable_block = 0;
next_failsafe_block = 0;
@@ -1456,49 +1449,15 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
/*
* When the table has no indexes (i.e. in the one-pass strategy case),
- * make log report that lazy_vacuum_heap_rel would've made had there been
- * indexes. (As in the two-pass strategy case, only make this report when
- * there were LP_DEAD line pointers vacuumed in lazy_vacuum_heap_page.)
+ * produce debug output that lazy_vacuum_heap_rel would've made had there
+ * been indexes. (As in the two-pass strategy case, only do so when there
+ * were LP_DEAD line pointers vacuumed in lazy_vacuum_heap_page.)
*/
if (vacrel->nindexes == 0 && vacrel->lpdead_item_pages > 0)
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("table \"%s\": removed %lld dead item identifiers in %u pages",
vacrel->relname, (long long) vacrel->lpdead_items,
vacrel->lpdead_item_pages)));
-
- /*
- * Make a log report summarizing pruning and freezing.
- *
- * The autovacuum specific logging in heap_vacuum_rel summarizes an entire
- * VACUUM operation, whereas each VACUUM VERBOSE log report generally
- * summarizes a single round of index/heap vacuuming (or rel truncation).
- * It wouldn't make sense to report on pruning or freezing while following
- * that convention, though. You can think of this log report as a summary
- * of our first pass over the heap.
- */
- initStringInfo(&buf);
- appendStringInfo(&buf,
- _("%lld dead row versions cannot be removed yet, oldest xmin: %u\n"),
- (long long) vacrel->new_dead_tuples, vacrel->OldestXmin);
- appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
- "Skipped %u pages due to buffer pins, ",
- vacrel->pinskipped_pages),
- vacrel->pinskipped_pages);
- appendStringInfo(&buf, ngettext("%u frozen page.\n",
- "%u frozen pages.\n",
- vacrel->frozenskipped_pages),
- vacrel->frozenskipped_pages);
- appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
-
- ereport(elevel,
- (errmsg("table \"%s.%s\": found %lld removable, %lld nonremovable row versions in %u out of %u pages",
- vacrel->relnamespace,
- vacrel->relname,
- (long long) vacrel->tuples_deleted,
- (long long) vacrel->num_tuples, vacrel->scanned_pages,
- nblocks),
- errdetail_internal("%s", buf.data)));
- pfree(buf.data);
}
/*
@@ -1989,11 +1948,6 @@ lazy_vacuum(LVRelState *vacrel)
* calls.)
*/
vacrel->do_index_vacuuming = false;
- ereport(elevel,
- (errmsg("table \"%s\": index scan bypassed: %u pages from table (%.2f%% of total) have %lld dead item identifiers",
- vacrel->relname, vacrel->lpdead_item_pages,
- 100.0 * vacrel->lpdead_item_pages / vacrel->rel_pages,
- (long long) vacrel->lpdead_items)));
}
else if (lazy_vacuum_all_indexes(vacrel))
{
@@ -2136,7 +2090,6 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
{
int index;
BlockNumber vacuumed_pages;
- PGRUsage ru0;
Buffer vmbuffer = InvalidBuffer;
LVSavedErrInfo saved_err_info;
@@ -2153,7 +2106,6 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
VACUUM_ERRCB_PHASE_VACUUM_HEAP,
InvalidBlockNumber, InvalidOffsetNumber);
- pg_rusage_init(&ru0);
vacuumed_pages = 0;
index = 0;
@@ -2200,10 +2152,9 @@ lazy_vacuum_heap_rel(LVRelState *vacrel)
(index == vacrel->lpdead_items &&
vacuumed_pages == vacrel->lpdead_item_pages));
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("table \"%s\": removed %lld dead item identifiers in %u pages",
- vacrel->relname, (long long) index, vacuumed_pages),
- errdetail_internal("%s", pg_rusage_show(&ru0))));
+ vacrel->relname, (long long) index, vacuumed_pages)));
/* Revert to the previous phase information for error traceback */
restore_vacuum_error_info(vacrel, &saved_err_info);
@@ -2513,7 +2464,7 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat,
ivinfo.analyze_only = false;
ivinfo.report_progress = false;
ivinfo.estimated_count = true;
- ivinfo.message_level = elevel;
+ ivinfo.message_level = DEBUG2;
ivinfo.num_heap_tuples = reltuples;
ivinfo.strategy = vacrel->bstrategy;
@@ -2561,7 +2512,7 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat,
ivinfo.analyze_only = false;
ivinfo.report_progress = false;
ivinfo.estimated_count = estimated_count;
- ivinfo.message_level = elevel;
+ ivinfo.message_level = DEBUG2;
ivinfo.num_heap_tuples = reltuples;
ivinfo.strategy = vacrel->bstrategy;
@@ -2647,10 +2598,6 @@ lazy_truncate_heap(LVRelState *vacrel)
*/
do
{
- PGRUsage ru0;
-
- pg_rusage_init(&ru0);
-
/*
* We need full exclusive lock on the relation in order to do
* truncation. If we can't get it, give up rather than waiting --- we
@@ -2678,7 +2625,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;
@@ -2748,12 +2695,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);
}
@@ -2812,7 +2757,7 @@ count_nondeletable_pages(LVRelState *vacrel, bool *lock_waiter_detected)
{
if (LockHasWaitersRelation(vacrel->rel, AccessExclusiveLock))
{
- ereport(elevel,
+ ereport(DEBUG2,
(errmsg("table \"%s\": suspending truncate due to conflicting lock request",
vacrel->relname)));
@@ -2979,7 +2924,7 @@ dead_items_alloc(LVRelState *vacrel, int nworkers)
else
vacrel->pvs = parallel_vacuum_init(vacrel->rel, vacrel->indrels,
vacrel->nindexes, nworkers,
- max_items, elevel,
+ max_items, DEBUG2,
vacrel->bstrategy);
/* If parallel mode started, dead_items space is allocated in DSM */
diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c
index c94c187d3..499d157eb 100644
--- a/src/backend/commands/vacuum.c
+++ b/src/backend/commands/vacuum.c
@@ -268,7 +268,7 @@ ExecVacuum(ParseState *pstate, VacuumStmt *vacstmt, bool isTopLevel)
/* user-invoked vacuum is never "for wraparound" */
params.is_wraparound = false;
- /* user-invoked vacuum never uses this parameter */
+ /* user-invoked vacuum uses VACOPT_VERBOSE instead of log_min_duration */
params.log_min_duration = -1;
/* Now go through the common routine */
--
2.30.2
On Thu, Jan 6, 2022 at 10:21 AM Peter Geoghegan <pg@bowt.ie> wrote:
The patch bitrot again, so attached is a rebased version, v3.
I pushed a version of this patch earlier. This final version didn't go
quite as far as v3 did: it retained a few VACUUM VERBOSE only INFO
messages (it didn't demote them to DEBUG2). See the commit message for
details.
Thank you for your review work, Masahiko and Andres.
--
Peter Geoghegan