Hi
I've recently resumed work on this proposal.
I was revising tests that use the injection point, but given that there
was a recent talk at PGConf.EU about further features based on this
proposal [1], I thought it might be of interest to some. Therefore, I'll
share a patch that removes the injection point section for now.
Due to both the lack of an alternative implementation and the following
comment, I’ve taken the approach of wrapping all plan nodes:
On Tue, Mar 26, 2024 at 11:35 AM Andres Freund and...@anarazel.de wrote:
Andres, did you have some clever idea for this feature that would
avoid the need to do this?
No. I think it's acceptable though.
As a primary change since the last version, I have added wrapping
processing for child nodes other than left/right tree nodes in response
to the feedback in comment [2].
For nodes other than CustomScanState, I have confirmed via DEBUG logs
that the wrap/unwrap code is being executed. However, I'm still somewhat
uncertain whether CustomScanState should be included in this process.
For testing, I ran below queries in three sessions concurrently during
make installcheck and encountered no issues.
=# select pg_log_query_plan(pid) from pg_stat_activity;
=# \watch 0.1
[1]
https://www.postgresql.eu/events/pgconfeu2024/sessions/session/5689-debugging-active-queries-with-mid-flight-instrumented-explain-plans/
[2]
https://www.postgresql.org/message-id/CA%2BTgmoaaEQtuope6za%3D3GSCZ%2BWJFT4DbF5Cnv0QXFmDnZ_PqFw%40mail.gmail.com
Regards,
--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.
From 4d41f7ebcac9248c834b245b61b7140618cf3794 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <torikos...@oss.nttdata.com>
Date: Mon, 28 Oct 2024 21:48:07 +0900
Subject: [PATCH v39] 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.
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.
On receipt of the request, codes for logging plan is wrapped
to every ExecProcNode 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.
---
contrib/auto_explain/auto_explain.c | 23 +-
doc/src/sgml/func.sgml | 50 +++
src/backend/access/transam/xact.c | 7 +
src/backend/catalog/system_functions.sql | 2 +
src/backend/commands/explain.c | 372 ++++++++++++++++++-
src/backend/executor/execMain.c | 12 +
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/explain.h | 12 +
src/include/miscadmin.h | 1 +
src/include/nodes/execnodes.h | 3 +
src/include/storage/procsignal.h | 2 +
src/include/tcop/pquery.h | 2 +-
src/test/regress/expected/misc_functions.out | 54 ++-
src/test/regress/sql/misc_functions.sql | 41 +-
17 files changed, 555 insertions(+), 42 deletions(-)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 623a674f99..bd421d08ac 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -399,26 +399,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] = '}';
- }
+ ExplainAssembleLogOutput(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 7be0324ac8..ec6627e2e6 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -28281,6 +28281,25 @@ 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></entry>
+ </row>
+
<row>
<entry role="func_table_entry"><para role="func_signature">
<indexterm>
@@ -28399,6 +28418,37 @@ LOG: Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560
because it may generate a large number of log messages.
</para>
+ <para>
+ <function>pg_log_query_plan</function> can be used
+ to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_query_plan(201116);
+ pg_log_query_plan
+---------------------------
+ t
+(1 row)
+</programlisting>
+The format of the query plan is the same as when <literal>VERBOSE</literal>,
+<literal>COSTS</literal>, <literal>SETTINGS</literal> and
+<literal>FORMAT TEXT</literal> are used in the <command>EXPLAIN</command>
+command. For example:
+<screen>
+LOG: query plan running on backend with PID 201116 is:
+ Query Text: SELECT * FROM pgbench_accounts;
+ Seq Scan on public.pgbench_accounts (cost=0.00..52787.00 rows=2000000 width=97)
+ Output: aid, bid, abalance, filler
+ Settings: work_mem = '1MB'
+ Query Identifier: 8621255546560739680
+</screen>
+ Note that when the target is executing nested statements(statements executed
+ inside a function), only the innermost query plan is logged.
+ </para>
+
+ <para>
+ When a subtransaction is aborted, <function>pg_log_query_plan</function>
+ cannot log the query plan after the abort.
+ </para>
+
</sect2>
<sect2 id="functions-admin-backup">
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 004f7e10e5..62bd6ee61a 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.h"
#include "commands/tablecmds.h"
#include "commands/trigger.h"
#include "common/pg_prng.h"
@@ -2903,6 +2904,9 @@ AbortTransaction(void)
/* Reset snapshot export state. */
SnapBuildResetExportedSnapshotState();
+ /* Reset pg_log_query_plan() related state. */
+ ResetLogQueryPlanState();
+
/*
* If this xact has started any unfinished parallel operation, clean up
* its workers and exit parallel mode. Don't warn about leaked resources.
@@ -5304,6 +5308,9 @@ AbortSubTransaction(void)
/* Reset logical streaming state. */
ResetLogicalStreamingState();
+ /* Reset pg_log_query_plan() related state. */
+ 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 20d3b9b73f..deed14b5fb 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -796,6 +796,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/explain.c b/src/backend/commands/explain.c
index 7c0fd63b2f..c44c940b19 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -22,6 +22,7 @@
#include "jit/jit.h"
#include "libpq/pqformat.h"
#include "libpq/protocol.h"
+#include "miscadmin.h"
#include "nodes/extensible.h"
#include "nodes/makefuncs.h"
#include "nodes/nodeFuncs.h"
@@ -29,7 +30,9 @@
#include "parser/parsetree.h"
#include "rewrite/rewriteHandler.h"
#include "storage/bufmgr.h"
+#include "storage/procarray.h"
#include "tcop/tcopprot.h"
+#include "utils/backend_status.h"
#include "utils/builtins.h"
#include "utils/guc_tables.h"
#include "utils/json.h"
@@ -41,6 +44,11 @@
#include "utils/typcache.h"
#include "utils/xml.h"
+bool ProcessLogQueryPlanInterruptActive = false;
+
+/* Currently executing query's QueryDesc */
+QueryDesc *ActiveQueryDesc = NULL;
+
/* Hook for plugins to get control in ExplainOneQuery() */
ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
@@ -179,7 +187,10 @@ static void ExplainIndentText(ExplainState *es);
static void ExplainJSONLineEnding(ExplainState *es);
static void ExplainYAMLLineStarting(ExplainState *es);
static void escape_yaml(StringInfo buf, const char *str);
+static TupleTableSlot *ExecProcNodeWithExplain(PlanState *ps);
static SerializeMetrics GetSerializationMetrics(DestReceiver *dest);
+static void WrapExecProcNodeWithExplain(PlanState *ps);
+static void UnwrapExecProcNodeWithExplain(PlanState *ps);
@@ -882,6 +893,37 @@ ExplainPrintSettings(ExplainState *es)
}
}
+/*
+ * ExplainAssembleLogOutput -
+ * Assemble es->str for logging according to specified options and format
+ */
+
+void
+ExplainAssembleLogOutput(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] = '}';
+ }
+}
+
/*
* ExplainPrintPlan -
* convert a QueryDesc's plan tree to text and append it to es->str
@@ -1954,6 +1996,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 ...
+ * 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
@@ -1961,7 +2006,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 &&
@@ -5910,3 +5955,328 @@ GetSerializationMetrics(DestReceiver *dest)
return empty;
}
+
+/*
+ * HandleLogQueryPlanInterrupt -
+ * 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 */
+}
+
+/*
+ * ResetLogQueryPlanState -
+ * Clear pg_log_query_plan() related state during (sub)transaction abort
+ */
+void
+ResetLogQueryPlanState(void)
+{
+ /*
+ * After abort, some elements of ActiveQueryDesc is freed. To avoid
+ * accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+ ProcessLogQueryPlanInterruptActive = false;
+}
+
+/*
+ * WrapMultiExecProcNodesWithExplain -
+ * Wrap array of PlanStates ExecProcNodes with ExecProcNodeWithExplain
+ */
+static void
+WrapMultiExecProcNodesWithExplain(PlanState **planstates, int nplans)
+{
+ int i;
+
+ for (i = 0; i < nplans; i++)
+ WrapExecProcNodeWithExplain(planstates[i]);
+}
+
+/*
+ * WrapCustomPlanChildExecProcNodesWithExplain -
+ * Wrap CustomScanstate children's ExecProcNodes with ExecProcNodeWithExplain
+ */
+static void
+WrapCustomPlanChildExecProcNodesWithExplain(CustomScanState *css)
+{
+ ListCell *cell;
+
+ foreach(cell, css->custom_ps)
+ WrapExecProcNodeWithExplain((PlanState *) lfirst(cell));
+}
+
+/*
+ * WrapExecProcNodeWithExplain -
+ * Wrap ExecProcNode with ExecProcNodeWithExplain recursively
+ */
+static void
+WrapExecProcNodeWithExplain(PlanState *ps)
+{
+ /* wrapping can be done only once */
+ if (ps->ExecProcNodeOriginal != NULL)
+ return;
+
+ check_stack_depth();
+
+ ps->ExecProcNodeOriginal = ps->ExecProcNode;
+ ps->ExecProcNode = ExecProcNodeWithExplain;
+
+ if (ps->lefttree != NULL)
+ WrapExecProcNodeWithExplain(ps->lefttree);
+ if (ps->righttree != NULL)
+ WrapExecProcNodeWithExplain(ps->righttree);
+
+ /* special child plans */
+ switch (nodeTag(ps->plan))
+ {
+ case T_Append:
+ ereport(DEBUG1, errmsg("wrapping Append"));
+ WrapMultiExecProcNodesWithExplain(((AppendState *) ps)->appendplans,
+ ((AppendState *) ps)->as_nplans);
+ break;
+ case T_MergeAppend:
+ ereport(DEBUG1, errmsg("wrapping MergeAppend"));
+ WrapMultiExecProcNodesWithExplain(((MergeAppendState *) ps)->mergeplans,
+ ((MergeAppendState *) ps)->ms_nplans);
+ break;
+ case T_BitmapAnd:
+ ereport(DEBUG1, errmsg("wrapping BitmapAndState"));
+ WrapMultiExecProcNodesWithExplain(((BitmapAndState *) ps)->bitmapplans,
+ ((BitmapAndState *) ps)->nplans);
+ break;
+ case T_BitmapOr:
+ ereport(DEBUG1, errmsg("wrapping BitmapOrtate"));
+ WrapMultiExecProcNodesWithExplain(((BitmapOrState *) ps)->bitmapplans,
+ ((BitmapOrState *) ps)->nplans);
+ break;
+ case T_SubqueryScan:
+ ereport(DEBUG1, errmsg("wrapping Subquery"));
+ WrapExecProcNodeWithExplain(((SubqueryScanState *) ps)->subplan);
+ break;
+ case T_CustomScan:
+ ereport(DEBUG1, errmsg("wrapping CustomScanState"));
+ WrapCustomPlanChildExecProcNodesWithExplain((CustomScanState *) ps);
+ break;
+ default:
+ break;
+ }
+}
+
+/*
+ * UnwrapMultiExecProcNodesWithExplain -
+ * Unwrap array of PlanStates ExecProcNodes with ExecProcNodeWithExplain
+ */
+static void
+UnwrapMultiExecProcNodesWithExplain(PlanState **planstates, int nplans)
+{
+ int i;
+
+ for (i = 0; i < nplans; i++)
+ UnwrapExecProcNodeWithExplain(planstates[i]);
+}
+
+/*
+ * UnwrapCustomPlanChildExecProcNodesWithExplain -
+ * Unwrap CustomScanstate children's ExecProcNodes with ExecProcNodeWithExplain
+ */
+static void
+UnwrapCustomPlanChildExecProcNodesWithExplain(CustomScanState *css)
+{
+ ListCell *cell;
+
+ foreach(cell, css->custom_ps)
+ UnwrapExecProcNodeWithExplain((PlanState *) lfirst(cell));
+}
+
+/*
+ * UnwrapExecProcNodeWithExplain -
+ * Unwrap ExecProcNode with ExecProcNodeWithExplain recursively
+ */
+static void
+UnwrapExecProcNodeWithExplain(PlanState *ps)
+{
+ Assert(ps->ExecProcNodeOriginal != NULL);
+
+ check_stack_depth();
+
+ ps->ExecProcNode = ps->ExecProcNodeOriginal;
+ ps->ExecProcNodeOriginal = NULL;
+
+ if (ps->lefttree != NULL)
+ UnwrapExecProcNodeWithExplain(ps->lefttree);
+ if (ps->righttree != NULL)
+ UnwrapExecProcNodeWithExplain(ps->righttree);
+
+ /* special child plans */
+ switch (nodeTag(ps->plan))
+ {
+ case T_Append:
+ ereport(DEBUG1, errmsg("unwrapping Append"));
+ UnwrapMultiExecProcNodesWithExplain(((AppendState *) ps)->appendplans,
+ ((AppendState *) ps)->as_nplans);
+ break;
+ case T_MergeAppend:
+ ereport(DEBUG1, errmsg("unwrapping MergeAppend"));
+ UnwrapMultiExecProcNodesWithExplain(((MergeAppendState *) ps)->mergeplans,
+ ((MergeAppendState *) ps)->ms_nplans);
+ break;
+ case T_BitmapAnd:
+ ereport(DEBUG1, errmsg("unwrapping BitmapAndState"));
+ UnwrapMultiExecProcNodesWithExplain(((BitmapAndState *) ps)->bitmapplans,
+ ((BitmapAndState *) ps)->nplans);
+ break;
+ case T_BitmapOr:
+ ereport(DEBUG1, errmsg("unwrapping BitmapOrtate"));
+ UnwrapMultiExecProcNodesWithExplain(((BitmapOrState *) ps)->bitmapplans,
+ ((BitmapOrState *) ps)->nplans);
+ break;
+ case T_SubqueryScan:
+ ereport(DEBUG1, errmsg("unwrapping Subquery"));
+ UnwrapExecProcNodeWithExplain(((SubqueryScanState *) ps)->subplan);
+ break;
+ case T_CustomScan:
+ ereport(DEBUG1, errmsg("unwrapping CustomScanState"));
+ UnwrapCustomPlanChildExecProcNodesWithExplain((CustomScanState *) ps);
+ break;
+ default:
+ break;
+ }
+}
+
+/*
+ * ExecProcNodeWithExplain -
+ * Wrap ExecProcNode with codes which logs currently running plan
+ */
+static 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;
+
+ ExplainAssembleLogOutput(es, ActiveQueryDesc, EXPLAIN_FORMAT_TEXT, 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(ActiveQueryDesc->planstate);
+
+ /*
+ * Since unwrapping has already done, call ExecProcNode() not
+ * ExecProcNodeOriginal().
+ */
+ return ps->ExecProcNode(ps);
+}
+
+/*
+ * ProcessLogQueryPlanInterrupt
+ * Add wrapper which logs explain of the plan to ExecProcNodes
+ *
+ * Since running EXPLAIN codes at any arbitrary CHECK_FOR_INTERRUPTS() is
+ * unsafe, this function just wraps every ExecProcNode.
+ * In this way, EXPLAIN code is only executed at the timing of ExecProcNode,
+ * which seems safe.
+ */
+void
+ProcessLogQueryPlanInterrupt(void)
+{
+ LogQueryPlanPending = false;
+
+ /* Cannot re-enter */
+ 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);
+ ProcessLogQueryPlanInterruptActive = false;
+}
+
+/*
+ * pg_log_query_plan
+ * 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/executor/execMain.c b/src/backend/executor/execMain.c
index cc9a594cba..f502a37bd7 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/explain.h"
#include "commands/matview.h"
#include "commands/trigger.h"
#include "executor/executor.h"
@@ -296,10 +297,21 @@ ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction, uint64 count,
bool execute_once)
{
+ /*
+ * Update ActiveQueryDesc here to enable retrieval of the currently
+ * running queryDesc for nested queries.
+ */
+ QueryDesc *save_ActiveQueryDesc;
+
+ save_ActiveQueryDesc = ActiveQueryDesc;
+ ActiveQueryDesc = queryDesc;
+
if (ExecutorRun_hook)
(*ExecutorRun_hook) (queryDesc, direction, count, execute_once);
else
standard_ExecutorRun(queryDesc, direction, count, execute_once);
+
+ ActiveQueryDesc = save_ActiveQueryDesc;
}
void
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index 87027f27eb..50c5c263a9 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.h"
#include "miscadmin.h"
#include "pgstat.h"
#include "port/pg_bitutils.h"
@@ -688,6 +689,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 8cc23a9cef..59b1cd48f7 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.h"
#include "commands/prepare.h"
#include "common/pg_prng.h"
#include "jit/jit.h"
@@ -3500,6 +3501,9 @@ ProcessInterrupts(void)
if (LogMemoryContextPending)
ProcessLogMemoryContextInterrupt();
+ if (LogQueryPlanPending)
+ ProcessLogQueryPlanInterrupt();
+
if (ParallelApplyMessagePending)
HandleParallelApplyMessages();
}
diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c
index 03a54451ac..6cf12197b0 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -39,6 +39,8 @@ volatile sig_atomic_t IdleSessionTimeoutPending = false;
volatile sig_atomic_t ProcSignalBarrierPending = false;
volatile sig_atomic_t LogMemoryContextPending = false;
volatile sig_atomic_t IdleStatsUpdateTimeoutPending = false;
+volatile sig_atomic_t LogQueryPlanPending = false;
+
volatile uint32 InterruptHoldoffCount = 0;
volatile uint32 QueryCancelHoldoffCount = 0;
volatile uint32 CritSectionCount = 0;
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index 1ec0d6f6b5..8451ace7c0 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8434,6 +8434,12 @@
prorettype => 'bool', proargtypes => 'int4',
prosrc => 'pg_log_backend_memory_contexts' },
+# logging plan of the running query on the specified backend
+{ oid => '8000', descr => 'log plan of the running query on the specified backend',
+ proname => 'pg_log_query_plan',
+ provolatile => 'v', prorettype => 'bool',
+ proargtypes => 'int4', prosrc => 'pg_log_query_plan' },
+
# non-persistent series generator
{ oid => '1066', descr => 'non-persistent series generator',
proname => 'generate_series', prorows => '1000',
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index aa5872bc15..45853705d7 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -17,6 +17,9 @@
#include "lib/stringinfo.h"
#include "parser/parse_node.h"
+extern PGDLLIMPORT QueryDesc *ActiveQueryDesc;
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
+
typedef enum ExplainSerializeOption
{
EXPLAIN_SERIALIZE_NONE,
@@ -71,6 +74,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 */
} ExplainState;
/* Hook for plugins to get control in ExplainOneQuery() */
@@ -110,6 +114,10 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
const BufferUsage *bufusage,
const MemoryContextCounters *mem_counters);
+extern void ExplainAssembleLogOutput(ExplainState *es, QueryDesc *queryDesc,
+ int logFormat, bool logTriggers,
+ int logParameterMaxLength);
+
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
@@ -144,4 +152,8 @@ extern void ExplainCloseGroup(const char *objtype, const char *labelname,
extern DestReceiver *CreateExplainSerializeDestReceiver(ExplainState *es);
+extern void HandleLogQueryPlanInterrupt(void);
+extern void ProcessLogQueryPlanInterrupt(void);
+extern void ResetLogQueryPlanState(void);
+
#endif /* EXPLAIN_H */
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index e26d108a47..f675c4c78f 100644
--- a/src/include/miscadmin.h
+++ b/src/include/miscadmin.h
@@ -96,6 +96,7 @@ extern PGDLLIMPORT volatile sig_atomic_t IdleSessionTimeoutPending;
extern PGDLLIMPORT volatile sig_atomic_t ProcSignalBarrierPending;
extern PGDLLIMPORT volatile sig_atomic_t LogMemoryContextPending;
extern PGDLLIMPORT volatile sig_atomic_t IdleStatsUpdateTimeoutPending;
+extern PGDLLIMPORT volatile sig_atomic_t LogQueryPlanPending;
extern PGDLLIMPORT volatile sig_atomic_t CheckClientConnectionPending;
extern PGDLLIMPORT volatile sig_atomic_t ClientConnectionLost;
diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h
index b67d5186a2..39ab680ae6 100644
--- a/src/include/nodes/execnodes.h
+++ b/src/include/nodes/execnodes.h
@@ -1135,6 +1135,9 @@ typedef struct PlanState
ExecProcNodeMtd ExecProcNodeReal; /* actual function, if above is a
* wrapper */
+ ExecProcNodeMtd ExecProcNodeOriginal; /* temporary place when adding
+ * process for ExecProcNode */
+
Instrumentation *instrument; /* Optional runtime stats for this node */
WorkerInstrumentation *worker_instrument; /* per-worker instrumentation */
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h
index 221073def3..fb79a40316 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,8 @@ typedef enum
PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for shutdown */
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+ PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current
+ * query */
PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */
/* Recovery conflict reasons */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index 073fb323bc..3dd7edf93c 100644
--- a/src/include/tcop/pquery.h
+++ b/src/include/tcop/pquery.h
@@ -21,7 +21,7 @@ struct PlannedStmt; /* avoid including plannodes.h here */
extern PGDLLIMPORT Portal ActivePortal;
-
+extern PGDLLIMPORT QueryDesc *ActiveQueryDesc;
extern PortalStrategy ChoosePortalStrategy(List *stmts);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index 36b1201f9f..daa9450ea5 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 b7495d70eb..2da9de300b 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
--
2.39.2
