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 24 : 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 bool 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 24 : _PG_init(void)
97 : {
98 : /* Define custom GUC variables. */
99 24 : 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 24 : 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 24 : 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 24 : 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 24 : 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 24 : 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 24 : 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 24 : 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 24 : 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 24 : 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 24 : 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 24 : 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 24 : 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 24 : MarkGUCPrefixReserved("auto_explain");
249 :
250 : /* Install hooks. */
251 24 : prev_ExecutorStart = ExecutorStart_hook;
252 24 : ExecutorStart_hook = explain_ExecutorStart;
253 24 : prev_ExecutorRun = ExecutorRun_hook;
254 24 : ExecutorRun_hook = explain_ExecutorRun;
255 24 : prev_ExecutorFinish = ExecutorFinish_hook;
256 24 : ExecutorFinish_hook = explain_ExecutorFinish;
257 24 : prev_ExecutorEnd = ExecutorEnd_hook;
258 24 : ExecutorEnd_hook = explain_ExecutorEnd;
259 24 : }
260 :
261 : /*
262 : * ExecutorStart hook: start up logging if needed
263 : */
264 : static bool
265 20 : explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
266 : {
267 : bool plan_valid;
268 :
269 : /*
270 : * At the beginning of each top-level statement, decide whether we'll
271 : * sample this statement. If nested-statement explaining is enabled,
272 : * either all nested statements will be explained or none will.
273 : *
274 : * When in a parallel worker, we should do nothing, which we can implement
275 : * cheaply by pretending we decided not to sample the current statement.
276 : * If EXPLAIN is active in the parent session, data will be collected and
277 : * reported back to the parent, and it's no business of ours to interfere.
278 : */
279 20 : if (nesting_level == 0)
280 : {
281 20 : if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
282 20 : current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
283 : else
284 0 : current_query_sampled = false;
285 : }
286 :
287 20 : if (auto_explain_enabled())
288 : {
289 : /* Enable per-node instrumentation iff log_analyze is required. */
290 20 : if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
291 : {
292 20 : if (auto_explain_log_timing)
293 20 : queryDesc->instrument_options |= INSTRUMENT_TIMER;
294 : else
295 0 : queryDesc->instrument_options |= INSTRUMENT_ROWS;
296 20 : if (auto_explain_log_buffers)
297 0 : queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
298 20 : if (auto_explain_log_wal)
299 0 : queryDesc->instrument_options |= INSTRUMENT_WAL;
300 : }
301 : }
302 :
303 20 : if (prev_ExecutorStart)
304 0 : plan_valid = prev_ExecutorStart(queryDesc, eflags);
305 : else
306 20 : plan_valid = standard_ExecutorStart(queryDesc, eflags);
307 :
308 : /* The plan may have become invalid during standard_ExecutorStart() */
309 20 : if (!plan_valid)
310 0 : return false;
311 :
312 20 : if (auto_explain_enabled())
313 : {
314 : /*
315 : * Set up to track total elapsed time in ExecutorRun. Make sure the
316 : * space is allocated in the per-query context so it will go away at
317 : * ExecutorEnd.
318 : */
319 20 : if (queryDesc->totaltime == NULL)
320 : {
321 : MemoryContext oldcxt;
322 :
323 20 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
324 20 : queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
325 20 : MemoryContextSwitchTo(oldcxt);
326 : }
327 : }
328 :
329 20 : return true;
330 : }
331 :
332 : /*
333 : * ExecutorRun hook: all we need do is track nesting depth
334 : */
335 : static void
336 20 : explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
337 : uint64 count)
338 : {
339 20 : nesting_level++;
340 20 : PG_TRY();
341 : {
342 20 : if (prev_ExecutorRun)
343 0 : prev_ExecutorRun(queryDesc, direction, count);
344 : else
345 20 : standard_ExecutorRun(queryDesc, direction, count);
346 : }
347 0 : PG_FINALLY();
348 : {
349 20 : nesting_level--;
350 : }
351 20 : PG_END_TRY();
352 20 : }
353 :
354 : /*
355 : * ExecutorFinish hook: all we need do is track nesting depth
356 : */
357 : static void
358 20 : explain_ExecutorFinish(QueryDesc *queryDesc)
359 : {
360 20 : nesting_level++;
361 20 : PG_TRY();
362 : {
363 20 : if (prev_ExecutorFinish)
364 0 : prev_ExecutorFinish(queryDesc);
365 : else
366 20 : standard_ExecutorFinish(queryDesc);
367 : }
368 0 : PG_FINALLY();
369 : {
370 20 : nesting_level--;
371 : }
372 20 : PG_END_TRY();
373 20 : }
374 :
375 : /*
376 : * ExecutorEnd hook: log results if needed
377 : */
378 : static void
379 20 : explain_ExecutorEnd(QueryDesc *queryDesc)
380 : {
381 20 : if (queryDesc->totaltime && auto_explain_enabled())
382 : {
383 : MemoryContext oldcxt;
384 : double msec;
385 :
386 : /*
387 : * Make sure we operate in the per-query context, so any cruft will be
388 : * discarded later during ExecutorEnd.
389 : */
390 20 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
391 :
392 : /*
393 : * Make sure stats accumulation is done. (Note: it's okay if several
394 : * levels of hook all do this.)
395 : */
396 20 : InstrEndLoop(queryDesc->totaltime);
397 :
398 : /* Log plan if duration is exceeded. */
399 20 : msec = queryDesc->totaltime->total * 1000.0;
400 20 : if (msec >= auto_explain_log_min_duration)
401 : {
402 20 : ExplainState *es = NewExplainState();
403 :
404 20 : es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
405 20 : es->verbose = auto_explain_log_verbose;
406 20 : es->buffers = (es->analyze && auto_explain_log_buffers);
407 20 : es->wal = (es->analyze && auto_explain_log_wal);
408 20 : es->timing = (es->analyze && auto_explain_log_timing);
409 20 : es->summary = es->analyze;
410 : /* No support for MEMORY */
411 : /* es->memory = false; */
412 20 : es->format = auto_explain_log_format;
413 20 : es->settings = auto_explain_log_settings;
414 :
415 20 : ExplainBeginOutput(es);
416 20 : ExplainQueryText(es, queryDesc);
417 20 : ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
418 20 : ExplainPrintPlan(es, queryDesc);
419 20 : if (es->analyze && auto_explain_log_triggers)
420 0 : ExplainPrintTriggers(es, queryDesc);
421 20 : if (es->costs)
422 20 : ExplainPrintJITSummary(es, queryDesc);
423 20 : ExplainEndOutput(es);
424 :
425 : /* Remove last line break */
426 20 : if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
427 14 : es->str->data[--es->str->len] = '\0';
428 :
429 : /* Fix JSON to output an object */
430 20 : if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
431 : {
432 6 : es->str->data[0] = '{';
433 6 : es->str->data[es->str->len - 1] = '}';
434 : }
435 :
436 : /*
437 : * Note: we rely on the existing logging of context or
438 : * debug_query_string to identify just which statement is being
439 : * reported. This isn't ideal but trying to do it here would
440 : * often result in duplication.
441 : */
442 20 : ereport(auto_explain_log_level,
443 : (errmsg("duration: %.3f ms plan:\n%s",
444 : msec, es->str->data),
445 : errhidestmt(true)));
446 : }
447 :
448 20 : MemoryContextSwitchTo(oldcxt);
449 : }
450 :
451 20 : if (prev_ExecutorEnd)
452 0 : prev_ExecutorEnd(queryDesc);
453 : else
454 20 : standard_ExecutorEnd(queryDesc);
455 20 : }
|
