v34-0002-Log-plan-along-with-instrumentation-details.patch

From fc656131a2920a8c8a583d749cb7c18c3c57fbfa Mon Sep 17 00:00:00 2001
From: Rafael Castro <rafaelthca@gmail.com>
Date: Wed, 6 Dec 2023 19:18:32 -0300
Subject: [PATCH v34 2/2] Log plan along with instrumentation details

Instrumentation is enabled when using EXPLAIN ANALYZE or with auto_explain
and the proper settings.

A plan output with instrumentation also contains details for nodes that
weren't executed yet, depicted with (never executed). This incremental
patch also includes a new visualization, depicted with (in progress)
that denotes nodes currently being executed, ie, function InstrStartNode
was called but InstrStopNode not yet.
---
 src/backend/commands/explain.c    | 131 +++++++++++++++++++++++-------
 src/backend/executor/instrument.c |  20 ++++-
 src/include/executor/instrument.h |   1 +
 3 files changed, 120 insertions(+), 32 deletions(-)

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index a3c0a6a3d9..7369a75cf7 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1066,8 +1066,17 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
 		char	   *relname;
 		char	   *conname = NULL;
 
-		/* Must clean up instrumentation state */
-		InstrEndLoop(instr);
+		/* Signaled explain, clone instrumentation */
+		if (es->signaled) {
+			instr = palloc(sizeof(*instr));
+			*instr = *(rInfo->ri_TrigInstrument + nt);
+			/* Force end loop even if node is in progress */
+			InstrEndLoopForce(instr);
+		}
+		else {
+			instr = rInfo->ri_TrigInstrument + nt;
+			InstrEndLoop(instr);
+		}
 
 		/*
 		 * We ignore triggers that were never invoked; they likely aren't
@@ -1230,6 +1239,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 	const char *operation = NULL;
 	const char *custom_name = NULL;
 	ExplainWorkersState *save_workers_state = es->workers_state;
+	Instrumentation *local_instr = NULL;
 	int			save_indent = es->indent;
 	bool		haschildren;
 
@@ -1682,37 +1692,63 @@ ExplainNode(PlanState *planstate, List *ancestors,
 	/*
 	 * We have to forcibly clean up the instrumentation state because we
 	 * haven't done ExecutorEnd yet.  This is pretty grotty ...
-	 * This cleanup should not be done when the query has already been
-	 * executed and explain has been called by signal, as the target query
-	 * may use instrumentation and clean itself up.
 	 *
 	 * Note: contrib/auto_explain could cause instrumentation to be set up
 	 * even though we didn't ask for it here.  Be careful not to print any
 	 * instrumentation results the user didn't ask for.  But we do the
 	 * InstrEndLoop call anyway, if possible, to reduce the number of cases
 	 * auto_explain has to contend with.
+	 *
+	 * For regular explains instrumentation clean up is called directly in
+	 * the main instrumentation objects. Signaled plan logging needs to clone
+	 * instrumentation object and forcibly end the loop in nodes that may
+	 * be running.
 	 */
