[CF 5330] v44 - Logging plan of the currently running query

This branch was automatically generated by a robot using es from an email thread registered at: https://commitfest.postgresql.org//5330 The branch will be overwritten each time a new version is posted to the thread, and also periodically to check for bitrot caused by changes on the master branch. (es): https://www.postgresql.org/message-id/[email protected] Author(s): Atsushi Torikoshi

Author: Commitfest Bot

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 \