public inbox for [email protected]
help / color / mirror / Atom feedRe: RFC: Logging plan of the running query
15+ messages / 7 participants
[nested] [flat]
* Re: RFC: Logging plan of the running query
@ 2024-03-13 05:28 torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-14 01:02 ` Re: RFC: Logging plan of the running query jian he <[email protected]>
0 siblings, 2 replies; 15+ messages in thread
From: torikoshia @ 2024-03-13 05:28 UTC (permalink / raw)
To: [email protected]; +Cc: James Coleman <[email protected]>; Julien Rouhaud <[email protected]>; Andres Freund <[email protected]>; [email protected]; Étienne BERSAC <[email protected]>; [email protected]; [email protected]; [email protected]; [email protected]
On Fri, Feb 16, 2024 at 11:42 PM torikoshia <[email protected]>
wrote:
> I'm not so sure about the implementation now, i.e. finding the next
> node
> to be executed from the planstate tree, but I'm going to try this
> approach.
Attached a patch which takes this approach.
- I saw no way to find the next node to be executed from the planstate
tree, so the patch wraps all the ExecProcNode of the planstate tree at
CHECK_FOR_INTERRUPTS().
- To prevent overhead of this wrapped function call, unwrap it at the
end of EXPLAIN code execution.
- I first tried to use ExecSetExecProcNode() for wrapping, but it
'changes' ExecProcNodeMtd of nodes, not 'adds' some process to
ExecProcNodeMtd. I'm not sure this is the right approach, but attached
patch adds new member ExecProcNodeOriginal to PlanState to preserve
original ExecProcNodeMtd.
Any comments are welcomed.
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
Attachments:
[text/x-diff] v38-0001-Add-function-to-log-the-plan-of-the-query.patch (33.5K, ../../[email protected]/2-v38-0001-Add-function-to-log-the-plan-of-the-query.patch)
download | inline diff:
From a374bf485e6e7237314179313ac7cb61a0ad784b Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
Date: Wed, 13 Mar 2024 13:47:18 +0900
Subject: [PATCH v38] Add function to log the plan of the query
Currently, we have to wait for the query execution to finish
to check its plan. This is not so convenient when
investigating long-running queries on production environments
where we cannot use debuggers.
To improve this situation, this patch adds
pg_log_query_plan() function that requests to log the
plan of the specified backend process.
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, EXPLAIN codes for logging is wrapped
to every ExecProcNode and when the executor runs one of
ExecProcNode, the plan is logged. These EXPLAIN codes are
unwrapped when EXPLAIN codes actually run once.
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.
---
contrib/auto_explain/Makefile | 2 +
contrib/auto_explain/auto_explain.c | 23 +-
contrib/auto_explain/t/001_auto_explain.pl | 35 +++
doc/src/sgml/func.sgml | 50 ++++
src/backend/access/transam/xact.c | 17 ++
src/backend/catalog/system_functions.sql | 2 +
src/backend/commands/explain.c | 228 +++++++++++++++++-
src/backend/executor/execMain.c | 19 ++
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 | 9 +
src/include/miscadmin.h | 1 +
src/include/nodes/execnodes.h | 3 +
src/include/storage/procsignal.h | 1 +
src/include/tcop/pquery.h | 2 +-
src/include/utils/elog.h | 1 +
.../injection_points/injection_points.c | 11 +
src/test/regress/expected/misc_functions.out | 54 ++++-
src/test/regress/sql/misc_functions.sql | 41 +++-
21 files changed, 473 insertions(+), 42 deletions(-)
diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile
index efd127d3ca..64fe0e0573 100644
--- a/contrib/auto_explain/Makefile
+++ b/contrib/auto_explain/Makefile
@@ -8,6 +8,8 @@ PGFILEDESC = "auto_explain - logging facility for execution plans"
TAP_TESTS = 1
+EXTRA_INSTALL = src/test/modules/injection_points
+
ifdef USE_PGXS
PG_CONFIG = pg_config
PGXS := $(shell $(PG_CONFIG) --pgxs)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 677c135f59..e041b10b0e 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -401,26 +401,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/contrib/auto_explain/t/001_auto_explain.pl b/contrib/auto_explain/t/001_auto_explain.pl
index 0e5b34afa9..36a787174e 100644
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -35,6 +35,8 @@ $node->append_conf('postgresql.conf', "auto_explain.log_min_duration = 0");
$node->append_conf('postgresql.conf', "auto_explain.log_analyze = on");
$node->start;
+$node->safe_psql('postgres', 'CREATE EXTENSION injection_points');
+
# Simple query.
my $log_contents = query_log($node, "SELECT * FROM pg_class;");
@@ -212,4 +214,37 @@ REVOKE SET ON PARAMETER auto_explain.log_format FROM regress_user1;
DROP USER regress_user1;
});
+# Check that using both auto_explain and pg_log_query_plan() works fine
+
+$node->safe_psql('postgres', q{SELECT injection_points_attach('executor-run', 'logqueryplan')});
+
+$log_contents = query_log(
+ $node,
+ "SELECT * FROM pg_class;",
+ {
+ "auto_explain.log_verbose" => "on",
+ "auto_explain.log_settings" => "on",
+ "auto_explain.log_analyze" => "off",
+ "compute_query_id" => "on"
+ });
+
+like(
+ $log_contents,
+ qr/query plan running on backend with PID/,
+ "with pg_log_query_plan(), pg_log_query_plan() logged");
+
+like(
+ $log_contents,
+ qr/duration: .+ms plan:/,
+ "with pg_log_query_plan(), auto_explain logged");
+
+$log_contents =~ /(Query Text:.*Query Identifier: \d+).*(Query Text:.*Query Identifier: \d+)/s;
+my $pg_log_plan_query_output = $1;
+my $auto_explain_output = $2;
+
+cmp_ok(
+ $pg_log_plan_query_output, "eq",
+ $auto_explain_output,
+ "with pg_log_plan_query_log(), logged plans are the same");
+
done_testing();
diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml
index 0bb7aeb40e..6f4285e18d 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -27195,6 +27195,25 @@ SELECT collation for ('foo' COLLATE "de_DE");
</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>
@@ -27309,6 +27328,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 statements are executed inside a function, only the
+ plan of the most deeply nested query 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 1d930752c5..ac6682768c 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -60,6 +60,7 @@
#include "storage/procarray.h"
#include "storage/sinvaladt.h"
#include "storage/smgr.h"
+#include "tcop/pquery.h"
#include "utils/builtins.h"
#include "utils/combocid.h"
#include "utils/guc.h"
@@ -2768,6 +2769,14 @@ AbortTransaction(void)
*/
sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
+ /*
+ * Reset pg_log_query_plan() related global variables.
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+ ProcessLogQueryPlanInterruptActive = false;
+
/*
* check the current transaction state
*/
@@ -5185,6 +5194,14 @@ AbortSubTransaction(void)
*/
sigprocmask(SIG_SETMASK, &UnBlockSig, NULL);
+ /*
+ * Reset pg_log_query_plan() related global variables.
+ * When ActiveQueryDesc is referenced after abort, some of its elements
+ * are freed. To avoid accessing them, reset ActiveQueryDesc here.
+ */
+ ActiveQueryDesc = NULL;
+ ProcessLogQueryPlanInterruptActive = false;
+
/*
* check the current transaction state
*/
diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql
index fe2bb50f46..2e50b596cd 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -757,6 +757,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 a9d5056af4..12c2052dec 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -20,6 +20,7 @@
#include "commands/prepare.h"
#include "foreign/fdwapi.h"
#include "jit/jit.h"
+#include "miscadmin.h"
#include "nodes/extensible.h"
#include "nodes/makefuncs.h"
#include "nodes/nodeFuncs.h"
@@ -27,7 +28,10 @@
#include "parser/parsetree.h"
#include "rewrite/rewriteHandler.h"
#include "storage/bufmgr.h"
+#include "storage/procarray.h"
+#include "tcop/pquery.h"
#include "tcop/tcopprot.h"
+#include "utils/backend_status.h"
#include "utils/builtins.h"
#include "utils/guc_tables.h"
#include "utils/json.h"
@@ -39,6 +43,7 @@
#include "utils/typcache.h"
#include "utils/xml.h"
+bool ProcessLogQueryPlanInterruptActive = false;
/* Hook for plugins to get control in ExplainOneQuery() */
ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
@@ -154,6 +159,9 @@ 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 void WrapExecProcNodeWithExplain(PlanState *ps);
+static void UnWrapExecProcNodeWithExplain(PlanState *ps);
+static TupleTableSlot *ExecProcNodeWithExplain(PlanState *ps);
@@ -795,6 +803,37 @@ ExplainPrintSettings(ExplainState *es)
}
}
+/*
+ * ExplainAssembleLogOutput -
+ * Assemble es->str for logging according to specified contents 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
@@ -1705,6 +1744,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
@@ -1712,7 +1754,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 &&
@@ -5193,3 +5235,187 @@ escape_yaml(StringInfo buf, const char *str)
{
escape_json(buf, str);
}
+
+/*
+ * 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 */
+}
+
+/*
+ * WrapExecProcNodeWithExplain -
+ * Wrap ExecProcNode with ExecProcNodeWithExplain recursively
+ */
+static void
+WrapExecProcNodeWithExplain(PlanState *ps)
+{
+ /* wrapping can be done only once */
+ if (ps->ExecProcNodeOriginal != NULL)
+ return;
+
+ ps->ExecProcNodeOriginal = ps->ExecProcNode;
+ ps->ExecProcNode = ExecProcNodeWithExplain;
+
+ if (ps->lefttree != NULL)
+ WrapExecProcNodeWithExplain(ps->lefttree);
+ if (ps->righttree != NULL)
+ WrapExecProcNodeWithExplain(ps->righttree);
+}
+
+/*
+ * UnWrapExecProcNodeWithExplain -
+ * Unwrap ExecProcNode with ExecProcNodeWithExplain recursively
+ */
+static void
+UnWrapExecProcNodeWithExplain(PlanState *ps)
+{
+ Assert(ps->ExecProcNodeOriginal != NULL);
+
+ ps->ExecProcNode = ps->ExecProcNodeOriginal;
+ ps->ExecProcNodeOriginal = NULL;
+
+ if (ps->lefttree != NULL)
+ UnWrapExecProcNodeWithExplain(ps->lefttree);
+ if (ps->righttree != NULL)
+ UnWrapExecProcNodeWithExplain(ps->righttree);
+}
+
+/*
+ * 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() seems
+ * unsafe, this function just wraps every ExecProcNodes.
+ * In this way, EXPLAIN code is only executed at the timing of ExecProcNode,
+ * which is 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 940499cc61..407dc3fe91 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -55,6 +55,7 @@
#include "tcop/utility.h"
#include "utils/acl.h"
#include "utils/backend_status.h"
+#include "utils/injection_point.h"
#include "utils/lsyscache.h"
#include "utils/partcache.h"
#include "utils/rls.h"
@@ -70,6 +71,9 @@ ExecutorEnd_hook_type ExecutorEnd_hook = NULL;
/* Hook for plugin to get control in ExecCheckPermissions() */
ExecutorCheckPerms_hook_type ExecutorCheckPerms_hook = NULL;
+/* Currently executing query's QueryDesc */
+QueryDesc *ActiveQueryDesc = NULL;
+
/* decls for local routines only used within this module */
static void InitPlan(QueryDesc *queryDesc, int eflags);
static void CheckValidRowMarkRel(Relation rel, RowMarkType markType);
@@ -295,10 +299,25 @@ 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;
+
+#ifdef USE_INJECTION_POINTS
+ INJECTION_POINT("executor-run");
+#endif
+
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 ca41b56952..4043c62538 100644
--- a/src/backend/storage/ipc/procsignal.c
+++ b/src/backend/storage/ipc/procsignal.c
@@ -20,6 +20,7 @@
#include "access/parallel.h"
#include "port/pg_bitutils.h"
#include "commands/async.h"
+#include "commands/explain.h"
#include "miscadmin.h"
#include "pgstat.h"
#include "replication/logicalworker.h"
@@ -652,6 +653,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 6b7903314a..e7fe9a1343 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"
@@ -3460,6 +3461,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 5b536ac50d..3e5b71f4e2 100644
--- a/src/backend/utils/init/globals.c
+++ b/src/backend/utils/init/globals.c
@@ -38,6 +38,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 291ed876fc..a7b2860061 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8267,6 +8267,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 cf195f1359..2d06bf297e 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -17,6 +17,8 @@
#include "lib/stringinfo.h"
#include "parser/parse_node.h"
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
+
typedef enum ExplainFormat
{
EXPLAIN_FORMAT_TEXT,
@@ -61,6 +63,7 @@ typedef struct ExplainState
bool hide_workers; /* set if we find an invisible Gather */
/* 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() */
@@ -100,6 +103,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);
@@ -132,4 +139,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
extern void ExplainCloseGroup(const char *objtype, const char *labelname,
bool labeled, ExplainState *es);
+extern void HandleLogQueryPlanInterrupt(void);
+extern void ProcessLogQueryPlanInterrupt(void);
#endif /* EXPLAIN_H */
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index f900da6157..745c1fa812 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 444a5f0fd5..ddec21ab5d 100644
--- a/src/include/nodes/execnodes.h
+++ b/src/include/nodes/execnodes.h
@@ -1050,6 +1050,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 7d290ea7d0..2e7e1e2d45 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,7 @@ 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/include/utils/elog.h b/src/include/utils/elog.h
index 054dd2bf62..3c6bd1ea7c 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -167,6 +167,7 @@ struct Node;
extern bool message_level_is_interesting(int elevel);
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
extern bool errstart(int elevel, const char *domain);
extern pg_attribute_cold bool errstart_cold(int elevel, const char *domain);
extern void errfinish(const char *filename, int lineno, const char *funcname);
diff --git a/src/test/modules/injection_points/injection_points.c b/src/test/modules/injection_points/injection_points.c
index 7f52d758c5..9e846f04e7 100644
--- a/src/test/modules/injection_points/injection_points.c
+++ b/src/test/modules/injection_points/injection_points.c
@@ -17,6 +17,7 @@
#include "postgres.h"
+#include "commands/explain.h"
#include "fmgr.h"
#include "storage/condition_variable.h"
#include "storage/lwlock.h"
@@ -54,6 +55,7 @@ static InjectionPointSharedState *inj_state = NULL;
extern PGDLLEXPORT void injection_error(const char *name);
extern PGDLLEXPORT void injection_notice(const char *name);
extern PGDLLEXPORT void injection_wait(const char *name);
+extern PGDLLEXPORT void injection_HandleLogQueryPlanInterrupt(const char *name);
/*
@@ -160,6 +162,13 @@ injection_wait(const char *name)
SpinLockRelease(&inj_state->lock);
}
+void
+injection_HandleLogQueryPlanInterrupt(const char *name)
+{
+ HandleLogQueryPlanInterrupt();
+ elog(LOG, "triggered injection_HandleLogQueryPlanInterrupt for injection point %s", name);
+}
+
/*
* SQL function for creating an injection point.
*/
@@ -177,6 +186,8 @@ injection_points_attach(PG_FUNCTION_ARGS)
function = "injection_notice";
else if (strcmp(action, "wait") == 0)
function = "injection_wait";
+ else if (strcmp(action, "logqueryplan") == 0)
+ function = "injection_HandleLogQueryPlanInterrupt";
else
elog(ERROR, "incorrect action \"%s\" for injection point creation", action);
diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out
index d5f61dfad9..c51f379b84 100644
--- a/src/test/regress/expected/misc_functions.out
+++ b/src/test/regress/expected/misc_functions.out
@@ -276,14 +276,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
--------------------------------
@@ -297,8 +298,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
------------------------
@@ -306,15 +307,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
--------------------------------
@@ -323,8 +324,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 928b04db7f..8e603b7255 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -68,39 +68,60 @@ SELECT test_canonicalize_path('./abc/./def/.');
SELECT test_canonicalize_path('./abc/././def/.');
SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
+
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
WHERE backend_type = 'checkpointer';
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
+ TO regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
+ FROM regress_log_function;
+
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
base-commit: 0b84f5c419a300dc1b1a70cf63b9907208e52643
--
2.39.2
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2024-03-13 19:33 ` Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
1 sibling, 1 reply; 15+ messages in thread
From: Robert Haas @ 2024-03-13 19:33 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: [email protected]; James Coleman <[email protected]>; Julien Rouhaud <[email protected]>; Andres Freund <[email protected]>; Étienne BERSAC <[email protected]>; [email protected]; [email protected]; [email protected]
On Wed, Mar 13, 2024 at 1:28 AM torikoshia <[email protected]> wrote:
> - I saw no way to find the next node to be executed from the planstate
> tree, so the patch wraps all the ExecProcNode of the planstate tree at
> CHECK_FOR_INTERRUPTS().
I don't think it does this correctly, because some node types have
children other than the left and right node. See /* special child
plans */ in ExplainNode().
But also ... having to wrap the entire plan tree like this seems
pretty awful. I don't really like the idea of a large-scan plan
modification like this in the middle of the query. I also wonder
whether it interacts properly with JIT. But at the same time, I wonder
how you're supposed to avoid it.
Andres, did you have some clever idea for this feature that would
avoid the need to do this?
--
Robert Haas
EDB: http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
@ 2024-03-26 02:34 ` Andres Freund <[email protected]>
2024-10-28 13:05 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 15+ messages in thread
From: Andres Freund @ 2024-03-26 02:34 UTC (permalink / raw)
To: Robert Haas <[email protected]>; +Cc: torikoshia <[email protected]>; [email protected]; James Coleman <[email protected]>; Julien Rouhaud <[email protected]>; Étienne BERSAC <[email protected]>; [email protected]; [email protected]; [email protected]
Hi,
On 2024-03-13 15:33:02 -0400, Robert Haas wrote:
> But also ... having to wrap the entire plan tree like this seems
> pretty awful. I don't really like the idea of a large-scan plan
> modification like this in the middle of the query.
It's not great. But I also don't really see an alternative with this approach.
I guess we could invent a new CFI version that gets the current PlanState and
use that in all of src/backend/executor/node* and pass the PlanState to that -
but then we could just as well just directly process the interrupt there.
> I also wonder whether it interacts properly with JIT.
I don't think there's a problem unless somebody invests a lot of time in
JITing much more of the query. Which will require a lot more work, basically
redesigning the executor...
> 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.
However it might be worth inventing an executor tree walker in a preliminary
step. We have already quite a few switches over all plan nodes, which we could
largely replace with a helper.
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
@ 2024-10-28 13:05 ` torikoshia <[email protected]>
2025-02-03 12:46 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 15+ messages in thread
From: torikoshia @ 2024-10-28 13:05 UTC (permalink / raw)
To: [email protected]; +Cc: Robert Haas <[email protected]>; [email protected]; James Coleman <[email protected]>; Julien Rouhaud <[email protected]>; Étienne BERSAC <[email protected]>; [email protected]; [email protected]; [email protected]; [email protected]
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 [email protected] 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-mi...
[2]
https://www.postgresql.org/message-id/CA%2BTgmoaaEQtuope6za%3D3GSCZ%2BWJFT4DbF5Cnv0QXFmDnZ_PqFw%40ma...
Regards,
--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.
Attachments:
[text/x-diff] v39-0001-Add-function-to-log-the-plan-of-the-currently-ru.patch (32.8K, ../../[email protected]/2-v39-0001-Add-function-to-log-the-plan-of-the-currently-ru.patch)
download | inline diff:
From 4d41f7ebcac9248c834b245b61b7140618cf3794 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
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
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2024-10-28 13:05 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2025-02-03 12:46 ` torikoshia <[email protected]>
2025-03-08 15:42 ` Re: RFC: Logging plan of the running query Akshat Jaimini <[email protected]>
0 siblings, 1 reply; 15+ messages in thread
From: torikoshia @ 2025-02-03 12:46 UTC (permalink / raw)
To: [email protected]; +Cc: Robert Haas <[email protected]>; James Coleman <[email protected]>; Julien Rouhaud <[email protected]>; Étienne BERSAC <[email protected]>; [email protected]; [email protected]; [email protected]; [email protected]
Hi,
Rebased the patch since it couldn't be applied anymore.
--
Regards,
--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.
Attachments:
[text/x-diff] v40-0001-Add-function-to-log-the-plan-of-the-currently-ru.patch (32.8K, ../../[email protected]/2-v40-0001-Add-function-to-log-the-plan-of-the-currently-ru.patch)
download | inline diff:
From 3f580c17214595eb8d6013674f5f054ec352ab7a Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
Date: Mon, 3 Feb 2025 21:22:40 +0900
Subject: [PATCH v40] 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 f1ad876e82..7f97c1fd51 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 7efc81936a..26fd78e926 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -28409,6 +28409,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>
@@ -28527,6 +28546,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 d331ab90d7..1c630b3a8b 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -36,6 +36,7 @@
#include "catalog/pg_enum.h"
#include "catalog/storage.h"
#include "commands/async.h"
+#include "commands/explain.h"
#include "commands/tablecmds.h"
#include "commands/trigger.h"
#include "common/pg_prng.h"
@@ -2897,6 +2898,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.
@@ -5285,6 +5289,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 591157b1d1..8be3b020b9 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -793,6 +793,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 c24e66f82e..9e5c1aed9b 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);
@@ -889,6 +900,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
@@ -1961,6 +2003,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
@@ -1968,7 +2013,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 &&
@@ -5917,3 +5962,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 604cb0625b..57780568d3 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"
@@ -295,10 +296,21 @@ void
ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction, uint64 count)
{
+ /*
+ * 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);
else
standard_ExecutorRun(queryDesc, direction, count);
+
+ ActiveQueryDesc = save_ActiveQueryDesc;
}
void
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index 7401b6e625..66fa5bdc32 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 5655348a2e..c6a7526b93 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"
@@ -3497,6 +3498,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 b844f9fdae..1e4d90f58b 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 5b8c2ad2a5..e7a0066bcf 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8474,6 +8474,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 ea7419951f..a089fc3169 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 a2b63495ee..291c20187d 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 aca15f771a..5a7ffd4ee2 100644
--- a/src/include/nodes/execnodes.h
+++ b/src/include/nodes/execnodes.h
@@ -1151,6 +1151,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 022fd8ed93..c666a4d708 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,8 @@ typedef enum
PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for shutdown */
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+ PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current
+ * query */
PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */
/* Recovery conflict reasons */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index fa3cc5f2df..73e16cf7c4 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 106dedb519..ca05bd4328 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 753a0f41c0..4c98196956 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -109,39 +109,60 @@ SELECT test_canonicalize_path('./abc/./def/.');
SELECT test_canonicalize_path('./abc/././def/.');
SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
+
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
WHERE backend_type = 'checkpointer';
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
+ TO regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
+ FROM regress_log_function;
+
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
base-commit: 622f678c10202c8a0b350794d504eeef7b773e90
--
2.48.1
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2024-10-28 13:05 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-02-03 12:46 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2025-03-08 15:42 ` Akshat Jaimini <[email protected]>
2025-03-10 05:10 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 15+ messages in thread
From: Akshat Jaimini @ 2025-03-08 15:42 UTC (permalink / raw)
To: [email protected]; +Cc: Atsushi Torikoshi <[email protected]>
Hi,
I think there is still some problem with the patch. I am not able to apply it to the master branch.
Can you please take another look at it?
Thanks,
Akshat Jaimini
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2024-10-28 13:05 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-02-03 12:46 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-08 15:42 ` Re: RFC: Logging plan of the running query Akshat Jaimini <[email protected]>
@ 2025-03-10 05:10 ` torikoshia <[email protected]>
2025-03-21 12:40 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
0 siblings, 1 reply; 15+ messages in thread
From: torikoshia @ 2025-03-10 05:10 UTC (permalink / raw)
To: Akshat Jaimini <[email protected]>; +Cc: [email protected]
On 2025-03-09 00:42, Akshat Jaimini wrote:
> Hi,
> I think there is still some problem with the patch. I am not able to
> apply it to the master branch.
>
> Can you please take another look at it?
Thanks for pointing it out!
Modified it.
BTW the patch adds about 400 lines to explain.c and it may be better to
split the file as well as 9173e8b6046, but I leave it as it is for now.
--
Regards,
--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.
Attachments:
[text/x-diff] v41-0001-Add-function-to-log-the-plan-of-the-currently-ru.patch (32.9K, ../../[email protected]/2-v41-0001-Add-function-to-log-the-plan-of-the-currently-ru.patch)
download | inline diff:
From 699264fbc1f4e99114966eaeba55a0ec5184e1c2 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
Date: Mon, 10 Mar 2025 14:01:54 +0900
Subject: [PATCH v41] 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 7007a226c0..85cfe1b4f4 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -408,26 +408,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 51dd8ad657..d1a16a89fb 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -28553,6 +28553,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>
@@ -28671,6 +28690,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 1b4f21a88d..ca973a0368 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -36,6 +36,7 @@
#include "catalog/pg_enum.h"
#include "catalog/storage.h"
#include "commands/async.h"
+#include "commands/explain.h"
#include "commands/tablecmds.h"
#include "commands/trigger.h"
#include "common/pg_prng.h"
@@ -2897,6 +2898,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.
@@ -5285,6 +5289,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 566f308e44..ec2e1c1fd9 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -775,6 +775,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;
REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
+
--
-- We also set up some things as accessible to standard roles.
--
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index d8a7232ced..7f63f47fce 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -24,6 +24,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"
@@ -31,7 +32,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"
@@ -43,6 +46,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;
@@ -154,6 +162,9 @@ static ExplainWorkersState *ExplainCreateWorkersState(int num_workers);
static void ExplainOpenWorker(int n, ExplainState *es);
static void ExplainCloseWorker(int n, ExplainState *es);
static void ExplainFlushWorkersState(ExplainState *es);
+static TupleTableSlot *ExecProcNodeWithExplain(PlanState *ps);
+static void WrapExecProcNodeWithExplain(PlanState *ps);
+static void UnwrapExecProcNodeWithExplain(PlanState *ps);
@@ -875,6 +886,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
@@ -1947,6 +1989,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
@@ -1954,7 +1999,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 &&
@@ -4931,3 +4976,328 @@ ExplainFlushWorkersState(ExplainState *es)
pfree(wstate->worker_state_save);
pfree(wstate);
}
+
+/*
+ * 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 0493b7d536..63284517fa 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"
@@ -362,10 +363,21 @@ void
ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction, uint64 count)
{
+ /*
+ * 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);
else
standard_ExecutorRun(queryDesc, direction, count);
+
+ ActiveQueryDesc = save_ActiveQueryDesc;
}
void
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index 7d20196550..ced80588ab 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"
@@ -690,6 +691,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 947ffb4042..f4c4e64f9f 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"
@@ -3499,6 +3500,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 b844f9fdae..1e4d90f58b 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 cede992b6e..c8ed884109 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8499,6 +8499,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 64547bd9b9..47c8376a60 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() */
@@ -112,6 +116,10 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, CachedPlan *cplan,
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);
@@ -120,4 +128,8 @@ extern void ExplainPrintJITSummary(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainQueryParameters(ExplainState *es, ParamListInfo params, int maxlen);
+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 a2b63495ee..291c20187d 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 a323fa98bb..73431a3223 100644
--- a/src/include/nodes/execnodes.h
+++ b/src/include/nodes/execnodes.h
@@ -1160,6 +1160,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 022fd8ed93..c666a4d708 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,8 @@ typedef enum
PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for shutdown */
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+ PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current
+ * query */
PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */
/* Recovery conflict reasons */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index fa3cc5f2df..73e16cf7c4 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 d3f5d16a67..7dcb9951e7 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 aaebb29833..92330355f6 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -109,39 +109,60 @@ SELECT test_canonicalize_path('./abc/./def/.');
SELECT test_canonicalize_path('./abc/././def/.');
SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
+
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
WHERE backend_type = 'checkpointer';
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
+ TO regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
+ FROM regress_log_function;
+
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
base-commit: e033696596566d422a0eae47adca371a210ed730
--
2.48.1
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2024-10-28 13:05 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-02-03 12:46 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-08 15:42 ` Re: RFC: Logging plan of the running query Akshat Jaimini <[email protected]>
2025-03-10 05:10 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2025-03-21 12:40 ` torikoshia <[email protected]>
2025-03-31 18:51 ` Re: RFC: Logging plan of the running query Sadeq Dousti <[email protected]>
2025-03-31 19:24 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
0 siblings, 2 replies; 15+ messages in thread
From: torikoshia @ 2025-03-21 12:40 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]
Hi,
Rebased it again.
On 2025-03-10 14:10, torikoshia wrote:
> BTW the patch adds about 400 lines to explain.c and it may be better
> to split the file as well as 9173e8b6046, but I leave it as it is for
> now.
This part remains unchanged.
--
Regards,
--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.
Attachments:
[text/x-diff] v42-0001-Add-function-to-log-the-plan-of-the-currently-ru.patch (33.4K, ../../[email protected]/2-v42-0001-Add-function-to-log-the-plan-of-the-currently-ru.patch)
download | inline diff:
From ea5092a13e7ac426ac40397ceff5f67355b7723f Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <[email protected]>
Date: Fri, 21 Mar 2025 21:34:08 +0900
Subject: [PATCH v42] 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 | 13 +
src/include/commands/explain_state.h | 1 +
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 +-
18 files changed, 557 insertions(+), 42 deletions(-)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 3b73bd1910..5807135000 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -409,26 +409,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 6fa1d6586b..da80b7ef8a 100644
--- a/doc/src/sgml/func.sgml
+++ b/doc/src/sgml/func.sgml
@@ -28570,6 +28570,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>
@@ -28688,6 +28707,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 b885513f76..1b4c0abea5 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -36,6 +36,7 @@
#include "catalog/pg_enum.h"
#include "catalog/storage.h"
#include "commands/async.h"
+#include "commands/explain.h"
#include "commands/tablecmds.h"
#include "commands/trigger.h"
#include "common/pg_prng.h"
@@ -2904,6 +2905,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.
@@ -5296,6 +5300,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 566f308e44..ec2e1c1fd9 100644
--- a/src/backend/catalog/system_functions.sql
+++ b/src/backend/catalog/system_functions.sql
@@ -775,6 +775,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;
REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC;
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
+
--
-- We also set up some things as accessible to standard roles.
--
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 391b34a2af..bdfe545e76 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -26,6 +26,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"
@@ -33,7 +34,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"
@@ -45,6 +48,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;
@@ -165,6 +173,9 @@ static ExplainWorkersState *ExplainCreateWorkersState(int num_workers);
static void ExplainOpenWorker(int n, ExplainState *es);
static void ExplainCloseWorker(int n, ExplainState *es);
static void ExplainFlushWorkersState(ExplainState *es);
+static TupleTableSlot *ExecProcNodeWithExplain(PlanState *ps);
+static void WrapExecProcNodeWithExplain(PlanState *ps);
+static void UnwrapExecProcNodeWithExplain(PlanState *ps);
@@ -756,6 +767,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
@@ -1828,6 +1870,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
@@ -1835,7 +1880,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 &&
@@ -4987,3 +5032,328 @@ ExplainFlushWorkersState(ExplainState *es)
pfree(wstate->worker_state_save);
pfree(wstate);
}
+
+/*
+ * 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 e9bd98c773..755387d70b 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"
@@ -362,10 +363,21 @@ void
ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction, uint64 count)
{
+ /*
+ * 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);
else
standard_ExecutorRun(queryDesc, direction, count);
+
+ ActiveQueryDesc = save_ActiveQueryDesc;
}
void
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index 7d20196550..ced80588ab 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"
@@ -690,6 +691,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 0554a4ae3c..cf97f2030b 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"
@@ -3507,6 +3508,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 b844f9fdae..1e4d90f58b 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 890822eaf7..f47359fe3c 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -8509,6 +8509,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 387839eb5d..dba686ac97 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -18,6 +18,9 @@
struct ExplainState; /* defined in explain_state.h */
+extern PGDLLIMPORT QueryDesc *ActiveQueryDesc;
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
+
/* Hook for plugins to get control in ExplainOneQuery() */
typedef void (*ExplainOneQuery_hook_type) (Query *query,
int cursorOptions,
@@ -72,6 +75,12 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, CachedPlan *cplan,
const BufferUsage *bufusage,
const MemoryContextCounters *mem_counters);
+extern void ExplainAssembleLogOutput(struct ExplainState *es, QueryDesc *queryDesc,
+ int logFormat, bool logTriggers,
+ int logParameterMaxLength);
+
+extern void ExplainPrintPlan(struct ExplainState *es, QueryDesc *queryDesc);
+extern void ExplainPrintTriggers(struct ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintPlan(struct ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintTriggers(struct ExplainState *es,
QueryDesc *queryDesc);
@@ -83,4 +92,8 @@ extern void ExplainQueryText(struct ExplainState *es, QueryDesc *queryDesc);
extern void ExplainQueryParameters(struct ExplainState *es,
ParamListInfo params, int maxlen);
+extern void HandleLogQueryPlanInterrupt(void);
+extern void ProcessLogQueryPlanInterrupt(void);
+extern void ResetLogQueryPlanState(void);
+
#endif /* EXPLAIN_H */
diff --git a/src/include/commands/explain_state.h b/src/include/commands/explain_state.h
index 32728f5d1a..fcef956396 100644
--- a/src/include/commands/explain_state.h
+++ b/src/include/commands/explain_state.h
@@ -71,6 +71,7 @@ typedef struct ExplainState
* entry */
/* state related to the current plan node */
ExplainWorkersState *workers_state; /* needed if parallel plan */
+ bool signaled; /* whether explain is called by signal */
/* extensions */
void **extension_state;
int extension_state_allocated;
diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h
index 603d042435..3f46354cda 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 d4d4e65518..b95e4b97d0 100644
--- a/src/include/nodes/execnodes.h
+++ b/src/include/nodes/execnodes.h
@@ -1160,6 +1160,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 022fd8ed93..c666a4d708 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -35,6 +35,8 @@ typedef enum
PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for shutdown */
PROCSIG_BARRIER, /* global barrier interrupt */
PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */
+ PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current
+ * query */
PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */
/* Recovery conflict reasons */
diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h
index fa3cc5f2df..73e16cf7c4 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 d3f5d16a67..7dcb9951e7 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 aaebb29833..92330355f6 100644
--- a/src/test/regress/sql/misc_functions.sql
+++ b/src/test/regress/sql/misc_functions.sql
@@ -109,39 +109,60 @@ SELECT test_canonicalize_path('./abc/./def/.');
SELECT test_canonicalize_path('./abc/././def/.');
SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno');
+-- Test logging functions
--
--- pg_log_backend_memory_contexts()
---
--- Memory contexts are logged and they are not returned to the function.
+-- The outputs of these functions are logged and they are not returned to
+-- the function.
-- Furthermore, their contents can vary depending on the timing. However,
-- we can at least verify that the code doesn't fail, and that the
-- permissions are set properly.
--
+-- pg_log_backend_memory_contexts()
+
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity
WHERE backend_type = 'checkpointer';
-CREATE ROLE regress_log_memory;
+CREATE ROLE regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no
GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- TO regress_log_memory;
+ TO regress_log_function;
-SELECT has_function_privilege('regress_log_memory',
+SELECT has_function_privilege('regress_log_function',
'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes
-SET ROLE regress_log_memory;
+SET ROLE regress_log_function;
SELECT pg_log_backend_memory_contexts(pg_backend_pid());
RESET ROLE;
REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer)
- FROM regress_log_memory;
+ FROM regress_log_function;
+
+-- pg_log_query_plan()
+SELECT pg_log_query_plan(pg_backend_pid());
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- no
+
+GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ TO regress_log_function;
+
+SELECT has_function_privilege('regress_log_function',
+ 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes
+
+SET ROLE regress_log_function;
+SELECT pg_log_query_plan(pg_backend_pid());
+RESET ROLE;
+
+REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer)
+ FROM regress_log_function;
-DROP ROLE regress_log_memory;
+DROP ROLE regress_log_function;
--
-- Test some built-in SRFs
base-commit: 1d617a20284f887cb9cdfe5693eec155e8016517
--
2.48.1
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2024-10-28 13:05 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-02-03 12:46 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-08 15:42 ` Re: RFC: Logging plan of the running query Akshat Jaimini <[email protected]>
2025-03-10 05:10 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-21 12:40 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2025-03-31 18:51 ` Sadeq Dousti <[email protected]>
2025-04-03 05:34 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
1 sibling, 1 reply; 15+ messages in thread
From: Sadeq Dousti @ 2025-03-31 18:51 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: [email protected]; Sergey Dudoladov <[email protected]>
Hi,
Sergey and I reviewed this patch and have a few comments, listed below.
> BTW the patch adds about 400 lines to explain.c and it may be better
> to split the file as well as 9173e8b6046, but I leave it as it is for
> now.
1. As rightfully described by the OP above, explain.c has grown too big. In
addition, explain.h is added to quite a number of other files.
2. We wanted to entertain the possibility of a GUC variable to enable the
feature. That is, having it disabled by default, and the DBA can
selectively enable it on the fly. The reasoning is that it can affect some
workloads in an unforeseen way, so this choice can make the next Postgres
release safer. In future releases, we can make the default "enabled",
assuming enough real-world scenarios have proven the feature safe (i.e.,
not affecting the DB performance noticeably).
3. In the email thread for this patch, we saw some attempts to measure the
performance overhead of the feature. We suggest a more rigorous study,
including memory overhead in addition to time overhead. We came to the
conclusion that analytical workloads - with complicated query plans - and a
high query rate are the best to attempt such benchmarks.
4. In PGConf EU 2024, there was a talk by Rafael Castro titled "Debugging
active queries" [1], and he also submitted a recent patch titled "Proposal:
Progressive explain" [2]. We see a lot of similarities in the idea behind
that patch and this one, and would like to suggest joining forces for an
ideal outcome.
[1] https://www.youtube.com/watch?v=6ahTb-7C05c
[2] https://commitfest.postgresql.org/patch/5473/
Best Regards,
Sadeq Dousti & Sergey Dudoladov
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2024-10-28 13:05 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-02-03 12:46 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-08 15:42 ` Re: RFC: Logging plan of the running query Akshat Jaimini <[email protected]>
2025-03-10 05:10 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-21 12:40 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-31 18:51 ` Re: RFC: Logging plan of the running query Sadeq Dousti <[email protected]>
@ 2025-04-03 05:34 ` torikoshia <[email protected]>
0 siblings, 0 replies; 15+ messages in thread
From: torikoshia @ 2025-04-03 05:34 UTC (permalink / raw)
To: Sadeq Dousti <[email protected]>; +Cc: [email protected]; Sergey Dudoladov <[email protected]>
On 2025-04-01 03:51, Sadeq Dousti wrote:
> Hi,
>
> Sergey and I reviewed this patch and have a few comments, listed
> below.
Thanks for your review!
>> BTW the patch adds about 400 lines to explain.c and it may be better
>> to split the file as well as 9173e8b6046, but I leave it as it is
> for
>> now.
>
> 1. As rightfully described by the OP above, explain.c has grown too
> big. In addition, explain.h is added to quite a number of other files.
Agreed.
>
> 2. We wanted to entertain the possibility of a GUC variable to enable
> the feature. That is, having it disabled by default, and the DBA can
> selectively enable it on the fly. The reasoning is that it can affect
> some workloads in an unforeseen way, so this choice can make the next
> Postgres release safer. In future releases, we can make the default
> "enabled", assuming enough real-world scenarios have proven the
> feature safe (i.e., not affecting the DB performance noticeably).
Agreed.
> 3. In the email thread for this patch, we saw some attempts to measure
> the performance overhead of the feature. We suggest a more rigorous
> study, including memory overhead in addition to time overhead. We came
> to the conclusion that analytical workloads - with complicated query
> plans - and a high query rate are the best to attempt such benchmarks.
Agreed.
> 4. In PGConf EU 2024, there was a talk by Rafael Castro titled
> "Debugging active queries" [1], and he also submitted a recent patch
> titled "Proposal: Progressive explain" [2]. We see a lot of
> similarities in the idea behind that patch and this one, and would
> like to suggest joining forces for an ideal outcome.
As we have been discussing in this thread recently, I believe that since
this patch has a narrower scope, it makes sense to complete it first and
then extend it to support progress tracking in a step-by-step manner.
--
Regards,
--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2024-10-28 13:05 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-02-03 12:46 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-08 15:42 ` Re: RFC: Logging plan of the running query Akshat Jaimini <[email protected]>
2025-03-10 05:10 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-21 12:40 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2025-03-31 19:24 ` Robert Haas <[email protected]>
2025-04-01 01:43 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
1 sibling, 1 reply; 15+ messages in thread
From: Robert Haas @ 2025-03-31 19:24 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: [email protected]; [email protected]; Rafael Thofehrn Castro <[email protected]>
On Fri, Mar 21, 2025 at 8:40 AM torikoshia <[email protected]> wrote:
> Rebased it again.
Hi,
I apologize for not having noticed this thread sooner. I just became
aware of it as a result of a discussion in the hacking Discord server.
I think this has got a lot over overlap with the progressive EXPLAIN
patch from Rafael Castro, which I have been reviewing, but I am not
sure why we have two different patch sets here. Why is that?
Thanks,
--
Robert Haas
EDB: http://www.enterprisedb.com
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
2024-03-26 02:34 ` Re: RFC: Logging plan of the running query Andres Freund <[email protected]>
2024-10-28 13:05 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-02-03 12:46 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-08 15:42 ` Re: RFC: Logging plan of the running query Akshat Jaimini <[email protected]>
2025-03-10 05:10 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-21 12:40 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2025-03-31 19:24 ` Re: RFC: Logging plan of the running query Robert Haas <[email protected]>
@ 2025-04-01 01:43 ` torikoshia <[email protected]>
0 siblings, 0 replies; 15+ messages in thread
From: torikoshia @ 2025-04-01 01:43 UTC (permalink / raw)
To: Robert Haas <[email protected]>; [email protected]; +Cc: [email protected]; [email protected]
On 2025-04-01 04:24, Robert Haas wrote:
> On Fri, Mar 21, 2025 at 8:40 AM torikoshia <[email protected]>
> wrote:
>> Rebased it again.
>
> Hi,
>
> I apologize for not having noticed this thread sooner.
Thank you for your checking! No worries.
> I just became
> aware of it as a result of a discussion in the hacking Discord server.
> I think this has got a lot over overlap with the progressive EXPLAIN
> patch from Rafael Castro, which I have been reviewing, but I am not
> sure why we have two different patch sets here. Why is that?
This thread proposes a feature to log the results of a plain EXPLAIN
(without ANALYZE). From Rafael Castro's presentation materials at
pgconf.eu 2024 [1], I understand that he built a new patch on top of
this one, adding functionality to track execution progress and display
results in a view.
He also mentioned that he used the way of wrapping plan nodes from this
patch during the development to solve a problem[2].
I think that's why there are overlaps between the two.
Previously, Rafael proposed a patch in this thread that added execution
progress tracking. However, I felt that expanding the scope could make
it harder to get the patch reviewed or committed. So, I suggested first
completing a feature that only retrieves the execution plan of a running
query, and then developing execution progress tracking afterward[3].
As far as I remember, he did not respond to this thread after my
suggestion but instead started a new thread later[4]. Based on that, I
assume he would not have agreed with my proposed approach.
Rafael, please let us know if there are any misunderstandings in the
above.
In this thread, I aimed to output the plan without requiring prior
configuration if possible. However, based on your comment on Rafael's
thread[5], it seems that this approach would be difficult:
One way in which this proposal seems safer than previous proposals is
that previous proposals have involved session A poking session B and
trying to get session B to emit an EXPLAIN on the fly with no prior
setup. That would be very useful, but I think it's more difficult and
more risky than this proposal, where all the configuration happens in
the session that is going to emit the EXPLAIN output.
I was considering whether to introduce a GUC in this patch to allow for
prior setup before outputting the plan or to switch to Rafael's patch
after reviewing its details. However, since there isn’t much time left
before the feature freeze, if you have already reviewed Rafael's patch
and there is a chance it could be committed, it would be better to focus
on that.
[1] https://www.youtube.com/watch?v=6ahTb-7C05c (mentions this patch
after the 12-minute mark)
[2]
https://www.postgresql.org/message-id/CAG0ozMo30smtXXOR8bSCbhaZAQHo4%3DezerLitpERk85Q0ga%2BFw%40mail...
[3]
https://www.postgresql.org/message-id/c161b5e7e1888eb9c9eb182a7d9dcf89%40oss.nttdata.com
[4]
https://www.postgresql.org/message-id/flat/CAG0ozMo30smtXXOR8bSCbhaZAQHo4%3DezerLitpERk85Q0ga%2BFw%4...
[5]
https://www.postgresql.org/message-id/CA%2BTgmoaD985%2BVLwR93c8PjSaoBqxw72Eu7pfBJcArzhjJ71aRw%40mail...
--
Regards,
--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
@ 2024-03-14 01:02 ` jian he <[email protected]>
2024-03-18 05:39 ` Re: RFC: Logging plan of the running query torikoshia <[email protected]>
1 sibling, 1 reply; 15+ messages in thread
From: jian he @ 2024-03-14 01:02 UTC (permalink / raw)
To: torikoshia <[email protected]>; +Cc: [email protected]; James Coleman <[email protected]>; Julien Rouhaud <[email protected]>; Andres Freund <[email protected]>; Étienne BERSAC <[email protected]>; [email protected]; [email protected]; [email protected]
On Wed, Mar 13, 2024 at 1:28 PM torikoshia <[email protected]> wrote:
>
> On Fri, Feb 16, 2024 at 11:42 PM torikoshia <[email protected]>
> wrote:
> > I'm not so sure about the implementation now, i.e. finding the next
> > node
> > to be executed from the planstate tree, but I'm going to try this
> > approach.
>
> Attached a patch which takes this approach.
>
one minor issue.
I understand the regress test, compare the expected outcome with
testrun outcome,
but can you enlighten me about how you check if the change you made in
contrib/auto_explain/t/001_auto_explain.pl is correct.
(i am not familiar with perl).
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index cf195f1359..2d06bf297e 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -17,6 +17,8 @@
#include "lib/stringinfo.h"
#include "parser/parse_node.h"
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index 054dd2bf62..3c6bd1ea7c 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -167,6 +167,7 @@ struct Node;
extern bool message_level_is_interesting(int elevel);
+extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
utils/elog.h is already included in src/include/postgres.h.
you don't need to declare ProcessLogQueryPlanInterruptActive at
include/commands/explain.h?
generally a variable should only declare once?
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: RFC: Logging plan of the running query
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-14 01:02 ` Re: RFC: Logging plan of the running query jian he <[email protected]>
@ 2024-03-18 05:39 ` torikoshia <[email protected]>
0 siblings, 0 replies; 15+ messages in thread
From: torikoshia @ 2024-03-18 05:39 UTC (permalink / raw)
To: jian he <[email protected]>; [email protected]; +Cc: [email protected]; James Coleman <[email protected]>; Julien Rouhaud <[email protected]>; Andres Freund <[email protected]>; Étienne BERSAC <[email protected]>; [email protected]; [email protected]
On 2024-03-14 04:33, Robert Haas wrote:
Thanks for your review!
> On Wed, Mar 13, 2024 at 1:28 AM torikoshia <[email protected]>
> wrote:
>> - I saw no way to find the next node to be executed from the planstate
>> tree, so the patch wraps all the ExecProcNode of the planstate tree at
>> CHECK_FOR_INTERRUPTS().
>
> I don't think it does this correctly, because some node types have
> children other than the left and right node. See /* special child
> plans */ in ExplainNode().
Agreed.
> But also ... having to wrap the entire plan tree like this seems
> pretty awful. I don't really like the idea of a large-scan plan
> modification like this in the middle of the query.
Yeah, but I haven't come up with other ideas to select the appropriate
node to wrap.
> Andres, did you have some clever idea for this feature that would
> avoid the need to do this?
On 2024-03-14 10:02, jian he wrote:
> On Wed, Mar 13, 2024 at 1:28 PM torikoshia <[email protected]>
> wrote:
>>
>> On Fri, Feb 16, 2024 at 11:42 PM torikoshia
>> <[email protected]>
>> wrote:
>> > I'm not so sure about the implementation now, i.e. finding the next
>> > node
>> > to be executed from the planstate tree, but I'm going to try this
>> > approach.
>>
>> Attached a patch which takes this approach.
>>
>
> one minor issue.
> I understand the regress test, compare the expected outcome with
> testrun outcome,
> but can you enlighten me about how you check if the change you made in
> contrib/auto_explain/t/001_auto_explain.pl is correct.
> (i am not familiar with perl).
$pg_log_plan_query_output saves the output plan of pg_log_query_plan()
and $auto_explain_output saves the output plan of auto_explain.
The test checks the both are the same using cmp_ok().
Did I answer your question?
> diff --git a/src/include/commands/explain.h
> b/src/include/commands/explain.h
> index cf195f1359..2d06bf297e 100644
> --- a/src/include/commands/explain.h
> +++ b/src/include/commands/explain.h
> @@ -17,6 +17,8 @@
> #include "lib/stringinfo.h"
> #include "parser/parse_node.h"
> +extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
>
> diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
> index 054dd2bf62..3c6bd1ea7c 100644
> --- a/src/include/utils/elog.h
> +++ b/src/include/utils/elog.h
> @@ -167,6 +167,7 @@ struct Node;
> extern bool message_level_is_interesting(int elevel);
> +extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive;
>
> utils/elog.h is already included in src/include/postgres.h.
> you don't need to declare ProcessLogQueryPlanInterruptActive at
> include/commands/explain.h?
> generally a variable should only declare once?
Yeah, this declaration is not necessary and we should add include
commands/explain.h to src/backend/access/transam/xact.c.
--
Regards,
--
Atsushi Torikoshi
NTT DATA Group Corporation
^ permalink raw reply [nested|flat] 15+ messages in thread
* [PATCH v3 1/3] Adding per backend commit and rollback counters
@ 2025-08-04 08:14 Bertrand Drouvot <[email protected]>
0 siblings, 0 replies; 15+ messages in thread
From: Bertrand Drouvot @ 2025-08-04 08:14 UTC (permalink / raw)
It relies on the existing per backend statistics that has been added in
9aea73fc61d. A new function is called in AtEOXact_PgStat() to increment those
two new counters.
---
src/backend/utils/activity/pgstat_backend.c | 57 +++++++++++++++++++++
src/backend/utils/activity/pgstat_xact.c | 1 +
src/include/pgstat.h | 8 +++
src/include/utils/pgstat_internal.h | 4 +-
4 files changed, 69 insertions(+), 1 deletion(-)
78.9% src/backend/utils/activity/
11.2% src/include/utils/
9.8% src/include/
diff --git a/src/backend/utils/activity/pgstat_backend.c b/src/backend/utils/activity/pgstat_backend.c
index 8714a85e2d9..bf164854c4b 100644
--- a/src/backend/utils/activity/pgstat_backend.c
+++ b/src/backend/utils/activity/pgstat_backend.c
@@ -47,6 +47,11 @@ static bool backend_has_iostats = false;
*/
static WalUsage prevBackendWalUsage;
+/*
+ * For backend commit and rollback statistics.
+ */
+static bool backend_has_xactstats = false;
+
/*
* Utility routines to report I/O stats for backends, kept here to avoid
* exposing PendingBackendStats to the outside world.
@@ -259,6 +264,34 @@ pgstat_flush_backend_entry_wal(PgStat_EntryRef *entry_ref)
prevBackendWalUsage = pgWalUsage;
}
+/*
+ * Flush out locally pending backend transaction statistics. Locking is managed
+ * by the caller.
+ */
+static void
+pgstat_flush_backend_entry_xact(PgStat_EntryRef *entry_ref)
+{
+ PgStatShared_Backend *shbackendent;
+
+ /*
+ * This function can be called even if nothing at all has happened for
+ * transaction statistics. In this case, avoid unnecessarily modifying
+ * the stats entry.
+ */
+ if (!backend_has_xactstats)
+ return;
+
+ shbackendent = (PgStatShared_Backend *) entry_ref->shared_stats;
+
+ shbackendent->stats.xact_commit += PendingBackendStats.pending_xact_commit;
+ shbackendent->stats.xact_rollback += PendingBackendStats.pending_xact_rollback;
+
+ PendingBackendStats.pending_xact_commit = 0;
+ PendingBackendStats.pending_xact_rollback = 0;
+
+ backend_has_xactstats = false;
+}
+
/*
* Flush out locally pending backend statistics
*
@@ -283,6 +316,10 @@ pgstat_flush_backend(bool nowait, bits32 flags)
pgstat_backend_wal_have_pending())
has_pending_data = true;
+ /* Some transaction data pending? */
+ if ((flags & PGSTAT_BACKEND_FLUSH_XACT) && backend_has_xactstats)
+ has_pending_data = true;
+
if (!has_pending_data)
return false;
@@ -298,6 +335,9 @@ pgstat_flush_backend(bool nowait, bits32 flags)
if (flags & PGSTAT_BACKEND_FLUSH_WAL)
pgstat_flush_backend_entry_wal(entry_ref);
+ if (flags & PGSTAT_BACKEND_FLUSH_XACT)
+ pgstat_flush_backend_entry_xact(entry_ref);
+
pgstat_unlock_entry(entry_ref);
return false;
@@ -400,3 +440,20 @@ pgstat_backend_reset_timestamp_cb(PgStatShared_Common *header, TimestampTz ts)
{
((PgStatShared_Backend *) header)->stats.stat_reset_timestamp = ts;
}
+
+void
+AtEOXact_PgStat_Backend(bool isCommit, bool parallel)
+{
+ /* Don't count parallel worker transaction stats */
+ if (!parallel)
+ {
+ /* Count transaction commit or abort */
+ if (isCommit)
+ PendingBackendStats.pending_xact_commit++;
+ else
+ PendingBackendStats.pending_xact_rollback++;
+
+ backend_has_xactstats = true;
+ pgstat_report_fixed = true;
+ }
+}
diff --git a/src/backend/utils/activity/pgstat_xact.c b/src/backend/utils/activity/pgstat_xact.c
index bc9864bd8d9..cd1c501c165 100644
--- a/src/backend/utils/activity/pgstat_xact.c
+++ b/src/backend/utils/activity/pgstat_xact.c
@@ -42,6 +42,7 @@ AtEOXact_PgStat(bool isCommit, bool parallel)
PgStat_SubXactStatus *xact_state;
AtEOXact_PgStat_Database(isCommit, parallel);
+ AtEOXact_PgStat_Backend(isCommit, parallel);
/* handle transactional stats information */
xact_state = pgStatXactStack;
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 202bd2d5ace..9efc0e10ebf 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -490,6 +490,8 @@ typedef struct PgStat_Backend
TimestampTz stat_reset_timestamp;
PgStat_BktypeIO io_stats;
PgStat_WalCounters wal_counters;
+ PgStat_Counter xact_commit;
+ PgStat_Counter xact_rollback;
} PgStat_Backend;
/* ---------
@@ -502,6 +504,12 @@ typedef struct PgStat_BackendPending
* Backend statistics store the same amount of IO data as PGSTAT_KIND_IO.
*/
PgStat_PendingIO pending_io;
+
+ /*
+ * Transaction statistics pending flush.
+ */
+ PgStat_Counter pending_xact_commit;
+ PgStat_Counter pending_xact_rollback;
} PgStat_BackendPending;
/*
diff --git a/src/include/utils/pgstat_internal.h b/src/include/utils/pgstat_internal.h
index 6cf00008f63..23ea8ffd618 100644
--- a/src/include/utils/pgstat_internal.h
+++ b/src/include/utils/pgstat_internal.h
@@ -616,12 +616,14 @@ extern void pgstat_archiver_snapshot_cb(void);
/* flags for pgstat_flush_backend() */
#define PGSTAT_BACKEND_FLUSH_IO (1 << 0) /* Flush I/O statistics */
#define PGSTAT_BACKEND_FLUSH_WAL (1 << 1) /* Flush WAL statistics */
-#define PGSTAT_BACKEND_FLUSH_ALL (PGSTAT_BACKEND_FLUSH_IO | PGSTAT_BACKEND_FLUSH_WAL)
+#define PGSTAT_BACKEND_FLUSH_XACT (1 << 2) /* Flush xact statistics */
+#define PGSTAT_BACKEND_FLUSH_ALL (PGSTAT_BACKEND_FLUSH_IO | PGSTAT_BACKEND_FLUSH_WAL | PGSTAT_BACKEND_FLUSH_XACT)
extern bool pgstat_flush_backend(bool nowait, bits32 flags);
extern bool pgstat_backend_flush_cb(bool nowait);
extern void pgstat_backend_reset_timestamp_cb(PgStatShared_Common *header,
TimestampTz ts);
+extern void AtEOXact_PgStat_Backend(bool isCommit, bool parallel);
/*
* Functions in pgstat_bgwriter.c
--
2.34.1
--u6+Li7FU79Mt/lVd
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
filename="v3-0002-Adding-XID-generation-count-per-backend.patch"
^ permalink raw reply [nested|flat] 15+ messages in thread
end of thread, other threads:[~2025-08-04 08:14 UTC | newest]
Thread overview: 15+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2024-03-13 05:28 Re: RFC: Logging plan of the running query torikoshia <[email protected]>
2024-03-13 19:33 ` Robert Haas <[email protected]>
2024-03-26 02:34 ` Andres Freund <[email protected]>
2024-10-28 13:05 ` torikoshia <[email protected]>
2025-02-03 12:46 ` torikoshia <[email protected]>
2025-03-08 15:42 ` Akshat Jaimini <[email protected]>
2025-03-10 05:10 ` torikoshia <[email protected]>
2025-03-21 12:40 ` torikoshia <[email protected]>
2025-03-31 18:51 ` Sadeq Dousti <[email protected]>
2025-04-03 05:34 ` torikoshia <[email protected]>
2025-03-31 19:24 ` Robert Haas <[email protected]>
2025-04-01 01:43 ` torikoshia <[email protected]>
2024-03-14 01:02 ` jian he <[email protected]>
2024-03-18 05:39 ` torikoshia <[email protected]>
2025-08-04 08:14 [PATCH v3 1/3] Adding per backend commit and rollback counters Bertrand Drouvot <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox