Age Owner TLA 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 :
5254 tgl 25 GIC 9 : PG_MODULE_MAGIC;
5254 tgl 26 ECB :
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
5254 tgl 93 CBC 9 : _PG_init(void)
94 : {
95 : /* Define custom GUC variables. */
5210 96 9 : 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 :
277 michael 108 GNC 9 : 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 :
5210 tgl 120 CBC 9 : 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 :
1466 tomas.vondra 131 GIC 9 : DefineCustomBoolVariable("auto_explain.log_settings",
1466 tomas.vondra 132 ECB : "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 :
5210 tgl 142 GIC 9 : DefineCustomBoolVariable("auto_explain.log_verbose",
5254 tgl 143 ECB : "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 :
4863 rhaas 153 GIC 9 : DefineCustomBoolVariable("auto_explain.log_buffers",
4863 rhaas 154 ECB : "Log buffers usage.",
155 : NULL,
156 : &auto_explain_log_buffers,
157 : false,
158 : PGC_SUSET,
159 : 0,
160 : NULL,
161 : NULL,
162 : NULL);
163 :
1098 akapila 164 GIC 9 : DefineCustomBoolVariable("auto_explain.log_wal",
1098 akapila 165 ECB : "Log WAL usage.",
166 : NULL,
167 : &auto_explain_log_wal,
168 : false,
169 : PGC_SUSET,
170 : 0,
171 : NULL,
172 : NULL,
173 : NULL);
174 :
3323 alvherre 175 GIC 9 : DefineCustomBoolVariable("auto_explain.log_triggers",
3323 alvherre 176 ECB : "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 :
4990 tgl 186 GIC 9 : DefineCustomEnumVariable("auto_explain.log_format",
4990 tgl 187 ECB : "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 :
1713 andrew 198 CBC 9 : 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 :
5210 tgl 210 9 : 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 :
4079 rhaas 221 GIC 9 : DefineCustomBoolVariable("auto_explain.log_timing",
4079 rhaas 222 ECB : "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 :
2583 magnus 232 GIC 9 : DefineCustomRealVariable("auto_explain.sample_rate",
2585 magnus 233 ECB : "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 :
412 tgl 245 GIC 9 : MarkGUCPrefixReserved("auto_explain");
246 :
247 : /* Install hooks. */
5254 248 9 : prev_ExecutorStart = ExecutorStart_hook;
249 9 : ExecutorStart_hook = explain_ExecutorStart;
250 9 : prev_ExecutorRun = ExecutorRun_hook;
251 9 : ExecutorRun_hook = explain_ExecutorRun;
4424 252 9 : prev_ExecutorFinish = ExecutorFinish_hook;
253 9 : ExecutorFinish_hook = explain_ExecutorFinish;
5254 254 9 : prev_ExecutorEnd = ExecutorEnd_hook;
255 9 : ExecutorEnd_hook = explain_ExecutorEnd;
256 9 : }
5254 tgl 257 ECB :
258 : /*
259 : * ExecutorStart hook: start up logging if needed
260 : */
4841 261 : static void
5254 tgl 262 CBC 8 : explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
5254 tgl 263 ECB : {
2585 magnus 264 : /*
1406 tgl 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 : */
1406 tgl 274 CBC 8 : if (nesting_level == 0)
275 : {
1406 tgl 276 GIC 8 : if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
497 277 8 : current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
278 : else
1406 tgl 279 UIC 0 : current_query_sampled = false;
280 : }
281 :
1406 tgl 282 GIC 8 : if (auto_explain_enabled())
283 : {
284 : /* Enable per-node instrumentation iff log_analyze is required. */
5210 285 8 : if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
4863 rhaas 286 ECB : {
4079 rhaas 287 GIC 8 : if (auto_explain_log_timing)
4079 rhaas 288 CBC 8 : queryDesc->instrument_options |= INSTRUMENT_TIMER;
4079 rhaas 289 ECB : else
4079 rhaas 290 UIC 0 : queryDesc->instrument_options |= INSTRUMENT_ROWS;
4863 rhaas 291 GBC 8 : if (auto_explain_log_buffers)
4863 rhaas 292 UIC 0 : queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
1098 akapila 293 GIC 8 : if (auto_explain_log_wal)
1098 akapila 294 LBC 0 : queryDesc->instrument_options |= INSTRUMENT_WAL;
295 : }
296 : }
5254 tgl 297 ECB :
5254 tgl 298 GIC 8 : if (prev_ExecutorStart)
5254 tgl 299 LBC 0 : prev_ExecutorStart(queryDesc, eflags);
5254 tgl 300 ECB : else
5254 tgl 301 GIC 8 : standard_ExecutorStart(queryDesc, eflags);
5254 tgl 302 EUB :
1406 tgl 303 CBC 8 : if (auto_explain_enabled())
5254 tgl 304 EUB : {
5254 tgl 305 ECB : /*
5050 bruce 306 EUB : * 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 : */
5254 tgl 310 CBC 8 : if (queryDesc->totaltime == NULL)
5254 tgl 311 EUB : {
312 : MemoryContext oldcxt;
5254 tgl 313 ECB :
5254 tgl 314 GIC 8 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
697 efujita 315 CBC 8 : queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
5254 tgl 316 GIC 8 : MemoryContextSwitchTo(oldcxt);
317 : }
318 : }
319 8 : }
320 :
321 : /*
5254 tgl 322 ECB : * ExecutorRun hook: all we need do is track nesting depth
323 : */
324 : static void
2208 rhaas 325 GIC 8 : explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
2208 rhaas 326 ECB : uint64 count, bool execute_once)
5254 tgl 327 : {
5254 tgl 328 CBC 8 : nesting_level++;
5254 tgl 329 GIC 8 : PG_TRY();
330 : {
5254 tgl 331 CBC 8 : if (prev_ExecutorRun)
2208 rhaas 332 UIC 0 : prev_ExecutorRun(queryDesc, direction, count, execute_once);
333 : else
2208 rhaas 334 GIC 8 : standard_ExecutorRun(queryDesc, direction, count, execute_once);
335 : }
1255 peter 336 UIC 0 : PG_FINALLY();
5254 tgl 337 ECB : {
5254 tgl 338 GIC 8 : nesting_level--;
339 : }
5254 tgl 340 CBC 8 : PG_END_TRY();
341 8 : }
342 :
4424 tgl 343 ECB : /*
4424 tgl 344 EUB : * ExecutorFinish hook: all we need do is track nesting depth
345 : */
4424 tgl 346 ECB : static void
4424 tgl 347 GIC 8 : explain_ExecutorFinish(QueryDesc *queryDesc)
4424 tgl 348 EUB : {
4424 tgl 349 GIC 8 : nesting_level++;
4424 tgl 350 CBC 8 : PG_TRY();
351 : {
352 8 : if (prev_ExecutorFinish)
4424 tgl 353 LBC 0 : prev_ExecutorFinish(queryDesc);
354 : else
4424 tgl 355 GIC 8 : standard_ExecutorFinish(queryDesc);
356 : }
1255 peter 357 UIC 0 : PG_FINALLY();
358 : {
4424 tgl 359 CBC 8 : nesting_level--;
360 : }
361 8 : PG_END_TRY();
362 8 : }
363 :
5254 tgl 364 ECB : /*
5254 tgl 365 EUB : * ExecutorEnd hook: log results if needed
366 : */
4841 tgl 367 ECB : static void
5254 tgl 368 GIC 8 : explain_ExecutorEnd(QueryDesc *queryDesc)
5254 tgl 369 EUB : {
1406 tgl 370 GIC 8 : if (queryDesc->totaltime && auto_explain_enabled())
5254 tgl 371 ECB : {
372 : MemoryContext oldcxt;
5050 bruce 373 : double msec;
5254 tgl 374 :
375 : /*
376 : * Make sure we operate in the per-query context, so any cruft will be
377 : * discarded later during ExecutorEnd.
378 : */
796 tgl 379 GIC 8 : oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
796 tgl 380 ECB :
381 : /*
5050 bruce 382 : * Make sure stats accumulation is done. (Note: it's okay if several
383 : * levels of hook all do this.)
384 : */
5254 tgl 385 GIC 8 : InstrEndLoop(queryDesc->totaltime);
386 :
387 : /* Log plan if duration is exceeded. */
388 8 : msec = queryDesc->totaltime->total * 1000.0;
5210 389 8 : if (msec >= auto_explain_log_min_duration)
390 : {
3006 tgl 391 CBC 8 : ExplainState *es = NewExplainState();
392 :
3006 tgl 393 GIC 8 : es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
394 8 : es->verbose = auto_explain_log_verbose;
395 8 : es->buffers = (es->analyze && auto_explain_log_buffers);
1098 akapila 396 8 : es->wal = (es->analyze && auto_explain_log_wal);
3006 tgl 397 CBC 8 : es->timing = (es->analyze && auto_explain_log_timing);
3006 tgl 398 GIC 8 : es->summary = es->analyze;
399 8 : es->format = auto_explain_log_format;
1466 tomas.vondra 400 CBC 8 : es->settings = auto_explain_log_settings;
3006 tgl 401 ECB :
3006 tgl 402 GIC 8 : ExplainBeginOutput(es);
3006 tgl 403 CBC 8 : ExplainQueryText(es, queryDesc);
277 michael 404 GNC 8 : ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
3006 tgl 405 GIC 8 : ExplainPrintPlan(es, queryDesc);
3006 tgl 406 CBC 8 : if (es->analyze && auto_explain_log_triggers)
3006 tgl 407 LBC 0 : ExplainPrintTriggers(es, queryDesc);
1657 andres 408 CBC 8 : if (es->costs)
1649 409 8 : ExplainPrintJITSummary(es, queryDesc);
3006 tgl 410 8 : ExplainEndOutput(es);
5254 tgl 411 ECB :
412 : /* Remove last line break */
3006 tgl 413 CBC 8 : if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
3006 tgl 414 GIC 6 : es->str->data[--es->str->len] = '\0';
5254 tgl 415 ECB :
4073 andrew 416 : /* Fix JSON to output an object */
4073 andrew 417 CBC 8 : if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
4073 andrew 418 ECB : {
3006 tgl 419 CBC 2 : es->str->data[0] = '{';
3006 tgl 420 GBC 2 : es->str->data[es->str->len - 1] = '}';
4073 andrew 421 ECB : }
422 :
5254 tgl 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 : */
1713 andrew 429 GIC 8 : ereport(auto_explain_log_level,
5254 tgl 430 ECB : (errmsg("duration: %.3f ms plan:\n%s",
431 : msec, es->str->data),
4790 bruce 432 : errhidestmt(true)));
5254 tgl 433 : }
434 :
796 tgl 435 GIC 8 : MemoryContextSwitchTo(oldcxt);
436 : }
437 :
5254 438 8 : if (prev_ExecutorEnd)
5254 tgl 439 UIC 0 : prev_ExecutorEnd(queryDesc);
440 : else
5254 tgl 441 GIC 8 : standard_ExecutorEnd(queryDesc);
5254 tgl 442 CBC 8 : }
|
