Skip to content

Commit 2abb0b9

Browse files
Atsushi TorikoshiCommitfest Bot
authored andcommitted
Add function to log the plan of the currently running
Currently, we have to wait for the query execution to finish to know its plan either using EXPLAIN ANALYZE or auto_explain. This is not so convenient, for example when investigating long-running queries on production environments. To improve this situation, this patch adds pg_log_query_plan() function that requests to log the plan of the currently executing query. On receipt of the request, ExecProcNodes of the current plan node and its subsidiary nodes are wrapped with ExecProcNodeFirst, which implelements logging query plan. When executor executes the one of the wrapped nodes, the query plan is logged. Our initial idea was to send a signal to the target backend process, which invokes EXPLAIN logic at the next CHECK_FOR_INTERRUPTS() call. However, we realized during prototyping that EXPLAIN is complex and may not be safely executed at arbitrary interrupt points. 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. Todo: Consider removing the PID from the log output of pg_log_backend_memory_contexts() and pg_log_query_plan(). For detail, see the discussion: https://www.postgresql.org/message-id/CA%2BTgmoY81r7npTS34N_5MLA_u6ghfor5HoSaar53veXUYu1OxQ%40mail.gmail.com
1 parent 50eb4e1 commit 2abb0b9

File tree

24 files changed

+647
-34
lines changed

24 files changed

+647
-34
lines changed

contrib/auto_explain/auto_explain.c

Lines changed: 4 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
#include <limits.h>
1616

1717
#include "access/parallel.h"
18+
#include "commands/dynamic_explain.h"
1819
#include "commands/explain.h"
1920
#include "commands/explain_format.h"
2021
#include "commands/explain_state.h"
@@ -404,26 +405,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
404405
es->format = auto_explain_log_format;
405406
es->settings = auto_explain_log_settings;
406407

407-
ExplainBeginOutput(es);
408-
ExplainQueryText(es, queryDesc);
409-
ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
410-
ExplainPrintPlan(es, queryDesc);
411-
if (es->analyze && auto_explain_log_triggers)
412-
ExplainPrintTriggers(es, queryDesc);
413-
if (es->costs)
414-
ExplainPrintJITSummary(es, queryDesc);
415-
ExplainEndOutput(es);
416-
417-
/* Remove last line break */
418-
if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
419-
es->str->data[--es->str->len] = '\0';
420-
421-
/* Fix JSON to output an object */
422-
if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
423-
{
424-
es->str->data[0] = '{';
425-
es->str->data[es->str->len - 1] = '}';
426-
}
408+
ExplainStringAssemble(es, queryDesc, auto_explain_log_format,
409+
auto_explain_log_triggers,
410+
auto_explain_log_parameter_max_length);
427411

428412
/*
429413
* Note: we rely on the existing logging of context or

doc/src/sgml/func/func-admin.sgml

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -184,6 +184,30 @@
184184
</para></entry>
185185
</row>
186186

187+
<row>
188+
<entry role="func_table_entry"><para role="func_signature">
189+
<indexterm>
190+
<primary>pg_log_query_plan</primary>
191+
</indexterm>
192+
<function>pg_log_query_plan</function> ( <parameter>pid</parameter> <type>integer</type> )
193+
<returnvalue>boolean</returnvalue>
194+
</para>
195+
<para>
196+
Requests to log the plan of the query currently running on the
197+
backend with specified process ID.
198+
It will be logged at <literal>LOG</literal> message level and
199+
will appear in the server log based on the log
200+
configuration set (See <xref linkend="runtime-config-logging"/>
201+
for more information), but will not be sent to the client
202+
regardless of <xref linkend="guc-client-min-messages"/>.
203+
</para>
204+
<para>
205+
This function is restricted to superusers by default, but other
206+
users can be granted EXECUTE to run the function.
207+
</para></entry>
208+
</row>
209+
210+
187211
<row>
188212
<entry role="func_table_entry"><para role="func_signature">
189213
<indexterm>

src/backend/access/transam/xact.c

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@
3636
#include "catalog/pg_enum.h"
3737
#include "catalog/storage.h"
3838
#include "commands/async.h"
39+
#include "commands/dynamic_explain.h"
3940
#include "commands/tablecmds.h"
4041
#include "commands/trigger.h"
4142
#include "common/pg_prng.h"
@@ -215,6 +216,7 @@ typedef struct TransactionStateData
215216
bool parallelChildXact; /* is any parent transaction parallel? */
216217
bool chain; /* start a new block after this one */
217218
bool topXidLogged; /* for a subxact: is top-level XID logged? */
219+
QueryDesc *queryDesc; /* my current QueryDesc */
218220
struct TransactionStateData *parent; /* back link to parent */
219221
} TransactionStateData;
220222

