Age Owner Branch data TLA 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 "jit/jit.h"
22 : : #include "nodes/params.h"
23 : : #include "utils/guc.h"
24 : :
5625 tgl@sss.pgh.pa.us 25 :CBC 10 : 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 : 10 : _PG_init(void)
94 : : {
95 : : /* Define custom GUC variables. */
5581 96 : 10 : 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 : :
648 michael@paquier.xyz 108 : 10 : 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 : :
5581 tgl@sss.pgh.pa.us 120 : 10 : 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 : :
1837 tomas.vondra@postgre 131 : 10 : 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 : :
5581 tgl@sss.pgh.pa.us 142 : 10 : 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 : :
5234 rhaas@postgresql.org 153 : 10 : 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 : :
1469 akapila@postgresql.o 164 : 10 : 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 : :
3694 alvherre@alvh.no-ip. 175 : 10 : 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 : :
5361 tgl@sss.pgh.pa.us 186 : 10 : 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 : :
2084 andrew@dunslane.net 198 : 10 : 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 : :
5581 tgl@sss.pgh.pa.us 210 : 10 : 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 : :
4450 rhaas@postgresql.org 221 : 10 : 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 : :
2954 magnus@hagander.net 232 : 10 : 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 : :
783 tgl@sss.pgh.pa.us 245 : 10 : MarkGUCPrefixReserved("auto_explain");
246 : :
247 : : /* Install hooks. */
5625 248 : 10 : prev_ExecutorStart = ExecutorStart_hook;
249 : 10 : ExecutorStart_hook = explain_ExecutorStart;
250 : 10 : prev_ExecutorRun = ExecutorRun_hook;
251 : 10 : ExecutorRun_hook = explain_ExecutorRun;
4795 252 : 10 : prev_ExecutorFinish = ExecutorFinish_hook;
253 : 10 : ExecutorFinish_hook = explain_ExecutorFinish;
5625 254 : 10 : prev_ExecutorEnd = ExecutorEnd_hook;
255 : 10 : ExecutorEnd_hook = explain_ExecutorEnd;
256 : 10 : }
257 : :
258 : : /*
259 : : * ExecutorStart hook: start up logging if needed
260 : : */
261 : : static void
262 : 9 : 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 : : */
1777 274 [ + - ]: 9 : if (nesting_level == 0)
275 : : {
276 [ + - + - ]: 9 : if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
868 277 : 9 : current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
278 : : else
1777 tgl@sss.pgh.pa.us 279 :UBC 0 : current_query_sampled = false;
280 : : }
281 : :
1777 tgl@sss.pgh.pa.us 282 [ + - - + :CBC 9 : if (auto_explain_enabled())
- - + - ]
283 : : {
284 : : /* Enable per-node instrumentation iff log_analyze is required. */
5581 285 [ + - + - ]: 9 : if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
286 : : {
4450 rhaas@postgresql.org 287 [ + - ]: 9 : if (auto_explain_log_timing)
288 : 9 : queryDesc->instrument_options |= INSTRUMENT_TIMER;
289 : : else
4450 rhaas@postgresql.org 290 :UBC 0 : queryDesc->instrument_options |= INSTRUMENT_ROWS;
5234 rhaas@postgresql.org 291 [ - + ]:CBC 9 : if (auto_explain_log_buffers)
5234 rhaas@postgresql.org 292 :UBC 0 : queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
1469 akapila@postgresql.o 293 [ - + ]:CBC 9 : if (auto_explain_log_wal)
1469 akapila@postgresql.o 294 :UBC 0 : queryDesc->instrument_options |= INSTRUMENT_WAL;
295 : : }
296 : : }
297 : :
5625 tgl@sss.pgh.pa.us 298 [ - + ]:CBC 9 : if (prev_ExecutorStart)
5625 tgl@sss.pgh.pa.us 299 :UBC 0 : prev_ExecutorStart(queryDesc, eflags);
300 : : else
5625 tgl@sss.pgh.pa.us 301 :CBC 9 : standard_ExecutorStart(queryDesc, eflags);
302 : :
1777 303 [ + - - + : 9 : 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 : : */
5625 310 [ + - ]: 9 : if (queryDesc->totaltime == NULL)
311 : : {
312 : : MemoryContext oldcxt;
313 : :
314 : 9 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
1068 efujita@postgresql.o 315 : 9 : queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
5625 tgl@sss.pgh.pa.us 316 : 9 : MemoryContextSwitchTo(oldcxt);
317 : : }
318 : : }
319 : 9 : }
320 : :
321 : : /*
322 : : * ExecutorRun hook: all we need do is track nesting depth
323 : : */
324 : : static void
2579 rhaas@postgresql.org 325 : 9 : explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
326 : : uint64 count, bool execute_once)
327 : : {
5625 tgl@sss.pgh.pa.us 328 : 9 : nesting_level++;
329 [ + - ]: 9 : PG_TRY();
330 : : {
331 [ - + ]: 9 : if (prev_ExecutorRun)
2579 rhaas@postgresql.org 332 :UBC 0 : prev_ExecutorRun(queryDesc, direction, count, execute_once);
333 : : else
2579 rhaas@postgresql.org 334 :CBC 9 : standard_ExecutorRun(queryDesc, direction, count, execute_once);
335 : : }
1626 peter@eisentraut.org 336 :UBC 0 : PG_FINALLY();
337 : : {
5625 tgl@sss.pgh.pa.us 338 :CBC 9 : nesting_level--;
339 : : }
340 [ - + ]: 9 : PG_END_TRY();
341 : 9 : }
342 : :
343 : : /*
344 : : * ExecutorFinish hook: all we need do is track nesting depth
345 : : */
346 : : static void
4795 347 : 9 : explain_ExecutorFinish(QueryDesc *queryDesc)
348 : : {
349 : 9 : nesting_level++;
350 [ + - ]: 9 : PG_TRY();
351 : : {
352 [ - + ]: 9 : if (prev_ExecutorFinish)
4795 tgl@sss.pgh.pa.us 353 :UBC 0 : prev_ExecutorFinish(queryDesc);
354 : : else
4795 tgl@sss.pgh.pa.us 355 :CBC 9 : standard_ExecutorFinish(queryDesc);
356 : : }
1626 peter@eisentraut.org 357 :UBC 0 : PG_FINALLY();
358 : : {
4795 tgl@sss.pgh.pa.us 359 :CBC 9 : nesting_level--;
360 : : }
361 [ - + ]: 9 : PG_END_TRY();
362 : 9 : }
363 : :
364 : : /*
365 : : * ExecutorEnd hook: log results if needed
366 : : */
367 : : static void
5625 368 : 9 : explain_ExecutorEnd(QueryDesc *queryDesc)
369 : : {
1777 370 [ + - + - : 9 : 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 : : */
1167 379 : 9 : 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 : : */
5625 385 : 9 : InstrEndLoop(queryDesc->totaltime);
386 : :
387 : : /* Log plan if duration is exceeded. */
388 : 9 : msec = queryDesc->totaltime->total * 1000.0;
5581 389 [ + - ]: 9 : if (msec >= auto_explain_log_min_duration)
390 : : {
3377 391 : 9 : ExplainState *es = NewExplainState();
392 : :
393 [ + - + - ]: 9 : es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
394 : 9 : es->verbose = auto_explain_log_verbose;
395 [ + - - + ]: 9 : es->buffers = (es->analyze && auto_explain_log_buffers);
1469 akapila@postgresql.o 396 [ + - - + ]: 9 : es->wal = (es->analyze && auto_explain_log_wal);
3377 tgl@sss.pgh.pa.us 397 [ + - + - ]: 9 : es->timing = (es->analyze && auto_explain_log_timing);
398 : 9 : es->summary = es->analyze;
399 : : /* No support for MEMORY */
400 : : /* es->memory = false; */
401 : 9 : es->format = auto_explain_log_format;
1837 tomas.vondra@postgre 402 : 9 : es->settings = auto_explain_log_settings;
403 : :
3377 tgl@sss.pgh.pa.us 404 : 9 : ExplainBeginOutput(es);
405 : 9 : ExplainQueryText(es, queryDesc);
648 michael@paquier.xyz 406 : 9 : ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
3377 tgl@sss.pgh.pa.us 407 : 9 : ExplainPrintPlan(es, queryDesc);
408 [ + - - + ]: 9 : if (es->analyze && auto_explain_log_triggers)
3377 tgl@sss.pgh.pa.us 409 :UBC 0 : ExplainPrintTriggers(es, queryDesc);
2028 andres@anarazel.de 410 [ + - ]:CBC 9 : if (es->costs)
2020 411 : 9 : ExplainPrintJITSummary(es, queryDesc);
3377 tgl@sss.pgh.pa.us 412 : 9 : ExplainEndOutput(es);
413 : :
414 : : /* Remove last line break */
415 [ + - + + ]: 9 : if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
416 : 6 : es->str->data[--es->str->len] = '\0';
417 : :
418 : : /* Fix JSON to output an object */
4444 andrew@dunslane.net 419 [ + + ]: 9 : if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
420 : : {
3377 tgl@sss.pgh.pa.us 421 : 3 : es->str->data[0] = '{';
422 : 3 : es->str->data[es->str->len - 1] = '}';
423 : : }
424 : :
425 : : /*
426 : : * Note: we rely on the existing logging of context or
427 : : * debug_query_string to identify just which statement is being
428 : : * reported. This isn't ideal but trying to do it here would
429 : : * often result in duplication.
430 : : */
2084 andrew@dunslane.net 431 [ + - ]: 9 : ereport(auto_explain_log_level,
432 : : (errmsg("duration: %.3f ms plan:\n%s",
433 : : msec, es->str->data),
434 : : errhidestmt(true)));
435 : : }
436 : :
1167 tgl@sss.pgh.pa.us 437 : 9 : MemoryContextSwitchTo(oldcxt);
438 : : }
439 : :
5625 440 [ - + ]: 9 : if (prev_ExecutorEnd)
5625 tgl@sss.pgh.pa.us 441 :UBC 0 : prev_ExecutorEnd(queryDesc);
442 : : else
5625 tgl@sss.pgh.pa.us 443 :CBC 9 : standard_ExecutorEnd(queryDesc);
444 : 9 : }
|
