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