Date: Sun, 2 Feb 2020 00:02:59 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: Masahiko Sawada <masahiko.sawada@2ndquadrant.com>
Cc: Andres Freund <andres@anarazel.de>,
	Michael Paquier <michael@paquier.xyz>,
	Alvaro Herrera <alvherre@2ndquadrant.com>,
	pgsql-hackers@postgresql.org
Subject: Re: error context for vacuum to include block number
Message-ID: <20200202060259.GG13621@telsasoft.com>
References: <20191226155704.GA12890@telsasoft.com>
 <20200102162701.GA2709@telsasoft.com>
 <20200120054159.GT26045@telsasoft.com>
 <20200120191120.s2pyx4ib4yubavxe@alap3.anarazel.de>
 <20200120214929.GV26045@telsasoft.com>
 <20200126202938.dqtavh6vr3vgpw53@alap3.anarazel.de>
 <20200127053813.GS13621@telsasoft.com>
 <CA+fd4k71fHRYJAeGxigGza5U+_HDJcBAbMniiMK2xz5GHhsMmQ@mail.gmail.com>
 <20200127225018.GY13621@telsasoft.com>
 <CA+fd4k48wcdYpr-4UsLzchohOk6pwW3Aijmw_PR4hEXJBcs8Xw@mail.gmail.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="Ubca5Sl/zyRO+Ah+"
Content-Disposition: inline
In-Reply-To: 
 <CA+fd4k48wcdYpr-4UsLzchohOk6pwW3Aijmw_PR4hEXJBcs8Xw@mail.gmail.com>
User-Agent: Mutt/1.5.24 (2015-08-30)
Precedence: bulk


--Ubca5Sl/zyRO+Ah+
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

Thanks for reviewing again

On Sun, Feb 02, 2020 at 10:45:12AM +0900, Masahiko Sawada wrote:
> Thank you for updating the patch. Here is some review comments:
> 
> 1.
> +typedef struct
> +{
> +   char        *relnamespace;
> +   char        *relname;
> +   char        *indname; /* If vacuuming index */
> 
> I think "Non-null if vacuuming index" is better.

Actually it's undefined garbage (not NULL) if not vacuuming index.

> And tablename is better than relname for accuracy?

The existing code uses relname, so I left that, since it's strange to
start using tablename and then write things like:

|       errcbarg.tblname = relname;
...
|       errcontext(_("while scanning block %u of relation \"%s.%s\""),
|                       cbarg->blkno, cbarg->relnamespace, cbarg->tblname);

Also, mat views can be vacuumed.

> 2.
> +   BlockNumber blkno;
> +   int         stage;  /* 0: scan heap; 1: vacuum heap; 2: vacuum index */
> +} vacuum_error_callback_arg;
> 
> Why do we not support index cleanup phase?

The patch started out just handling scan_heap.  The added vacuum_heap.  Then
added vacuum_index.  Now, I've added index cleanup.

> 4.
> +    /*
> +     * Setup error traceback support for ereport()
> +     * ->relnamespace and ->relname are already set
> +     */
> +    errcbarg.blkno = InvalidBlockNumber; /* Not known yet */
> +    errcbarg.stage = 1;
> 
> relnamespace and relname of errcbarg is not set as it is initialized
> in this function.

Thanks. That's an oversight from switching back to local vars instead of
LVRelStats while updating the patch while out of town..

I don't know how to consistently test the vacuum_heap case, but rechecked it just now.

postgres=# SET client_min_messages=debug; SET statement_timeout=0; UPDATE t SET a=1+a; SET statement_timeout=150; VACUUM(VERBOSE, PARALLEL 1) t;
...
2020-02-01 23:11:06.482 CST [26609] ERROR:  canceling statement due to statement timeout
2020-02-01 23:11:06.482 CST [26609] CONTEXT:  while vacuuming block 33 of relation "public.t"

