Date: Fri, 13 Dec 2019 16:47:35 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: Michael Paquier <michael@paquier.xyz>
Cc: Alvaro Herrera <alvherre@2ndquadrant.com>,
	Andres Freund <andres@anarazel.de>, pgsql-hackers@postgresql.org
Subject: Re: error context for vacuum to include block number
Message-ID: <20191213224735.GY2082@telsasoft.com>
References: <20191211165425.4ewww2s5k5cafi4l@alap3.anarazel.de>
 <20191211153353.GA23008@alvherre.pgsql>
 <20191213030831.GT2082@telsasoft.com>
 <20191213132850.GA103520@paquier.xyz>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="e5GLnnZ8mDMEwH4V"
Content-Disposition: inline
In-Reply-To: <20191213132850.GA103520@paquier.xyz>
User-Agent: Mutt/1.5.24 (2015-08-30)
Precedence: bulk


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

On Fri, Dec 13, 2019 at 10:28:50PM +0900, Michael Paquier wrote:

>> v4-0001-Rename-buf-to-avoid-shadowing-buf-of-another-type.patch
>> v4-0002-Remove-redundant-call-to-vacuum-progress.patch
>> v4-0003-deduplication.patch
>> v4-0004-vacuum-errcontext-to-show-block-being-processed.patch
>> v4-0005-add-errcontext-callback-in-lazy_vacuum_heap-too.patch

> What is the purpose of 0001 in the context of this thread?  One could
> say the same about 0002 and 0003.  Anyway, you are right with 0002 as
> the progress value for PROGRESS_VACUUM_PHASE gets updated twice in a
> row with the same value.  So let's clean up that.  

It's related code which I cleaned up before adding new stuff.  Not essential,
thus separate (0002 should be backpatched).

> The refactoring in 0003 is interesting, so I would be tempted to merge
> it.  Now you have one small issue in it:
> -    /*
> -     * Forget the now-vacuumed tuples, and press on, but be careful
> -     * not to reset latestRemovedXid since we want that value to be
> -     * valid.
> -     */
> +     lazy_vacuum_heap_index(onerel, vacrelstats, Irel, nindexes, indstats);
>       vacrelstats->num_dead_tuples = 0;
> -     vacrelstats->num_index_scans++;
> You are moving this comment within lazy_vacuum_heap_index, but it
> applies to num_dead_tuples and not num_index_scans, no?  You should
> keep the incrementation of num_index_scans within the routine though.

Thank you, fixed.

-- 
Justin Pryzby
System Administrator
Telsasoft
+1-952-707-8581

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

From db8a62da96a7591345bb4dc2a7c725bd0d4878d1 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Wed, 27 Nov 2019 20:07:10 -0600
Subject: [PATCH v5 1/5] 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 a3c4a1d..043ebb4 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -517,7 +517,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,
@@ -1481,33 +1481,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


--e5GLnnZ8mDMEwH4V
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v5-0002-Remove-redundant-call-to-vacuum-progress.patch"

From ec23b44c94c6cf849edf957ced6b866a8bfe1a76 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Thu, 12 Dec 2019 20:42:27 -0600
Subject: [PATCH v5 2/5] Remove redundant call to vacuum progress..

..introduced at c16dc1aca

Should be backpatched to 9.6
---
 src/backend/access/heap/vacuumlazy.c | 3 ---
 1 file changed, 3 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 043ebb4..49f3bed 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1444,9 +1444,6 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		hvp_val[1] = vacrelstats->num_index_scans + 1;
 		pgstat_progress_update_multi_param(2, hvp_index, hvp_val);
 
-		/* Remove tuples from heap */
-		pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
-									 PROGRESS_VACUUM_PHASE_VACUUM_HEAP);
 		lazy_vacuum_heap(onerel, vacrelstats);
 		vacrelstats->num_index_scans++;
 	}
-- 
2.7.4


--e5GLnnZ8mDMEwH4V
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="v5-0003-deduplication.patch"

From 579d7d3d19353de3a85c1b9ee23b6a584c4eaef2 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Thu, 12 Dec 2019 19:57:25 -0600
Subject: [PATCH v5 3/5] deduplication

