Skip to content

Commit b7bb20c

Browse files
author
Commitfest Bot
committed
[CF 5330] v50 - Logging plan of the currently running query
This branch was automatically generated by a robot using patches from an email thread registered at: https://commitfest.postgresql.org/patch/5330 The branch will be overwritten each time a new patch version is posted to the thread, and also periodically to check for bitrot caused by changes on the master branch. Patch(es): https://www.postgresql.org/message-id/[email protected] Author(s): Atsushi Torikoshi
2 parents 50eb4e1 + 2abb0b9 commit b7bb20c

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)