v3-0001-Unify-VACUUM-VERBOSE-and-log_autovacuum_min_durat.patch

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