-	if (planstate->instrument && !es->signaled)
-		InstrEndLoop(planstate->instrument);
+	if (planstate->instrument) {
+	 	/* In flight explain. Clone instrumentation */
+	 	if (es->signaled) {
+			local_instr = palloc(sizeof(*local_instr));
+			*local_instr = *planstate->instrument;
+			/* Force end loop even if node is in progress */
+			InstrEndLoopForce(local_instr);
+	 	}
+	 	/* Use main instrumentation */
+	 	else {
+	 		local_instr = planstate->instrument;
+	 		InstrEndLoop(local_instr);
+	 	}
+	}
 
 	if (es->analyze &&
-		planstate->instrument && planstate->instrument->nloops > 0)
+		local_instr && local_instr->nloops > 0)
 	{
-		double		nloops = planstate->instrument->nloops;
-		double		startup_ms = 1000.0 * planstate->instrument->startup / nloops;
-		double		total_ms = 1000.0 * planstate->instrument->total / nloops;
-		double		rows = planstate->instrument->ntuples / nloops;
+		double		nloops = local_instr->nloops;
+		double		startup_ms = 1000.0 * local_instr->startup / nloops;
+		double		total_ms = 1000.0 * local_instr->total / nloops;
+		double		rows = local_instr->ntuples / nloops;
 
 		if (es->format == EXPLAIN_FORMAT_TEXT)
 		{
 			if (es->timing)
-				appendStringInfo(es->str,
+				/* Node in progress */
+				if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime))
+					appendStringInfo(es->str,
+								 " (actual time=%.3f..%.3f rows=%.0f loops=%.0f) (in progress)",
+								 startup_ms, total_ms, rows, nloops);
+				else
+					appendStringInfo(es->str,
 								 " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
 								 startup_ms, total_ms, rows, nloops);
 			else
-				appendStringInfo(es->str,
-								 " (actual rows=%.0f loops=%.0f)",
-								 rows, nloops);
+				/* Node in progress */
+				if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime))
+					appendStringInfo(es->str,
+									 " (actual rows=%.0f loops=%.0f) (in progress)",
+									 rows, nloops);
+				else
+					appendStringInfo(es->str,
+									 " (actual rows=%.0f loops=%.0f)",
+									 rows, nloops);
 		}
 		else
 		{
@@ -1848,7 +1884,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 										   planstate, es);
 			if (es->analyze)
 				ExplainPropertyFloat("Heap Fetches", NULL,
-									 planstate->instrument->ntuples2, 0, es);
+									 local_instr->ntuples2, 0, es);
 			break;
 		case T_BitmapIndexScan:
 			show_scan_qual(((BitmapIndexScan *) plan)->indexqualorig,
@@ -2143,10 +2179,10 @@ ExplainNode(PlanState *planstate, List *ancestors,
 	}
 
 	/* Show buffer/WAL usage */
-	if (es->buffers && planstate->instrument)
-		show_buffer_usage(es, &planstate->instrument->bufusage, false);
-	if (es->wal && planstate->instrument)
-		show_wal_usage(es, &planstate->instrument->walusage);
+	if (es->buffers && local_instr)
+		show_buffer_usage(es, &local_instr->bufusage, false);
+	if (es->wal && local_instr)
+		show_wal_usage(es, &local_instr->walusage);
 
 	/* Prepare per-worker buffer/WAL usage */
 	if (es->workers_state && (es->buffers || es->wal) && es->verbose)
@@ -4127,11 +4163,22 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors,
 			double		total;
 			double		insert_path;
 			double		other_path;
-
-			InstrEndLoop(outerPlanState(mtstate)->instrument);
+			Instrumentation *local_instr;
+
+			/* Signaled explain, clone instrumentation */
+			if (es->signaled) {
+				local_instr = palloc(sizeof(*local_instr));
+				*local_instr = *outerPlanState(mtstate)->instrument;
+				/* Force end loop even if node is in progress */
+				InstrEndLoopForce(local_instr);
+			}
+			else {
+				local_instr = outerPlanState(mtstate)->instrument;
+				InstrEndLoop(local_instr);
+			}
 
 			/* count the number of source rows */
-			total = outerPlanState(mtstate)->instrument->ntuples;
+			total = local_instr->ntuples;
 			other_path = mtstate->ps.instrument->ntuples2;
 			insert_path = total - other_path;
 
@@ -4143,7 +4190,7 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors,
 	}
 	else if (node->operation == CMD_MERGE)
 	{
-		/* EXPLAIN ANALYZE display of tuples processed */
+		/* Signaled explain, clone instrumentation */
 		if (es->analyze && mtstate->ps.instrument)
 		{
 			double		total;
@@ -4151,11 +4198,22 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors,
 			double		update_path;
 			double		delete_path;
 			double		skipped_path;
-
-			InstrEndLoop(outerPlanState(mtstate)->instrument);
+			Instrumentation *local_instr;
+
+			/* In flight explain. Clone instrumentation */
+			if (es->signaled) {
+				local_instr = palloc(sizeof(*local_instr));
+				*local_instr = *outerPlanState(mtstate)->instrument;
+				/* Force end loop even if node is in progress */
+				InstrEndLoopForce(local_instr);
+			}
+			else {
+				local_instr = outerPlanState(mtstate)->instrument;
+				InstrEndLoop(local_instr);
+			}
 
 			/* count the number of source rows */
-			total = outerPlanState(mtstate)->instrument->ntuples;
+			total = local_instr->ntuples;
 			insert_path = mtstate->mt_merge_inserted;
 			update_path = mtstate->mt_merge_updated;
 			delete_path = mtstate->mt_merge_deleted;
@@ -5228,6 +5286,18 @@ ProcessLogQueryPlanInterrupt(void)
 	es->verbose = true;
 	es->signaled = true;
 
+	/*
+	 * Adjust instrumentation related settings based
+	 * on QueryDesc object.
+	 */
+	es->analyze = ActiveQueryDesc->instrument_options;
+	es->buffers = (ActiveQueryDesc->instrument_options &
+		INSTRUMENT_BUFFERS) != 0;
+	es->wal = (ActiveQueryDesc->instrument_options &
+		INSTRUMENT_WAL) != 0;
+	es->timing = (ActiveQueryDesc->instrument_options &
+		INSTRUMENT_TIMER) != 0;
+
 	ExplainAssembleLogOutput(es, ActiveQueryDesc, EXPLAIN_FORMAT_TEXT, 0, -1);
 
 	ereport(LOG_SERVER_ONLY,
@@ -5272,10 +5342,11 @@ pg_log_query_plan(PG_FUNCTION_ARGS)
 	}
 
 	be_status = pgstat_get_beentry_by_backend_id(proc->backendId);
-	if (be_status->st_backendType != B_BACKEND)
+	if (be_status->st_backendType != B_BACKEND &&
+		be_status->st_backendType != B_BG_WORKER)
 	{
 		ereport(WARNING,
-				(errmsg("PID %d is not a PostgreSQL client backend process", pid)));
+				(errmsg("PID %d is not a PostgreSQL client backend or background worker process", pid)));
 		PG_RETURN_BOOL(false);
 	}
 
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index c383f34c06..7000e4d8bc 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -25,6 +25,8 @@ static WalUsage save_pgWalUsage;
 static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add);
 static void WalUsageAdd(WalUsage *dst, WalUsage *add);
 
