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 :
25 22 : 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
96 22 : _PG_init(void)
97 : {
98 : /* Define custom GUC variables. */
99 22 : 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 :
111 22 : 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 :
123 22 : 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 :
134 22 : 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 :
145 22 : 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 :
156 22 : 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 :
167 22 : 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 :
178 22 : 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 :
189 22 : 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 :
201 22 : 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 :
213 22 : 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 :
224 22 : 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 :
235 22 : 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 :
248 22 : MarkGUCPrefixReserved("auto_explain");
249 :
250 : /* Install hooks. */
251 22 : prev_ExecutorStart = ExecutorStart_hook;
252 22 : ExecutorStart_hook = explain_ExecutorStart;
253 22 : prev_ExecutorRun = ExecutorRun_hook;
254 22 : ExecutorRun_hook = explain_ExecutorRun;
255 22 : prev_ExecutorFinish = ExecutorFinish_hook;
256 22 : ExecutorFinish_hook = explain_ExecutorFinish;
257 22 : prev_ExecutorEnd = ExecutorEnd_hook;
258 22 : ExecutorEnd_hook = explain_ExecutorEnd;
259 22 : }
260 :
261 : /*
262 : * ExecutorStart hook: start up logging if needed
263 : */
264 : static void
265 20 : 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 : */
277 20 : if (nesting_level == 0)
278 : {
279 20 : if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
280 20 : current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
281 : else
282 0 : current_query_sampled = false;
283 : }
284 :
285 20 : if (auto_explain_enabled())
286 : {
287 : /* Enable per-node instrumentation iff log_analyze is required. */
288 20 : if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
289 : {
290 20 : if (auto_explain_log_timing)
291 20 : queryDesc->instrument_options |= INSTRUMENT_TIMER;
292 : else
293 0 : queryDesc->instrument_options |= INSTRUMENT_ROWS;
294 20 : if (auto_explain_log_buffers)
295 0 : queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
296 20 : if (auto_explain_log_wal)
297 0 : queryDesc->instrument_options |= INSTRUMENT_WAL;
298 : }
299 : }
300 :
301 20 : if (prev_ExecutorStart)
302 0 : prev_ExecutorStart(queryDesc, eflags);
303 : else
304 20 : standard_ExecutorStart(queryDesc, eflags);
305 :
306 20 : 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 : */
313 20 : if (queryDesc->totaltime == NULL)
314 : {
315 : MemoryContext oldcxt;
316 :
317 20 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
318 20 : queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
319 20 : MemoryContextSwitchTo(oldcxt);
320 : }
321 : }
322 20 : }
323 :
324 : /*
325 : * ExecutorRun hook: all we need do is track nesting depth
326 : */
327 : static void
328 20 : explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
329 : uint64 count)
330 : {
331 20 : nesting_level++;
332 20 : PG_TRY();
333 : {
334 20 : if (prev_ExecutorRun)
335 0 : prev_ExecutorRun(queryDesc, direction, count);
336 : else
337 20 : standard_ExecutorRun(queryDesc, direction, count);
338 : }
339 0 : PG_FINALLY();
340 : {
341 20 : nesting_level--;
342 : }
343 20 : PG_END_TRY();
344 20 : }
345 :
346 : /*
347 : * ExecutorFinish hook: all we need do is track nesting depth
348 : */
349 : static void
350 20 : explain_ExecutorFinish(QueryDesc *queryDesc)
351 : {
352 20 : nesting_level++;
353 20 : PG_TRY();
354 : {
355 20 : if (prev_ExecutorFinish)
356 0 : prev_ExecutorFinish(queryDesc);
357 : else
358 20 : standard_ExecutorFinish(queryDesc);
359 : }
360 0 : PG_FINALLY();
361 : {
362 20 : nesting_level--;
363 : }
364 20 : PG_END_TRY();
365 20 : }
366 :
367 : /*
368 : * ExecutorEnd hook: log results if needed
369 : */
370 : static void
371 20 : explain_ExecutorEnd(QueryDesc *queryDesc)
372 : {
373 20 : 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 : */
382 20 : 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 : */
388 20 : InstrEndLoop(queryDesc->totaltime);
389 :
390 : /* Log plan if duration is exceeded. */
391 20 : msec = queryDesc->totaltime->total * 1000.0;
392 20 : if (msec >= auto_explain_log_min_duration)
393 : {
394 20 : ExplainState *es = NewExplainState();
395 :
396 20 : es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
397 20 : es->verbose = auto_explain_log_verbose;
398 20 : es->buffers = (es->analyze && auto_explain_log_buffers);
399 20 : es->wal = (es->analyze && auto_explain_log_wal);
400 20 : es->timing = (es->analyze && auto_explain_log_timing);
401 20 : es->summary = es->analyze;
402 : /* No support for MEMORY */
403 : /* es->memory = false; */
404 20 : es->format = auto_explain_log_format;
405 20 : es->settings = auto_explain_log_settings;
406 :
407 20 : ExplainBeginOutput(es);
408 20 : ExplainQueryText(es, queryDesc);
409 20 : ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
410 20 : ExplainPrintPlan(es, queryDesc);
411 20 : if (es->analyze && auto_explain_log_triggers)
412 0 : ExplainPrintTriggers(es, queryDesc);
413 20 : if (es->costs)
414 20 : ExplainPrintJITSummary(es, queryDesc);
415 20 : ExplainEndOutput(es);
416 :
417 : /* Remove last line break */
418 20 : if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
419 14 : es->str->data[--es->str->len] = '\0';
420 :
421 : /* Fix JSON to output an object */
422 20 : if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
423 : {
424 6 : es->str->data[0] = '{';
425 6 : 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 : */
434 20 : ereport(auto_explain_log_level,
435 : (errmsg("duration: %.3f ms plan:\n%s",
436 : msec, es->str->data),
437 : errhidestmt(true)));
438 : }
439 :
440 20 : MemoryContextSwitchTo(oldcxt);
441 : }
442 :
443 20 : if (prev_ExecutorEnd)
444 0 : prev_ExecutorEnd(queryDesc);
445 : else
446 20 : standard_ExecutorEnd(queryDesc);
447 20 : }
|