---
 src/backend/access/heap/vacuumlazy.c | 102 +++++++++++++++--------------------
 1 file changed, 43 insertions(+), 59 deletions(-)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 49f3bed..145a8a2 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -153,6 +153,7 @@ static BufferAccessStrategy vac_strategy;
 static void lazy_scan_heap(Relation onerel, VacuumParams *params,
 						   LVRelStats *vacrelstats, Relation *Irel, int nindexes,
 						   bool aggressive);
+static void lazy_vacuum_heap_index(Relation onerel, LVRelStats *vacrelstats, Relation *Irel, int nindexes, IndexBulkDeleteResult **indstats);
 static void lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats);
 static bool lazy_check_needs_freeze(Buffer buf, bool *hastup);
 static void lazy_vacuum_index(Relation indrel,
@@ -740,12 +741,6 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		if ((vacrelstats->max_dead_tuples - vacrelstats->num_dead_tuples) < MaxHeapTuplesPerPage &&
 			vacrelstats->num_dead_tuples > 0)
 		{
-			const int	hvp_index[] = {
-				PROGRESS_VACUUM_PHASE,
-				PROGRESS_VACUUM_NUM_INDEX_VACUUMS
-			};
-			int64		hvp_val[2];
-
 			/*
 			 * Before beginning index vacuuming, we release any pin we may
 			 * hold on the visibility map page.  This isn't necessary for
@@ -758,31 +753,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 				vmbuffer = InvalidBuffer;
 			}
 
-			/* Log cleanup info before we touch indexes */
-			vacuum_log_cleanup_info(onerel, vacrelstats);
-
-			/* Report that we are now vacuuming indexes */
-			pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
-										 PROGRESS_VACUUM_PHASE_VACUUM_INDEX);
-
-			/* Remove index entries */
-			for (i = 0; i < nindexes; i++)
-				lazy_vacuum_index(Irel[i],
-								  &indstats[i],
-								  vacrelstats);
 
-			/*
-			 * Report that we are now vacuuming the heap.  We also increase
-			 * the number of index scans here; note that by using
-			 * pgstat_progress_update_multi_param we can update both
-			 * parameters atomically.
-			 */
-			hvp_val[0] = PROGRESS_VACUUM_PHASE_VACUUM_HEAP;
-			hvp_val[1] = vacrelstats->num_index_scans + 1;
-			pgstat_progress_update_multi_param(2, hvp_index, hvp_val);
-
-			/* Remove tuples from heap */
-			lazy_vacuum_heap(onerel, vacrelstats);
+			lazy_vacuum_heap_index(onerel, vacrelstats, Irel, nindexes, indstats);
 
 			/*
 			 * Forget the now-vacuumed tuples, and press on, but be careful
@@ -790,7 +762,6 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			 * valid.
 			 */
 			vacrelstats->num_dead_tuples = 0;
-			vacrelstats->num_index_scans++;
 
 			/*
 			 * Vacuum the Free Space Map to make newly-freed space visible on
@@ -1418,34 +1389,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 
 	/* If any tuples need to be deleted, perform final vacuum cycle */
 	/* XXX put a threshold on min number of tuples here? */
-	if (vacrelstats->num_dead_tuples > 0)
-	{
-		const int	hvp_index[] = {
-			PROGRESS_VACUUM_PHASE,
-			PROGRESS_VACUUM_NUM_INDEX_VACUUMS
-		};
-		int64		hvp_val[2];
-
-		/* Log cleanup info before we touch indexes */
-		vacuum_log_cleanup_info(onerel, vacrelstats);
-
-		/* Report that we are now vacuuming indexes */
-		pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
-									 PROGRESS_VACUUM_PHASE_VACUUM_INDEX);
-
-		/* Remove index entries */
-		for (i = 0; i < nindexes; i++)
-			lazy_vacuum_index(Irel[i],
-							  &indstats[i],
-							  vacrelstats);
-
-		/* Report that we are now vacuuming the heap */
-		hvp_val[0] = PROGRESS_VACUUM_PHASE_VACUUM_HEAP;
-		hvp_val[1] = vacrelstats->num_index_scans + 1;
-		pgstat_progress_update_multi_param(2, hvp_index, hvp_val);
-
-		lazy_vacuum_heap(onerel, vacrelstats);
-		vacrelstats->num_index_scans++;
+	if (vacrelstats->num_dead_tuples > 0) {
+		lazy_vacuum_heap_index(onerel, vacrelstats, Irel, nindexes, indstats);
 	}
 
 	/*
@@ -1507,6 +1452,45 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	pfree(sbuf.data);
 }
 
+static void
+lazy_vacuum_heap_index(Relation onerel, LVRelStats *vacrelstats, Relation *Irel, int nindexes, IndexBulkDeleteResult **indstats)
+{
+	const int	hvp_index[] = {
+		PROGRESS_VACUUM_PHASE,
+		PROGRESS_VACUUM_NUM_INDEX_VACUUMS
+	};
+	int64		hvp_val[2];
+	int			i;
+
+	/* Log cleanup info before we touch indexes */
+	vacuum_log_cleanup_info(onerel, vacrelstats);
+
+	/* Report that we are now vacuuming indexes */
+	pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
+								 PROGRESS_VACUUM_PHASE_VACUUM_INDEX);
+
+	/* Remove index entries */
+	for (i = 0; i < nindexes; i++)
+		lazy_vacuum_index(Irel[i],
+						  &indstats[i],
+						  vacrelstats);
+
+	/*
+	 * Report that we are now vacuuming the heap.  We also increase
+	 * the number of index scans here; note that by using
+	 * pgstat_progress_update_multi_param we can update both
+	 * parameters atomically.
+	 */
+	hvp_val[0] = PROGRESS_VACUUM_PHASE_VACUUM_HEAP;
+	hvp_val[1] = vacrelstats->num_index_scans + 1;
+	pgstat_progress_update_multi_param(2, hvp_index, hvp_val);
+
+	/* Remove tuples from heap */
+	lazy_vacuum_heap(onerel, vacrelstats);
+
+	vacrelstats->num_index_scans++;
+}
+
 
 /*
  *	lazy_vacuum_heap() -- second pass over the heap
-- 
2.7.4


--e5GLnnZ8mDMEwH4V
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v5-0004-vacuum-errcontext-to-show-block-being-processed.patch"

From d1d8180ffc3d944bedf7b108371698bcc8f58457 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Thu, 12 Dec 2019 20:54:37 -0600
Subject: [PATCH v5 4/5] vacuum errcontext to show block being processed

As requested here.
https://www.postgresql.org/message-id/20190807235154.erbmr4o4bo6vgnjv%40alap3.anarazel.de
---
 src/backend/access/heap/vacuumlazy.c | 38 ++++++++++++++++++++++++++++++++++++
 1 file changed, 38 insertions(+)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 145a8a2..5f44543 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -138,6 +138,12 @@ typedef struct LVRelStats
 	bool		lock_waiter_detected;
 } LVRelStats;
 
+typedef struct
+{
+	char *relname;
+	char *relnamespace;
+	BlockNumber blkno;
+} vacuum_error_callback_arg;
 
 /* A few variables that don't seem worth passing around as parameters */
 static int	elevel = -1;