+static void InstrEndLoopInternal(Instrumentation *instr, bool force);
+
 
 /* Allocate new instrumentation structure(s) */
 Instrumentation *
@@ -137,7 +139,7 @@ InstrUpdateTupleCount(Instrumentation *instr, double nTuples)
 
 /* Finish a run cycle for a plan node */
 void
-InstrEndLoop(Instrumentation *instr)
+InstrEndLoopInternal(Instrumentation *instr, bool force)
 {
 	double		totaltime;
 
@@ -145,7 +147,7 @@ InstrEndLoop(Instrumentation *instr)
 	if (!instr->running)
 		return;
 
-	if (!INSTR_TIME_IS_ZERO(instr->starttime))
+	if (!INSTR_TIME_IS_ZERO(instr->starttime) && !force)
 		elog(ERROR, "InstrEndLoop called on running node");
 
 	/* Accumulate per-cycle statistics into totals */
@@ -164,6 +166,20 @@ InstrEndLoop(Instrumentation *instr)
 	instr->tuplecount = 0;
 }
 
+/* Safely finish a run cycle for a plan node */
+void
+InstrEndLoop(Instrumentation *instr)
+{
+	InstrEndLoopInternal(instr, false);
+}
+
+/* Forcibly finish a run cycle for a plan node */
+void
+InstrEndLoopForce(Instrumentation *instr)
+{
+	InstrEndLoopInternal(instr, true);
+}
+
 /* aggregate instrumentation information */
 void
 InstrAggNode(Instrumentation *dst, Instrumentation *add)
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index d5d69941c5..b7c98dfd78 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -108,6 +108,7 @@ extern void InstrStartNode(Instrumentation *instr);
 extern void InstrStopNode(Instrumentation *instr, double nTuples);
 extern void InstrUpdateTupleCount(Instrumentation *instr, double nTuples);
 extern void InstrEndLoop(Instrumentation *instr);
+extern void InstrEndLoopForce(Instrumentation *instr);
 extern void InstrAggNode(Instrumentation *dst, Instrumentation *add);
 extern void InstrStartParallelQuery(void);
 extern void InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage);
-- 
2.32.0 (Apple Git-132)