From 0a5f3ad741468c1c4bdbffb48b69f6610524e6d7 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 15 Dec 2019 17:00:29 -0600
Subject: [PATCH v2 4/6] reduce to DEBUG status logged from vacuum_heap/index..

..since they can run multiple times, which is both excessively noisy, and
confusing, due to showing multiple, multi-line messages with rusage.

Also output (at DEBUG) a message indicating the action to be taken, before
starting it.  To avoid outputting a message about completion of one step, and
taking a long time before outputting anything about the next/current step.

I'm taking as a guiding principle to elog whenever calling
pgstat_progress_update_param.
---
 src/backend/access/heap/vacuumlazy.c | 20 +++++++++++++++-----
 1 file changed, 15 insertions(+), 5 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index f45968c..2e1e8cc 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -506,6 +506,7 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
 	/* Report that we are now doing final cleanup */
 	pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
 								 PROGRESS_VACUUM_PHASE_FINAL_CLEANUP);
+	elog(DEBUG1, "cleaning up");
 
 	/*
 	 * Update statistics in pg_class.
@@ -1757,9 +1758,12 @@ lazy_vacuum_all_indexes(Relation onerel, Relation *Irel,
 	{
 		int			idx;
 
-		for (idx = 0; idx < nindexes; idx++)
+		for (idx = 0; idx < nindexes; idx++) {
+			ereport(DEBUG1, (errmsg("\"%s\": vacuuming index",
+							RelationGetRelationName(Irel[idx]))));
 			lazy_vacuum_index(Irel[idx], &stats[idx], vacrelstats->dead_tuples,
 							  vacrelstats->old_live_tuples);
+		}
 	}
 
 	/* Increase and report the number of index scans */
@@ -1794,6 +1798,8 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
 	/* Report that we are now vacuuming the heap */
 	pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
 								 PROGRESS_VACUUM_PHASE_VACUUM_HEAP);
+	ereport(DEBUG1, (errmsg("\"%s\": vacuuming heap",
+					RelationGetRelationName(onerel))));
 
 	/* Setup error traceback support for ereport() */
 	errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(onerel));
@@ -1845,7 +1851,7 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
 		vmbuffer = InvalidBuffer;
 	}
 
-	ereport(elevel,
+	ereport(DEBUG1,
 			(errmsg("\"%s\": removed %d row versions in %d pages",
 					RelationGetRelationName(onerel),
 					tupindex, npages),
@@ -2323,10 +2329,13 @@ lazy_cleanup_all_indexes(Relation *Irel, IndexBulkDeleteResult **stats,
 	}
 	else
 	{
-		for (idx = 0; idx < nindexes; idx++)
+		for (idx = 0; idx < nindexes; idx++) {
+			ereport(DEBUG1, (errmsg("cleaning up index \"%s\"",
+							RelationGetRelationName(Irel[idx]))));
 			lazy_cleanup_index(Irel[idx], &stats[idx],
 							   vacrelstats->new_rel_tuples,
 							   vacrelstats->tupcount_pages < vacrelstats->rel_pages);
+		}
 	}
 }
 
@@ -2366,7 +2375,7 @@ lazy_vacuum_index(Relation indrel, IndexBulkDeleteResult **stats,
 	else
 		msg = gettext_noop("scanned index \"%s\" to remove %d row versions");
 
-	ereport(elevel,
+	ereport(DEBUG1,
 			(errmsg(msg,
 					RelationGetRelationName(indrel),
 					dead_tuples->num_tuples),
@@ -2409,7 +2418,7 @@ lazy_cleanup_index(Relation indrel,
 	else
 		msg = gettext_noop("index \"%s\" now contains %.0f row versions in %u pages");
 
-	ereport(elevel,
+	ereport(DEBUG1,
 			(errmsg(msg,
 					RelationGetRelationName(indrel),
 					(*stats)->num_index_tuples,
@@ -2475,6 +2484,7 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
 	/* Report that we are now truncating */
 	pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
 								 PROGRESS_VACUUM_PHASE_TRUNCATE);
+	elog(DEBUG1, "truncating heap");
 
 	/*
 	 * Loop until no more truncating can be done.
-- 
2.7.4