@@ -176,6 +182,7 @@ static bool lazy_tid_reaped(ItemPointer itemptr, void *state);
 static int	vac_cmp_itemptr(const void *left, const void *right);
 static bool heap_page_is_all_visible(Relation rel, Buffer buf,
 									 TransactionId *visibility_cutoff_xid, bool *all_frozen);
+static void vacuum_error_callback(void *arg);
 
 
 /*
@@ -525,6 +532,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 		PROGRESS_VACUUM_MAX_DEAD_TUPLES
 	};
 	int64		initprog_val[3];
+	ErrorContextCallback errcallback;
+	vacuum_error_callback_arg errcbarg;
 
 	pg_rusage_init(&ru0);
 
@@ -636,6 +645,15 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	else
 		skipping_blocks = false;
 
+	/* Setup error traceback support for ereport() */
+	errcallback.callback = vacuum_error_callback;
+	errcbarg.relname = relname;
+	errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(onerel));
+	errcbarg.blkno = InvalidBlockNumber; /* Not known yet */
+	errcallback.arg = (void *) &errcbarg;
+	errcallback.previous = error_context_stack;
+	error_context_stack = &errcallback;
+
 	for (blkno = 0; blkno < nblocks; blkno++)
 	{
 		Buffer		buf;
@@ -657,6 +675,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 #define FORCE_CHECK_PAGE() \
 		(blkno == nblocks - 1 && should_attempt_truncation(params, vacrelstats))
 
+		errcbarg.blkno = blkno;
+
 		pgstat_progress_update_param(PROGRESS_VACUUM_HEAP_BLKS_SCANNED, blkno);
 
 		if (blkno == next_unskippable_block)
@@ -754,7 +774,10 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			}
 
 
+			/* Don't use the errcontext handler outside this function */
+			error_context_stack = errcallback.previous;
 			lazy_vacuum_heap_index(onerel, vacrelstats, Irel, nindexes, indstats);
