Add function to log the plan of the currently running

Currently, we have to wait for the query execution to finish
to know its plan either using EXPLAIN ANALYZE or auto_explain.
This is not so convenient, for example when investigating
long-running queries on production environments.
To improve this situation, this patch adds pg_log_query_plan()
function that requests to log the plan of the currently
executing query.

On receipt of the request, ExecProcNodes of the current plan
node and its subsidiary nodes are wrapped with
ExecProcNodeFirst, which implelements logging query plan.
When executor executes the one of the wrapped nodes, the
query plan is logged.

Our initial idea was to send a signal to the target backend
process, which invokes EXPLAIN logic at the next
CHECK_FOR_INTERRUPTS() call. However, we realized during
prototyping that EXPLAIN is complex and may not be safely
executed at arbitrary interrupt points.

By default, only superusers are allowed to request to log the
plans because allowing any users to issue this request at an
unbounded rate would cause lots of log messages and which can
lead to denial of service.

Todo: Consider removing the PID from the log output of
pg_log_backend_memory_contexts() and pg_log_query_plan().
For detail, see the discussion:
https://www.postgresql.org/message-id/CA%2BTgmoY81r7npTS34N_5MLA_u6ghfor5HoSaar53veXUYu1OxQ%40mail.gmail.com

Author: atorik

contrib/auto_explain/auto_explain.c

@@ -16,6 +16,7 @@
 
 #include "access/parallel.h"
 #include "commands/defrem.h"
+#include "commands/dynamic_explain.h"
 #include "commands/explain.h"
 #include "commands/explain_format.h"
 #include "commands/explain_state.h"
@@ -451,32 +452,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
 
 			apply_extension_options(es, extension_options);
 
-			ExplainBeginOutput(es);
-			ExplainQueryText(es, queryDesc);
-			ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
-			ExplainPrintPlan(es, queryDesc);
-			if (es->analyze && auto_explain_log_triggers)
-				ExplainPrintTriggers(es, queryDesc);
-			if (es->costs)
-				ExplainPrintJITSummary(es, queryDesc);
-			if (explain_per_plan_hook)
-				(*explain_per_plan_hook) (queryDesc->plannedstmt,
-										  NULL, es,
-										  queryDesc->sourceText,
-										  queryDesc->params,
-										  queryDesc->estate->es_queryEnv);
-			ExplainEndOutput(es);
-
-			/* Remove last line break */
-			if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
-				es->str->data[--es->str->len] = '\0';
-
-			/* Fix JSON to output an object */
-			if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
-			{
-				es->str->data[0] = '{';
-				es->str->data[es->str->len - 1] = '}';
-			}
+			ExplainStringAssemble(es, queryDesc, auto_explain_log_format,
+								  auto_explain_log_triggers,
+								  auto_explain_log_parameter_max_length);
 
 			/*
 			 * Note: we rely on the existing logging of context or

doc/src/sgml/func/func-admin.sgml

@@ -184,6 +184,30 @@
        </para></entry>
       </row>
 
+      <row>
+       <entry role="func_table_entry"><para role="func_signature">
+        <indexterm>
+         <primary>pg_log_query_plan</primary>
+        </indexterm>
+        <function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+        <returnvalue>boolean</returnvalue>
+       </para>
+       <para>
+        Requests to log the plan of the query currently running on the
+        backend with specified process ID.
+        It will be logged at <literal>LOG</literal> message level and
+        will appear in the server log based on the log
+        configuration set (See <xref linkend="runtime-config-logging"/>
+        for more information), but will not be sent to the client
+        regardless of <xref linkend="guc-client-min-messages"/>.
+       </para>
+       <para>
+        This function is restricted to superusers by default, but other
+        users can be granted EXECUTE to run the function.
+       </para></entry>
+      </row>
+
+
       <row>
        <entry role="func_table_entry"><para role="func_signature">
         <indexterm>

src/backend/access/transam/xact.c

@@ -37,6 +37,7 @@
 #include "catalog/pg_enum.h"
 #include "catalog/storage.h"
 #include "commands/async.h"
+#include "commands/dynamic_explain.h"
 #include "commands/tablecmds.h"
 #include "commands/trigger.h"
 #include "common/pg_prng.h"
@@ -217,6 +218,7 @@ typedef struct TransactionStateData
 	bool		parallelChildXact;	/* is any parent transaction parallel? */
 	bool		chain;			/* start a new block after this one */
 	bool		topXidLogged;	/* for a subxact: is top-level XID logged? */
