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 adds pg_log_query_plan() function that requests to log the plan of the currently executing query. On receipt of the request, codes for logging plan is wrapped to every ExecProcNode 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. 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.

Author: Atsushi Torikoshi

contrib/auto_explain/auto_explain.c

@@ -15,6 +15,7 @@
 #include <limits.h>
 
 #include "access/parallel.h"
+#include "commands/dynamic_explain.h"
 #include "commands/explain.h"
 #include "commands/explain_format.h"
 #include "commands/explain_state.h"
@@ -412,26 +413,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
 es->format = auto_explain_log_format;
 es->settings = auto_explain_log_settings;
 
-ExplainBeginOutput(es);
-ExplainQueryText(es, queryDesc);
-ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
-ExplainPrintPlan(es, queryDesc);
-if (es->analyze && auto_explain_log_triggers)
-ExplainPrintTriggers(es, queryDesc);
-if (es->costs)
-ExplainPrintJITSummary(es, queryDesc);
-ExplainEndOutput(es);
-
-/* Remove last line break */
-if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
-es->str->data[--es->str->len] = '\0';
-
-/* Fix JSON to output an object */
-if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
-{
-es->str->data[0] = '{';
-es->str->data[es->str->len - 1] = '}';
-}
+ExplainStringAssemble(es, queryDesc, auto_explain_log_format,
+auto_explain_log_triggers,
+auto_explain_log_parameter_max_length);
 
 /*
 * Note: we rely on the existing logging of context or

doc/src/sgml/func.sgml

@@ -28821,6 +28821,29 @@ acl | {postgres=arwdDxtm/postgres,foo=r/postgres}
 </para></entry>
 </row>
 
+<row>
+<entry role="func_table_entry"><para role="func_signature">
+<indexterm>
+<primary>pg_log_query_plan</primary>
+</indexterm>
+<function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
+<returnvalue>boolean</returnvalue>
+</para>
+<para>
+Requests to log the plan of the query currently running on the
+backend with specified process ID.
+It will be logged at <literal>LOG</literal> message level and
+will appear in the server log based on the log
+configuration set (See <xref linkend="runtime-config-logging"/>
+for more information), but will not be sent to the client
+regardless of <xref linkend="guc-client-min-messages"/>.
+</para>
+<para>
+This function is restricted to superusers by default, but other
+users can be granted EXECUTE to run the function.
+</para></entry>
+</row>
+
 <row>
 <entry role="func_table_entry"><para role="func_signature">
 <indexterm>
@@ -28971,6 +28994,38 @@ stats_timestamp | 2025-03-24 13:55:47.796698+01
 will be less resource intensive when only the local backend is of interest.
 </para>
 </note>
+</para>
+
+<para>
+<function>pg_log_query_plan</function> can be used
+to log the plan of a backend process. For example:
+<programlisting>
+postgres=# SELECT pg_log_query_plan(201116);
+pg_log_query_plan
+---------------------------
+t
+(1 row)
+</programlisting>
+The format of the query plan is the same as when <literal>VERBOSE</literal>,
+<literal>COSTS</literal>, <literal>SETTINGS</literal> and
+<literal>FORMAT TEXT</literal> are used in the <command>EXPLAIN</command>
+command. For example:
+<screen>
+LOG: query plan running on backend with PID 201116 is:
+Query Text: SELECT * FROM pgbench_accounts;
+Seq Scan on public.pgbench_accounts (cost=0.00..52787.00 rows=2000000 width=97)
+Output: aid, bid, abalance, filler
+Settings: work_mem = '1MB'
+Query Identifier: 8621255546560739680
+</screen>
+Note that when the target is executing nested statements(statements executed
+inside a function), only the innermost query plan is logged.
+Note that logging plan may take some time, as it occurs when
+the plan node is executed. For example, when a query is
+running <function>pg_sleep</function>, the plan will not be
+logged until the function execution completes.
+Similarly, when a query is running under the extended query
+protocol, the plan is logged only during the execute step.
 </para>
 
 </sect2>

src/backend/access/transam/xact.c

@@ -36,6 +36,7 @@
 #include "catalog/pg_enum.h"
 #include "catalog/storage.h"
 #include "commands/async.h"
+#include "commands/dynamic_explain.h"
 #include "commands/tablecmds.h"
 #include "commands/trigger.h"
 #include "common/pg_prng.h"
@@ -2904,6 +2905,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 resources.
@@ -5296,6 +5300,9 @@ AbortSubTransaction(void)
 /* Reset logical state. */
 ResetLogicalState();
 
+/* Reset pg_log_query_plan() related state. */
+ResetLogQueryPlanState();
+
 /*
 * No need for SnapBuildResetExportedSnapshotState() here, snapshot
 * exports are not supported in subtransactions.

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.
 --

src/backend/commands/Makefile

@@ -32,6 +32,7 @@ OBJS = \
 define.o \
 discard.o \
 dropcmds.o \
+dynamic_explain.o \
 event_trigger.o \
 explain.o \
 explain_dr.o \