Log the plan of the currently running query (v54)

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);
+}