+	QueryDesc  *queryDesc;		/* my current QueryDesc */
 	struct TransactionStateData *parent;	/* back link to parent */
 } TransactionStateData;
 
@@ -250,6 +252,7 @@ static TransactionStateData TopTransactionStateData = {
 	.state = TRANS_DEFAULT,
 	.blockState = TBLOCK_DEFAULT,
 	.topXidLogged = false,
+	.queryDesc = NULL,
 };
 
 /*
@@ -935,6 +938,27 @@ GetCurrentTransactionNestLevel(void)
 	return s->nestingLevel;
 }
 
+/*
+ * SetCurrentQueryDesc
+ */
+void
+SetCurrentQueryDesc(QueryDesc *queryDesc)
+{
+	TransactionState s = CurrentTransactionState;
+
+	s->queryDesc = queryDesc;
+}
+
+/*
+ * GetCurrentQueryDesc
+ */
+QueryDesc *
+GetCurrentQueryDesc(void)
+{
+	TransactionState s = CurrentTransactionState;
+
+	return s->queryDesc;
+}
 
 /*
  *	TransactionIdIsCurrentTransactionId
@@ -2953,6 +2977,9 @@ AbortTransaction(void)
 	/* Reset snapshot export state. */
 	SnapBuildResetExportedSnapshotState();
 
+	/* Reset current query plan state used for logging. */
+	SetCurrentQueryDesc(NULL);
+
 	/*
 	 * If this xact has started any unfinished parallel operation, clean up
 	 * its workers and exit parallel mode.  Don't warn about leaked resources.
@@ -5352,6 +5379,13 @@ AbortSubTransaction(void)
 	/* Reset logical streaming state. */
 	ResetLogicalStreamingState();
 
