vacuum verbose detail logs are unclear (show debug lines at *start* of each stage?)

From d27f2cb5262ec3d3511de44ec7c15d1b1235e5ee Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Wed, 27 Nov 2019 20:07:10 -0600
Subject: [PATCH v1 1/6] Rename buf to avoid shadowing buf of another type

---
 src/backend/access/heap/vacuumlazy.c | 20 ++++++++++----------
 1 file changed, 10 insertions(+), 10 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 5a48b66..1338963 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -609,7 +609,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	BlockNumber next_unskippable_block;
 	bool		skipping_blocks;
 	xl_heap_freeze_tuple *frozen;
-	StringInfoData buf;
+	StringInfoData sbuf;
 	const int	initprog_index[] = {
 		PROGRESS_VACUUM_PHASE,
 		PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -1443,33 +1443,33 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	 * 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);
-	appendStringInfo(&buf,
+	initStringInfo(&sbuf);
+	appendStringInfo(&sbuf,
 					 _("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
 					 nkeep, OldestXmin);
-	appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
+	appendStringInfo(&sbuf, _("There were %.0f unused item identifiers.\n"),
 					 nunused);
-	appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
+	appendStringInfo(&sbuf, ngettext("Skipped %u page due to buffer pins, ",
 									"Skipped %u pages due to buffer pins, ",
 									vacrelstats->pinskipped_pages),
 					 vacrelstats->pinskipped_pages);
-	appendStringInfo(&buf, ngettext("%u frozen page.\n",
+	appendStringInfo(&sbuf, ngettext("%u frozen page.\n",
 									"%u frozen pages.\n",
 									vacrelstats->frozenskipped_pages),
 					 vacrelstats->frozenskipped_pages);
-	appendStringInfo(&buf, ngettext("%u page is entirely empty.\n",
+	appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
 									"%u pages are entirely empty.\n",
 									empty_pages),
 					 empty_pages);
-	appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
+	appendStringInfo(&sbuf, _("%s."), pg_rusage_show(&ru0));
 
 	ereport(elevel,
 			(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
 					RelationGetRelationName(onerel),
 					tups_vacuumed, num_tuples,
 					vacrelstats->scanned_pages, nblocks),
-			 errdetail_internal("%s", buf.data)));
-	pfree(buf.data);
+			 errdetail_internal("%s", sbuf.data)));
+	pfree(sbuf.data);
 }
 
 /*
-- 
2.7.4

From bb92c8a6220000789e2fc9c852172624d5f9f773 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 13:38:49 -0600
Subject: [PATCH v1 2/6] vacuumlazy: typos in comments

---
 src/backend/access/heap/vacuumlazy.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 1338963..532698d 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1279,7 +1279,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			/*
 			 * It should never be the case that the visibility map page is set
 			 * while the page-level bit is clear, but the reverse is allowed
-			 * (if checksums are not enabled).  Regardless, set the both bits
+			 * (if checksums are not enabled).  Regardless, set both bits
 			 * so that we get back in sync.
 			 *
 			 * NB: If the heap page is all-visible but the VM bit is not set,
@@ -1335,7 +1335,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		}
 
 		/*
-		 * If the all-visible page is turned out to be all-frozen but not
+		 * If the all-visible page turned out to be all-frozen but not
 		 * marked, we should so mark it.  Note that all_frozen is only valid
 		 * if all_visible is true, so we must check both.
 		 */
-- 
2.7.4

From 2e11bd7284727fd4ec05cc2a5c57c6b379752e15 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Wed, 1 Jan 2020 17:35:35 -0600
Subject: [PATCH v1 3/6] Indent VACUUM VERBOSE multi-line errdetail messages..

I borrowed the format from ShowUsage.
---
 src/backend/access/heap/vacuumlazy.c | 38 +++++++++++++++++++++++-------------
 1 file changed, 24 insertions(+), 14 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 532698d..c8d5538 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -591,7 +591,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	BlockNumber nblocks,
 				blkno;
 	HeapTupleData tuple;
-	char	   *relname;
+	char	   *relname,
+		   *msgprefix;
 	TransactionId relfrozenxid = onerel->rd_rel->relfrozenxid;
 	TransactionId relminmxid = onerel->rd_rel->relminmxid;
 	BlockNumber empty_pages,