@@ -248,6 +250,7 @@ static TransactionStateData TopTransactionStateData = {
248250
.state = TRANS_DEFAULT,
249251
.blockState = TBLOCK_DEFAULT,
250252
.topXidLogged = false,
253+
.queryDesc = NULL,
251254
};
252255

253256
/*
@@ -933,6 +936,27 @@ GetCurrentTransactionNestLevel(void)
933936
return s->nestingLevel;
934937
}
935938

939+
/*
940+
* SetCurrentQueryDesc
941+
*/
942+
void
943+
SetCurrentQueryDesc(QueryDesc *queryDesc)
944+
{
945+
TransactionState s = CurrentTransactionState;
946+
947+
s->queryDesc = queryDesc;
948+
}
949+
950+
/*
951+
* GetCurrentQueryDesc
952+
*/
953+
QueryDesc *
954+
GetCurrentQueryDesc(void)
955+
{
956+
TransactionState s = CurrentTransactionState;
957+
958+
return s->queryDesc;
959+
}
936960

937961
/*
938962
* TransactionIdIsCurrentTransactionId
@@ -2916,6 +2940,9 @@ AbortTransaction(void)
29162940
/* Reset snapshot export state. */
29172941
SnapBuildResetExportedSnapshotState();
29182942

2943+
/* Reset current query plan state used for logging. */
2944+
SetCurrentQueryDesc(NULL);
2945+
29192946
/*
29202947
* If this xact has started any unfinished parallel operation, clean up
29212948
* its workers and exit parallel mode. Don't warn about leaked resources.
@@ -5308,6 +5335,13 @@ AbortSubTransaction(void)
53085335
/* Reset logical streaming state. */
53095336
ResetLogicalStreamingState();
53105337

