On 2026-09-25 16:08, torikoshia wrote:
On 2026-09-18 18:46, Andrei Lepikhov wrote:
On 08/09/2026 15:17, torikoshia wrote:
On 2026-08-31 22:12, Andrei Lepikhov wrote:
What if an automation tool, triggered by certain events, requests a
query plan
when a query goes over its quota? If we could identify the query
plan in the
log, the tool could find the plan, decide whether to request it
again, and
choose to either interrupt the query or let it run a bit longer.
Would the following approach address your concern?
- When pg_log_query_plan() is called, it generates a request ID,
returns the ID
to the caller, and passes it to the target backend.
- The target backend includes the ID either in the resulting plan log
or in a
log message indicating that the request could not be completed.
Yes, I think this is a good way to explore.
I also see this code as an initial step toward a future full-fledged
feature
that might need a shared memory structure for extra parameters.
EXPLAIN by
itself, even in verbose mode, has limited benefits. In practice, the
actual
number of rows and loops is way more useful. Because of this, I think
the
feature should be designed so that future core changes or extensions
can pass
some flags, such as 'interrupt query execution and calculate actual
instrumentation' or 'use specific explain settings'.
I agree that the feature as currently proposed would be useful only in
limited situations, since it only shows the execution plan. Supporting
EXPLAIN options, particularly ANALYZE, would make it more useful.
Before
we can support those capabilities, though, we first need to establish a
safe way to obtain the execution plan of a running query. That is the
focus of the current patch.
I am currently trying to implement the request ID approach to associate
each call to pg_log_query_plan() with the corresponding log output. I
think this can be reviewed separately from the mechanism for safely
obtaining the plan, so I intend to keep the latter in 0001 and put the
request ID support in a separate patch, 0002.
Added patch 0002 to implement this approach.
It generates request IDs from a cluster-wide counter and includes each
ID in both the return value of pg_log_query_plan() and the corresponding
log message:
=# select pg_log_query_plan(15726);
pg_log_query_plan
-------------------
3
LOG: 00000: query and its plan for queryid -6193732234003165941
requested by request ID 3 running on backend with PID 15726 are:
Query Text: select * from pgbench_accounts a cross join
pgbench_branches b;
Nested Loop (cost=0.00..4111474.17 rows=327839400 width=200)
-> Seq Scan on pgbench_accounts a (cost=0.00..13463.80
rows=520380 width=100)
-> Materialize (cost=0.00..19.45 rows=630 width=100)
-> Seq Scan on pgbench_branches b (cost=0.00..16.30
rows=630 width=100)
The patch allocates one shared-memory request slot per backend slot at
server startup. Each slot holds a request ID, a target PID, a request
state, and a spinlock, requiring roughly two dozen bytes per backend
slot, depending on the platform. There is also a small control structure
for the shared counter, so the overall memory requirement seems modest.
As noted in the code comment, the request structure could also be
extended to carry EXPLAIN options in a future patch.
0001 patch has not been changed from v60, which focuses on obtaining
the execution plan of a running query safely.
What do you think?
--
Thanks,
--
Atsushi Torikoshi
Seconded from NTT DATA CORPORATION to SRA OSS K.K.
From 6fd6bc54ee82c0169b59b614fc58fc318d7cd284 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
Date: Mon, 19 Oct 2026 15:17:32 +0900
Subject: [PATCH v61 1/2] 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 implements logging query plan.
When the executor next invokes 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.
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
---
contrib/auto_explain/auto_explain.c | 29 +--
doc/src/sgml/func/func-admin.sgml | 37 +++
src/backend/access/transam/xact.c | 33 +++
src/backend/commands/Makefile | 1 +
src/backend/commands/explain.c | 43 +++-
src/backend/commands/explain_running.c | 212 ++++++++++++++++++
src/backend/commands/meson.build | 1 +
src/backend/executor/execMain.c | 23 ++
src/backend/executor/execProcnode.c | 37 ++-
src/backend/storage/ipc/procsignal.c | 4 +
src/backend/tcop/postgres.c | 4 +
src/backend/utils/init/globals.c | 2 +
src/include/access/xact.h | 3 +
src/include/catalog/pg_proc.dat | 7 +
src/include/commands/explain.h | 3 +
src/include/commands/explain_running.h | 24 ++
src/include/commands/explain_state.h | 1 +
src/include/miscadmin.h | 1 +
src/include/storage/procsignal.h | 2 +
src/test/modules/test_misc/meson.build | 1 +
.../test_misc/t/016_pg_log_query_plan.pl | 102 +++++++++
src/test/regress/expected/misc_functions.out | 38 ++++
src/test/regress/sql/misc_functions.sql | 31 +++
23 files changed, 601 insertions(+), 38 deletions(-)
create mode 100644 src/backend/commands/explain_running.c
create mode 100644 src/include/commands/explain_running.h
create mode 100644 src/test/modules/test_misc/t/016_pg_log_query_plan.pl
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 97ce498d0c1..07014cab366 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -451,32 +451,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
diff --git a/doc/src/sgml/func/func-admin.sgml b/doc/src/sgml/func/func-admin.sgml
index 64b0e7bb972..462378dc1f0 100644
--- a/doc/src/sgml/func/func-admin.sgml
+++ b/doc/src/sgml/func/func-admin.sgml
@@ -184,6 +184,43 @@
</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>
+ The plan is logged when the target backend next reaches a
+ point where the running plan can be inspected. If the backend
+ is spending a long time in work that does not reach such a
+ point, the log output can be delayed until that work
+ completes. If the query finishes before such a point is
+ reached, no plan may be logged.
+ </para>
+ <para>
+ If the target backend is executing a nested query when it
+ processes the request, only the plan of the innermost
+ executing query is logged.
+ </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>
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 702cbb9df10..9fd49f8160b 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -218,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;
@@ -251,6 +252,7 @@ static TransactionStateData TopTransactionStateData = {
.state = TRANS_DEFAULT,
.blockState = TBLOCK_DEFAULT,
.topXidLogged = false,
+ .queryDesc = NULL,
};
/*
@@ -936,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
@@ -2970,6 +2993,9 @@ AbortTransaction(void)
/* Reset snapshot export state. */
SnapBuildResetExportedSnapshotState();
+ /* Reset current QueryDesc. */
+ 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.
@@ -5382,6 +5408,13 @@ AbortSubTransaction(void)
/* Reset logical streaming state. */
ResetLogicalStreamingState();
+ /*
+ * Reset current QueryDesc. 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.
diff --git a/src/backend/commands/Makefile b/src/backend/commands/Makefile
index 71331c9c9e5..e6d20edff53 100644
--- a/src/backend/commands/Makefile
+++ b/src/backend/commands/Makefile
@@ -35,6 +35,7 @@ OBJS = \
explain.o \
explain_dr.o \
explain_format.o \
+ explain_running.o \
explain_state.o \
extension.o \
foreigncmds.o \
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 4b1ad4227ac..33bb4d250a2 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1092,6 +1092,43 @@ 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);
+ 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 (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 +1864,9 @@ 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 explaining a running query, 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 +1874,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->running)
InstrEndLoop(planstate->instrument);
if (es->analyze &&
diff --git a/src/backend/commands/explain_running.c b/src/backend/commands/explain_running.c
new file mode 100644
index 00000000000..6af2cf214a6
--- /dev/null
+++ b/src/backend/commands/explain_running.c
@@ -0,0 +1,212 @@
+/*-------------------------------------------------------------------------
+ *
+ * explain_running.c
+ * Explain query plans during execution
+ *
+ * Portions Copyright (c) 1996-2026, PostgreSQL Global Development Group
+ * Portions Copyright (c) 1994-5, Regents of the University of California
+ *
+ * IDENTIFICATION
+ * src/backend/commands/explain_running.c
+ *
+ *-------------------------------------------------------------------------
+ */
+#include "postgres.h"
+
+#include "access/xact.h"
+#include "commands/explain.h"
+#include "commands/explain_format.h"
+#include "commands/explain_running.h"
+#include "commands/explain_state.h"
+#include "executor/executor.h"
+#include "miscadmin.h"
+#include "nodes/nodeFuncs.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;
+
+static bool wrapExecProcNode(PlanState *ps, void *context);
+
+/*
+ * Wrap all the underlying ExecProcNode with ExecProcNodeFirst.
+ */
+static bool
+wrapExecProcNode(PlanState *ps, void *context)
+{
+ if (ps == NULL)
+ return false;
+
+ ExecSetExecProcNode(ps, ps->ExecProcNodeReal);
+
+ return planstate_tree_walker(ps, wrapExecProcNode, context);
+}
+
+/*
+ * 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 */
+}
+
+/*
+ * Actual plan logging function.
+ */
+void
+LogQueryPlan(void)
+{
+ ExplainState *es;
+ MemoryContext cxt;
+ MemoryContext old_cxt;
+ QueryDesc *queryDesc;
+
+ /*
+ * 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)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("query plan logging was requested but there was no opportunity to do it"));
+ LogQueryPlanPending = false;
+ return;
+ }
+
+ cxt = AllocSetContextCreate(CurrentMemoryContext,
+ "log_query_plan temporary context",
+ ALLOCSET_DEFAULT_SIZES);
+ old_cxt = MemoryContextSwitchTo(cxt);
+
+ es = NewExplainState();
+ es->running = true;
+
+ PG_TRY();
+ {
+ ExplainStringAssemble(es, queryDesc, es->format, false, -1);
+
+ ereport(LOG_SERVER_ONLY,
+ errmsg("query and its plan for queryid " INT64_FORMAT " running on backend with PID %d are:\n%s",
+ queryDesc->plannedstmt->queryId, MyProcPid,
+ es->str->data));
+ }
+ PG_FINALLY();
+ {
+ MemoryContextSwitchTo(old_cxt);
+ MemoryContextDelete(cxt);
+ LogQueryPlanPending = false;
+ }
+ PG_END_TRY();
+}
+
+/*
+ * 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)
+ {
+ ereport(LOG_SERVER_ONLY,
+ errmsg("query plan logging was requested but there was no opportunity to do it"));
+ 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();
+ {
+ INJECTION_POINT("log-query-interrupt", NULL);
+
+ /*
+ * Wrap ExecProcNodes with ExecProcNodeFirst, which logs query plan
+ * when LogQueryPlanPending is true.
+ */
+ (void) wrapExecProcNode(querydesc->planstate, NULL);
+ }
+ 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 a backend to log its
+ * plan because the output is written to the server log, which in many cases
+ * can only be read by superusers.
+ * 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 = NULL;
+
+ proc = BackendPidGetProc(pid);
+
+ if (proc != NULL)
+ be_status = pgstat_get_beentry_by_proc_number(proc->vxid.procNumber);
+
+ if (proc == NULL || be_status == NULL || be_status->st_procpid != pid)
+ {
+ /*
+ * 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);
+ }
+
+ 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/meson.build b/src/backend/commands/meson.build
index d4b224cb5b8..13347f74386 100644
--- a/src/backend/commands/meson.build
+++ b/src/backend/commands/meson.build
@@ -23,6 +23,7 @@ backend_sources += files(
'explain.c',
'explain_dr.c',
'explain_format.c',
+ 'explain_running.c',
'explain_state.c',
'extension.c',
'foreigncmds.c',
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index d7a8f36ca1d..970f02ae4f5 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -44,6 +44,7 @@
#include "access/xact.h"
#include "catalog/namespace.h"
#include "catalog/partition.h"
+#include "commands/explain_running.h"
#include "commands/matview.h"
#include "commands/trigger.h"
#include "executor/executor.h"
@@ -323,6 +324,7 @@ standard_ExecutorRun(QueryDesc *queryDesc,
DestReceiver *dest;
bool sendTuples;
MemoryContext oldcontext;
+ QueryDesc *oldQueryDesc;
/* sanity checks */
Assert(queryDesc != NULL);
@@ -335,6 +337,13 @@ standard_ExecutorRun(QueryDesc *queryDesc,
/* caller must ensure the query's snapshot is active */
Assert(GetActiveSnapshot() == estate->es_snapshot);
+ /*
+ * Save current QueryDesc here to enable retrieval of the currently
+ * running queryDesc for nested queries.
+ */
+ oldQueryDesc = GetCurrentQueryDesc();
+ SetCurrentQueryDesc(queryDesc);
+
/*
* Switch into per-query memory context
*/
@@ -397,6 +406,20 @@ standard_ExecutorRun(QueryDesc *queryDesc,
InstrStop(queryDesc->query_instr);
MemoryContextSwitchTo(oldcontext);
+ SetCurrentQueryDesc(oldQueryDesc);
+
+ /*
+ * Ensure LogQueryPlanPending is initialized in case there was no time for
+ * logging the plan. Otherwise plan will be logged at the next query
+ * execution on the same session.
+ */
+ if (LogQueryPlanPending)
+ {
+ ereport(LOG_SERVER_ONLY,
+ (errmsg("query plan logging was requested but there was no opportunity to do it for queryid " INT64_FORMAT,
+ queryDesc->plannedstmt->queryId)));
+ LogQueryPlanPending = false;
+ }
}
/* ----------------------------------------------------------------
diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c
index 7c4c66e323f..912cdd15859 100644
--- a/src/backend/executor/execProcnode.c
+++ b/src/backend/executor/execProcnode.c
@@ -72,6 +72,7 @@
*/
#include "postgres.h"
+#include "commands/explain_running.h"
#include "executor/executor.h"
#include "executor/instrument.h"
#include "executor/nodeAgg.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,21 +443,37 @@ 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
@@ -527,7 +545,6 @@ MultiExecProcNode(PlanState *node)
return result;
}
-
/* ----------------------------------------------------------------
* ExecEndNode
*
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index 21a77f98c1d..1d551cc16bf 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/explain_running.h"
#include "commands/repack.h"
#include "miscadmin.h"
#include "pgstat.h"
@@ -713,6 +714,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 b6bdfe213fe..c05b5f56778 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/explain_running.h"
#include "commands/explain_state.h"
#include "commands/prepare.h"
#include "commands/repack.h"
@@ -3699,6 +3700,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 bbd28d14d99..de84fd9cfa3 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/access/xact.h b/src/include/access/xact.h
index a8cbdf247c8..0570fdd3277 100644
--- a/src/include/access/xact.h
+++ b/src/include/access/xact.h
@@ -432,6 +432,7 @@ typedef struct xl_xact_parsed_abort
TimestampTz origin_timestamp;
} xl_xact_parsed_abort;
+typedef struct QueryDesc QueryDesc;
/* ----------------
* extern definitions
@@ -458,6 +459,8 @@ extern TimestampTz GetCurrentStatementStartTimestamp(void);
extern TimestampTz GetCurrentTransactionStopTimestamp(void);
extern void SetCurrentStatementStartTimestamp(void);
extern int GetCurrentTransactionNestLevel(void);
+extern QueryDesc *GetCurrentQueryDesc(void);
+extern void SetCurrentQueryDesc(QueryDesc *queryDesc);
extern bool TransactionIdIsCurrentTransactionId(TransactionId xid);
extern int GetTopReadOnlyTransactionNestLevel(void);
extern void CommandCounterIncrement(void);
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index 5e4c9e503f8..ee9644c2cba 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8796,6 +8796,13 @@
prorettype => 'bool', proargtypes => 'int4',
prosrc => 'pg_log_backend_memory_contexts', proacl => '{POSTGRES=X}' },
+# 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',
+ proacl => '{POSTGRES=X}' },
+
# non-persistent series generator
{ oid => '1066', descr => 'non-persistent series generator',
proname => 'generate_series', prorows => '1000',
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 472e141bba3..633ac94ea58 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -81,5 +81,8 @@ extern void ExplainPrintJITSummary(ExplainState *es,
extern void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainQueryParameters(ExplainState *es,
ParamListInfo params, int maxlen);
+extern void ExplainStringAssemble(ExplainState *es, QueryDesc *queryDesc,
+ int logFormat, bool logTriggers,
+ int logParameterMaxLength);
#endif /* EXPLAIN_H */
diff --git a/src/include/commands/explain_running.h b/src/include/commands/explain_running.h
new file mode 100644
index 00000000000..316ef25be60
--- /dev/null
+++ b/src/include/commands/explain_running.h
@@ -0,0 +1,24 @@
+/*-------------------------------------------------------------------------
+ *
+ * explain_running.h
+ * prototypes for explain_running.c
+ *
+ * Portions Copyright (c) 1996-2026, PostgreSQL Global Development Group
+ * Portions Copyright (c) 1994-5, Regents of the University of California
+ *
+ * src/include/commands/explain_running.h
+ *
+ *-------------------------------------------------------------------------
+ */
+#ifndef EXPLAIN_RUNNING_H
+#define EXPLAIN_RUNNING_H
+
+#include "executor/executor.h"
+#include "commands/explain_state.h"
+
+extern void HandleLogQueryPlanInterrupt(void);
+extern void ProcessLogQueryPlanInterrupt(void);
+extern void LogQueryPlan(void);
+extern Datum pg_log_query_plan(PG_FUNCTION_ARGS);
+
+#endif /* EXPLAIN_RUNNING_H */
diff --git a/src/include/commands/explain_state.h b/src/include/commands/explain_state.h
index 97bc7ed49f6..4b90f5eaa0a 100644
--- a/src/include/commands/explain_state.h
+++ b/src/include/commands/explain_state.h
@@ -73,6 +73,7 @@ typedef struct ExplainState
* entry */
/* state related to the current plan node */
ExplainWorkersState *workers_state; /* needed if parallel plan */
+ bool running; /* whether target query is running */
/* extensions */
void **extension_state;
int extension_state_allocated;
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 8d6aacc4d5a..38341b26f4e 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -98,6 +98,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 aaa158bfd66..c2142043e2d 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 */
PROCSIG_SLOTSYNC_MESSAGE, /* ask slot synchronization to stop */
PROCSIG_REPACK_MESSAGE, /* Message from repack worker */
diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build
index 5d81f5b13be..bf37af4628c 100644
--- a/src/test/modules/test_misc/meson.build
+++ b/src/test/modules/test_misc/meson.build
@@ -24,6 +24,7 @@ tests += {
't/013_temp_obj_multisession.pl',
't/014_log_statement_max_length.pl',
't/015_temp_schema_exit_deferrable.pl',
+ 't/016_pg_log_query_plan.pl',
],
# The injection points are cluster-wide, so disable installcheck
'runningcheck': false,
diff --git a/src/test/modules/test_misc/t/016_pg_log_query_plan.pl b/src/test/modules/test_misc/t/016_pg_log_query_plan.pl
new file mode 100644
index 00000000000..9e7f06f3d89
--- /dev/null
+++ b/src/test/modules/test_misc/t/016_pg_log_query_plan.pl
@@ -0,0 +1,102 @@
+
+# Copyright (c) 2024-2026, PostgreSQL Global Development Group
+
+use strict;
+use warnings FATAL => 'all';
+use locale;
+
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Test that pg_log_query_plan() actually logs the query plan of
+# another backend executing a query.
+
+# This test requires timing coordinations:
+# 1) The target backend must be executing a query when
+# pg_log_query_plan() sends the signal.
+# 2) We must confirm that the target backend actually received the
+# signal that requests logging of the plan.
+#
+# We use an advisory lock and an injection point to control them
+# respectively.
+
+if ($ENV{enable_injection_points} ne 'yes')
+{
+ plan skip_all => 'Injection points not supported by this build';
+}
+
+# Node initialization
+my $node = PostgreSQL::Test::Cluster->new('node');
+$node->init();
+$node->start;
+
+# Check if the extension injection_points is available, as it may be
+# possible that this script is run with installcheck, where the module
+# would not be installed by default.
+if (!$node->check_extension('injection_points'))
+{
+ plan skip_all => 'Extension injection_points not installed';
+}
+
+$node->safe_psql('postgres', 'CREATE EXTENSION injection_points;');
+
+my $psql_session1 = $node->background_psql('postgres');
+my $psql_session2 = $node->background_psql('postgres');
+
+my $session1_pid = $psql_session1->query_safe("select pg_backend_pid()");
+
+# Set injection point in the logging plan request handler to ensure
+# that session1 received the signal of pg_log_query_plan().
+$psql_session1->query_safe(
+ qq[
+ SELECT injection_points_set_local();
+ SELECT injection_points_attach('log-query-interrupt', 'wait');
+]);
+
+# Use an advisory lock to make session1 blocked during query execution.
+$psql_session2->query_safe(
+ qq[
+ BEGIN;
+ SELECT pg_advisory_xact_lock(1);
+]);
+
+$psql_session1->query_until(
+ qr/wait_on_advisory_lock/, q(
+ \echo wait_on_advisory_lock
+ BEGIN;
+ SELECT pg_advisory_xact_lock(1);
+));
+
+# Confirm that session1 is actually waiting on the advisory lock.
+$node->wait_for_event('client backend', 'advisory');
+
+# Run pg_log_query_plan().
+$psql_session2->query_safe("SELECT pg_log_query_plan($session1_pid);");
+
+# Ensure that the signal of pg_log_query_plan() is actually
+# received by confirming session1 is waiting on the injection point.
+$node->wait_for_event('client backend', 'log-query-interrupt');
+
+# Commit the session 2 to release the advisory lock.
+$psql_session2->query_safe("COMMIT;");
+
+my $log_offset = -s $node->logfile;
+
+# Detach the injection point to start logging the plan.
+$psql_session2->query_safe(
+ qq[
+ SELECT injection_points_wakeup('log-query-interrupt');
+ SELECT injection_points_detach('log-query-interrupt');
+]);
+
+$node->wait_for_log(
+ "running on backend with PID $session1_pid ",
+ $log_offset);
+
+$psql_session1->query_safe("COMMIT;");
+
+ok($psql_session1->quit);
+ok($psql_session2->quit);
+
+done_testing();
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index 35d6ee2ce9e..c72b015e2e1 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -357,6 +357,44 @@ REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
FROM regress_log_memory;
DROP ROLE regress_log_memory;
--
+-- pg_log_query_plan()
+--
+-- Plans are logged and they are not returned to the function.
+-- Furthermore, their contents can vary depending on the optimizer.
+-- Here we just verify that the permissions are set properly.
+--
+-- The test that verifies the backend's query plan is actually
+-- logged is implemented in
+-- src/test/modules/test_misc/t/016_pg_log_query_plan.pl.
+CREATE ROLE regress_log_plan;
+SELECT has_function_privilege('regress_log_plan',
+ '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_plan;
+SELECT has_function_privilege('regress_log_plan',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+ has_function_privilege
+------------------------
+ t
+(1 row)
+
+SET ROLE regress_log_plan;
+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_plan;
+DROP ROLE regress_log_plan;
+--
-- Test some built-in SRFs
--
-- The outputs of these are variable, so we can't just print their results
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index 94b91964c04..7b709420c6e 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -113,6 +113,37 @@ REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
DROP ROLE regress_log_memory;
+--
+-- pg_log_query_plan()
+--
+-- Plans are logged and they are not returned to the function.
+-- Furthermore, their contents can vary depending on the optimizer.
+-- Here we just verify that the permissions are set properly.
+--
+-- The test that verifies the backend's query plan is actually
+-- logged is implemented in
+-- src/test/modules/test_misc/t/016_pg_log_query_plan.pl.
+
+CREATE ROLE regress_log_plan;
+
+SELECT has_function_privilege('regress_log_plan',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_plan;
+
+SELECT has_function_privilege('regress_log_plan',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_plan;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_plan;
+
+DROP ROLE regress_log_plan;
+
--
-- Test some built-in SRFs
--
--
2.48.1
From 5fe1130d412392caa7a22fa75536c58e320fa9ec Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
Date: Mon, 19 Oct 2026 16:29:56 +0900
Subject: [PATCH v61 2/2] Add request IDs and manage query plan logging
requests
Return a positive request ID from pg_log_query_plan() and include it in
server log messages so callers can associate a request with its output.
Generate IDs using a server-wide signed 64-bit counter in the range
1 through PG_INT64_MAX, wrapping to 1 after reaching the upper limit.
Since requests are processed asynchronously, store each request in a
shared-memory slot assigned to the target backend so it can retrieve the
request ID after the calling function returns. Allow only one outstanding
request per backend to prevent its ID from being overwritten before
processing completes.
---
doc/src/sgml/func/func-admin.sgml | 6 +-
src/backend/access/transam/xact.c | 6 +-
src/backend/commands/explain_running.c | 359 ++++++++++++++++--
src/backend/executor/execMain.c | 7 +-
src/backend/utils/init/postinit.c | 8 +
src/include/catalog/pg_proc.dat | 2 +-
src/include/commands/explain_running.h | 4 +
src/include/storage/subsystemlist.h | 1 +
.../test_misc/t/016_pg_log_query_plan.pl | 9 +-
src/test/regress/expected/misc_functions.out | 6 +-
src/test/regress/sql/misc_functions.sql | 2 +-
11 files changed, 365 insertions(+), 45 deletions(-)
diff --git a/doc/src/sgml/func/func-admin.sgml b/doc/src/sgml/func/func-admin.sgml
index 462378dc1f0..cde30c13fda 100644
--- a/doc/src/sgml/func/func-admin.sgml
+++ b/doc/src/sgml/func/func-admin.sgml
@@ -190,7 +190,7 @@
<primary>pg_log_query_plan</primary>
</indexterm>
<function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
- <returnvalue>boolean</returnvalue>
+ <returnvalue>bigint</returnvalue>
</para>
<para>
Requests to log the plan of the query currently running on the
@@ -201,6 +201,10 @@
for more information), but will not be sent to the client
regardless of <xref linkend="guc-client-min-messages"/>.
</para>
+ <para>
+ Each accepted request is assigned a positive request identifier, which
+ is returned by the function and is included in the server log message.
+ </para>
<para>
The plan is logged when the target backend next reaches a
point where the running plan can be inspected. If the backend
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 9fd49f8160b..0445e8a554f 100644
--- a/src/backend/access/transam/xact.c
+++ b/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/explain_running.h"
#include "commands/tablecmds.h"
#include "commands/trigger.h"
#include "common/pg_prng.h"
@@ -2993,8 +2994,9 @@ AbortTransaction(void)
/* Reset snapshot export state. */
SnapBuildResetExportedSnapshotState();
- /* Reset current QueryDesc. */
+ /* Discard the current QueryDesc and any unfinished plan logging request. */
SetCurrentQueryDesc(NULL);
+ AbortLogQueryPlanRequest();
/*
* If this xact has started any unfinished parallel operation, clean up
@@ -5412,8 +5414,10 @@ AbortSubTransaction(void)
* Reset current QueryDesc. 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().
+ * Discard any unfinished plan logging request as well.
*/
SetCurrentQueryDesc(NULL);
+ AbortLogQueryPlanRequest();
/*
* No need for SnapBuildResetExportedSnapshotState() here, snapshot
diff --git a/src/backend/commands/explain_running.c b/src/backend/commands/explain_running.c
index 6af2cf214a6..cd155b96937 100644
--- a/src/backend/commands/explain_running.c
+++ b/src/backend/commands/explain_running.c
@@ -21,16 +21,270 @@
#include "executor/executor.h"
#include "miscadmin.h"
#include "nodes/nodeFuncs.h"
+#include "storage/ipc.h"
#include "storage/proc.h"
#include "storage/procarray.h"
#include "storage/procsignal.h"
+#include "storage/shmem.h"
+#include "storage/spin.h"
+#include "storage/subsystems.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;
+typedef int64 LogQueryPlanRequestId;
+
+typedef struct LogQueryPlanRequestIdControl
+{
+ slock_t mutex;
+ LogQueryPlanRequestId next_request_id;
+} LogQueryPlanRequestIdControl;
+
+typedef enum LogQueryPlanRequestState
+{
+ LOG_QUERY_PLAN_REQUEST_IDLE = 0,
+ LOG_QUERY_PLAN_REQUEST_PENDING, /* Request registered but not yet taken by target backend */
+ LOG_QUERY_PLAN_REQUEST_PROCESSING, /* Request taken by target backend; processing in progress */
+} LogQueryPlanRequestState;
+
+typedef struct LogQueryPlanRequest
+{
+ LogQueryPlanRequestId request_id;
+ pid_t target_pid;
+ /* Future versions may add fields here to carry EXPLAIN options. */
+} LogQueryPlanRequest;
+
+typedef struct LogQueryPlanRequestSlot
+{
+ slock_t mutex;
+ LogQueryPlanRequestState state;
+ LogQueryPlanRequest request;
+} LogQueryPlanRequestSlot;
+
+static LogQueryPlanRequestSlot *LogQueryPlanRequestSlots;
+static LogQueryPlanRequestIdControl *LogQueryPlanRequestIdCtl;
+
+static void LogQueryPlanShmemRequest(void *arg);
+static void LogQueryPlanShmemInit(void *arg);
+static void LogQueryPlanRequestSlotCleanup(int code, Datum arg);
+
+const ShmemCallbacks LogQueryPlanShmemCallbacks = {
+ .request_fn = LogQueryPlanShmemRequest,
+ .init_fn = LogQueryPlanShmemInit,
+};
static bool wrapExecProcNode(PlanState *ps, void *context);
+static LogQueryPlanRequestId GenerateLogQueryPlanRequestId(void);
+static bool ReserveLogQueryPlanRequest(ProcNumber proc_number, pid_t pid,
+ LogQueryPlanRequestId request_id);
+static void RollbackLogQueryPlanRequest(ProcNumber proc_number, pid_t pid,
+ LogQueryPlanRequestId request_id);
+static LogQueryPlanRequest *TakePendingLogQueryPlanRequest(void);
+static LogQueryPlanRequest *GetProcessingLogQueryPlanRequest(void);
+static void FinishLogQueryPlanRequest(void);
+
+static void
+LogQueryPlanShmemRequest(void *arg)
+{
+ ShmemRequestStruct(.name = "Log Query Plan Request ID",
+ .size = sizeof(LogQueryPlanRequestIdControl),
+ .ptr = (void **) &LogQueryPlanRequestIdCtl,
+ );
+
+ ShmemRequestStruct(.name = "Log Query Plan Request Slots",
+ .size = mul_size(sizeof(LogQueryPlanRequestSlot), MaxBackends),
+ .ptr = (void **) &LogQueryPlanRequestSlots,
+ );
+}
+
+static void
+LogQueryPlanShmemInit(void *arg)
+{
+ SpinLockInit(&LogQueryPlanRequestIdCtl->mutex);
+ LogQueryPlanRequestIdCtl->next_request_id = 1;
+
+ for (int i = 0; i < MaxBackends; i++)
+ {
+ LogQueryPlanRequestSlot *slot = &LogQueryPlanRequestSlots[i];
+
+ SpinLockInit(&slot->mutex);
+ slot->state = LOG_QUERY_PLAN_REQUEST_IDLE;
+ }
+}
+
+/*
+ * Initialize the request slot assigned to a newly-started process.
+ */
+void
+LogQueryPlanRequestSlotInit(void)
+{
+ LogQueryPlanRequestSlot *slot;
+
+ Assert(MyBackendType == B_BACKEND);
+ slot = &LogQueryPlanRequestSlots[MyProcNumber];
+
+ SpinLockAcquire(&slot->mutex);
+ slot->state = LOG_QUERY_PLAN_REQUEST_IDLE;
+ SpinLockRelease(&slot->mutex);
+
+ on_shmem_exit(LogQueryPlanRequestSlotCleanup, Int32GetDatum(MyProcNumber));
+}
+
+/*
+ * Release a request slot when its process exits.
+ */
+static void
+LogQueryPlanRequestSlotCleanup(int code, Datum arg)
+{
+ ProcNumber proc_number = DatumGetInt32(arg);
+ LogQueryPlanRequestSlot *slot;
+
+ Assert(proc_number >= 0 && proc_number < MaxBackends);
+ slot = &LogQueryPlanRequestSlots[proc_number];
+
+ SpinLockAcquire(&slot->mutex);
+ slot->state = LOG_QUERY_PLAN_REQUEST_IDLE;
+ SpinLockRelease(&slot->mutex);
+}
+
+/*
+ * Generate an opaque request identifier from a shared counter.
+ *
+ * Keep identifiers positive and representable as SQL bigint, wrapping to 1
+ * after PG_INT64_MAX. Failed requests consume identifiers, too.
+ */
+static LogQueryPlanRequestId
+GenerateLogQueryPlanRequestId(void)
+{
+ LogQueryPlanRequestId id;
+
+ SpinLockAcquire(&LogQueryPlanRequestIdCtl->mutex);
+ id = LogQueryPlanRequestIdCtl->next_request_id;
+ LogQueryPlanRequestIdCtl->next_request_id =
+ (id == PG_INT64_MAX) ? 1 : id + 1;
+ SpinLockRelease(&LogQueryPlanRequestIdCtl->mutex);
+
+ return id;
+}
+
+/*
+ * Register a pending request in the target process's slot if it is idle.
+ * Return true on success, or false if a request is already pending or being
+ * processed.
+ */
+static bool
+ReserveLogQueryPlanRequest(ProcNumber proc_number, pid_t pid,
+ LogQueryPlanRequestId request_id)
+{
+ LogQueryPlanRequestSlot *slot;
+ bool reserved = false;
+
+ Assert(proc_number >= 0 && proc_number < MaxBackends);
+ slot = &LogQueryPlanRequestSlots[proc_number];
+
+ SpinLockAcquire(&slot->mutex);
+ if (slot->state == LOG_QUERY_PLAN_REQUEST_IDLE)
+ {
+ slot->request.request_id = request_id;
+ slot->request.target_pid = pid;
+ slot->state = LOG_QUERY_PLAN_REQUEST_PENDING;
+ reserved = true;
+ }
+ SpinLockRelease(&slot->mutex);
+
+ return reserved;
+}
+
+/*
+ * Undo a reservation after signal delivery fails, but only if the slot still
+ * contains the same pending request. Leave requests already taken by the
+ * target process or registered by another caller untouched.
+ */
+static void
+RollbackLogQueryPlanRequest(ProcNumber proc_number, pid_t pid,
+ LogQueryPlanRequestId request_id)
+{
+ LogQueryPlanRequestSlot *slot;
+
+ Assert(proc_number >= 0 && proc_number < MaxBackends);
+ slot = &LogQueryPlanRequestSlots[proc_number];
+
+ SpinLockAcquire(&slot->mutex);
+ if (slot->state == LOG_QUERY_PLAN_REQUEST_PENDING &&
+ slot->request.target_pid == pid &&
+ slot->request.request_id == request_id)
+ slot->state = LOG_QUERY_PLAN_REQUEST_IDLE;
+ SpinLockRelease(&slot->mutex);
+}
+
+/*
+ * Take a pending request and set its state to PROCESSING, or return NULL if
+ * none exists.
+ */
+static LogQueryPlanRequest *
+TakePendingLogQueryPlanRequest(void)
+{
+ LogQueryPlanRequestSlot *slot;
+ LogQueryPlanRequest *request = NULL;
+
+ slot = &LogQueryPlanRequestSlots[MyProcNumber];
+
+ SpinLockAcquire(&slot->mutex);
+ if (slot->state == LOG_QUERY_PLAN_REQUEST_PENDING &&
+ slot->request.target_pid == MyProcPid)
+ {
+ slot->state = LOG_QUERY_PLAN_REQUEST_PROCESSING;
+ request = &slot->request;
+ }
+ else
+ /* Clear under the lock so a new request's notification is not lost. */
+ LogQueryPlanPending = false;
+ SpinLockRelease(&slot->mutex);
+
+ return request;
+}
+
+/*
+ * Return the processing request, or return NULL if none exists.
+ */
+static LogQueryPlanRequest *
+GetProcessingLogQueryPlanRequest(void)
+{
+ LogQueryPlanRequestSlot *slot = &LogQueryPlanRequestSlots[MyProcNumber];
+ LogQueryPlanRequest *request = NULL;
+
+ SpinLockAcquire(&slot->mutex);
+ if (slot->state == LOG_QUERY_PLAN_REQUEST_PROCESSING)
+ request = &slot->request;
+ SpinLockRelease(&slot->mutex);
+
+ return request;
+}
+
+static void
+FinishLogQueryPlanRequest(void)
+{
+ LogQueryPlanRequestSlot *slot = &LogQueryPlanRequestSlots[MyProcNumber];
+
+ SpinLockAcquire(&slot->mutex);
+ /* Clear the notification before allowing another request to be registered. */
+ LogQueryPlanPending = false;
+ slot->state = LOG_QUERY_PLAN_REQUEST_IDLE;
+ SpinLockRelease(&slot->mutex);
+}
+
+/*
+ * Discard any unfinished request when a transaction or subtransaction aborts.
+ * Do not allocate or report errors here: the original error must be preserved.
+ */
+void
+AbortLogQueryPlanRequest(void)
+{
+ /* Only client backends use query plan logging request slots. */
+ if (MyBackendType != B_BACKEND)
+ return;
+
+ FinishLogQueryPlanRequest();
+}
/*
* Wrap all the underlying ExecProcNode with ExecProcNodeFirst.
@@ -71,6 +325,7 @@ LogQueryPlan(void)
MemoryContext cxt;
MemoryContext old_cxt;
QueryDesc *queryDesc;
+ LogQueryPlanRequest *request;
/*
* Current QueryDesc is valid only during standard_ExecutorRun. However,
@@ -81,12 +336,15 @@ LogQueryPlan(void)
if (queryDesc == NULL)
{
- ereport(LOG_SERVER_ONLY,
- errmsg("query plan logging was requested but there was no opportunity to do it"));
- LogQueryPlanPending = false;
+ FinishLogQueryPlanRequestWithoutPlan(0);
return;
}
+ request = GetProcessingLogQueryPlanRequest();
+
+ if (request == NULL)
+ return;
+
cxt = AllocSetContextCreate(CurrentMemoryContext,
"log_query_plan temporary context",
ALLOCSET_DEFAULT_SIZES);
@@ -100,19 +358,49 @@ LogQueryPlan(void)
ExplainStringAssemble(es, queryDesc, es->format, false, -1);
ereport(LOG_SERVER_ONLY,
- errmsg("query and its plan for queryid " INT64_FORMAT " running on backend with PID %d are:\n%s",
- queryDesc->plannedstmt->queryId, MyProcPid,
+ errmsg("query and its plan for queryid " INT64_FORMAT " requested by request ID " INT64_FORMAT " running on backend with PID %d are:\n%s",
+ queryDesc->plannedstmt->queryId,
+ request->request_id, MyProcPid,
es->str->data));
}
PG_FINALLY();
{
MemoryContextSwitchTo(old_cxt);
MemoryContextDelete(cxt);
- LogQueryPlanPending = false;
+ FinishLogQueryPlanRequest();
}
PG_END_TRY();
}
+/*
+ * Finish a request without logging its plan, and log the queryid and requestid if possible.
+ */
+void
+FinishLogQueryPlanRequestWithoutPlan(uint64 query_id)
+{
+ LogQueryPlanRequestSlot *slot = &LogQueryPlanRequestSlots[MyProcNumber];
+ LogQueryPlanRequestId request_id = 0;
+
+ SpinLockAcquire(&slot->mutex);
+ request_id = slot->request.request_id;
+ /* Clear the notification before allowing another request to be registered. */
+ LogQueryPlanPending = false;
+ slot->state = LOG_QUERY_PLAN_REQUEST_IDLE;
+ SpinLockRelease(&slot->mutex);
+
+ // request_id should have been set when the request was made.
+ Assert(request_id != 0);
+
+ if (query_id != 0)
+ ereport(LOG_SERVER_ONLY,
+ errmsg("query plan logging request " INT64_FORMAT " could not be completed because there was no opportunity to log the plan for queryid " INT64_FORMAT,
+ request_id, query_id));
+ else
+ ereport(LOG_SERVER_ONLY,
+ errmsg("query plan logging request " INT64_FORMAT " could not be completed because there was no opportunity to log the plan",
+ request_id));
+}
+
/*
* Process the request for logging query plan at CHECK_FOR_INTERRUPTS().
*
@@ -125,27 +413,25 @@ LogQueryPlan(void)
void
ProcessLogQueryPlanInterrupt(void)
{
- QueryDesc *querydesc = GetCurrentQueryDesc();
+ QueryDesc *querydesc;
+
+ /* Exit immediately if processing a request is already in progress. */
+ if (GetProcessingLogQueryPlanRequest() != NULL)
+ return;
+
+ /* Exit immediately when there is no pending request for this backend. */
+ if (TakePendingLogQueryPlanRequest() == NULL)
+ return;
+
+ querydesc = GetCurrentQueryDesc();
/* If current query has already finished, we can do nothing but exit */
if (querydesc == NULL)
{
- ereport(LOG_SERVER_ONLY,
- errmsg("query plan logging was requested but there was no opportunity to do it"));
- LogQueryPlanPending = false;
+ FinishLogQueryPlanRequestWithoutPlan(0);
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();
{
INJECTION_POINT("log-query-interrupt", NULL);
@@ -156,9 +442,10 @@ ProcessLogQueryPlanInterrupt(void)
*/
(void) wrapExecProcNode(querydesc->planstate, NULL);
}
- PG_FINALLY();
+ PG_CATCH();
{
- WrapNodesInProgress = false;
+ FinishLogQueryPlanRequest();
+ PG_RE_THROW();
}
PG_END_TRY();
}
@@ -176,7 +463,9 @@ pg_log_query_plan(PG_FUNCTION_ARGS)
{
int pid = PG_GETARG_INT32(0);
PGPROC *proc;
+ ProcNumber procNumber;
PgBackendStatus *be_status = NULL;
+ LogQueryPlanRequestId request_id;
proc = BackendPidGetProc(pid);
@@ -191,22 +480,34 @@ pg_log_query_plan(PG_FUNCTION_ARGS)
*/
ereport(WARNING,
(errmsg("PID %d is not a PostgreSQL backend process", pid)));
- PG_RETURN_BOOL(false);
+ PG_RETURN_NULL();
}
if (be_status->st_backendType != B_BACKEND)
{
ereport(WARNING,
(errmsg("PID %d is not a PostgreSQL client backend process", pid)));
- PG_RETURN_BOOL(false);
+ PG_RETURN_NULL();
+ }
+
+ procNumber = GetNumberFromPGProc(proc);
+ request_id = GenerateLogQueryPlanRequestId();
+
+ if (!ReserveLogQueryPlanRequest(procNumber, pid, request_id))
+ {
+ ereport(WARNING,
+ (errmsg("query plan request for PID %d is already pending", pid)));
+ PG_RETURN_NULL();
}
- if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->vxid.procNumber) < 0)
+ if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, procNumber) < 0)
{
+ /* The signal was not delivered, so undo our reservation if possible. */
+ RollbackLogQueryPlanRequest(procNumber, pid, request_id);
ereport(WARNING,
(errmsg("could not send signal to process %d: %m", pid)));
- PG_RETURN_BOOL(false);
+ PG_RETURN_NULL();
}
- PG_RETURN_BOOL(true);
+ PG_RETURN_INT64(request_id);
}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 970f02ae4f5..a747cfeccca 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -414,12 +414,7 @@ standard_ExecutorRun(QueryDesc *queryDesc,
* execution on the same session.
*/
if (LogQueryPlanPending)
- {
- ereport(LOG_SERVER_ONLY,
- (errmsg("query plan logging was requested but there was no opportunity to do it for queryid " INT64_FORMAT,
- queryDesc->plannedstmt->queryId)));
- LogQueryPlanPending = false;
- }
+ FinishLogQueryPlanRequestWithoutPlan(queryDesc->plannedstmt->queryId);
}
/* ----------------------------------------------------------------
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 8b6ea195eca..4cb0e292194 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -33,6 +33,7 @@
#include "catalog/pg_database.h"
#include "catalog/pg_db_role_setting.h"
#include "catalog/pg_tablespace.h"
+#include "commands/explain_running.h"
#include "libpq/auth.h"
#include "libpq/libpq-be.h"
#include "mb/pg_wchar.h"
@@ -733,6 +734,13 @@ InitPostgres(const char *in_dbname, Oid dboid,
elog(DEBUG3, "InitPostgres");
+ /*
+ * Initialize the query plan request slot before InitProcessPhase2()
+ * exposes me to other backends that can install requests.
+ */
+ if (MyBackendType == B_BACKEND)
+ LogQueryPlanRequestSlotInit();
+
/*
* Add my PGPROC struct to the ProcArray.
*
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index ee9644c2cba..479e0f2f421 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8799,7 +8799,7 @@
# 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',
+ provolatile => 'v', prorettype => 'int8',
proargtypes => 'int4', prosrc => 'pg_log_query_plan',
proacl => '{POSTGRES=X}' },
diff --git a/src/include/commands/explain_running.h b/src/include/commands/explain_running.h
index 316ef25be60..7d10c7763fb 100644
--- a/src/include/commands/explain_running.h
+++ b/src/include/commands/explain_running.h
@@ -15,10 +15,14 @@
#include "executor/executor.h"
#include "commands/explain_state.h"
+#include "storage/procnumber.h"
extern void HandleLogQueryPlanInterrupt(void);
extern void ProcessLogQueryPlanInterrupt(void);
extern void LogQueryPlan(void);
+extern void FinishLogQueryPlanRequestWithoutPlan(uint64 query_id);
+extern void AbortLogQueryPlanRequest(void);
+extern void LogQueryPlanRequestSlotInit(void);
extern Datum pg_log_query_plan(PG_FUNCTION_ARGS);
#endif /* EXPLAIN_RUNNING_H */
diff --git a/src/include/storage/subsystemlist.h b/src/include/storage/subsystemlist.h
index 9ad619080be..608b7c4ea7a 100644
--- a/src/include/storage/subsystemlist.h
+++ b/src/include/storage/subsystemlist.h
@@ -78,6 +78,7 @@ PG_SHMEM_SUBSYSTEM(BTreeShmemCallbacks)
PG_SHMEM_SUBSYSTEM(SyncScanShmemCallbacks)
PG_SHMEM_SUBSYSTEM(AsyncShmemCallbacks)
PG_SHMEM_SUBSYSTEM(StatsShmemCallbacks)
+PG_SHMEM_SUBSYSTEM(LogQueryPlanShmemCallbacks)
PG_SHMEM_SUBSYSTEM(WaitEventCustomShmemCallbacks)
#ifdef USE_INJECTION_POINTS
PG_SHMEM_SUBSYSTEM(InjectionPointShmemCallbacks)
diff --git a/src/test/modules/test_misc/t/016_pg_log_query_plan.pl b/src/test/modules/test_misc/t/016_pg_log_query_plan.pl
index 9e7f06f3d89..4a1e0b20adb 100644
--- a/src/test/modules/test_misc/t/016_pg_log_query_plan.pl
+++ b/src/test/modules/test_misc/t/016_pg_log_query_plan.pl
@@ -71,8 +71,11 @@ $psql_session1->query_until(
# Confirm that session1 is actually waiting on the advisory lock.
$node->wait_for_event('client backend', 'advisory');
-# Run pg_log_query_plan().
-$psql_session2->query_safe("SELECT pg_log_query_plan($session1_pid);");
+# Run pg_log_query_plan() and save the request ID for the log check.
+my $request_id =
+ $psql_session2->query_safe("SELECT pg_log_query_plan($session1_pid);");
+like($request_id, qr/^[1-9][0-9]*$/,
+ 'pg_log_query_plan returns a positive request ID');
# Ensure that the signal of pg_log_query_plan() is actually
# received by confirming session1 is waiting on the injection point.
@@ -91,7 +94,7 @@ $psql_session2->query_safe(
]);
$node->wait_for_log(
- "running on backend with PID $session1_pid ",
+ qr/request ID $request_id running on backend with PID $session1_pid /,
$log_offset);
$psql_session1->query_safe("COMMIT;");
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index c72b015e2e1..5073876619d 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -384,9 +384,9 @@ SELECT has_function_privilege('regress_log_plan',
(1 row)
SET ROLE regress_log_plan;
-SELECT pg_log_query_plan(pg_backend_pid());
- pg_log_query_plan
--------------------
+SELECT pg_log_query_plan(pg_backend_pid()) > 0 AS request_id_valid;
+ request_id_valid
+------------------
t
(1 row)
diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql
index 7b709420c6e..7113aceaccb 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -136,7 +136,7 @@ SELECT has_function_privilege('regress_log_plan',
'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
SET ROLE regress_log_plan;
-SELECT pg_log_query_plan(pg_backend_pid());
+SELECT pg_log_query_plan(pg_backend_pid()) > 0 AS request_id_valid;
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
--
2.48.1