> 5.
> @@ -177,6 +177,7 @@ typedef struct LVShared
>      * the lazy vacuum.
>      */
>     Oid         relid;
> +   char        relname[NAMEDATALEN];   /* tablename, used for error callback */
> 
> How about getting relation
> name from index relation? That is, in lazy_vacuum_index we can get
> table oid from the index relation by IndexGetRelation() and therefore
> we can get the table name which is in palloc'd memory. That way we
> don't need to add relname to any existing struct such as LVRelStats
> and LVShared.

See attached

Also, I think we shouldn't show a block number if it's "Invalid", to avoid
saying "while vacuuming block 4294967295 of relation ..."

For now, I made it not show any errcontext at all in that case.

--Ubca5Sl/zyRO+Ah+
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v16-0001-vacuum-errcontext-to-show-block-being-processed.patch"

From 94f715818dcdf3225a3e7404e395e4a0f0818b0c Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Thu, 12 Dec 2019 20:54:37 -0600
Subject: [PATCH v16 1/3] 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 | 94 ++++++++++++++++++++++++++++++++++++
 1 file changed, 94 insertions(+)

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 8ce5011..43859bd 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -292,6 +292,13 @@ typedef struct LVRelStats
 	bool		lock_waiter_detected;
 } LVRelStats;
 
+typedef struct
+{
+	char 		*relnamespace;
+	char		*relname;
+	BlockNumber blkno;
+	int			phase;	/* Reusing same enums as for progress reporting */
+} vacuum_error_callback_arg;
 
 /* A few variables that don't seem worth passing around as parameters */
 static int	elevel = -1;
@@ -361,6 +368,7 @@ static void end_parallel_vacuum(Relation *Irel, IndexBulkDeleteResult **stats,
 								LVParallelState *lps, int nindexes);
 static LVSharedIndStats *get_indstats(LVShared *lvshared, int n);
 static bool skip_parallel_vacuum_index(Relation indrel, LVShared *lvshared);
+static void vacuum_error_callback(void *arg);
 
 
 /*
@@ -724,6 +732,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);
 
@@ -870,6 +880,17 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 	else
 		skipping_blocks = false;
 
+	/* Setup error traceback support for ereport() */
+	errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(onerel));
+	errcbarg.relname = relname;
+	errcbarg.blkno = InvalidBlockNumber; /* Not known yet */
+	errcbarg.phase = PROGRESS_VACUUM_PHASE_SCAN_HEAP;
+
+	errcallback.callback = vacuum_error_callback;
+	errcallback.arg = (void *) &errcbarg;
+	errcallback.previous = error_context_stack;
+	error_context_stack = &errcallback;
+
 	for (blkno = 0; blkno < nblocks; blkno++)
 	{
 		Buffer		buf;
@@ -891,6 +912,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)
@@ -987,6 +1010,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 				vmbuffer = InvalidBuffer;
 			}
 
+			/* Pop the error context stack */
+			error_context_stack = errcallback.previous;
+
 			/* Work on all the indexes, then the heap */
 			lazy_vacuum_all_indexes(onerel, Irel, indstats,
 									vacrelstats, lps, nindexes);
@@ -994,6 +1020,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
 			/* Remove tuples from heap */
 			lazy_vacuum_heap(onerel, vacrelstats);
 
+			/* Replace error context while continuing heap scan */
+			error_context_stack = &errcallback;
+
 			/*
 			 * Forget the now-vacuumed tuples, and press on, but be careful
 			 * not to reset latestRemovedXid since we want that value to be
@@ -1597,6 +1626,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);
 
@@ -1772,11 +1804,26 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
 	int			npages;
 	PGRUsage	ru0;
 	Buffer		vmbuffer = InvalidBuffer;
+	ErrorContextCallback errcallback;
+	vacuum_error_callback_arg errcbarg;
 
 	/* Report that we are now vacuuming the heap */
 	pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
 								 PROGRESS_VACUUM_PHASE_VACUUM_HEAP);
 