@@ -1440,28 +1441,37 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 						tups_vacuumed, vacuumed_pages)));
 
 	/*
+	 * Indent multi-line DETAIL if being sent to client (verbose)
+	 * We don't know if it's sent to the client (client_min_messages);
+	 * Also, that affects output to the logfile, too; assume that it's more
+	 * important to format messages requested by the client than to make
+	 * verbose logs pretty when also sent to the logfile.
+	 */
+	msgprefix = elevel==INFO ? "!\t" : "";
+
+	/*
 	 * This is pretty messy, but we split it up so that we can skip emitting
 	 * individual parts of the message when not applicable.
 	 */
 	initStringInfo(&sbuf);
 	appendStringInfo(&sbuf,
-					 _("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
+					 _("! %.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
 					 nkeep, OldestXmin);
-	appendStringInfo(&sbuf, _("There were %.0f unused item identifiers.\n"),
-					 nunused);
-	appendStringInfo(&sbuf, ngettext("Skipped %u page due to buffer pins, ",
-									"Skipped %u pages due to buffer pins, ",
+	appendStringInfo(&sbuf, _("%sThere were %.0f unused item identifiers.\n"),
+					 msgprefix, nunused);
+	appendStringInfo(&sbuf, ngettext("%sSkipped %u page due to buffer pins, ",
+									"%sSkipped %u pages due to buffer pins, ",
 									vacrelstats->pinskipped_pages),
-					 vacrelstats->pinskipped_pages);
+					 msgprefix, vacrelstats->pinskipped_pages);
 	appendStringInfo(&sbuf, ngettext("%u frozen page.\n",
 									"%u frozen pages.\n",
 									vacrelstats->frozenskipped_pages),
 					 vacrelstats->frozenskipped_pages);
-	appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
-									"%u pages are entirely empty.\n",
+	appendStringInfo(&sbuf, ngettext("%s%u page is entirely empty.\n",
+									"%s%u pages are entirely empty.\n",
 									empty_pages),
-					 empty_pages);
-	appendStringInfo(&sbuf, _("%s."), pg_rusage_show(&ru0));
+					 msgprefix, empty_pages);
+	appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
 
 	ereport(elevel,
 			(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
@@ -1828,9 +1838,9 @@ lazy_cleanup_index(Relation indrel,
 					RelationGetRelationName(indrel),
 					stats->num_index_tuples,
 					stats->num_pages),
-			 errdetail("%.0f index row versions were removed.\n"
-					   "%u index pages have been deleted, %u are currently reusable.\n"
-					   "%s.",
+			 errdetail("! %.0f index row versions were removed.\n"
+					   "!\t%u index pages have been deleted, %u are currently reusable.\n"
+					   "!\t%s.",
 					   stats->tuples_removed,
 					   stats->pages_deleted, stats->pages_free,
 					   pg_rusage_show(&ru0))));
-- 
2.7.4

From 10d3c94e9e38c29086627631564c9e6d4d620ca2 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 15 Dec 2019 17:00:29 -0600
Subject: [PATCH v1 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 c8d5538..08ad6b5 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -326,6 +326,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.
@@ -1429,8 +1430,11 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	/* Do post-vacuum cleanup and statistics update for each index */
 	if (vacrelstats->useindex)
 	{
-		for (i = 0; i < nindexes; i++)
+		for (i = 0; i < nindexes; i++) {
+			ereport(DEBUG1, (errmsg("cleaning up index \"%s\"",
+							RelationGetRelationName(Irel[i]))));
 			lazy_cleanup_index(Irel[i], indstats[i], vacrelstats);
+		}
 	}
 
 	/* If no indexes, make log report that lazy_vacuum_heap would've made */
@@ -1503,8 +1507,11 @@ lazy_vacuum_all_indexes(Relation onerel, LVRelStats *vacrelstats,
 								 PROGRESS_VACUUM_PHASE_VACUUM_INDEX);
 
 	/* Remove index entries */
-	for (i = 0; i < nindexes; i++)
+	for (i = 0; i < nindexes; i++) {
+		ereport(DEBUG1, (errmsg("\"%s\": vacuuming index",
+						RelationGetRelationName(Irel[i]))));
 		lazy_vacuum_index(Irel[i], &indstats[i], vacrelstats);
+	}
 
 	/* Increase and report the number of index scans */
 	vacrelstats->num_index_scans++;
@@ -1538,6 +1545,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));
@@ -1589,7 +1598,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),
@@ -1780,7 +1789,7 @@ lazy_vacuum_index(Relation indrel,
 	*stats = index_bulk_delete(&ivinfo, *stats,
 							   lazy_tid_reaped, (void *) vacrelstats);
 
-	ereport(elevel,
+	ereport(DEBUG1,
 			(errmsg("scanned index \"%s\" to remove %d row versions",
 					RelationGetRelationName(indrel),
 					vacrelstats->num_dead_tuples),
@@ -1833,7 +1842,7 @@ lazy_cleanup_index(Relation indrel,
 							InvalidMultiXactId,
 							false);
 
-	ereport(elevel,
+	ereport(DEBUG1,
 			(errmsg("index \"%s\" now contains %.0f row versions in %u pages",
 					RelationGetRelationName(indrel),
 					stats->num_index_tuples,
@@ -1901,6 +1910,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

From aec813b2fe066093ce7355f22b7396dd13b8e11b Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 14:56:02 -0600
Subject: [PATCH v1 5/6] Report number of pages_allvisible/frozen..

..as requested by Jeff Janes
---
 src/backend/access/heap/vacuumlazy.c | 37 ++++++++++++++++++++++++++++++------
 1 file changed, 31 insertions(+), 6 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 08ad6b5..b739d49 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -125,7 +125,9 @@ typedef struct LVRelStats
 	double		new_rel_tuples; /* new estimated total # of tuples */
 	double		new_live_tuples;	/* new estimated total # of live tuples */
 	double		new_dead_tuples;	/* new estimated total # of dead tuples */
-	BlockNumber pages_removed;
+	BlockNumber pages_removed;	/* Due to truncation */
+	BlockNumber pages_frozen;
+	BlockNumber pages_allvisible;
 	double		tuples_deleted;
 	BlockNumber nonempty_pages; /* actually, last nonempty page + 1 */
 	/* List of TIDs of tuples we intend to delete */
@@ -427,11 +429,13 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
 							 get_namespace_name(RelationGetNamespace(onerel)),
 							 RelationGetRelationName(onerel),
 							 vacrelstats->num_index_scans);
-			appendStringInfo(&buf, _("pages: %u removed, %u remain, %u skipped due to pins, %u skipped frozen\n"),
+			appendStringInfo(&buf, _("pages: %u removed, %u remain, %u skipped due to pins, %u skipped frozen, %u marked all visible, %u marked frozen\n"),
 							 vacrelstats->pages_removed,
 							 vacrelstats->rel_pages,
 							 vacrelstats->pinskipped_pages,
-							 vacrelstats->frozenskipped_pages);
+							 vacrelstats->frozenskipped_pages,
+							 vacrelstats->pages_allvisible,
+							 vacrelstats->pages_frozen);
 			appendStringInfo(&buf,
 							 _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u\n"),
 							 vacrelstats->tuples_deleted,
@@ -647,6 +651,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	vacrelstats->scanned_pages = 0;
 	vacrelstats->tupcount_pages = 0;
 	vacrelstats->nonempty_pages = 0;
+	vacrelstats->pages_frozen = 0;
+	vacrelstats->pages_allvisible = 0;
+
 	vacrelstats->latestRemovedXid = InvalidTransactionId;
 
 	lazy_space_alloc(vacrelstats, nblocks);
@@ -944,6 +951,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 				visibilitymap_set(onerel, blkno, buf, InvalidXLogRecPtr,
 								  vmbuffer, InvalidTransactionId,
 								  VISIBILITYMAP_ALL_VISIBLE | VISIBILITYMAP_ALL_FROZEN);
+				vacrelstats->pages_allvisible++;
+				vacrelstats->pages_frozen++;
 				END_CRIT_SECTION();
 			}
 
@@ -1275,8 +1284,12 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		{
 			uint8		flags = VISIBILITYMAP_ALL_VISIBLE;
 
-			if (all_frozen)
+			if (all_frozen) {
 				flags |= VISIBILITYMAP_ALL_FROZEN;
+				vacrelstats->pages_frozen++;
+			}
+
+			vacrelstats->pages_allvisible++;
 
 			/*
 			 * It should never be the case that the visibility map page is set
@@ -1475,6 +1488,14 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 									"%s%u pages are entirely empty.\n",
 									empty_pages),
 					 msgprefix, empty_pages);
+	appendStringInfo(&sbuf, ngettext("%sMarked %u page all visible, ",
+									"%sMarked %u pages all visible, ",
+									vacrelstats->pages_allvisible),
+					msgprefix, vacrelstats->pages_allvisible);
+	appendStringInfo(&sbuf, ngettext("%u page frozen.\n",
+									"%u pages frozen.\n",
+									vacrelstats->pages_frozen),
+					vacrelstats->pages_frozen);
 	appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
 
 	ereport(elevel,
@@ -1692,10 +1713,14 @@ lazy_vacuum_page(Relation onerel, BlockNumber blkno, Buffer buffer,
 		uint8		flags = 0;
 
 		/* Set the VM all-frozen bit to flag, if needed */
-		if ((vm_status & VISIBILITYMAP_ALL_VISIBLE) == 0)
+		if ((vm_status & VISIBILITYMAP_ALL_VISIBLE) == 0) {
 			flags |= VISIBILITYMAP_ALL_VISIBLE;
-		if ((vm_status & VISIBILITYMAP_ALL_FROZEN) == 0 && all_frozen)
+			vacrelstats->pages_allvisible++;
+		}
+		if ((vm_status & VISIBILITYMAP_ALL_FROZEN) == 0 && all_frozen) {
 			flags |= VISIBILITYMAP_ALL_FROZEN;
+			vacrelstats->pages_frozen++;
+		}
 
 		Assert(BufferIsValid(*vmbuffer));
 		if (flags != 0)
-- 
2.7.4

From 9902620947ae0ce100f58329929518b7e9ec9143 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 16:02:50 -0600
Subject: [PATCH v1 6/6] Report number of hint bits written..

..as requested by Jeff Janes
---
 src/backend/access/heap/vacuumlazy.c | 38 ++++++++++++++++++++++++------------
 1 file changed, 26 insertions(+), 12 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index b739d49..d08cac3 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -128,6 +128,7 @@ typedef struct LVRelStats
 	BlockNumber pages_removed;	/* Due to truncation */
 	BlockNumber pages_frozen;
 	BlockNumber pages_allvisible;
+	double		hintbit_tuples;
 	double		tuples_deleted;
 	BlockNumber nonempty_pages; /* actually, last nonempty page + 1 */
 	/* List of TIDs of tuples we intend to delete */
@@ -437,11 +438,12 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
 							 vacrelstats->pages_allvisible,
 							 vacrelstats->pages_frozen);
 			appendStringInfo(&buf,
-							 _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u\n"),
+							 _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u, wrote %.0f hint bits\n"),
 							 vacrelstats->tuples_deleted,
 							 vacrelstats->new_rel_tuples,
 							 vacrelstats->new_dead_tuples,
-							 OldestXmin);
+							 OldestXmin,
+							 vacrelstats->hintbit_tuples);
 			appendStringInfo(&buf,
 							 _("buffer usage: %d hits, %d misses, %d dirtied\n"),
 							 VacuumPageHit,
@@ -962,14 +964,6 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		}
 
 		/*
-		 * Prune all HOT-update chains in this page.
-		 *
-		 * We count tuples removed by the pruning step as removed by VACUUM.
-		 */
-		tups_vacuumed += heap_page_prune(onerel, buf, OldestXmin, false,
-										 &vacrelstats->latestRemovedXid);
-
-		/*
 		 * Now scan the page to collect vacuumable items and check for tuples
 		 * requiring freezing.
 		 */
@@ -989,6 +983,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			 offnum = OffsetNumberNext(offnum))
 		{
 			ItemId		itemid;
+			HTSV_Result satisfies;
+			int			oldmask;
 
 			itemid = PageGetItemId(page, offnum);
 
@@ -1040,7 +1036,11 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			 * cases impossible (e.g. in-progress insert from the same
 			 * transaction).
 			 */
-			switch (HeapTupleSatisfiesVacuum(&tuple, OldestXmin, buf))
+			oldmask = tuple.t_data->t_infomask;
+			satisfies = HeapTupleSatisfiesVacuum(&tuple, OldestXmin, buf);
+			if (oldmask != tuple.t_data->t_infomask)
+				vacrelstats->hintbit_tuples++;
+			switch (satisfies)
 			{
 				case HEAPTUPLE_DEAD:
 
@@ -1179,7 +1179,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 				 * Each non-removable tuple must be checked to see if it needs
 				 * freezing.  Note we already have exclusive buffer lock.
 				 */
-				if (heap_prepare_freeze_tuple(tuple.t_data,
+				// Avoid freezing HEAPTUPLE_DEAD, as required
+				if (satisfies!=HEAPTUPLE_DEAD &&
+						heap_prepare_freeze_tuple(tuple.t_data,
 											  relfrozenxid, relminmxid,
 											  FreezeLimit, MultiXactCutoff,
 											  &frozen[nfrozen],
@@ -1192,6 +1194,14 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		}						/* scan along page */
 
 		/*
+		 * Prune all HOT-update chains in this page.
+		 *
+		 * We count tuples removed by the pruning step as removed by VACUUM.
+		 */
+		tups_vacuumed += heap_page_prune(onerel, buf, OldestXmin, false,
+										 &vacrelstats->latestRemovedXid);
+
+		/*
 		 * If we froze any tuples, mark the buffer dirty, and write a WAL
 		 * record recording the changes.  We must log the changes to be
 		 * crash-safe against future truncation of CLOG.
@@ -1496,6 +1506,10 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 									"%u pages frozen.\n",
 									vacrelstats->pages_frozen),
 					vacrelstats->pages_frozen);
+	appendStringInfo(&sbuf, ngettext("%sWrote %.0f hint bit.\n",
+									"%sWrote %.0f hint bits.\n",
+									vacrelstats->hintbit_tuples),
+									msgprefix, vacrelstats->hintbit_tuples);
 	appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
 
 	ereport(elevel,
-- 
2.7.4

From 17b5f411873efa08ef31352d0e78379b4f7aaaa2 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 16:02:50 -0600
Subject: [PATCH v2 6/6] Report number of hint bits written..

..as requested by Jeff Janes
---
 src/backend/access/heap/vacuumlazy.c | 38 ++++++++++++++++++++++++------------
 1 file changed, 26 insertions(+), 12 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 49e214e..3383807 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -283,6 +283,7 @@ typedef struct LVRelStats
 	BlockNumber pages_removed;	/* Due to truncation */
 	BlockNumber pages_frozen;
 	BlockNumber pages_allvisible;
+	double		hintbit_tuples;
 	double		tuples_deleted;
 	BlockNumber nonempty_pages; /* actually, last nonempty page + 1 */
 	LVDeadTuples *dead_tuples;
@@ -617,11 +618,12 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
 							 vacrelstats->pages_allvisible,
 							 vacrelstats->pages_frozen);
 			appendStringInfo(&buf,
-							 _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u\n"),
+							 _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u, wrote %.0f hint bits\n"),
 							 vacrelstats->tuples_deleted,
 							 vacrelstats->new_rel_tuples,
 							 vacrelstats->new_dead_tuples,
-							 OldestXmin);
+							 OldestXmin,
+							 vacrelstats->hintbit_tuples);
 			appendStringInfo(&buf,
 							 _("buffer usage: %d hits, %d misses, %d dirtied\n"),
 							 VacuumPageHit,
@@ -1191,14 +1193,6 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		}
 
 		/*
-		 * Prune all HOT-update chains in this page.
-		 *
-		 * We count tuples removed by the pruning step as removed by VACUUM.
-		 */
-		tups_vacuumed += heap_page_prune(onerel, buf, OldestXmin, false,
-										 &vacrelstats->latestRemovedXid);
-
-		/*
 		 * Now scan the page to collect vacuumable items and check for tuples
 		 * requiring freezing.
 		 */
@@ -1218,6 +1212,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			 offnum = OffsetNumberNext(offnum))
 		{
 			ItemId		itemid;
+			HTSV_Result satisfies;
+			int			oldmask;
 
 			itemid = PageGetItemId(page, offnum);
 
@@ -1269,7 +1265,11 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			 * cases impossible (e.g. in-progress insert from the same
 			 * transaction).
 			 */
-			switch (HeapTupleSatisfiesVacuum(&tuple, OldestXmin, buf))
+			oldmask = tuple.t_data->t_infomask;
+			satisfies = HeapTupleSatisfiesVacuum(&tuple, OldestXmin, buf);
+			if (oldmask != tuple.t_data->t_infomask)
+				vacrelstats->hintbit_tuples++;
+			switch (satisfies)
 			{
 				case HEAPTUPLE_DEAD:
 
@@ -1408,7 +1408,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 				 * Each non-removable tuple must be checked to see if it needs
 				 * freezing.  Note we already have exclusive buffer lock.
 				 */
-				if (heap_prepare_freeze_tuple(tuple.t_data,
+				// Avoid freezing HEAPTUPLE_DEAD, as required
+				if (satisfies!=HEAPTUPLE_DEAD &&
+						heap_prepare_freeze_tuple(tuple.t_data,
 											  relfrozenxid, relminmxid,
 											  FreezeLimit, MultiXactCutoff,
 											  &frozen[nfrozen],
@@ -1421,6 +1423,14 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		}						/* scan along page */
 
 		/*
+		 * Prune all HOT-update chains in this page.
+		 *
+		 * We count tuples removed by the pruning step as removed by VACUUM.
+		 */
+		tups_vacuumed += heap_page_prune(onerel, buf, OldestXmin, false,
+										 &vacrelstats->latestRemovedXid);
+
+		/*
 		 * If we froze any tuples, mark the buffer dirty, and write a WAL
 		 * record recording the changes.  We must log the changes to be
 		 * crash-safe against future truncation of CLOG.
@@ -1727,6 +1737,10 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 									"%u pages frozen.\n",
 									vacrelstats->pages_frozen),
 					vacrelstats->pages_frozen);
+	appendStringInfo(&sbuf, ngettext("%sWrote %.0f hint bit.\n",
+									"%sWrote %.0f hint bits.\n",
+									vacrelstats->hintbit_tuples),
+									msgprefix, vacrelstats->hintbit_tuples);
 	appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
 
 	ereport(elevel,
-- 
2.7.4

From 83407b81dfc1ed2dfaa6f115dc6c4a276efb07fc Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Wed, 27 Nov 2019 20:07:10 -0600
Subject: [PATCH v2 1/6] Rename buf to avoid shadowing buf of another type

---
 src/backend/access/heap/vacuumlazy.c | 20 ++++++++++----------
 1 file changed, 10 insertions(+), 10 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index f380437..5a66ba4 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -803,7 +803,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	BlockNumber next_unskippable_block;
 	bool		skipping_blocks;
 	xl_heap_freeze_tuple *frozen;
-	StringInfoData buf;
+	StringInfoData sbuf;
 	const int	initprog_index[] = {
 		PROGRESS_VACUUM_PHASE,
 		PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -1677,33 +1677,33 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	 * 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);
-	appendStringInfo(&buf,
+	initStringInfo(&sbuf);
+	appendStringInfo(&sbuf,
 					 _("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
 					 nkeep, OldestXmin);
-	appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
+	appendStringInfo(&sbuf, _("There were %.0f unused item identifiers.\n"),
 					 nunused);
-	appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
+	appendStringInfo(&sbuf, ngettext("Skipped %u page due to buffer pins, ",
 									"Skipped %u pages due to buffer pins, ",
 									vacrelstats->pinskipped_pages),
 					 vacrelstats->pinskipped_pages);
-	appendStringInfo(&buf, ngettext("%u frozen page.\n",
+	appendStringInfo(&sbuf, ngettext("%u frozen page.\n",
 									"%u frozen pages.\n",
 									vacrelstats->frozenskipped_pages),
 					 vacrelstats->frozenskipped_pages);
-	appendStringInfo(&buf, ngettext("%u page is entirely empty.\n",
+	appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
 									"%u pages are entirely empty.\n",
 									empty_pages),
 					 empty_pages);
-	appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
+	appendStringInfo(&sbuf, _("%s."), pg_rusage_show(&ru0));
 
 	ereport(elevel,
 			(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
 					RelationGetRelationName(onerel),
 					tups_vacuumed, num_tuples,
 					vacrelstats->scanned_pages, nblocks),
-			 errdetail_internal("%s", buf.data)));
-	pfree(buf.data);
+			 errdetail_internal("%s", sbuf.data)));
+	pfree(sbuf.data);
 }
 
 /*
-- 
2.7.4

From ddfff05abecacf810612576f4d73d86e449d74fe Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 13:38:49 -0600
Subject: [PATCH v2 2/6] vacuumlazy: typos in comments

---
 src/backend/access/heap/vacuumlazy.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 5a66ba4..cb83056 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1508,7 +1508,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			/*
 			 * It should never be the case that the visibility map page is set
 			 * while the page-level bit is clear, but the reverse is allowed
-			 * (if checksums are not enabled).  Regardless, set the both bits
+			 * (if checksums are not enabled).  Regardless, set both bits
 			 * so that we get back in sync.
 			 *
 			 * NB: If the heap page is all-visible but the VM bit is not set,
@@ -1564,7 +1564,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		}
 
 		/*
-		 * If the all-visible page is turned out to be all-frozen but not
+		 * If the all-visible page turned out to be all-frozen but not
 		 * marked, we should so mark it.  Note that all_frozen is only valid
 		 * if all_visible is true, so we must check both.
 		 */
-- 
2.7.4

From d77fb8fa723afcadcc4edd5ce08f4246556f65e0 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Wed, 1 Jan 2020 17:35:35 -0600
Subject: [PATCH v2 3/6] Indent VACUUM VERBOSE multi-line errdetail messages..

I borrowed the format from ShowUsage.
---
 src/backend/access/heap/vacuumlazy.c | 38 +++++++++++++++++++++++-------------
 1 file changed, 24 insertions(+), 14 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index cb83056..f45968c 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -785,7 +785,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	BlockNumber nblocks,
 				blkno;
 	HeapTupleData tuple;
-	char	   *relname;
+	char	   *relname,
+		   *msgprefix;
 	TransactionId relfrozenxid = onerel->rd_rel->relfrozenxid;
 	TransactionId relminmxid = onerel->rd_rel->relminmxid;
 	BlockNumber empty_pages,
@@ -1674,28 +1675,37 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 						tups_vacuumed, vacuumed_pages)));
 
 	/*
+	 * Indent multi-line DETAIL if being sent to client (verbose)
+	 * We don't know if it's sent to the client (client_min_messages);
+	 * Also, that affects output to the logfile, too; assume that it's more
+	 * important to format messages requested by the client than to make
+	 * verbose logs pretty when also sent to the logfile.
+	 */
+	msgprefix = elevel==INFO ? "!\t" : "";
+
+	/*
 	 * This is pretty messy, but we split it up so that we can skip emitting
 	 * individual parts of the message when not applicable.
 	 */
 	initStringInfo(&sbuf);
 	appendStringInfo(&sbuf,
-					 _("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
+					 _("! %.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
 					 nkeep, OldestXmin);
-	appendStringInfo(&sbuf, _("There were %.0f unused item identifiers.\n"),
-					 nunused);
-	appendStringInfo(&sbuf, ngettext("Skipped %u page due to buffer pins, ",
-									"Skipped %u pages due to buffer pins, ",
+	appendStringInfo(&sbuf, _("%sThere were %.0f unused item identifiers.\n"),
+					 msgprefix, nunused);
+	appendStringInfo(&sbuf, ngettext("%sSkipped %u page due to buffer pins, ",
+									"%sSkipped %u pages due to buffer pins, ",
 									vacrelstats->pinskipped_pages),
-					 vacrelstats->pinskipped_pages);
+					 msgprefix, vacrelstats->pinskipped_pages);
 	appendStringInfo(&sbuf, ngettext("%u frozen page.\n",
 									"%u frozen pages.\n",
 									vacrelstats->frozenskipped_pages),
 					 vacrelstats->frozenskipped_pages);
-	appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
-									"%u pages are entirely empty.\n",
+	appendStringInfo(&sbuf, ngettext("%s%u page is entirely empty.\n",
+									"%s%u pages are entirely empty.\n",
 									empty_pages),
-					 empty_pages);
-	appendStringInfo(&sbuf, _("%s."), pg_rusage_show(&ru0));
+					 msgprefix, empty_pages);
+	appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
 
 	ereport(elevel,
 			(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
@@ -2404,9 +2414,9 @@ lazy_cleanup_index(Relation indrel,
 					RelationGetRelationName(indrel),
 					(*stats)->num_index_tuples,
 					(*stats)->num_pages),
-			 errdetail("%.0f index row versions were removed.\n"
-					   "%u index pages have been deleted, %u are currently reusable.\n"
-					   "%s.",
+			 errdetail("! %.0f index row versions were removed.\n"
+					   "!\t%u index pages have been deleted, %u are currently reusable.\n"
+					   "!\t%s.",
 					   (*stats)->tuples_removed,
 					   (*stats)->pages_deleted, (*stats)->pages_free,
 					   pg_rusage_show(&ru0))));
-- 
2.7.4

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

From 49a2dc5a4a95cb7ccce42326cdbf32a1feadc7dc Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 14:56:02 -0600
Subject: [PATCH v2 5/6] Report number of pages_allvisible/frozen..

..as requested by Jeff Janes
---
 src/backend/access/heap/vacuumlazy.c | 37 ++++++++++++++++++++++++++++++------
 1 file changed, 31 insertions(+), 6 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 2e1e8cc..49e214e 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -280,7 +280,9 @@ typedef struct LVRelStats
 	double		new_rel_tuples; /* new estimated total # of tuples */
 	double		new_live_tuples;	/* new estimated total # of live tuples */
 	double		new_dead_tuples;	/* new estimated total # of dead tuples */
-	BlockNumber pages_removed;
+	BlockNumber pages_removed;	/* Due to truncation */
+	BlockNumber pages_frozen;
+	BlockNumber pages_allvisible;
 	double		tuples_deleted;
 	BlockNumber nonempty_pages; /* actually, last nonempty page + 1 */
 	LVDeadTuples *dead_tuples;
@@ -607,11 +609,13 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
 							 get_namespace_name(RelationGetNamespace(onerel)),
 							 RelationGetRelationName(onerel),
 							 vacrelstats->num_index_scans);
-			appendStringInfo(&buf, _("pages: %u removed, %u remain, %u skipped due to pins, %u skipped frozen\n"),
+			appendStringInfo(&buf, _("pages: %u removed, %u remain, %u skipped due to pins, %u skipped frozen, %u marked all visible, %u marked frozen\n"),
 							 vacrelstats->pages_removed,
 							 vacrelstats->rel_pages,
 							 vacrelstats->pinskipped_pages,
-							 vacrelstats->frozenskipped_pages);
+							 vacrelstats->frozenskipped_pages,
+							 vacrelstats->pages_allvisible,
+							 vacrelstats->pages_frozen);
 			appendStringInfo(&buf,
 							 _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u\n"),
 							 vacrelstats->tuples_deleted,
@@ -841,6 +845,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	vacrelstats->scanned_pages = 0;
 	vacrelstats->tupcount_pages = 0;
 	vacrelstats->nonempty_pages = 0;
+	vacrelstats->pages_frozen = 0;
+	vacrelstats->pages_allvisible = 0;
+
 	vacrelstats->latestRemovedXid = InvalidTransactionId;
 
 	/*
@@ -1173,6 +1180,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 				visibilitymap_set(onerel, blkno, buf, InvalidXLogRecPtr,
 								  vmbuffer, InvalidTransactionId,
 								  VISIBILITYMAP_ALL_VISIBLE | VISIBILITYMAP_ALL_FROZEN);
+				vacrelstats->pages_allvisible++;
+				vacrelstats->pages_frozen++;
 				END_CRIT_SECTION();
 			}
 
@@ -1504,8 +1513,12 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		{
 			uint8		flags = VISIBILITYMAP_ALL_VISIBLE;
 
-			if (all_frozen)
+			if (all_frozen) {
 				flags |= VISIBILITYMAP_ALL_FROZEN;
+				vacrelstats->pages_frozen++;
+			}
+
+			vacrelstats->pages_allvisible++;
 
 			/*
 			 * It should never be the case that the visibility map page is set
@@ -1706,6 +1719,14 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 									"%s%u pages are entirely empty.\n",
 									empty_pages),
 					 msgprefix, empty_pages);
+	appendStringInfo(&sbuf, ngettext("%sMarked %u page all visible, ",
+									"%sMarked %u pages all visible, ",
+									vacrelstats->pages_allvisible),
+					msgprefix, vacrelstats->pages_allvisible);
+	appendStringInfo(&sbuf, ngettext("%u page frozen.\n",
+									"%u pages frozen.\n",
+									vacrelstats->pages_frozen),
+					vacrelstats->pages_frozen);
 	appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
 
 	ereport(elevel,
@@ -1946,10 +1967,14 @@ lazy_vacuum_page(Relation onerel, BlockNumber blkno, Buffer buffer,
 		uint8		flags = 0;
 
 		/* Set the VM all-frozen bit to flag, if needed */
-		if ((vm_status & VISIBILITYMAP_ALL_VISIBLE) == 0)
+		if ((vm_status & VISIBILITYMAP_ALL_VISIBLE) == 0) {
 			flags |= VISIBILITYMAP_ALL_VISIBLE;
-		if ((vm_status & VISIBILITYMAP_ALL_FROZEN) == 0 && all_frozen)
+			vacrelstats->pages_allvisible++;
+		}
+		if ((vm_status & VISIBILITYMAP_ALL_FROZEN) == 0 && all_frozen) {
 			flags |= VISIBILITYMAP_ALL_FROZEN;
+			vacrelstats->pages_frozen++;
+		}
 
 		Assert(BufferIsValid(*vmbuffer));
 		if (flags != 0)
-- 
2.7.4

From a3d0b41435655615ab13f808ec7c30e53e596e50 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sat, 25 Jan 2020 21:25:37 -0600
Subject: [PATCH v3 1/4] Remove gettext erronously readded at 580ddce

---
 src/backend/access/heap/vacuumlazy.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 8ce5011..8e8ea9d 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1690,7 +1690,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 									"%u pages are entirely empty.\n",
 									empty_pages),
 					 empty_pages);
-	appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
+	appendStringInfo(&buf, "%s.", pg_rusage_show(&ru0));
 
 	ereport(elevel,
 			(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
-- 
2.7.4

From 2db7c4e3482120b2a83cda74603f2454da7eaa03 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sat, 25 Jan 2020 22:50:46 -0600
Subject: [PATCH v3 2/4] vacuum verbose: use ngettext() everywhere possible

---
 src/backend/access/heap/vacuumlazy.c | 9 ++++++---
 1 file changed, 6 insertions(+), 3 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 8e8ea9d..eb903d5 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1673,10 +1673,13 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	 * individual parts of the message when not applicable.
 	 */
 	initStringInfo(&buf);
-	appendStringInfo(&buf,
-					 _("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
+	appendStringInfo(&buf, ngettext("%.0f dead row version cannot be removed yet, oldest xmin: %u\n",
+									"%.0f dead row versions cannot be removed yet, oldest xmin: %u\n",
+									nkeep),
 					 nkeep, OldestXmin);
-	appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
+	appendStringInfo(&buf, ngettext("There was %.0f unused item identifier.\n",
+									"There were %.0f unused item identifiers.\n",
+									nunused),
 					 nunused);
 	appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
 									"Skipped %u pages due to buffer pins, ",
-- 
2.7.4

From 3467bf485972065f73c25a8f1e66c7c4f0bd5d23 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sat, 25 Jan 2020 21:47:05 -0600
Subject: [PATCH v3 3/4] vacuum verbose: prefix write multi-line output to
 client..

..but do not change output to logfile, which isn't unclear.

I borrowed the format from ShowUsage.

TODO: lazy_cleanup_index
---
 src/backend/access/heap/vacuumlazy.c | 58 ++++++++++++++++++++++++++----------
 1 file changed, 43 insertions(+), 15 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index eb903d5..6f85af7 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -307,6 +307,7 @@ static BufferAccessStrategy vac_strategy;
 static void lazy_scan_heap(Relation onerel, VacuumParams *params,
 						   LVRelStats *vacrelstats, Relation *Irel, int nindexes,
 						   bool aggressive);
+static void vacuum_msg(StringInfoData *buf, const char *prefix, LVRelStats *vacrelstats, double nkeep, double nunused, BlockNumber empty_pages, PGRUsage *ru0);
 static void lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats);
 static bool lazy_check_needs_freeze(Buffer buf, bool *hastup);
 static void lazy_vacuum_all_indexes(Relation onerel, Relation *Irel,
@@ -717,7 +718,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	BlockNumber next_unskippable_block;
 	bool		skipping_blocks;
 	xl_heap_freeze_tuple *frozen;
-	StringInfoData buf;
+	StringInfoData logdetail,
+				clientdetail;
 	const int	initprog_index[] = {
 		PROGRESS_VACUUM_PHASE,
 		PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -1668,40 +1670,66 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 						RelationGetRelationName(onerel),
 						tups_vacuumed, vacuumed_pages)));
 
+	/* Write separate log messages to client (with prefix) and logfile (without prefix) */
+	vacuum_msg(&logdetail, "", vacrelstats, nkeep, nunused, empty_pages, &ru0);
+	vacuum_msg(&clientdetail, "! ", vacrelstats, nkeep, nunused, empty_pages, &ru0);
+
+	ereport(elevel,
+			(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
+					RelationGetRelationName(onerel),
+					tups_vacuumed, num_tuples,
+					vacrelstats->scanned_pages, nblocks),
+			 errdetail_log("%s", logdetail.data),
+			 errdetail_internal("%s", clientdetail.data)));
+
+	pfree(logdetail.data);
+	pfree(clientdetail.data);
+}
+
+/* Populate buf with string to be freed by caller */
+static void
+vacuum_msg(StringInfoData *buf, const char *prefix, LVRelStats *vacrelstats, double nkeep, double nunused, BlockNumber empty_pages, PGRUsage *ru0)
+{
 	/*
 	 * 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);
-	appendStringInfo(&buf, ngettext("%.0f dead row version cannot be removed yet, oldest xmin: %u\n",
+	initStringInfo(buf);
+	if (prefix)
+		appendStringInfoString(buf, prefix);
+	appendStringInfo(buf, ngettext("%.0f dead row version cannot be removed yet, oldest xmin: %u\n",
 									"%.0f dead row versions cannot be removed yet, oldest xmin: %u\n",
 									nkeep),
 					 nkeep, OldestXmin);
-	appendStringInfo(&buf, ngettext("There was %.0f unused item identifier.\n",
+
+	if (prefix)
+		appendStringInfoString(buf, prefix);
+	appendStringInfo(buf, ngettext("There was %.0f unused item identifier.\n",
 									"There were %.0f unused item identifiers.\n",
 									nunused),
 					 nunused);
-	appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
+
+	if (prefix)
+		appendStringInfoString(buf, prefix);
+	appendStringInfo(buf, ngettext("Skipped %u page due to buffer pins, ",
 									"Skipped %u pages due to buffer pins, ",
 									vacrelstats->pinskipped_pages),
 					 vacrelstats->pinskipped_pages);
-	appendStringInfo(&buf, ngettext("%u frozen page.\n",
+	appendStringInfo(buf, ngettext("%u frozen page.\n",
 									"%u frozen pages.\n",
 									vacrelstats->frozenskipped_pages),
 					 vacrelstats->frozenskipped_pages);
-	appendStringInfo(&buf, ngettext("%u page is entirely empty.\n",
+
+	if (prefix)
+		appendStringInfoString(buf, prefix);
+	appendStringInfo(buf, ngettext("%u page is entirely empty.\n",
 									"%u pages are entirely empty.\n",
 									empty_pages),
 					 empty_pages);
-	appendStringInfo(&buf, "%s.", pg_rusage_show(&ru0));
 
-	ereport(elevel,
-			(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
-					RelationGetRelationName(onerel),
-					tups_vacuumed, num_tuples,
-					vacrelstats->scanned_pages, nblocks),
-			 errdetail_internal("%s", buf.data)));
-	pfree(buf.data);
+	if (prefix)
+		appendStringInfoString(buf, prefix);
+	appendStringInfo(buf, "%s.", pg_rusage_show(ru0));
 }
 
 /*
-- 
2.7.4

From 55fea31f5d3d99a94eba206ec5a75f94e1f43097 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 15 Dec 2019 17:00:29 -0600
Subject: [PATCH v3 4/4] 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 | 24 +++++++++++++++++-------
 1 file changed, 17 insertions(+), 7 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 6f85af7..95d999f 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -501,6 +501,7 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
 		lazy_truncate_heap(onerel, vacrelstats);
 
 	/* Report that we are now doing final cleanup */
+	elog(DEBUG1, "cleaning up");
 	pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
 								 PROGRESS_VACUUM_PHASE_FINAL_CLEANUP);
 
@@ -1773,9 +1774,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 */
@@ -1805,6 +1809,8 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
 	Buffer		vmbuffer = InvalidBuffer;
 
 	/* Report that we are now vacuuming the heap */
+	ereport(DEBUG1, (errmsg("\"%s\": vacuuming heap",
+					RelationGetRelationName(onerel))));
 	pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
 								 PROGRESS_VACUUM_PHASE_VACUUM_HEAP);
 
@@ -1848,7 +1854,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),
@@ -2093,13 +2099,13 @@ lazy_parallel_vacuum_indexes(Relation *Irel, IndexBulkDeleteResult **stats,
 		}
 
 		if (lps->lvshared->for_cleanup)
-			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),
 							lps->pcxt->nworkers_launched, nworkers)));
 		else
-			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),
@@ -2326,10 +2332,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);
+		}
 	}
 }
 
@@ -2369,7 +2378,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),
@@ -2412,7 +2421,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,
@@ -2476,6 +2485,7 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
 	pg_rusage_init(&ru0);
 
 	/* Report that we are now truncating */
+	elog(DEBUG1, "truncating heap");
 	pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
 								 PROGRESS_VACUUM_PHASE_TRUNCATE);
 
-- 
2.7.4