Line data Source code
1 : /*-------------------------------------------------------------------------
2 : *
3 : * auto_explain.c
4 : *
5 : *
6 : * Copyright (c) 2008-2023, 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 "jit/jit.h"
22 : #include "nodes/params.h"
23 : #include "utils/guc.h"
24 :
25 22 : PG_MODULE_MAGIC;
26 :
27 : /* GUC variables */
28 : static int auto_explain_log_min_duration = -1; /* msec or -1 */
29 : static int auto_explain_log_parameter_max_length = -1; /* bytes or -1 */
30 : static bool auto_explain_log_analyze = false;
31 : static bool auto_explain_log_verbose = false;
32 : static bool auto_explain_log_buffers = false;
33 : static bool auto_explain_log_wal = false;
34 : static bool auto_explain_log_triggers = false;
35 : static bool auto_explain_log_timing = true;
36 : static bool auto_explain_log_settings = false;
37 : static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
38 : static int auto_explain_log_level = LOG;
39 : static bool auto_explain_log_nested_statements = false;
40 : static double auto_explain_sample_rate = 1;
41 :
42 : static const struct config_enum_entry format_options[] = {
43 : {"text", EXPLAIN_FORMAT_TEXT, false},
44 : {"xml", EXPLAIN_FORMAT_XML, false},
45 : {"json", EXPLAIN_FORMAT_JSON, false},
46 : {"yaml", EXPLAIN_FORMAT_YAML, false},
47 : {NULL, 0, false}
48 : };
49 :
50 : static const struct config_enum_entry loglevel_options[] = {
51 : {"debug5", DEBUG5, false},
52 : {"debug4", DEBUG4, false},
53 : {"debug3", DEBUG3, false},
54 : {"debug2", DEBUG2, false},
55 : {"debug1", DEBUG1, false},
56 : {"debug", DEBUG2, true},
57 : {"info", INFO, false},
58 : {"notice", NOTICE, false},
59 : {"warning", WARNING, false},
60 : {"log", LOG, false},
61 : {NULL, 0, false}
62 : };
63 :
64 : /* Current nesting depth of ExecutorRun calls */
65 : static int nesting_level = 0;
66 :
67 : /* Is the current top-level query to be sampled? */
68 : static bool current_query_sampled = false;
69 :
70 : #define auto_explain_enabled() \
71 : (auto_explain_log_min_duration >= 0 && \
72 : (nesting_level == 0 || auto_explain_log_nested_statements) && \
73 : current_query_sampled)
74 :
75 : /* Saved hook values in case of unload */
76 : static ExecutorStart_hook_type prev_ExecutorStart = NULL;
77 : static ExecutorRun_hook_type prev_ExecutorRun = NULL;
78 : static ExecutorFinish_hook_type prev_ExecutorFinish = NULL;
79 : static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
80 :
81 : static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
82 : static void explain_ExecutorRun(QueryDesc *queryDesc,
83 : ScanDirection direction,
84 : uint64 count, bool execute_once);
85 : static void explain_ExecutorFinish(QueryDesc *queryDesc);
86 : static void explain_ExecutorEnd(QueryDesc *queryDesc);
87 :
88 :
89 : /*
90 : * Module load callback
91 : */
92 : void
93 22 : _PG_init(void)
94 : {
95 : /* Define custom GUC variables. */
96 22 : DefineCustomIntVariable("auto_explain.log_min_duration",
97 : "Sets the minimum execution time above which plans will be logged.",
98 : "Zero prints all plans. -1 turns this feature off.",
99 : &auto_explain_log_min_duration,
100 : -1,
101 : -1, INT_MAX,
102 : PGC_SUSET,
103 : GUC_UNIT_MS,
104 : NULL,
105 : NULL,
106 : NULL);
107 :
108 22 : DefineCustomIntVariable("auto_explain.log_parameter_max_length",
109 : "Sets the maximum length of query parameters to log.",
110 : "Zero logs no query parameters, -1 logs them in full.",
111 : &auto_explain_log_parameter_max_length,
112 : -1,
113 : -1, INT_MAX,
114 : PGC_SUSET,
115 : GUC_UNIT_BYTE,
116 : NULL,
117 : NULL,
118 : NULL);
119 :
120 22 : DefineCustomBoolVariable("auto_explain.log_analyze",
121 : "Use EXPLAIN ANALYZE for plan logging.",
122 : NULL,
123 : &auto_explain_log_analyze,
124 : false,
125 : PGC_SUSET,
126 : 0,
127 : NULL,
128 : NULL,
129 : NULL);
130 :
131 22 : DefineCustomBoolVariable("auto_explain.log_settings",
132 : "Log modified configuration parameters affecting query planning.",
133 : NULL,
134 : &auto_explain_log_settings,
135 : false,
136 : PGC_SUSET,
137 : 0,
138 : NULL,
139 : NULL,
140 : NULL);
141 :
142 22 : DefineCustomBoolVariable("auto_explain.log_verbose",
143 : "Use EXPLAIN VERBOSE for plan logging.",
144 : NULL,
145 : &auto_explain_log_verbose,
146 : false,
147 : PGC_SUSET,
148 : 0,
149 : NULL,
150 : NULL,
151 : NULL);
152 :
153 22 : DefineCustomBoolVariable("auto_explain.log_buffers",
154 : "Log buffers usage.",
155 : NULL,
156 : &auto_explain_log_buffers,
157 : false,
158 : PGC_SUSET,
159 : 0,
160 : NULL,
161 : NULL,
162 : NULL);
163 :
164 22 : DefineCustomBoolVariable("auto_explain.log_wal",
165 : "Log WAL usage.",
166 : NULL,
167 : &auto_explain_log_wal,
168 : false,
169 : PGC_SUSET,
170 : 0,
171 : NULL,
172 : NULL,
173 : NULL);
174 :
175 22 : DefineCustomBoolVariable("auto_explain.log_triggers",
176 : "Include trigger statistics in plans.",
177 : "This has no effect unless log_analyze is also set.",
178 : &auto_explain_log_triggers,
179 : false,
180 : PGC_SUSET,
181 : 0,
182 : NULL,
183 : NULL,
184 : NULL);
185 :
186 22 : DefineCustomEnumVariable("auto_explain.log_format",
187 : "EXPLAIN format to be used for plan logging.",
188 : NULL,
189 : &auto_explain_log_format,
190 : EXPLAIN_FORMAT_TEXT,
191 : format_options,
192 : PGC_SUSET,
193 : 0,
194 : NULL,
195 : NULL,
196 : NULL);
197 :
198 22 : DefineCustomEnumVariable("auto_explain.log_level",
199 : "Log level for the plan.",
200 : NULL,
201 : &auto_explain_log_level,
202 : LOG,
203 : loglevel_options,
204 : PGC_SUSET,
205 : 0,
206 : NULL,
207 : NULL,
208 : NULL);
209 :
210 22 : DefineCustomBoolVariable("auto_explain.log_nested_statements",
211 : "Log nested statements.",
212 : NULL,
213 : &auto_explain_log_nested_statements,
214 : false,
215 : PGC_SUSET,
216 : 0,
217 : NULL,
218 : NULL,
219 : NULL);
220 :
221 22 : DefineCustomBoolVariable("auto_explain.log_timing",
222 : "Collect timing data, not just row counts.",
223 : NULL,
224 : &auto_explain_log_timing,
225 : true,
226 : PGC_SUSET,
227 : 0,
228 : NULL,
229 : NULL,
230 : NULL);
231 :
232 22 : DefineCustomRealVariable("auto_explain.sample_rate",
233 : "Fraction of queries to process.",
234 : NULL,
235 : &auto_explain_sample_rate,
236 : 1.0,
237 : 0.0,
238 : 1.0,
239 : PGC_SUSET,
240 : 0,
241 : NULL,
242 : NULL,
243 : NULL);
244 :
245 22 : MarkGUCPrefixReserved("auto_explain");
246 :
247 : /* Install hooks. */
248 22 : prev_ExecutorStart = ExecutorStart_hook;
249 22 : ExecutorStart_hook = explain_ExecutorStart;
250 22 : prev_ExecutorRun = ExecutorRun_hook;
251 22 : ExecutorRun_hook = explain_ExecutorRun;
252 22 : prev_ExecutorFinish = ExecutorFinish_hook;
253 22 : ExecutorFinish_hook = explain_ExecutorFinish;
254 22 : prev_ExecutorEnd = ExecutorEnd_hook;
255 22 : ExecutorEnd_hook = explain_ExecutorEnd;
256 22 : }
257 :
258 : /*
259 : * ExecutorStart hook: start up logging if needed
260 : */
261 : static void
262 20 : explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
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 : prev_ExecutorStart(queryDesc, eflags);
300 : else
301 20 : standard_ExecutorStart(queryDesc, eflags);
302 :
303 20 : if (auto_explain_enabled())
304 : {
305 : /*
306 : * Set up to track total elapsed time in ExecutorRun. Make sure the
307 : * space is allocated in the per-query context so it will go away at
308 : * ExecutorEnd.
309 : */
310 20 : if (queryDesc->totaltime == NULL)
311 : {
312 : MemoryContext oldcxt;
313 :
314 20 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
315 20 : queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
316 20 : MemoryContextSwitchTo(oldcxt);
317 : }
318 : }
319 20 : }
320 :
321 : /*
322 : * ExecutorRun hook: all we need do is track nesting depth
323 : */
324 : static void
325 20 : explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
326 : uint64 count, bool execute_once)
327 : {
328 20 : nesting_level++;
329 20 : PG_TRY();
330 : {
331 20 : if (prev_ExecutorRun)
332 0 : prev_ExecutorRun(queryDesc, direction, count, execute_once);
333 : else
334 20 : standard_ExecutorRun(queryDesc, direction, count, execute_once);
335 : }
336 0 : PG_FINALLY();
337 : {
338 20 : nesting_level--;
339 : }
340 20 : PG_END_TRY();
341 20 : }
342 :
343 : /*
344 : * ExecutorFinish hook: all we need do is track nesting depth
345 : */
346 : static void
347 20 : explain_ExecutorFinish(QueryDesc *queryDesc)
348 : {
349 20 : nesting_level++;
350 20 : PG_TRY();
351 : {
352 20 : if (prev_ExecutorFinish)
353 0 : prev_ExecutorFinish(queryDesc);
354 : else
355 20 : standard_ExecutorFinish(queryDesc);
356 : }
357 0 : PG_FINALLY();
358 : {
359 20 : nesting_level--;
360 : }
361 20 : PG_END_TRY();
362 20 : }
363 :
364 : /*
365 : * ExecutorEnd hook: log results if needed
366 : */
367 : static void
368 20 : explain_ExecutorEnd(QueryDesc *queryDesc)
369 : {
370 20 : if (queryDesc->totaltime && auto_explain_enabled())
371 : {
372 : MemoryContext oldcxt;
373 : double msec;
374 :
375 : /*
376 : * Make sure we operate in the per-query context, so any cruft will be
377 : * discarded later during ExecutorEnd.
378 : */
379 20 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
380 :
381 : /*
382 : * Make sure stats accumulation is done. (Note: it's okay if several
383 : * levels of hook all do this.)
384 : */
385 20 : InstrEndLoop(queryDesc->totaltime);
386 :
387 : /* Log plan if duration is exceeded. */
388 20 : msec = queryDesc->totaltime->total * 1000.0;
389 20 : if (msec >= auto_explain_log_min_duration)
390 : {
391 20 : ExplainState *es = NewExplainState();
392 :
393 20 : es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
394 20 : es->verbose = auto_explain_log_verbose;
395 20 : es->buffers = (es->analyze && auto_explain_log_buffers);
396 20 : es->wal = (es->analyze && auto_explain_log_wal);
397 20 : es->timing = (es->analyze && auto_explain_log_timing);
398 20 : es->summary = es->analyze;
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 : }
|