+	/*
+	 * Setup error traceback support for ereport()
+	 */
+	errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(onerel));
+	errcbarg.relname = RelationGetRelationName(onerel);
+	errcbarg.blkno = InvalidBlockNumber; /* Not known yet */
+	errcbarg.phase = PROGRESS_VACUUM_PHASE_VACUUM_HEAP;
+
+	errcallback.callback = vacuum_error_callback;
+	errcallback.arg = (void *) &errcbarg;
+	errcallback.previous = error_context_stack;
+	error_context_stack = &errcallback;
+
 	pg_rusage_init(&ru0);
 	npages = 0;
 
@@ -1791,6 +1838,7 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
 		vacuum_delay_point();
 
 		tblk = ItemPointerGetBlockNumber(&vacrelstats->dead_tuples->itemptrs[tupindex]);
+		errcbarg.blkno = tblk;
 		buf = ReadBufferExtended(onerel, MAIN_FORKNUM, tblk, RBM_NORMAL,
 								 vac_strategy);
 		if (!ConditionalLockBufferForCleanup(buf))
@@ -1811,6 +1859,9 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
 		npages++;
 	}
 
+	/* Pop the error context stack */
+	error_context_stack = errcallback.previous;
+
 	if (BufferIsValid(vmbuffer))
 	{
 		ReleaseBuffer(vmbuffer);
@@ -2318,6 +2369,8 @@ lazy_vacuum_index(Relation indrel, IndexBulkDeleteResult **stats,
 	IndexVacuumInfo ivinfo;
 	const char *msg;
 	PGRUsage	ru0;
+	ErrorContextCallback errcallback;
+	vacuum_error_callback_arg errcbarg;
 
 	pg_rusage_init(&ru0);
 
@@ -2329,10 +2382,23 @@ lazy_vacuum_index(Relation indrel, IndexBulkDeleteResult **stats,
 	ivinfo.num_heap_tuples = reltuples;
 	ivinfo.strategy = vac_strategy;
 
+	/* Setup error traceback support for ereport() */
+	errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(indrel));
+	errcbarg.relname = RelationGetRelationName(indrel);
+	errcbarg.phase = PROGRESS_VACUUM_PHASE_VACUUM_INDEX;
+
+	errcallback.callback = vacuum_error_callback;
+	errcallback.arg = (void *) &errcbarg;
+	errcallback.previous = error_context_stack;
+	error_context_stack = &errcallback;
+
 	/* Do bulk deletion */
 	*stats = index_bulk_delete(&ivinfo, *stats,
 							   lazy_tid_reaped, (void *) dead_tuples);
 
+	/* Pop the error context stack */
+	error_context_stack = errcallback.previous;
+
 	if (IsParallelWorker())
 		msg = gettext_noop("scanned index \"%s\" to remove %d row versions by parallel vacuum worker");
 	else
@@ -3375,3 +3441,31 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc)
 	table_close(onerel, ShareUpdateExclusiveLock);
 	pfree(stats);
 }
+
+/*
+ * Error context callback for errors occurring during vacuum.
+ */
+static void
+vacuum_error_callback(void *arg)
+{
+	vacuum_error_callback_arg *cbarg = arg;
+
+	switch (cbarg->phase) {
+		case PROGRESS_VACUUM_PHASE_SCAN_HEAP:
+			if (cbarg->blkno!=InvalidBlockNumber)
+				errcontext(_("while scanning block %u of relation \"%s.%s\""),
+						cbarg->blkno, cbarg->relnamespace, cbarg->relname);
+			break;
+
+		case PROGRESS_VACUUM_PHASE_VACUUM_HEAP:
+			if (cbarg->blkno!=InvalidBlockNumber)
+				errcontext(_("while vacuuming block %u of relation \"%s.%s\""),
+						cbarg->blkno, cbarg->relnamespace, cbarg->relname);
+			break;
+
+		case PROGRESS_VACUUM_PHASE_VACUUM_INDEX:
+			errcontext(_("while vacuuming index \"%s.%s\""),
+					cbarg->relnamespace, cbarg->relname);
+			break;
+	}
+}
-- 
2.7.4


