Date: Tue, 21 Jan 2020 07:49:34 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: Jeff Janes <jeff.janes@gmail.com>
Cc: pgsql-hackers <pgsql-hackers@postgresql.org>
Subject: Re: vacuum verbose detail logs are unclear; log at *start* of each
 stage; show allvisible/frozen/hintbits
Message-ID: <20200121134934.GY26045@telsasoft.com>
References: <20191220171132.GB30414@telsasoft.com>
 <CAMkU=1xAyWnwnLGORBOD=pyv=ccEkDi=wKeyhwF=gtB7QxLBwQ@mail.gmail.com>
 <20200113004542.GA26045@telsasoft.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="2VOk7s3pVsDYAazo"
Content-Disposition: inline
In-Reply-To: <20200113004542.GA26045@telsasoft.com>
User-Agent: Mutt/1.5.24 (2015-08-30)
Precedence: bulk


--2VOk7s3pVsDYAazo
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

Rebased against 40d964ec997f64227bc0ff5e058dc4a5770a70a9
I added to March CF https://commitfest.postgresql.org/27/2425/

--2VOk7s3pVsDYAazo
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v2-0001-Rename-buf-to-avoid-shadowing-buf-of-another-type.patch"

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


--2VOk7s3pVsDYAazo
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v2-0002-vacuumlazy-typos-in-comments.patch"

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


--2VOk7s3pVsDYAazo
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v2-0003-Indent-VACUUM-VERBOSE-multi-line-errdetail-messag.patch"

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


--2VOk7s3pVsDYAazo
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v2-0004-reduce-to-DEBUG-status-logged-from-vacuum_heap-in.patch"

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


--2VOk7s3pVsDYAazo
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v2-0005-Report-number-of-pages_allvisible-frozen.patch"

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


--2VOk7s3pVsDYAazo
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v2-0006-Report-number-of-hint-bits-written.patch"

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


--2VOk7s3pVsDYAazo--