+	/*
+	 * Reset current query plan state used for logging. Note that even after
+	 * this reset, it's still possible to obtain the parent transaction's
+	 * query plans, since they are preserved in standard_ExecutorRun().
+	 */
+	SetCurrentQueryDesc(NULL);
+
 	/*
 	 * No need for SnapBuildResetExportedSnapshotState() here, snapshot
 	 * exports are not supported in subtransactions.

src/backend/commands/Makefile

@@ -31,6 +31,7 @@ OBJS = \
 	define.o \
 	discard.o \
 	dropcmds.o \
+	dynamic_explain.o \
 	event_trigger.o \
 	explain.o \
 	explain_dr.o \

src/backend/commands/dynamic_explain.c

@@ -0,0 +1,188 @@
+/*-------------------------------------------------------------------------
+ *
+ * dynamic_explain.c
+ *	  Explain query plans during execution
+ *
+ * Portions Copyright (c) 1996-2025, PostgreSQL Global Development Group
+ * Portions Copyright (c) 1994-5, Regents of the University of California
+ *
+ * IDENTIFICATION
+ *	  src/backend/commands/dynamic_explain.c
+ *
+ *-------------------------------------------------------------------------
+ */
+#include "postgres.h"
+
+#include "access/xact.h"
+#include "commands/dynamic_explain.h"
+#include "commands/explain.h"
+#include "commands/explain_format.h"
+#include "commands/explain_state.h"
+#include "miscadmin.h"
+#include "storage/proc.h"
+#include "storage/procarray.h"
+#include "storage/procsignal.h"
+#include "utils/backend_status.h"
+#include "utils/injection_point.h"
+
+/* Is plan node wrapping for query plan logging currently in progress? */
+static bool WrapNodesInProgress = false;
+
+/*
+ * Handle receipt of an interrupt indicating logging the plan of the currently
+ * running query.
+ *
+ * All the actual work is deferred to ProcessLogQueryPlanInterrupt(),
+ * because we cannot safely emit a log message inside the signal handler.
+ */
+void
+HandleLogQueryPlanInterrupt(void)
+{
+#ifdef USE_INJECTION_POINTS
+	INJECTION_POINT("log-query-interrupt", NULL);
+#endif
+	InterruptPending = true;
+	LogQueryPlanPending = true;
+	/* latch will be set by procsignal_sigusr1_handler */
+}
+
+/*
+ * Actual plan logging function.
+ */
+void
+LogQueryPlan(void)
+{
+	ExplainState *es;
+	MemoryContext cxt;
+	MemoryContext old_cxt;
+	QueryDesc  *queryDesc;
+
+	cxt = AllocSetContextCreate(CurrentMemoryContext,
+								"log_query_plan temporary context",
+								ALLOCSET_DEFAULT_SIZES);
+
+	old_cxt = MemoryContextSwitchTo(cxt);
+
+	es = NewExplainState();
+
+	es->format = EXPLAIN_FORMAT_TEXT;
+	es->settings = true;
+	es->verbose = true;
+	es->signaled = true;
+
+	/*
+	 * Current QueryDesc is valid only during standard_ExecutorRun. However,
+	 * ExecProcNode can be called afterward(i.e., ExecPostprocessPlan). To
+	 * handle the case, check whether we have QueryDesc now.
+	 */
+	queryDesc = GetCurrentQueryDesc();
+
+	if (queryDesc == NULL)
+	{
+		LogQueryPlanPending = false;
+		return;
+	}
+
+	ExplainStringAssemble(es, queryDesc, es->format, 0, -1);
+
+	ereport(LOG_SERVER_ONLY,
+			errmsg("query and its plan running on backend with PID %d are:\n%s",
+				   MyProcPid, es->str->data));
+
+	MemoryContextSwitchTo(old_cxt);
+	MemoryContextDelete(cxt);
+
+	LogQueryPlanPending = false;
+}
+
+/*
+ * Process the request for logging query plan at CHECK_FOR_INTERRUPTS().
+ *
+ * Since executing EXPLAIN-related code at an arbitrary CHECK_FOR_INTERRUPTS()
+ * point is potentially unsafe, this function just wraps the nodes of
+ * ExecProcNode with ExecProcNodeFirst, which logs query plan if requested.
+ * This way ensures that EXPLAIN-related code is executed only during
+ * ExecProcNodeFirst, where it is considered safe.
+ */
+void
+ProcessLogQueryPlanInterrupt(void)
+{
+	QueryDesc *querydesc = GetCurrentQueryDesc();
+
+	/* If current query has already finished, we can do nothing but exit */
+	if (querydesc == NULL)
+	{
+		LogQueryPlanPending = false;
+		return;
+	}
+
+	/*
+	 * Exit immediately if wrapping plan is already in progress. This prevents
+	 * recursive calls, which could occur if logging is requested repeatedly and
+	 * rapidly, potentially leading to infinite recursion and crash.
+	 */
+	if (WrapNodesInProgress)
+		return;
+
+	WrapNodesInProgress = true;
+
+	PG_TRY();
+	{
+		/*
+		 * Wrap ExecProcNodes with ExecProcNodeFirst, which logs query plan
+		 * when LogQueryPlanPending is true.
+		 */
+		ExecSetExecProcNodeRecurse(querydesc->planstate);
+	}
+	PG_FINALLY();
+	{
+		WrapNodesInProgress = false;
+	}
+	PG_END_TRY();
+}
+
+/*
+ * Signal a backend process to log the query plan of the running query.
+ *
+ * By default, only superusers are allowed to signal to log the plan because
+ * allowing any users to issue this request at an unbounded rate would
+ * cause lots of log messages and which can lead to denial of service.
+ * Additional roles can be permitted with GRANT.
+ */
+Datum
+pg_log_query_plan(PG_FUNCTION_ARGS)
+{
+	int			pid = PG_GETARG_INT32(0);
+	PGPROC	   *proc;
+	PgBackendStatus *be_status;
+
+	proc = BackendPidGetProc(pid);
+
+	if (proc == NULL)
+	{
+		/*
+		 * This is just a warning so a loop-through-resultset will not abort
+		 * if one backend terminated on its own during the run.
+		 */
+		ereport(WARNING,
+				(errmsg("PID %d is not a PostgreSQL backend process", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	be_status = pgstat_get_beentry_by_proc_number(proc->vxid.procNumber);
+	if (be_status->st_backendType != B_BACKEND)
+	{
+		ereport(WARNING,
+				(errmsg("PID %d is not a PostgreSQL client backend process", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->vxid.procNumber) < 0)
+	{
+		ereport(WARNING,
+				(errmsg("could not send signal to process %d: %m", pid)));
+		PG_RETURN_BOOL(false);
+	}
+
+	PG_RETURN_BOOL(true);
+}