Age Owner Branch data TLA Line data Source code
1 : : /*-------------------------------------------------------------------------
2 : : *
3 : : * auto_explain.c
4 : : *
5 : : *
6 : : * Copyright (c) 2008-2025, PostgreSQL Global Development Group
7 : : *
8 : : * IDENTIFICATION
9 : : * contrib/auto_explain/auto_explain.c
10 : : *
11 : : *-------------------------------------------------------------------------
12 : : */
13 : : #include "postgres.h"
14 : :
15 : : #include <limits.h>
16 : :
17 : : #include "access/parallel.h"
18 : : #include "commands/explain.h"
19 : : #include "commands/explain_format.h"
20 : : #include "commands/explain_state.h"
21 : : #include "common/pg_prng.h"
22 : : #include "executor/instrument.h"
23 : : #include "utils/guc.h"
24 : :
164 tgl@sss.pgh.pa.us 25 :CBC 11 : PG_MODULE_MAGIC_EXT(
26 : : .name = "auto_explain",
27 : : .version = PG_VERSION
28 : : );
29 : :
30 : : /* GUC variables */
31 : : static int auto_explain_log_min_duration = -1; /* msec or -1 */
32 : : static int auto_explain_log_parameter_max_length = -1; /* bytes or -1 */
33 : : static bool auto_explain_log_analyze = false;
34 : : static bool auto_explain_log_verbose = false;
35 : : static bool auto_explain_log_buffers = false;
36 : : static bool auto_explain_log_wal = false;
37 : : static bool auto_explain_log_triggers = false;
38 : : static bool auto_explain_log_timing = true;
39 : : static bool auto_explain_log_settings = false;
40 : : static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
41 : : static int auto_explain_log_level = LOG;
42 : : static bool auto_explain_log_nested_statements = false;
43 : : static double auto_explain_sample_rate = 1;
44 : :
45 : : static const struct config_enum_entry format_options[] = {
46 : : {"text", EXPLAIN_FORMAT_TEXT, false},
47 : : {"xml", EXPLAIN_FORMAT_XML, false},
48 : : {"json", EXPLAIN_FORMAT_JSON, false},
49 : : {"yaml", EXPLAIN_FORMAT_YAML, false},
50 : : {NULL, 0, false}
51 : : };
52 : :
53 : : static const struct config_enum_entry loglevel_options[] = {
54 : : {"debug5", DEBUG5, false},
55 : : {"debug4", DEBUG4, false},
56 : : {"debug3", DEBUG3, false},
57 : : {"debug2", DEBUG2, false},
58 : : {"debug1", DEBUG1, false},
59 : : {"debug", DEBUG2, true},
60 : : {"info", INFO, false},
61 : : {"notice", NOTICE, false},
62 : : {"warning", WARNING, false},
63 : : {"log", LOG, false},
64 : : {NULL, 0, false}
65 : : };
66 : :
67 : : /* Current nesting depth of ExecutorRun calls */
68 : : static int nesting_level = 0;
69 : :
70 : : /* Is the current top-level query to be sampled? */
71 : : static bool current_query_sampled = false;
72 : :
73 : : #define auto_explain_enabled() \
74 : : (auto_explain_log_min_duration >= 0 && \
75 : : (nesting_level == 0 || auto_explain_log_nested_statements) && \
76 : : current_query_sampled)
77 : :
78 : : /* Saved hook values */
79 : : static ExecutorStart_hook_type prev_ExecutorStart = NULL;
80 : : static ExecutorRun_hook_type prev_ExecutorRun = NULL;
81 : : static ExecutorFinish_hook_type prev_ExecutorFinish = NULL;
82 : : static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
83 : :
84 : : static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
85 : : static void explain_ExecutorRun(QueryDesc *queryDesc,
86 : : ScanDirection direction,
87 : : uint64 count);
88 : : static void explain_ExecutorFinish(QueryDesc *queryDesc);
89 : : static void explain_ExecutorEnd(QueryDesc *queryDesc);
90 : :
91 : :
92 : : /*
93 : : * Module load callback
94 : : */
95 : : void
6135 96 : 11 : _PG_init(void)
97 : : {
98 : : /* Define custom GUC variables. */
6091 99 : 11 : DefineCustomIntVariable("auto_explain.log_min_duration",
100 : : "Sets the minimum execution time above which plans will be logged.",
101 : : "-1 disables logging plans. 0 means log all plans.",
102 : : &auto_explain_log_min_duration,
103 : : -1,
104 : : -1, INT_MAX,
105 : : PGC_SUSET,
106 : : GUC_UNIT_MS,
107 : : NULL,
108 : : NULL,
109 : : NULL);
110 : :
1158 michael@paquier.xyz 111 : 11 : DefineCustomIntVariable("auto_explain.log_parameter_max_length",
112 : : "Sets the maximum length of query parameter values to log.",
113 : : "-1 means log values in full.",
114 : : &auto_explain_log_parameter_max_length,
115 : : -1,
116 : : -1, INT_MAX,
117 : : PGC_SUSET,
118 : : GUC_UNIT_BYTE,
119 : : NULL,
120 : : NULL,
121 : : NULL);
122 : :
6091 tgl@sss.pgh.pa.us 123 : 11 : DefineCustomBoolVariable("auto_explain.log_analyze",
124 : : "Use EXPLAIN ANALYZE for plan logging.",
125 : : NULL,
126 : : &auto_explain_log_analyze,
127 : : false,
128 : : PGC_SUSET,
129 : : 0,
130 : : NULL,
131 : : NULL,
132 : : NULL);
133 : :
2347 tomas.vondra@postgre 134 : 11 : DefineCustomBoolVariable("auto_explain.log_settings",
135 : : "Log modified configuration parameters affecting query planning.",
136 : : NULL,
137 : : &auto_explain_log_settings,
138 : : false,
139 : : PGC_SUSET,
140 : : 0,
141 : : NULL,
142 : : NULL,
143 : : NULL);
144 : :
6091 tgl@sss.pgh.pa.us 145 : 11 : DefineCustomBoolVariable("auto_explain.log_verbose",
146 : : "Use EXPLAIN VERBOSE for plan logging.",
147 : : NULL,
148 : : &auto_explain_log_verbose,
149 : : false,
150 : : PGC_SUSET,
151 : : 0,
152 : : NULL,
153 : : NULL,
154 : : NULL);
155 : :
5744 rhaas@postgresql.org 156 : 11 : DefineCustomBoolVariable("auto_explain.log_buffers",
157 : : "Log buffers usage.",
158 : : NULL,
159 : : &auto_explain_log_buffers,
160 : : false,
161 : : PGC_SUSET,
162 : : 0,
163 : : NULL,
164 : : NULL,
165 : : NULL);
166 : :
1979 akapila@postgresql.o 167 : 11 : DefineCustomBoolVariable("auto_explain.log_wal",
168 : : "Log WAL usage.",
169 : : NULL,
170 : : &auto_explain_log_wal,
171 : : false,
172 : : PGC_SUSET,
173 : : 0,
174 : : NULL,
175 : : NULL,
176 : : NULL);
177 : :
4204 alvherre@alvh.no-ip. 178 : 11 : DefineCustomBoolVariable("auto_explain.log_triggers",
179 : : "Include trigger statistics in plans.",
180 : : "This has no effect unless log_analyze is also set.",
181 : : &auto_explain_log_triggers,
182 : : false,
183 : : PGC_SUSET,
184 : : 0,
185 : : NULL,
186 : : NULL,
187 : : NULL);
188 : :
5871 tgl@sss.pgh.pa.us 189 : 11 : DefineCustomEnumVariable("auto_explain.log_format",
190 : : "EXPLAIN format to be used for plan logging.",
191 : : NULL,
192 : : &auto_explain_log_format,
193 : : EXPLAIN_FORMAT_TEXT,
194 : : format_options,
195 : : PGC_SUSET,
196 : : 0,
197 : : NULL,
198 : : NULL,
199 : : NULL);
200 : :
2594 andrew@dunslane.net 201 : 11 : DefineCustomEnumVariable("auto_explain.log_level",
202 : : "Log level for the plan.",
203 : : NULL,
204 : : &auto_explain_log_level,
205 : : LOG,
206 : : loglevel_options,
207 : : PGC_SUSET,
208 : : 0,
209 : : NULL,
210 : : NULL,
211 : : NULL);
212 : :
6091 tgl@sss.pgh.pa.us 213 : 11 : DefineCustomBoolVariable("auto_explain.log_nested_statements",
214 : : "Log nested statements.",
215 : : NULL,
216 : : &auto_explain_log_nested_statements,
217 : : false,
218 : : PGC_SUSET,
219 : : 0,
220 : : NULL,
221 : : NULL,
222 : : NULL);
223 : :
4960 rhaas@postgresql.org 224 : 11 : DefineCustomBoolVariable("auto_explain.log_timing",
225 : : "Collect timing data, not just row counts.",
226 : : NULL,
227 : : &auto_explain_log_timing,
228 : : true,
229 : : PGC_SUSET,
230 : : 0,
231 : : NULL,
232 : : NULL,
233 : : NULL);
234 : :
3464 magnus@hagander.net 235 : 11 : DefineCustomRealVariable("auto_explain.sample_rate",
236 : : "Fraction of queries to process.",
237 : : NULL,
238 : : &auto_explain_sample_rate,
239 : : 1.0,
240 : : 0.0,
241 : : 1.0,
242 : : PGC_SUSET,
243 : : 0,
244 : : NULL,
245 : : NULL,
246 : : NULL);
247 : :
1293 tgl@sss.pgh.pa.us 248 : 11 : MarkGUCPrefixReserved("auto_explain");
249 : :
250 : : /* Install hooks. */
6135 251 : 11 : prev_ExecutorStart = ExecutorStart_hook;
252 : 11 : ExecutorStart_hook = explain_ExecutorStart;
253 : 11 : prev_ExecutorRun = ExecutorRun_hook;
254 : 11 : ExecutorRun_hook = explain_ExecutorRun;
5305 255 : 11 : prev_ExecutorFinish = ExecutorFinish_hook;
256 : 11 : ExecutorFinish_hook = explain_ExecutorFinish;
6135 257 : 11 : prev_ExecutorEnd = ExecutorEnd_hook;
258 : 11 : ExecutorEnd_hook = explain_ExecutorEnd;
259 : 11 : }
260 : :
261 : : /*
262 : : * ExecutorStart hook: start up logging if needed
263 : : */
264 : : static void
265 : 9 : explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
266 : : {
267 : : /*
268 : : * At the beginning of each top-level statement, decide whether we'll
269 : : * sample this statement. If nested-statement explaining is enabled,
270 : : * either all nested statements will be explained or none will.
271 : : *
272 : : * When in a parallel worker, we should do nothing, which we can implement
273 : : * cheaply by pretending we decided not to sample the current statement.
274 : : * If EXPLAIN is active in the parent session, data will be collected and
275 : : * reported back to the parent, and it's no business of ours to interfere.
276 : : */
2287 277 [ + - ]: 9 : if (nesting_level == 0)
278 : : {
279 [ + - + - ]: 9 : if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
1378 280 : 9 : current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
281 : : else
2287 tgl@sss.pgh.pa.us 282 :UBC 0 : current_query_sampled = false;
283 : : }
284 : :
2287 tgl@sss.pgh.pa.us 285 [ + - - + :CBC 9 : if (auto_explain_enabled())
- - + - ]
286 : : {
287 : : /* Enable per-node instrumentation iff log_analyze is required. */
6091 288 [ + - + - ]: 9 : if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
289 : : {
4960 rhaas@postgresql.org 290 [ + - ]: 9 : if (auto_explain_log_timing)
291 : 9 : queryDesc->instrument_options |= INSTRUMENT_TIMER;
292 : : else
4960 rhaas@postgresql.org 293 :UBC 0 : queryDesc->instrument_options |= INSTRUMENT_ROWS;
5744 rhaas@postgresql.org 294 [ - + ]:CBC 9 : if (auto_explain_log_buffers)
5744 rhaas@postgresql.org 295 :UBC 0 : queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
1979 akapila@postgresql.o 296 [ - + ]:CBC 9 : if (auto_explain_log_wal)
1979 akapila@postgresql.o 297 :UBC 0 : queryDesc->instrument_options |= INSTRUMENT_WAL;
298 : : }
299 : : }
300 : :
6135 tgl@sss.pgh.pa.us 301 [ - + ]:CBC 9 : if (prev_ExecutorStart)
107 amitlan@postgresql.o 302 :UBC 0 : prev_ExecutorStart(queryDesc, eflags);
303 : : else
107 amitlan@postgresql.o 304 :CBC 9 : standard_ExecutorStart(queryDesc, eflags);
305 : :
2287 tgl@sss.pgh.pa.us 306 [ + - - + : 9 : if (auto_explain_enabled())
- - + - ]
307 : : {
308 : : /*
309 : : * Set up to track total elapsed time in ExecutorRun. Make sure the
310 : : * space is allocated in the per-query context so it will go away at
311 : : * ExecutorEnd.
312 : : */
6135 313 [ + - ]: 9 : if (queryDesc->totaltime == NULL)
314 : : {
315 : : MemoryContext oldcxt;
316 : :
317 : 9 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
1578 efujita@postgresql.o 318 : 9 : queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
6135 tgl@sss.pgh.pa.us 319 : 9 : MemoryContextSwitchTo(oldcxt);
320 : : }
321 : : }
322 : 9 : }
323 : :
324 : : /*
325 : : * ExecutorRun hook: all we need do is track nesting depth
326 : : */
327 : : static void
3089 rhaas@postgresql.org 328 : 9 : explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
329 : : uint64 count)
330 : : {
6135 tgl@sss.pgh.pa.us 331 : 9 : nesting_level++;
332 [ + - ]: 9 : PG_TRY();
333 : : {
334 [ - + ]: 9 : if (prev_ExecutorRun)
271 tgl@sss.pgh.pa.us 335 :UBC 0 : prev_ExecutorRun(queryDesc, direction, count);
336 : : else
271 tgl@sss.pgh.pa.us 337 :CBC 9 : standard_ExecutorRun(queryDesc, direction, count);
338 : : }
2136 peter@eisentraut.org 339 :UBC 0 : PG_FINALLY();
340 : : {
6135 tgl@sss.pgh.pa.us 341 :CBC 9 : nesting_level--;
342 : : }
343 [ - + ]: 9 : PG_END_TRY();
344 : 9 : }
345 : :
346 : : /*
347 : : * ExecutorFinish hook: all we need do is track nesting depth
348 : : */
349 : : static void
5305 350 : 9 : explain_ExecutorFinish(QueryDesc *queryDesc)
351 : : {
352 : 9 : nesting_level++;
353 [ + - ]: 9 : PG_TRY();
354 : : {
355 [ - + ]: 9 : if (prev_ExecutorFinish)
5305 tgl@sss.pgh.pa.us 356 :UBC 0 : prev_ExecutorFinish(queryDesc);
357 : : else
5305 tgl@sss.pgh.pa.us 358 :CBC 9 : standard_ExecutorFinish(queryDesc);
359 : : }
2136 peter@eisentraut.org 360 :UBC 0 : PG_FINALLY();
361 : : {
5305 tgl@sss.pgh.pa.us 362 :CBC 9 : nesting_level--;
363 : : }
364 [ - + ]: 9 : PG_END_TRY();
365 : 9 : }
366 : :
367 : : /*
368 : : * ExecutorEnd hook: log results if needed
369 : : */
370 : : static void
6135 371 : 9 : explain_ExecutorEnd(QueryDesc *queryDesc)
372 : : {
2287 373 [ + - + - : 9 : if (queryDesc->totaltime && auto_explain_enabled())
- + - - +
- ]
374 : : {
375 : : MemoryContext oldcxt;
376 : : double msec;
377 : :
378 : : /*
379 : : * Make sure we operate in the per-query context, so any cruft will be
380 : : * discarded later during ExecutorEnd.
381 : : */
1677 382 : 9 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
383 : :
384 : : /*
385 : : * Make sure stats accumulation is done. (Note: it's okay if several
386 : : * levels of hook all do this.)
387 : : */
6135 388 : 9 : InstrEndLoop(queryDesc->totaltime);
389 : :
390 : : /* Log plan if duration is exceeded. */
391 : 9 : msec = queryDesc->totaltime->total * 1000.0;
6091 392 [ + - ]: 9 : if (msec >= auto_explain_log_min_duration)
393 : : {
3887 394 : 9 : ExplainState *es = NewExplainState();
395 : :
396 [ + - + - ]: 9 : es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
397 : 9 : es->verbose = auto_explain_log_verbose;
398 [ + - - + ]: 9 : es->buffers = (es->analyze && auto_explain_log_buffers);
1979 akapila@postgresql.o 399 [ + - - + ]: 9 : es->wal = (es->analyze && auto_explain_log_wal);
3887 tgl@sss.pgh.pa.us 400 [ + - + - ]: 9 : es->timing = (es->analyze && auto_explain_log_timing);
401 : 9 : es->summary = es->analyze;
402 : : /* No support for MEMORY */
403 : : /* es->memory = false; */
404 : 9 : es->format = auto_explain_log_format;
2347 tomas.vondra@postgre 405 : 9 : es->settings = auto_explain_log_settings;
406 : :
3887 tgl@sss.pgh.pa.us 407 : 9 : ExplainBeginOutput(es);
408 : 9 : ExplainQueryText(es, queryDesc);
1158 michael@paquier.xyz 409 : 9 : ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
3887 tgl@sss.pgh.pa.us 410 : 9 : ExplainPrintPlan(es, queryDesc);
411 [ + - - + ]: 9 : if (es->analyze && auto_explain_log_triggers)
3887 tgl@sss.pgh.pa.us 412 :UBC 0 : ExplainPrintTriggers(es, queryDesc);
2538 andres@anarazel.de 413 [ + - ]:CBC 9 : if (es->costs)
2530 414 : 9 : ExplainPrintJITSummary(es, queryDesc);
3887 tgl@sss.pgh.pa.us 415 : 9 : ExplainEndOutput(es);
416 : :
417 : : /* Remove last line break */
418 [ + - + + ]: 9 : if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
419 : 7 : es->str->data[--es->str->len] = '\0';
420 : :
421 : : /* Fix JSON to output an object */
4954 andrew@dunslane.net 422 [ + + ]: 9 : if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
423 : : {
3887 tgl@sss.pgh.pa.us 424 : 2 : es->str->data[0] = '{';
425 : 2 : es->str->data[es->str->len - 1] = '}';
426 : : }
427 : :
428 : : /*
429 : : * Note: we rely on the existing logging of context or
430 : : * debug_query_string to identify just which statement is being
431 : : * reported. This isn't ideal but trying to do it here would
432 : : * often result in duplication.
433 : : */
2594 andrew@dunslane.net 434 [ + - ]: 9 : ereport(auto_explain_log_level,
435 : : (errmsg("duration: %.3f ms plan:\n%s",
436 : : msec, es->str->data),
437 : : errhidestmt(true)));
438 : : }
439 : :
1677 tgl@sss.pgh.pa.us 440 : 9 : MemoryContextSwitchTo(oldcxt);
441 : : }
442 : :
6135 443 [ - + ]: 9 : if (prev_ExecutorEnd)
6135 tgl@sss.pgh.pa.us 444 :UBC 0 : prev_ExecutorEnd(queryDesc);
445 : : else
6135 tgl@sss.pgh.pa.us 446 :CBC 9 : standard_ExecutorEnd(queryDesc);
447 : 9 : }
|
