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