--Ubca5Sl/zyRO+Ah+
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v16-0002-Include-name-of-table-in-callback-for-index-vacu.patch"

From 4cfc623686cc7056365f7fbb39c422f3d5260fdb Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Mon, 27 Jan 2020 08:30:03 -0600
Subject: [PATCH v16 2/3] Include name of table in callback for index vacuum

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

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 43859bd..5d4fb3d 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -296,6 +296,7 @@ typedef struct
 {
 	char 		*relnamespace;
 	char		*relname;
+	char 		*indname; /* If vacuuming index */
 	BlockNumber blkno;
 	int			phase;	/* Reusing same enums as for progress reporting */
 } vacuum_error_callback_arg;
@@ -2384,7 +2385,8 @@ lazy_vacuum_index(Relation indrel, IndexBulkDeleteResult **stats,
 
 	/* Setup error traceback support for ereport() */
 	errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(indrel));
-	errcbarg.relname = RelationGetRelationName(indrel);
+	errcbarg.indname = RelationGetRelationName(indrel);
+	errcbarg.relname = get_rel_name(indrel->rd_index->indexrelid);
 	errcbarg.phase = PROGRESS_VACUUM_PHASE_VACUUM_INDEX;
 
 	errcallback.callback = vacuum_error_callback;
@@ -3464,8 +3466,8 @@ vacuum_error_callback(void *arg)
 			break;
 
 		case PROGRESS_VACUUM_PHASE_VACUUM_INDEX:
-			errcontext(_("while vacuuming index \"%s.%s\""),
-					cbarg->relnamespace, cbarg->relname);
+			errcontext(_("while vacuuming index \"%s.%s\" of relation \"%s\""),
+					cbarg->relnamespace, cbarg->indname, cbarg->relname);
 			break;
 	}
 }
-- 
2.7.4


--Ubca5Sl/zyRO+Ah+
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v16-0003-vacuum-error-callback-for-index-cleanup.patch"

From b094b63a6c209ecc7840445aa32dcd2f5b7c5cdc Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sat, 1 Feb 2020 22:41:48 -0600
Subject: [PATCH v16 3/3] vacuum error callback for index cleanup

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

diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 5d4fb3d..c14a917 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -2427,6 +2427,8 @@ lazy_cleanup_index(Relation indrel,
 	IndexVacuumInfo ivinfo;
 	const char *msg;
 	PGRUsage	ru0;
+	vacuum_error_callback_arg errcbarg;
+	ErrorContextCallback errcallback = { error_context_stack, vacuum_error_callback, &errcbarg, };
 
 	pg_rusage_init(&ru0);
 
@@ -2439,8 +2441,18 @@ lazy_cleanup_index(Relation indrel,
 	ivinfo.num_heap_tuples = reltuples;
 	ivinfo.strategy = vac_strategy;
 
+	/* Setup error traceback support for ereport() */
+	errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(indrel));
+	errcbarg.indname = RelationGetRelationName(indrel);
+	errcbarg.relname = get_rel_name(indrel->rd_index->indexrelid);
+	errcbarg.phase = PROGRESS_VACUUM_PHASE_INDEX_CLEANUP;
+	error_context_stack = &errcallback;
+
 	*stats = index_vacuum_cleanup(&ivinfo, *stats);
 
+	/* Pop the error context stack */
+	error_context_stack = errcallback.previous;
+
 	if (!(*stats))
 		return;
 
@@ -3469,5 +3481,10 @@ vacuum_error_callback(void *arg)
 			errcontext(_("while vacuuming index \"%s.%s\" of relation \"%s\""),
 					cbarg->relnamespace, cbarg->indname, cbarg->relname);
 			break;
+
+		case PROGRESS_VACUUM_PHASE_INDEX_CLEANUP:
+			errcontext(_("while cleaning up index \"%s.%s\" of relation \"%s\""),
+					cbarg->relnamespace, cbarg->indname, cbarg->relname);
+			break;
 	}
 }
-- 
2.7.4


--Ubca5Sl/zyRO+Ah+--