5338+
/*
5339+
* Reset current query plan state used for logging. Note that even after
5340+
* this reset, it's still possible to obtain the parent transaction's
5341+
* query plans, since they are preserved in standard_ExecutorRun().
5342+
*/
5343+
SetCurrentQueryDesc(NULL);
5344+
53115345
/*
53125346
* No need for SnapBuildResetExportedSnapshotState() here, snapshot
53135347
* exports are not supported in subtransactions.

src/backend/catalog/system_functions.sql

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -782,6 +782,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC;
782782

783783
REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC;
784784

785+
REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC;
786+
785787
--
786788
-- We also set up some things as accessible to standard roles.
787789
--

src/backend/commands/Makefile

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@ OBJS = \
3232
define.o \
3333
discard.o \
3434
dropcmds.o \
35+
dynamic_explain.o \
3536
event_trigger.o \
3637
explain.o \
3738
explain_dr.o \
Lines changed: 187 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,187 @@
1+
/*-------------------------------------------------------------------------
2+
*
3+
* dynamic_explain.c
4+
* Explain query plans during execution
5+
*
6+
* Portions Copyright (c) 1996-2025, PostgreSQL Global Development Group
7+
* Portions Copyright (c) 1994-5, Regents of the University of California
8+
*
9+
* IDENTIFICATION
10+
* src/backend/commands/dynamic_explain.c
11+
*
12+
*-------------------------------------------------------------------------
13+
*/
14+
#include "postgres.h"
15+
16+
#include "access/xact.h"
17+
#include "commands/dynamic_explain.h"
18+
#include "commands/explain.h"
19+
#include "commands/explain_format.h"
20+
#include "commands/explain_state.h"
21+
#include "miscadmin.h"
22+
#include "storage/proc.h"
23+
#include "storage/procarray.h"
24+
#include "utils/backend_status.h"
25+
#include "utils/injection_point.h"
26+
27+
/* Is plan node wrapping for query plan logging currently in progress? */
28+
static bool WrapNodesInProgress = false;
29+
30+
/*
31+
* Handle receipt of an interrupt indicating logging the plan of the currently
32+
* running query.
33+
*
34+
* All the actual work is deferred to ProcessLogQueryPlanInterrupt(),
35+
* because we cannot safely emit a log message inside the signal handler.
36+
*/
37+
void
38+
HandleLogQueryPlanInterrupt(void)
39+
{
40+
#ifdef USE_INJECTION_POINTS
41+
INJECTION_POINT("log-query-interrupt", NULL);
42+
#endif
43+
InterruptPending = true;
44+
LogQueryPlanPending = true;
45+
/* latch will be set by procsignal_sigusr1_handler */
46+
}
47+
48+
/*
49+
* Actual plan logging function.
50+
*/
51+
void
52+
LogQueryPlan(void)
53+
{
54+
ExplainState *es;
55+
MemoryContext cxt;
56+
MemoryContext old_cxt;
57+
QueryDesc *queryDesc;
58+
59+
cxt = AllocSetContextCreate(CurrentMemoryContext,
60+
"log_query_plan temporary context",
61+
ALLOCSET_DEFAULT_SIZES);
62+
63+
old_cxt = MemoryContextSwitchTo(cxt);
64+
65+
es = NewExplainState();
66+
67+
es->format = EXPLAIN_FORMAT_TEXT;
68+
es->settings = true;
69+
es->verbose = true;
70+
es->signaled = true;
71+
72+
/*
73+
* Current QueryDesc is valid only during standard_ExecutorRun. However,
74+
* ExecProcNode can be called afterward(i.e., ExecPostprocessPlan). To
75+
* handle the case, check whether we have QueryDesc now.
76+
*/
77+
queryDesc = GetCurrentQueryDesc();
78+
79+
if (queryDesc == NULL)
80+
{
81+
LogQueryPlanPending = false;
82+
return;
83+
}
84+
85+
ExplainStringAssemble(es, queryDesc, es->format, 0, -1);
86+
87+
ereport(LOG_SERVER_ONLY,
88+
errmsg("query and its plan running on backend with PID %d are:\n%s",
89+
MyProcPid, es->str->data));
90+
91+
MemoryContextSwitchTo(old_cxt);
92+
MemoryContextDelete(cxt);
93+
94+
LogQueryPlanPending = false;
95+
}
96+
97+
/*
98+
* Process the request for logging query plan at CHECK_FOR_INTERRUPTS().
99+
*
100+
* Since executing EXPLAIN-related code at an arbitrary CHECK_FOR_INTERRUPTS()
101+
* point is potentially unsafe, this function just wraps the nodes of
102+
* ExecProcNode with ExecProcNodeFirst, which logs query plan if requested.
103+
* This way ensures that EXPLAIN-related code is executed only during
104+
* ExecProcNodeFirst, where it is considered safe.
105+
*/
106+
void
107+
ProcessLogQueryPlanInterrupt(void)
108+
{
109+
QueryDesc *querydesc = GetCurrentQueryDesc();
110+
111+
/* If current query has already finished, we can do nothing but exit */
112+
if (querydesc == NULL)
113+
{
114+
LogQueryPlanPending = false;
115+
return;
116+
}
117+
118+
/*
119+
* Exit immediately if wrapping plan is already in progress. This prevents
120+
* recursive calls, which could occur if logging is requested repeatedly and
121+
* rapidly, potentially leading to infinite recursion and crash.
122+
*/
123+
if (WrapNodesInProgress)
124+
return;
125+
126+
WrapNodesInProgress = true;
127+
128+
PG_TRY();
129+
{
130+
/*
131+
* Wrap ExecProcNodes with ExecProcNodeFirst, which logs query plan
132+
* when LogQueryPlanPending is true.
133+
*/
134+
ExecSetExecProcNodeRecurse(querydesc->planstate);
135+
}
136+
PG_FINALLY();
137+
{
138+
WrapNodesInProgress = false;
139+
}
140+
PG_END_TRY();
141+
}
142+
143+
/*
144+
* Signal a backend process to log the query plan of the running query.
145+
*
146+
* By default, only superusers are allowed to signal to log the plan because
147+
* allowing any users to issue this request at an unbounded rate would
148+
* cause lots of log messages and which can lead to denial of service.
149+
* Additional roles can be permitted with GRANT.
150+
*/
151+
Datum
152+
pg_log_query_plan(PG_FUNCTION_ARGS)
153+
{
154+
int pid = PG_GETARG_INT32(0);
155+
PGPROC *proc;
156+
PgBackendStatus *be_status;
157+
158+
proc = BackendPidGetProc(pid);
159+
160+
if (proc == NULL)
161+
{
162+
/*
163+
* This is just a warning so a loop-through-resultset will not abort
164+
* if one backend terminated on its own during the run.
165+
*/
166+
ereport(WARNING,
167+
(errmsg("PID %d is not a PostgreSQL backend process", pid)));
168+
PG_RETURN_BOOL(false);
169+
}
170+
171+
be_status = pgstat_get_beentry_by_proc_number(proc->vxid.procNumber);
172+
if (be_status->st_backendType != B_BACKEND)
173+
{
174+
ereport(WARNING,
175+
(errmsg("PID %d is not a PostgreSQL client backend process", pid)));
176+
PG_RETURN_BOOL(false);
177+
}
178+
179+
if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->vxid.procNumber) < 0)
180+
{
181+
ereport(WARNING,
182+
(errmsg("could not send signal to process %d: %m", pid)));
183+
PG_RETURN_BOOL(false);
184+
}
185+
186+
PG_RETURN_BOOL(true);
187+
}

0 commit comments

Comments
 (0)