On Sat, Apr 5, 2025 at 3:14 PM Atsushi Torikoshi
<torikoshia.t...@gmail.com> wrote:
On Thu, Apr 3, 2025 at 11:10 PM Robert Haas <robertmh...@gmail.com>
wrote:
Do we really need ExecProcNodeOriginal? Can we find some way to reuse
ExecProcNodeReal instead of making the structure bigger?
I also wanted to implement this without adding elements to PlanState if
possible, but I haven't found a good solution, so the patch uses
ExecSetExecProcNode.
I tackled this again and the attached patch removes ExecProcNodeOriginal
from Planstate.
Instead of adding a new field, this version builds the behavior into the
existing wrapper function, ExecProcNodeFirst().
Since ExecProcNodeFirst() is already handling instrumentation-related
logic, the patch has maybe become a bit more complex to accommodate both
that and the new behavior.
While it might make sense to introduce a more general mechanism that
allows for stacking an arbitrary number of wrappers around ExecProcNode,
I’m not sure it's possible or worth the added complexity—such layered
wrapping doesn't seem like something we typically need.
What do you think?
--
Regards,
--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.
From 41944eb943f8f6b2fb731125ed0d50ad29bbd338 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <toriko...@sraoss.co.jp>
Date: Tue, 20 May 2025 22:01:40 +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, codes for logging plan is wrapped
to every ExecProcNode under the current executing plan node,
and when the executor runs one of ExecProcNode, the plan is
actually logged. These wrappers are unwrapped when once the
plan is logged.
In this way, we can avoid adding the overhead which we'll face
when adding CHECK_FOR_INTERRUPTS() like mechanisms in somewhere
in executor codes safely.
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.
---
contrib/auto_explain/auto_explain.c | 24 +-
doc/src/sgml/func.sgml | 55 +++
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 | 387 +++++++++++++++++++
src/backend/commands/explain.c | 38 +-
src/backend/commands/meson.build | 1 +
src/backend/executor/execMain.c | 10 +
src/backend/executor/execProcnode.c | 13 +-
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 | 28 ++
src/include/commands/explain.h | 5 +
src/include/commands/explain_state.h | 1 +
src/include/executor/executor.h | 1 +
src/include/miscadmin.h | 1 +
src/include/storage/procsignal.h | 2 +
src/include/tcop/pquery.h | 1 -
src/test/regress/expected/misc_functions.out | 54 ++-
src/test/regress/sql/misc_functions.sql | 41 +-
23 files changed, 648 insertions(+), 46 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 cd6625020a..e720ddf39f 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"
@@ -412,26 +413,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 b405525a46..700fdde184 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -28821,6 +28821,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>
@@ -28971,6 +28994,38 @@ stats_timestamp | 2025-03-24 13:55:47.796698+01
will be less resource intensive when only the local backend is of interest.
</para>
</note>
+ </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>
+ Note that when the target is executing nested statements(statements executed
+ inside a function), only the innermost query plan is logged.
+ Note that 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.
</para>
</sect2>
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index b885513f76..6ba9b8f824 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"
@@ -2904,6 +2905,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.
@@ -5296,6 +5303,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..55629ea554
--- /dev/null
+++ b/src/backend/commands/dynamic_explain.c
@@ -0,0 +1,387 @@
+/*-------------------------------------------------------------------------
+ *
+ * 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"
+
+/*
+ * True while this backend is processing a log query plan request,
+ * from the start of wrapping plan nodes until the log output is completed.
+ */
+static bool ProcessLogQueryPlanInterruptActive = false;
+
+/* Currently executing query's QueryDesc */
+static QueryDesc *ActiveQueryDesc = NULL;
+
+static void WrapExecProcNodeWithExplain(PlanState *ps);
+static void UnwrapExecProcNodeWithExplain(PlanState *ps);
+
+/*
+ * 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;
+ ProcessLogQueryPlanInterruptActive = false;
+}
+
+/*
+ * Wrap array of PlanState ExecProcNodes with ExecProcNodeWithExplain
+ */
+static void
+WrapPlanStatesWithExplain(PlanState **planstates, int nplans)
+{
+ int i;
+
+ for (i = 0; i < nplans; i++)
+ WrapExecProcNodeWithExplain(planstates[i]);
+}
+
+/*
+ * Wrap CustomScanState children's ExecProcNodes with ExecProcNodeWithExplain
+ */
+static void
+WrapCustomPlanChildWithExplain(CustomScanState *css)
+{
+ ListCell *cell;
+
+ foreach(cell, css->custom_ps)
+ WrapExecProcNodeWithExplain((PlanState *) lfirst(cell));
+}
+
+/*
+ * Recursively wrap all possible ExecProcNode().
+ *
+ * Recursion is 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.
+ */
+static void
+WrapExecProcNodeWithExplain(PlanState *ps)
+{
+ check_stack_depth();
+
+ ExecSetExecProcNode(ps, ps->ExecProcNodeReal);
+
+ if (ps->lefttree != NULL)
+ WrapExecProcNodeWithExplain(ps->lefttree);
+ if (ps->righttree != NULL)
+ WrapExecProcNodeWithExplain(ps->righttree);
+ if (ps->subPlan != NULL)
+ {
+ ListCell *l;
+
+ foreach(l, ps->subPlan)
+ {
+ SubPlanState *sstate = (SubPlanState *) lfirst(l);
+ WrapExecProcNodeWithExplain(sstate->planstate);
+ }
+ }
+
+ /* special child plans */
+ switch (nodeTag(ps->plan))
+ {
+ case T_Append:
+ WrapPlanStatesWithExplain(((AppendState *) ps)->appendplans,
+ ((AppendState *) ps)->as_nplans);
+ break;
+ case T_MergeAppend:
+ WrapPlanStatesWithExplain(((MergeAppendState *) ps)->mergeplans,
+ ((MergeAppendState *) ps)->ms_nplans);
+ break;
+ case T_BitmapAnd:
+ WrapPlanStatesWithExplain(((BitmapAndState *) ps)->bitmapplans,
+ ((BitmapAndState *) ps)->nplans);
+ break;
+ case T_BitmapOr:
+ WrapPlanStatesWithExplain(((BitmapOrState *) ps)->bitmapplans,
+ ((BitmapOrState *) ps)->nplans);
+ break;
+ case T_SubqueryScan:
+ WrapExecProcNodeWithExplain(((SubqueryScanState *) ps)->subplan);
+ break;
+ case T_CustomScan:
+ WrapCustomPlanChildWithExplain((CustomScanState *) ps);
+ break;
+ default:
+ break;
+ }
+}
+
+/*
+ * Unwrap array of PlanStates ExecProcNodes with ExecProcNodeWithExplain
+ */
+static void
+UnwrapPlanStatesWithExplain(PlanState **planstates, int nplans)
+{
+ int i;
+
+ for (i = 0; i < nplans; i++)
+ UnwrapExecProcNodeWithExplain(planstates[i]);
+}
+
+/*
+ * Unwrap CustomScanState children's ExecProcNodes with ExecProcNodeWithExplain
+ */
+static void
+UnwrapCustomPlanChildWithExplain(CustomScanState *css)
+{
+ ListCell *cell;
+
+ foreach(cell, css->custom_ps)
+ UnwrapExecProcNodeWithExplain((PlanState *) lfirst(cell));
+}
+
+/*
+ * Recursively unwrap all possible ExecProcNode().
+ *
+ * Unwrap ExecProcNode() or wrap it for instrumentation if needed.
+ * Since ExecProcNodeWithExplain() is wrapped ealier in ExecProcNodeFirst(),
+ * perform instrumentation wrapping in this function.
+ */
+static void
+UnwrapExecProcNodeWithExplain(PlanState *ps)
+{
+ check_stack_depth();
+
+ if (ps->instrument && INSTR_TIME_IS_ZERO(ps->instrument->starttime))
+ ps->ExecProcNode = ExecProcNodeInstr;
+ else
+ ps->ExecProcNode = ps->ExecProcNodeReal;
+
+ if (ps->lefttree != NULL)
+ UnwrapExecProcNodeWithExplain(ps->lefttree);
+ if (ps->righttree != NULL)
+ UnwrapExecProcNodeWithExplain(ps->righttree);
+ if (ps->subPlan != NULL)
+ {
+ ListCell *l;
+
+ foreach(l, ps->subPlan)
+ {
+ SubPlanState *sstate = (SubPlanState *) lfirst(l);
+
+ UnwrapExecProcNodeWithExplain(sstate->planstate);
+ }
+ }
+
+ /* special child plans */
+ switch (nodeTag(ps->plan))
+ {
+ case T_Append:
+ UnwrapPlanStatesWithExplain(((AppendState *) ps)->appendplans,
+ ((AppendState *) ps)->as_nplans);
+ break;
+ case T_MergeAppend:
+ UnwrapPlanStatesWithExplain(((MergeAppendState *) ps)->mergeplans,
+ ((MergeAppendState *) ps)->ms_nplans);
+ break;
+ case T_BitmapAnd:
+ UnwrapPlanStatesWithExplain(((BitmapAndState *) ps)->bitmapplans,
+ ((BitmapAndState *) ps)->nplans);
+ break;
+ case T_BitmapOr:
+ UnwrapPlanStatesWithExplain(((BitmapOrState *) ps)->bitmapplans,
+ ((BitmapOrState *) ps)->nplans);
+ break;
+ case T_SubqueryScan:
+ UnwrapExecProcNodeWithExplain(((SubqueryScanState *) ps)->subplan);
+ break;
+ case T_CustomScan:
+ UnwrapCustomPlanChildWithExplain((CustomScanState *) ps);
+ break;
+ default:
+ break;
+ }
+}
+
+/*
+ * Wrapper for logging currently running plan.
+ *
+ * ExecProcNode wrapper that performs logging plan of the currently running query.
+ */
+TupleTableSlot *
+ExecProcNodeWithExplain(PlanState *ps)
+{
+ ExplainState *es;
+ MemoryContext cxt;
+ MemoryContext old_cxt;
+
+ check_stack_depth();
+
+ 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 still be called afterward, such as ExecPostprocessPlan().
+ * To handle the case, check ActiveQueryDesc.
+ */
+ if (ActiveQueryDesc == NULL)
+ ereport(LOG_SERVER_ONLY,
+ errmsg("backend with PID %d is finishing query",
+ MyProcPid),
+ errhidestmt(true),
+ errhidecontext(true));
+ else
+ {
+ 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);
+
+ UnwrapExecProcNodeWithExplain(ps);
+
+ ProcessLogQueryPlanInterruptActive = false;
+
+ return ps->ExecProcNode(ps);
+}
+
+/*
+ * Perform logging plan for the currently running query.
+ *
+ * Since executing EXPLAIN-related code at an arbitrary CHECK_FOR_INTERRUPTS()
+ * point is potentially unsafe, this function just wraps the ExecProcNode() to
+ * log the query plan. This ensures that EXPLAIN code is executed only during
+ * ExecProcNode(), where it is considered safe.
+ */
+void
+ProcessLogQueryPlanInterrupt(void)
+{
+ LogQueryPlanPending = false;
+
+ /* Prevent re-entrance until the plan has been logged and the unwrapping has done */
+ if (ProcessLogQueryPlanInterruptActive)
+ return;
+
+ ProcessLogQueryPlanInterruptActive = true;
+
+ 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));
+
+ ProcessLogQueryPlanInterruptActive = false;
+ return;
+ }
+
+ WrapExecProcNodeWithExplain(ActiveQueryDesc->planstate);
+}
+
+bool
+GetProcessLogQueryPlanInterruptActive(void)
+{
+ return ProcessLogQueryPlanInterruptActive;
+}
+
+inline QueryDesc *
+GetActiveQueryDesc(void)
+{
+ return ActiveQueryDesc;
+}
+
+void
+inline 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)
+ {
+ /* Again, just a warning to allow loops */
+ 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 786ee865f1..fd37772504 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1100,6 +1100,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
@@ -1827,7 +1858,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 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
@@ -1835,7 +1869,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 7230f96810..b1f3e83b62 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"
@@ -380,6 +381,7 @@ standard_ExecutorRun(QueryDesc *queryDesc,
DestReceiver *dest;
bool sendTuples;
MemoryContext oldcontext;
+ QueryDesc *oldActiveQueryDesc;
/* sanity checks */
Assert(queryDesc != NULL);
@@ -393,6 +395,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
*/
@@ -455,6 +464,7 @@ standard_ExecutorRun(QueryDesc *queryDesc,
InstrStopNode(queryDesc->totaltime, estate->es_processed);
MemoryContextSwitchTo(oldcontext);
+ SetActiveQueryDesc(oldActiveQueryDesc);
}
/* ----------------------------------------------------------------
diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c
index f5f9cfbeea..dbdd99830b 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"
@@ -120,7 +121,6 @@
#include "nodes/nodeFuncs.h"
static TupleTableSlot *ExecProcNodeFirst(PlanState *node);
-static TupleTableSlot *ExecProcNodeInstr(PlanState *node);
static bool ExecShutdownNode_walker(PlanState *node, void *context);
@@ -456,12 +456,19 @@ ExecProcNodeFirst(PlanState *node)
*/
check_stack_depth();
+ /*
+ * If logging plan is requested, handle it first. If instrumentation is also
+ * requested, update the wrapper accordingly after logging plan is completed.
+ * See ExecProcNodeWithExplain().
+ */
+ if (GetProcessLogQueryPlanInterruptActive())
+ node->ExecProcNode = ExecProcNodeWithExplain;
/*
* 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;
@@ -475,7 +482,7 @@ ExecProcNodeFirst(PlanState *node)
* this a separate function, we avoid overhead in the normal case where
* no instrumentation is wanted.
*/
-static TupleTableSlot *
+TupleTableSlot *
ExecProcNodeInstr(PlanState *node)
{
TupleTableSlot *result;
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index ce69e26d72..765b5c6599 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"
@@ -694,6 +695,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
if (CheckProcSignal(PROCSIG_GET_MEMORY_CONTEXT))
HandleGetMemoryContextInterrupt();
+ 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 1ae51b1b39..082a714629 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"
@@ -3538,6 +3539,9 @@ ProcessInterrupts(void)
if (PublishMemoryContextPending)
ProcessGetMemoryContextInterrupt();
+ if (LogQueryPlanPending)
+ ProcessLogQueryPlanInterrupt();
+
if (ParallelApplyMessagePending)
ProcessParallelApplyMessages();
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index 92b0446b80..ffd5f712de 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -41,6 +41,8 @@ volatile sig_atomic_t ProcSignalBarrierPending = false;
volatile sig_atomic_t LogMemoryContextPending = false;
volatile sig_atomic_t PublishMemoryContextPending = 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 62beb71da2..ae793299e2 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8581,6 +8581,12 @@
proargnames => '{pid, summary, timeout, name, ident, type, path, level, total_bytes, total_nblocks, free_bytes, free_chunks, used_bytes, num_agg_contexts, stats_timestamp}',
prosrc => 'pg_get_process_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..75b864f63a
--- /dev/null
+++ b/src/include/commands/dynamic_explain.h
@@ -0,0 +1,28 @@
+/*-------------------------------------------------------------------------
+ *
+ * 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 ProcessLogQueryPlanInterrupt(void);
+extern bool GetProcessLogQueryPlanInterruptActive(void);
+extern QueryDesc *GetActiveQueryDesc(void);
+extern void SetActiveQueryDesc(QueryDesc *queryDesc);
+extern TupleTableSlot *ExecProcNodeWithExplain(PlanState *ps);
+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 03c5b3d73e..083567caf0 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -72,6 +72,8 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, CachedPlan *cplan,
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);
@@ -82,5 +84,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 ae99407db8..93faf9c811 100644
--- a/src/include/executor/executor.h
+++ b/src/include/executor/executor.h
@@ -295,6 +295,7 @@ extern void EvalPlanQualEnd(EPQState *epqstate);
*/
extern PlanState *ExecInitNode(Plan *node, EState *estate, int eflags);
extern void ExecSetExecProcNode(PlanState *node, ExecProcNodeMtd function);
+extern TupleTableSlot *ExecProcNodeInstr(PlanState *node);
extern Node *MultiExecProcNode(PlanState *node);
extern void ExecEndNode(PlanState *node);
extern void ExecShutdownNode(PlanState *node);
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 1e59a7f910..2b7d664812 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -97,6 +97,7 @@ 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 PublishMemoryContextPending;
+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 345d5a0ecb..60d6d80c4f 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -36,6 +36,8 @@ typedef enum
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
PROCSIG_GET_MEMORY_CONTEXT, /* ask backend to send 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 cc517ed5e9..2c4d2c3178 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,41 @@ 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()
+SELECT pg_log_query_plan(pg_backend_pid());
+ pg_log_query_plan
+-------------------
+ 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 5f9c77512d..d9df928389 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -109,39 +109,60 @@ 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()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+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: cbf53e2b8a8ed3fc6f554095a4e99591bd5193f6
--
2.43.0