+			error_context_stack = &errcallback;
 
 			/*
 			 * Forget the now-vacuumed tuples, and press on, but be careful
@@ -1359,6 +1382,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			RecordPageWithFreeSpace(onerel, blkno, freespace);
 	}
 
+	/* Pop the error context stack */
+	error_context_stack = errcallback.previous;
+
 	/* report that everything is scanned and vacuumed */
 	pgstat_progress_update_param(PROGRESS_VACUUM_HEAP_BLKS_SCANNED, blkno);
 
@@ -2335,3 +2361,15 @@ heap_page_is_all_visible(Relation rel, Buffer buf,
 
 	return all_visible;
 }
+
+/*
+ * Error context callback for errors occurring during vacuum.
+ */
+static void
+vacuum_error_callback(void *arg)
+{
+	vacuum_error_callback_arg *cbarg = arg;
+
+	errcontext("while scanning block %u of relation \"%s.%s\"",
+			cbarg->blkno, cbarg->relnamespace, cbarg->relname);
+}
-- 
2.7.4


--e5GLnnZ8mDMEwH4V
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v5-0005-add-errcontext-callback-in-lazy_vacuum_heap-too.patch"

From 3c4bbf5e1113299f9dc985fad394e3ccee545dc8 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Thu, 12 Dec 2019 20:34:03 -0600
Subject: [PATCH v5 5/5] add errcontext callback in lazy_vacuum_heap, too

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

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 5f44543..b680f5a 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1417,6 +1417,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	/* XXX put a threshold on min number of tuples here? */
 	if (vacrelstats->num_dead_tuples > 0) {
 		lazy_vacuum_heap_index(onerel, vacrelstats, Irel, nindexes, indstats);
+		error_context_stack = errcallback.previous;
 	}
 
 	/*
@@ -1537,6 +1538,18 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
 	PGRUsage	ru0;
 	Buffer		vmbuffer = InvalidBuffer;
 
+	ErrorContextCallback errcallback;
+	vacuum_error_callback_arg errcbarg;
+
+	/* Setup error traceback support for ereport() */
+	errcallback.callback = vacuum_error_callback;
+	errcbarg.relname = RelationGetRelationName(onerel);
+	errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(onerel));
+	errcbarg.blkno = InvalidBlockNumber; /* Not known yet */
+	errcallback.arg = (void *) &errcbarg;
+	/* errcallback.previous is unused: rely on the caller to reset its own prior callback */
+	error_context_stack = &errcallback;
+
 	pg_rusage_init(&ru0);
 	npages = 0;
 
@@ -1551,6 +1564,7 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
 		vacuum_delay_point();
 
 		tblk = ItemPointerGetBlockNumber(&vacrelstats->dead_tuples[tupindex]);
+		errcbarg.blkno = tblk;
 		buf = ReadBufferExtended(onerel, MAIN_FORKNUM, tblk, RBM_NORMAL,
 								 vac_strategy);
 		if (!ConditionalLockBufferForCleanup(buf))
-- 
2.7.4


--e5GLnnZ8mDMEwH4V--