On 2025-05-23 17:50, Atsushi Torikoshi wrote:
Thanks for the idea and the sample patch!
Agreed. I’ll go ahead and implement a new patch based on this approach.
Updated the patch.
Here are some notes:
As with the previous patches, this one wraps not only the currently
executing plan node but also recursively wraps the left, right, and
child nodes' ExecProcNode with ExecProcNodeFirst.
This is because modifying only the currently executing node caused
significant delays in plan logging when the left, right, or child nodes
took a long time to execute.
I observed the situation with the following query:
SELECT count(*) FROM pgbench_accounts a CROSS JOIN pgbench_accounts b;
Previous patches implemented unwrappers, but this one doesn’t.
This is because once the log is output,
GetProcessLogQueryPlanInterruptActive() returns false, so LogQueryPlan()
will no longer be called.
In the sample you previously provided, the LogQueryPlan function takes a
PlanState as an argument, but in this patch, it’s defined as void.
I made this change under the assumption that the plan can be obtained
from ActiveQueryDesc, and that PlanState is therefore unnecessary.
Please let me know if I’ve misunderstood anything.
Regards,
--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.
From 3483da9204475fb9dc7bdd67d5db32510bd32ab4 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <torikos...@oss.nttdata.com>
Date: Mon, 2 Jun 2025 21:10:06 +0900
Subject: [PATCH v45] Add function to log the plan of the currently running
query
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.
Upon receiving a request to log the query plan, the ExecProcNode
functions of the current plan node, as well as its left, right,
and other child nodes, are wrapped with ExecProcNodeFirst, which
implements the logging mechanism. When the executor invokes any
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.
Squashed commit of the following:
---
contrib/auto_explain/auto_explain.c | 24 +--
doc/src/sgml/func.sgml | 57 ++++++
src/backend/access/transam/xact.c | 13 ++
src/backend/catalog/system_functions.sql | 2 +
src/backend/commands/Makefile | 1 +
src/backend/commands/dynamic_explain.c | 195 +++++++++++++++++++
src/backend/commands/explain.c | 38 +++-
src/backend/commands/meson.build | 1 +
src/backend/executor/execMain.c | 17 ++
src/backend/executor/execProcnode.c | 120 +++++++++++-
src/backend/storage/ipc/procsignal.c | 4 +
src/backend/tcop/postgres.c | 4 +
src/backend/utils/init/globals.c | 2 +
src/include/catalog/pg_proc.dat | 6 +
src/include/commands/dynamic_explain.h | 29 +++
src/include/commands/explain.h | 5 +
src/include/commands/explain_state.h | 1 +
src/include/executor/executor.h | 1 +
src/include/miscadmin.h | 2 +-
src/include/storage/procsignal.h | 2 +
src/include/tcop/pquery.h | 1 -
src/test/regress/expected/misc_functions.out | 57 +++++-
src/test/regress/sql/misc_functions.sql | 45 ++++-
23 files changed, 573 insertions(+), 54 deletions(-)
create mode 100644 src/backend/commands/dynamic_explain.c
create mode 100644 src/include/commands/dynamic_explain.h
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 1f4badb492..6c4217c9d1 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -15,6 +15,7 @@
#include <limits.h>
#include "access/parallel.h"
+#include "commands/dynamic_explain.h"
#include "commands/explain.h"
#include "commands/explain_format.h"
#include "commands/explain_state.h"
@@ -404,26 +405,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
es->format = auto_explain_log_format;
es->settings = auto_explain_log_settings;
- 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);
- 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
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index c67688cbf5..75a48a5744 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -28684,6 +28684,29 @@ acl | {postgres=arwdDxtm/postgres,foo=r/postgres}
</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>
@@ -28802,6 +28825,40 @@ LOG: Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
because it may generate a large number of log messages.
</para>
+ <para>
+ <function>pg_log_query_plan</function> can be used
+ to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_query_plan(201116);
+ pg_log_query_plan
+---------------------------
+ t
+(1 row)
+</programlisting>
+The format of the query plan is the same as when <literal>VERBOSE</literal>,
+<literal>COSTS</literal>, <literal>SETTINGS</literal> and
+<literal>FORMAT TEXT</literal> are used in the <command>EXPLAIN</command>
+command. For example:
+<screen>
+LOG: query plan running on backend with PID 201116 is:
+ Query Text: SELECT * FROM pgbench_accounts;
+ Seq Scan on public.pgbench_accounts (cost=0.00..52787.00 rows=2000000 width=97)
+ Output: aid, bid, abalance, filler
+ Settings: work_mem = '1MB'
+ Query Identifier: 8621255546560739680
+</screen>
+ When the target is executing nested statements(statements executed
+ inside a function), only the innermost query plan is logged.
+ Logging plan may take some time, as it occurs when the plan node is
+ executed. For example, when a query is running <function>pg_sleep</function>,
+ the plan will not be logged until the function execution completes.
+ Similarly, when a query is running under the extended query
+ protocol, the plan is logged only during the execute step.
+ <function>pg_log_query_plan()</function> may return <literal>true</literal>
+ even if no plan is actually logged, when the query is already about to
+ finish and the plan logging request comes too late.
+ </para>
+
</sect2>
<sect2 id="functions-admin-backup">
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 2e67e998ad..5df4dd0253 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -36,6 +36,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"
@@ -2932,6 +2933,12 @@ AbortTransaction(void)
/* Reset snapshot export state. */
SnapBuildResetExportedSnapshotState();
+ /*
+ * After abort, some elements of ActiveQueryDesc are freed. To avoid
+ * accessing them, reset ActiveQueryDesc here.
+ */
+ ResetLogQueryPlanState();
+
/*
* If this xact has started any unfinished parallel operation, clean up
* its workers and exit parallel mode. Don't warn about leaked resources.
@@ -5324,6 +5331,12 @@ AbortSubTransaction(void)
/* Reset logical streaming state. */
ResetLogicalStreamingState();
+ /*
+ * After abort, some elements of ActiveQueryDesc are freed. To avoid
+ * accessing them, reset ActiveQueryDesc here.
+ */
+ ResetLogQueryPlanState();
+
/*
* No need for SnapBuildResetExportedSnapshotState() here, snapshot
* exports are not supported in subtransactions.
diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql
index 566f308e44..ec2e1c1fd9 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -775,6 +775,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;
REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
+
--
-- We also set up some things as accessible to standard roles.
--
diff --git a/src/backend/commands/Makefile b/src/backend/commands/Makefile
index cb2fbdc7c6..5e83907eb1 100644
--- a/src/backend/commands/Makefile
+++ b/src/backend/commands/Makefile
@@ -32,6 +32,7 @@ OBJS = \
define.o \
discard.o \
dropcmds.o \
+ dynamic_explain.o \
event_trigger.o \
explain.o \
explain_dr.o \
diff --git a/src/backend/commands/dynamic_explain.c b/src/backend/commands/dynamic_explain.c
new file mode 100644
index 0000000000..cfc13ce029
--- /dev/null
+++ b/src/backend/commands/dynamic_explain.c
@@ -0,0 +1,195 @@
+/*-------------------------------------------------------------------------
+ *
+ * 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 "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 "utils/backend_status.h"
+
+/* Currently executing query's QueryDesc */
+static QueryDesc *ActiveQueryDesc = NULL;
+
+/*
+ * 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)
+{
+ InterruptPending = true;
+ LogQueryPlanPending = true;
+ /* latch will be set by procsignal_sigusr1_handler */
+}
+
+/*
+ * Clear pg_log_query_plan() related state during (sub)transaction abort.
+ */
+void
+ResetLogQueryPlanState(void)
+{
+ ActiveQueryDesc = NULL;
+ LogQueryPlanPending = false;
+}
+
+/*
+ * Actual plan logging function.
+ */
+void
+LogQueryPlan(void)
+{
+ ExplainState *es;
+ MemoryContext cxt;
+ MemoryContext old_cxt;
+
+ 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;
+
+ /*
+ * ActiveQueryDesc is valid only during standard_ExecutorRun. However,
+ * ExecProcNode can be called afterward(i.e., ExecPostprocessPlan). To
+ * handle the case, check ActiveQueryDesc.
+ */
+ if (ActiveQueryDesc == NULL)
+ {
+ LogQueryPlanPending = false;
+
+ ereport(LOG_SERVER_ONLY,
+ errmsg("backend with PID %d is finishing query execution and cannot log the plan.",
+ MyProcPid),
+ errhidestmt(true),
+ errhidecontext(true));
+ }
+
+ ExplainStringAssemble(es, ActiveQueryDesc, es->format, 0, -1);
+
+ ereport(LOG_SERVER_ONLY,
+ errmsg("query plan running on backend with PID %d is:\n%s",
+ MyProcPid, es->str->data),
+ errhidestmt(true),
+ errhidecontext(true));
+
+ 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 corrent query plan if
+ * requested. This way ensures that EXPLAIN code is executed only during
+ * ExecProcNodeFirst, where it is considered safe.
+ */
+void
+ProcessLogQueryPlanInterrupt(void)
+{
+ if (ActiveQueryDesc == NULL)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("backend with PID %d is not running a query or a subtransaction is aborted",
+ MyProcPid),
+ errhidestmt(true),
+ errhidecontext(true));
+
+ LogQueryPlanPending = false;
+ return;
+ }
+
+ /* Wrap ExecProcNodes */
+ ExecSetExecProcNodeRecurse(ActiveQueryDesc->planstate);
+}
+
+/*
+ * Returns ActiveQueryDesc.
+ */
+QueryDesc *
+GetActiveQueryDesc(void)
+{
+ return ActiveQueryDesc;
+}
+
+/*
+ Set ActiveQueryDesc to queryDesc.
+ */
+void
+SetActiveQueryDesc(QueryDesc *queryDesc)
+{
+ ActiveQueryDesc = queryDesc;
+}
+
+/*
+ * 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);
+}
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 7e2792ead7..a68958c1ad 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1084,6 +1084,37 @@ ExplainQueryParameters(ExplainState *es, ParamListInfo params, int maxlen)
ExplainPropertyText("Query Parameters", str, es);
}
+/*
+ * ExplainStringAssemble -
+ * Assemble es->str for logging according to specified options and format
+ */
+
+void
+ExplainStringAssemble(ExplainState *es, QueryDesc *queryDesc, int logFormat,
+ bool logTriggers, int logParameterMaxLength)
+{
+ ExplainBeginOutput(es);
+ ExplainQueryText(es, queryDesc);
+ ExplainQueryParameters(es, queryDesc->params, logParameterMaxLength);
+ ExplainPrintPlan(es, queryDesc);
+ if (es->analyze && logTriggers)
+ ExplainPrintTriggers(es, queryDesc);
+ if (es->costs)
+ ExplainPrintJITSummary(es, queryDesc);
+ 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 (logFormat == EXPLAIN_FORMAT_JSON)
+ {
+ es->str->data[0] = '{';
+ es->str->data[es->str->len - 1] = '}';
+ }
+}
+
/*
* report_triggers -
* report execution stats for a single relation's triggers
@@ -1815,7 +1846,10 @@ 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 ...
+ * 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 requested 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
@@ -1823,7 +1857,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
* InstrEndLoop call anyway, if possible, to reduce the number of cases
* auto_explain has to contend with.
*/
- if (planstate->instrument)
+ if (planstate->instrument && !es->signaled)
InstrEndLoop(planstate->instrument);
if (es->analyze &&
diff --git a/src/backend/commands/meson.build b/src/backend/commands/meson.build
index dd4cde41d3..4a64b8e9d0 100644
--- a/src/backend/commands/meson.build
+++ b/src/backend/commands/meson.build
@@ -20,6 +20,7 @@ backend_sources += files(
'define.c',
'discard.c',
'dropcmds.c',
+ 'dynamic_explain.c',
'event_trigger.c',
'explain.c',
'explain_dr.c',
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 0391798dd2..99727e5571 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -43,6 +43,7 @@
#include "access/xact.h"
#include "catalog/namespace.h"
#include "catalog/partition.h"
+#include "commands/dynamic_explain.h"
#include "commands/matview.h"
#include "commands/trigger.h"
#include "executor/executor.h"
@@ -313,6 +314,7 @@ standard_ExecutorRun(QueryDesc *queryDesc,
DestReceiver *dest;
bool sendTuples;
MemoryContext oldcontext;
+ QueryDesc *oldActiveQueryDesc;
/* sanity checks */
Assert(queryDesc != NULL);
@@ -325,6 +327,13 @@ standard_ExecutorRun(QueryDesc *queryDesc,
/* caller must ensure the query's snapshot is active */
Assert(GetActiveSnapshot() == estate->es_snapshot);
+ /*
+ * Save ActiveQueryDesc here to enable retrieval of the currently running
+ * queryDesc for nested queries.
+ */
+ oldActiveQueryDesc = GetActiveQueryDesc();
+ SetActiveQueryDesc(queryDesc);
+
/*
* Switch into per-query memory context
*/
@@ -387,6 +396,14 @@ standard_ExecutorRun(QueryDesc *queryDesc,
InstrStopNode(queryDesc->totaltime, estate->es_processed);
MemoryContextSwitchTo(oldcontext);
+ SetActiveQueryDesc(oldActiveQueryDesc);
+
+ /*
+ * Ensure LogQueryPlanPending is initialized in case there was no time for
+ * logging the plan. Othewise plan will be logged at the next query
+ * execution on the same session.
+ */
+ LogQueryPlanPending = false;
}
/* ----------------------------------------------------------------
diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c
index f5f9cfbeea..e7749d15af 100644
--- a/src/backend/executor/execProcnode.c
+++ b/src/backend/executor/execProcnode.c
@@ -72,6 +72,7 @@
*/
#include "postgres.h"
+#include "commands/dynamic_explain.h"
#include "executor/executor.h"
#include "executor/nodeAgg.h"
#include "executor/nodeAppend.h"
@@ -431,9 +432,10 @@ ExecSetExecProcNode(PlanState *node, ExecProcNodeMtd function)
{
/*
* Add a wrapper around the ExecProcNode callback that checks stack depth
- * during the first execution and maybe adds an instrumentation wrapper.
- * When the callback is changed after execution has already begun that
- * means we'll superfluously execute ExecProcNodeFirst, but that seems ok.
+ * and query logging request during the execution and maybe adds an
+ * instrumentation wrapper. When the callback is changed after execution
+ * has already begun that means we'll superfluously execute
+ * ExecProcNodeFirst, but that seems ok.
*/
node->ExecProcNodeReal = function;
node->ExecProcNode = ExecProcNodeFirst;
@@ -441,27 +443,43 @@ ExecSetExecProcNode(PlanState *node, ExecProcNodeMtd function)
/*
- * ExecProcNode wrapper that performs some one-time checks, before calling
+ * ExecProcNode wrapper that performs some extra checks, before calling
* the relevant node method (possibly via an instrumentation wrapper).
+ *
+ * Normally, this is just invoked once for the first call to any given node,
+ * and thereafter we arrange to call ExecProcNodeInstr or the relevant node
+ * method directly. However, it's legal to reset node->ExecProcNode back to
+ * this function at any time, and we do that whenever the query plan might
+ * need to be printed, so that we only incur the cost of checking for that
+ * case when required.
*/
static TupleTableSlot *
ExecProcNodeFirst(PlanState *node)
{
/*
- * Perform stack depth check during the first execution of the node. We
- * only do so the first time round because it turns out to not be cheap on
- * some common architectures (eg. x86). This relies on the assumption
- * that ExecProcNode calls for a given plan node will always be made at
- * roughly the same stack depth.
+ * Perform a stack depth check. We don't want to do this all the time
+ * because it turns out to not be cheap on some common architectures (eg.
+ * x86). This relies on the assumption that ExecProcNode calls for a
+ * given plan node will always be made at roughly the same stack depth.
*/
check_stack_depth();
+ /*
+ * If we have been asked to print the query plan, do that now. We dare not
+ * try to do this directly from CHECK_FOR_INTERRUPTS() because we don't
+ * really know what the executor state is at that point, but we assume
+ * that when entering a node the state will be sufficiently consistent
+ * that trying to print the plan makes sense.
+ */
+ if (LogQueryPlanPending)
+ LogQueryPlan();
+
/*
* If instrumentation is required, change the wrapper to one that just
* does instrumentation. Otherwise we can dispense with all wrappers and
* have ExecProcNode() directly call the relevant function from now on.
*/
- if (node->instrument)
+ else if (node->instrument)
node->ExecProcNode = ExecProcNodeInstr;
else
node->ExecProcNode = node->ExecProcNodeReal;
@@ -546,6 +564,88 @@ MultiExecProcNode(PlanState *node)
return result;
}
+/*
+ * Wrap array of PlanState ExecProcNode with ExecProcNodeFirst.
+ */
+static void
+ExecSetExecProcNodeArray(PlanState **planstates, int nplans)
+{
+ int i;
+
+ for (i = 0; i < nplans; i++)
+ ExecSetExecProcNodeRecurse(planstates[i]);
+}
+
+/*
+ * Wrap CustomScanState children's ExecProcNode with ExecProcNodeFirst.
+ */
+static void
+CSSChildExecSetExecProcNodeArray(CustomScanState *css)
+{
+ ListCell *cell;
+
+ foreach(cell, css->custom_ps)
+ ExecSetExecProcNodeRecurse((PlanState *) lfirst(cell));
+}
+
+/*
+ * Recursively wrap all the underlying ExecProcNode with ExecProcNodeFirst.
+ *
+ * Recursion is usually necessary because the next ExecProcNode() call may be
+ * invoked not only through the current node, but also via lefttree, righttree,
+ * subPlan, or other special child plans.
+ */
+void
+ExecSetExecProcNodeRecurse(PlanState *ps)
+{
+ ExecSetExecProcNode(ps, ps->ExecProcNodeReal);
+
+ if (ps->lefttree != NULL)
+ ExecSetExecProcNodeRecurse(ps->lefttree);
+ if (ps->righttree != NULL)
+ ExecSetExecProcNodeRecurse(ps->righttree);
+ if (ps->subPlan != NULL)
+ {
+ ListCell *l;
+
+ foreach(l, ps->subPlan)
+ {
+ SubPlanState *sstate = (SubPlanState *) lfirst(l);
+
+ ExecSetExecProcNodeRecurse(sstate->planstate);
+ }
+ }
+
+ /* special child plans */
+ switch (nodeTag(ps->plan))
+ {
+ case T_Append:
+ ExecSetExecProcNodeArray(((AppendState *) ps)->appendplans,
+ ((AppendState *) ps)->as_nplans);
+ break;
+ case T_MergeAppend:
+ ExecSetExecProcNodeArray(((MergeAppendState *) ps)->mergeplans,
+ ((MergeAppendState *) ps)->ms_nplans);
+ break;
+ case T_BitmapAnd:
+ ExecSetExecProcNodeArray(((BitmapAndState *) ps)->bitmapplans,
+ ((BitmapAndState *) ps)->nplans);
+ break;
+ case T_BitmapOr:
+ ExecSetExecProcNodeArray(((BitmapOrState *) ps)->bitmapplans,
+ ((BitmapOrState *) ps)->nplans);
+ break;
+ case T_SubqueryScan:
+ ExecSetExecProcNodeRecurse(((SubqueryScanState *) ps)->subplan);
+ break;
+ case T_CustomScan:
+ CSSChildExecSetExecProcNodeArray((CustomScanState *) ps);
+ break;
+ default:
+ break;
+ }
+}
+
/* ----------------------------------------------------------------
* ExecEndNode
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index a9bb540b55..2226ad0216 100644
--- a/src/backend/storage/ipc/procsignal.c
+++ b/src/backend/storage/ipc/procsignal.c
@@ -19,6 +19,7 @@
#include "access/parallel.h"
#include "commands/async.h"
+#include "commands/dynamic_explain.h"
#include "miscadmin.h"
#include "pgstat.h"
#include "port/pg_bitutils.h"
@@ -691,6 +692,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT))
HandleLogMemoryContextInterrupt();
+ if (CheckProcSignal(PROCSIG_LOG_QUERY_PLAN))
+ HandleLogQueryPlanInterrupt();
+
if (CheckProcSignal(PROCSIG_PARALLEL_APPLY_MESSAGE))
HandleParallelApplyMessageInterrupt();
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 2f8c3d5f91..6bdc7ba77a 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -37,6 +37,7 @@
#include "catalog/pg_type.h"
#include "commands/async.h"
#include "commands/event_trigger.h"
+#include "commands/dynamic_explain.h"
#include "commands/prepare.h"
#include "common/pg_prng.h"
#include "jit/jit.h"
@@ -3533,6 +3534,9 @@ ProcessInterrupts(void)
if (LogMemoryContextPending)
ProcessLogMemoryContextInterrupt();
+ if (LogQueryPlanPending)
+ ProcessLogQueryPlanInterrupt();
+
if (ParallelApplyMessagePending)
ProcessParallelApplyMessages();
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index d31cb45a05..927ccda030 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -40,6 +40,8 @@ volatile sig_atomic_t IdleSessionTimeoutPending = false;
volatile sig_atomic_t ProcSignalBarrierPending = false;
volatile sig_atomic_t LogMemoryContextPending = false;
volatile sig_atomic_t IdleStatsUpdateTimeoutPending = false;
+volatile sig_atomic_t LogQueryPlanPending = false;
+
volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index d3d28a263f..e3bf1cb9cd 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8571,6 +8571,12 @@
prorettype => 'bool', proargtypes => 'int4',
prosrc => 'pg_log_backend_memory_contexts' },
+# logging plan of the running query on the specified backend
+{ oid => '8000', descr => 'log plan of the running query on the specified backend',
+ proname => 'pg_log_query_plan',
+ provolatile => 'v', prorettype => 'bool',
+ proargtypes => 'int4', prosrc => 'pg_log_query_plan' },
+
# non-persistent series generator
{ oid => '1066', descr => 'non-persistent series generator',
proname => 'generate_series', prorows => '1000',
diff --git a/src/include/commands/dynamic_explain.h b/src/include/commands/dynamic_explain.h
new file mode 100644
index 0000000000..be387a8cf9
--- /dev/null
+++ b/src/include/commands/dynamic_explain.h
@@ -0,0 +1,29 @@
+/*-------------------------------------------------------------------------
+ *
+ * dynamic_explain.h
+ * prototypes for dynamic_explain.c
+ *
+ * Portions Copyright (c) 1996-2025, PostgreSQL Global Development Group
+ * Portions Copyright (c) 1994-5, Regents of the University of California
+ *
+ * src/include/commands/dynamic_explain.h
+ *
+ *-------------------------------------------------------------------------
+ */
+#ifndef DYNAMIC_EXPLAIN_H
+#define DYNAMIC_EXPLAIN_H
+
+#include "executor/executor.h"
+#include "commands/explain_state.h"
+
+extern void HandleLogQueryPlanInterrupt(void);
+extern void ResetLogQueryPlanState(void);
+extern void ResetProcessLogQueryPlanInterruptActive(void);
+extern void ProcessLogQueryPlanInterrupt(void);
+extern QueryDesc *GetActiveQueryDesc(void);
+extern void SetActiveQueryDesc(QueryDesc *queryDesc);
+extern TupleTableSlot *ExecProcNodeWithExplain(PlanState *ps);
+extern void LogQueryPlan(void);
+extern Datum pg_log_query_plan(PG_FUNCTION_ARGS);
+
+#endif /* DYNAMIC_EXPLAIN_H */
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3b122f79ed..6aa838764e 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -70,6 +70,8 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
const BufferUsage *bufusage,
const MemoryContextCounters *mem_counters);
+extern void ExplainPrintPlan(struct ExplainState *es, QueryDesc *queryDesc);
+extern void ExplainPrintTriggers(struct ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintPlan(struct ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintTriggers(struct ExplainState *es,
QueryDesc *queryDesc);
@@ -80,5 +82,8 @@ extern void ExplainPrintJITSummary(struct ExplainState *es,
extern void ExplainQueryText(struct ExplainState *es, QueryDesc *queryDesc);
extern void ExplainQueryParameters(struct ExplainState *es,
ParamListInfo params, int maxlen);
+extern void ExplainStringAssemble(struct ExplainState *es, QueryDesc *queryDesc,
+ int logFormat, bool logTriggers,
+ int logParameterMaxLength);
#endif /* EXPLAIN_H */
diff --git a/src/include/commands/explain_state.h b/src/include/commands/explain_state.h
index 32728f5d1a..fcef956396 100644
--- a/src/include/commands/explain_state.h
+++ b/src/include/commands/explain_state.h
@@ -71,6 +71,7 @@ typedef struct ExplainState
* entry */
/* state related to the current plan node */
ExplainWorkersState *workers_state; /* needed if parallel plan */
+ bool signaled; /* whether explain is called by signal */
/* extensions */
void **extension_state;
int extension_state_allocated;
diff --git a/src/include/executor/executor.h b/src/include/executor/executor.h
index 104b059544..05a023940a 100644
--- a/src/include/executor/executor.h
+++ b/src/include/executor/executor.h
@@ -292,6 +292,7 @@ extern void EvalPlanQualEnd(EPQState *epqstate);
extern PlanState *ExecInitNode(Plan *node, EState *estate, int eflags);
extern void ExecSetExecProcNode(PlanState *node, ExecProcNodeMtd function);
extern Node *MultiExecProcNode(PlanState *node);
+extern void ExecSetExecProcNodeRecurse(PlanState *ps);
extern void ExecEndNode(PlanState *node);
extern void ExecShutdownNode(PlanState *node);
extern void ExecSetTupleBound(int64 tuples_needed, PlanState *child_node);
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 1bef98471c..b26d7b919c 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -96,7 +96,7 @@ extern PGDLLIMPORT volatile sig_atomic_t IdleSessionTimeoutPending;
extern PGDLLIMPORT volatile sig_atomic_t ProcSignalBarrierPending;
extern PGDLLIMPORT volatile sig_atomic_t LogMemoryContextPending;
extern PGDLLIMPORT volatile sig_atomic_t IdleStatsUpdateTimeoutPending;
-
+extern PGDLLIMPORT volatile sig_atomic_t LogQueryPlanPending;
extern PGDLLIMPORT volatile sig_atomic_t CheckClientConnectionPending;
extern PGDLLIMPORT volatile sig_atomic_t ClientConnectionLost;
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h
index afeeb1ca01..ea26242c86 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,8 @@ typedef enum
PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for shutdown */
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+ PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current
+ * query */
PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */
/* Recovery conflict reasons */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index fa3cc5f2df..7949abf76b 100644
--- a/src/include/tcop/pquery.h
+++ b/src/include/tcop/pquery.h
@@ -22,7 +22,6 @@ struct PlannedStmt; /* avoid including plannodes.h here */
extern PGDLLIMPORT Portal ActivePortal;
-
extern PortalStrategy ChoosePortalStrategy(List *stmts);
extern List *FetchPortalTargetList(Portal portal);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index c3b2b9d860..1ac584fa7f 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -316,14 +316,15 @@ SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
../jkl/mno
(1 row)
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
pg_log_backend_memory_contexts
--------------------------------
@@ -337,8 +338,8 @@ SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
t
(1 row)
-CREATE ROLE regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+CREATE ROLE regress_log_function;
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
has_function_privilege
------------------------
@@ -346,15 +347,15 @@ SELECT has_function_privilege('regress_log_memory',
(1 row)
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
-SELECT has_function_privilege('regress_log_memory',
+ TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
has_function_privilege
------------------------
t
(1 row)
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
pg_log_backend_memory_contexts
--------------------------------
@@ -363,8 +364,44 @@ SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
-DROP ROLE regress_log_memory;
+ FROM regress_log_function;
+-- pg_log_query_plan()
+-- Note that we're using a slightly more complex query here because
+-- a simple 'SELECT pg_log_query_plan(pg_backend_pid())' would finish
+-- before it reaches the code path that actually outputs the plan.
+SELECT result FROM (SELECT pg_log_query_plan(pg_backend_pid())) result;
+ result
+--------
+ (t)
+(1 row)
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+ has_function_privilege
+------------------------
+ f
+(1 row)
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+ has_function_privilege
+------------------------
+ t
+(1 row)
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan
+-------------------
+ t
+(1 row)
+
+RESET ROLE;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
--
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index 23792c4132..d8c141024e 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -109,39 +109,64 @@ SELECT test_canonicalize_path('./abc/./def/.');
SELECT test_canonicalize_path('./abc/././def/.');
SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
+
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
WHERE backend_type = 'checkpointer';
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
+ TO regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
+ FROM regress_log_function;
+
+-- pg_log_query_plan()
+-- Note that we're using a slightly more complex query here because
+-- a simple 'SELECT pg_log_query_plan(pg_backend_pid())' would finish
+-- before it reaches the code path that actually outputs the plan.
+
+SELECT result FROM (SELECT pg_log_query_plan(pg_backend_pid())) result;
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
base-commit: fc32be3c941f9d98dd9f549153a5fcea6c3e9b8b
--
2.48.1
