PostgreSQL Source Code git master
auto_explain.c
Go to the documentation of this file.
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
24
25/* GUC variables */
26static int auto_explain_log_min_duration = -1; /* msec or -1 */
27static int auto_explain_log_parameter_max_length = -1; /* bytes or -1 */
28static bool auto_explain_log_analyze = false;
29static bool auto_explain_log_verbose = false;
30static bool auto_explain_log_buffers = false;
31static bool auto_explain_log_wal = false;
32static bool auto_explain_log_triggers = false;
33static bool auto_explain_log_timing = true;
34static bool auto_explain_log_settings = false;
38static double auto_explain_sample_rate = 1;
39
40static 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
48static 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 */
63static int nesting_level = 0;
64
65/* Is the current top-level query to be sampled? */
66static 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 */
78
79static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
80static void explain_ExecutorRun(QueryDesc *queryDesc,
81 ScanDirection direction,
82 uint64 count);
83static void explain_ExecutorFinish(QueryDesc *queryDesc);
84static void explain_ExecutorEnd(QueryDesc *queryDesc);
85
86
87/*
88 * Module load callback
89 */
90void
92{
93 /* Define custom GUC variables. */
94 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.",
98 -1,
99 -1, INT_MAX,
100 PGC_SUSET,
102 NULL,
103 NULL,
104 NULL);
105
106 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.",
110 -1,
111 -1, INT_MAX,
112 PGC_SUSET,
114 NULL,
115 NULL,
116 NULL);
117
118 DefineCustomBoolVariable("auto_explain.log_analyze",
119 "Use EXPLAIN ANALYZE for plan logging.",
120 NULL,
122 false,
123 PGC_SUSET,
124 0,
125 NULL,
126 NULL,
127 NULL);
128
129 DefineCustomBoolVariable("auto_explain.log_settings",
130 "Log modified configuration parameters affecting query planning.",
131 NULL,
133 false,
134 PGC_SUSET,
135 0,
136 NULL,
137 NULL,
138 NULL);
139
140 DefineCustomBoolVariable("auto_explain.log_verbose",
141 "Use EXPLAIN VERBOSE for plan logging.",
142 NULL,
144 false,
145 PGC_SUSET,
146 0,
147 NULL,
148 NULL,
149 NULL);
150
151 DefineCustomBoolVariable("auto_explain.log_buffers",
152 "Log buffers usage.",
153 NULL,
155 false,
156 PGC_SUSET,
157 0,
158 NULL,
159 NULL,
160 NULL);
161
162 DefineCustomBoolVariable("auto_explain.log_wal",
163 "Log WAL usage.",
164 NULL,
166 false,
167 PGC_SUSET,
168 0,
169 NULL,
170 NULL,
171 NULL);
172
173 DefineCustomBoolVariable("auto_explain.log_triggers",
174 "Include trigger statistics in plans.",
175 "This has no effect unless log_analyze is also set.",
177 false,
178 PGC_SUSET,
179 0,
180 NULL,
181 NULL,
182 NULL);
183
184 DefineCustomEnumVariable("auto_explain.log_format",
185 "EXPLAIN format to be used for plan logging.",
186 NULL,
190 PGC_SUSET,
191 0,
192 NULL,
193 NULL,
194 NULL);
195
196 DefineCustomEnumVariable("auto_explain.log_level",
197 "Log level for the plan.",
198 NULL,
200 LOG,
202 PGC_SUSET,
203 0,
204 NULL,
205 NULL,
206 NULL);
207
208 DefineCustomBoolVariable("auto_explain.log_nested_statements",
209 "Log nested statements.",
210 NULL,
212 false,
213 PGC_SUSET,
214 0,
215 NULL,
216 NULL,
217 NULL);
218
219 DefineCustomBoolVariable("auto_explain.log_timing",
220 "Collect timing data, not just row counts.",
221 NULL,
223 true,
224 PGC_SUSET,
225 0,
226 NULL,
227 NULL,
228 NULL);
229
230 DefineCustomRealVariable("auto_explain.sample_rate",
231 "Fraction of queries to process.",
232 NULL,
234 1.0,
235 0.0,
236 1.0,
237 PGC_SUSET,
238 0,
239 NULL,
240 NULL,
241 NULL);
242
243 MarkGUCPrefixReserved("auto_explain");
244
245 /* Install hooks. */
254}
255
256/*
257 * ExecutorStart hook: start up logging if needed
258 */
259static void
260explain_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 if (nesting_level == 0)
273 {
276 else
277 current_query_sampled = false;
278 }
279
281 {
282 /* Enable per-node instrumentation iff log_analyze is required. */
284 {
287 else
293 }
294 }
295
297 prev_ExecutorStart(queryDesc, eflags);
298 else
299 standard_ExecutorStart(queryDesc, eflags);
300
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 if (queryDesc->totaltime == NULL)
309 {
310 MemoryContext oldcxt;
311
312 oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
313 queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
314 MemoryContextSwitchTo(oldcxt);
315 }
316 }
317}
318
319/*
320 * ExecutorRun hook: all we need do is track nesting depth
321 */
322static void
324 uint64 count)
325{
327 PG_TRY();
328 {
330 prev_ExecutorRun(queryDesc, direction, count);
331 else
332 standard_ExecutorRun(queryDesc, direction, count);
333 }
334 PG_FINALLY();
335 {
337 }
338 PG_END_TRY();
339}
340
341/*
342 * ExecutorFinish hook: all we need do is track nesting depth
343 */
344static void
346{
348 PG_TRY();
349 {
351 prev_ExecutorFinish(queryDesc);
352 else
353 standard_ExecutorFinish(queryDesc);
354 }
355 PG_FINALLY();
356 {
358 }
359 PG_END_TRY();
360}
361
362/*
363 * ExecutorEnd hook: log results if needed
364 */
365static void
367{
368 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 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 InstrEndLoop(queryDesc->totaltime);
384
385 /* Log plan if duration is exceeded. */
386 msec = queryDesc->totaltime->total * 1000.0;
388 {
390
394 es->wal = (es->analyze && auto_explain_log_wal);
396 es->summary = es->analyze;
397 /* No support for MEMORY */
398 /* es->memory = false; */
401
403 ExplainQueryText(es, queryDesc);
405 ExplainPrintPlan(es, queryDesc);
407 ExplainPrintTriggers(es, queryDesc);
408 if (es->costs)
409 ExplainPrintJITSummary(es, queryDesc);
411
412 /* Remove last line break */
413 if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
414 es->str->data[--es->str->len] = '\0';
415
416 /* Fix JSON to output an object */
418 {
419 es->str->data[0] = '{';
420 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 */
430 (errmsg("duration: %.3f ms plan:\n%s",
431 msec, es->str->data),
432 errhidestmt(true)));
433 }
434
435 MemoryContextSwitchTo(oldcxt);
436 }
437
439 prev_ExecutorEnd(queryDesc);
440 else
441 standard_ExecutorEnd(queryDesc);
442}
static ExecutorRun_hook_type prev_ExecutorRun
Definition: auto_explain.c:75
static int auto_explain_log_min_duration
Definition: auto_explain.c:26
static bool auto_explain_log_analyze
Definition: auto_explain.c:28
static void explain_ExecutorEnd(QueryDesc *queryDesc)
Definition: auto_explain.c:366
void _PG_init(void)
Definition: auto_explain.c:91
static bool auto_explain_log_wal
Definition: auto_explain.c:31
#define auto_explain_enabled()
Definition: auto_explain.c:68
PG_MODULE_MAGIC
Definition: auto_explain.c:23
static double auto_explain_sample_rate
Definition: auto_explain.c:38
static bool auto_explain_log_nested_statements
Definition: auto_explain.c:37
static int auto_explain_log_parameter_max_length
Definition: auto_explain.c:27
static bool auto_explain_log_verbose
Definition: auto_explain.c:29
static void explain_ExecutorFinish(QueryDesc *queryDesc)
Definition: auto_explain.c:345
static int nesting_level
Definition: auto_explain.c:63
static bool current_query_sampled
Definition: auto_explain.c:66
static void explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count)
Definition: auto_explain.c:323
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
Definition: auto_explain.c:260
static ExecutorStart_hook_type prev_ExecutorStart
Definition: auto_explain.c:74
static const struct config_enum_entry loglevel_options[]
Definition: auto_explain.c:48
static bool auto_explain_log_timing
Definition: auto_explain.c:33
static int auto_explain_log_format
Definition: auto_explain.c:35
static bool auto_explain_log_buffers
Definition: auto_explain.c:30
static bool auto_explain_log_triggers
Definition: auto_explain.c:32
static const struct config_enum_entry format_options[]
Definition: auto_explain.c:40
static ExecutorEnd_hook_type prev_ExecutorEnd
Definition: auto_explain.c:77
static int auto_explain_log_level
Definition: auto_explain.c:36
static ExecutorFinish_hook_type prev_ExecutorFinish
Definition: auto_explain.c:76
static bool auto_explain_log_settings
Definition: auto_explain.c:34
uint64_t uint64
Definition: c.h:489
int errhidestmt(bool hide_stmt)
Definition: elog.c:1411
int errmsg(const char *fmt,...)
Definition: elog.c:1070
#define LOG
Definition: elog.h:31
#define DEBUG3
Definition: elog.h:28
#define PG_TRY(...)
Definition: elog.h:371
#define WARNING
Definition: elog.h:36
#define DEBUG2
Definition: elog.h:29
#define PG_END_TRY(...)
Definition: elog.h:396
#define DEBUG1
Definition: elog.h:30
#define NOTICE
Definition: elog.h:35
#define PG_FINALLY(...)
Definition: elog.h:388
#define INFO
Definition: elog.h:34
#define ereport(elevel,...)
Definition: elog.h:149
#define DEBUG5
Definition: elog.h:26
#define DEBUG4
Definition: elog.h:27
ExecutorEnd_hook_type ExecutorEnd_hook
Definition: execMain.c:71
ExecutorFinish_hook_type ExecutorFinish_hook
Definition: execMain.c:70
ExecutorStart_hook_type ExecutorStart_hook
Definition: execMain.c:68
void standard_ExecutorStart(QueryDesc *queryDesc, int eflags)
Definition: execMain.c:139
ExecutorRun_hook_type ExecutorRun_hook
Definition: execMain.c:69
void standard_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count)
Definition: execMain.c:305
void standard_ExecutorEnd(QueryDesc *queryDesc)
Definition: execMain.c:473
void standard_ExecutorFinish(QueryDesc *queryDesc)
Definition: execMain.c:413
void(* ExecutorFinish_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:85
void(* ExecutorRun_hook_type)(QueryDesc *queryDesc, ScanDirection direction, uint64 count)
Definition: executor.h:79
void(* ExecutorStart_hook_type)(QueryDesc *queryDesc, int eflags)
Definition: executor.h:75
void(* ExecutorEnd_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:89
#define EXEC_FLAG_EXPLAIN_ONLY
Definition: executor.h:65
ExplainState * NewExplainState(void)
Definition: explain.c:387
void ExplainEndOutput(ExplainState *es)
Definition: explain.c:5481
void ExplainPrintJITSummary(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:1024
void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:1208
void ExplainBeginOutput(ExplainState *es)
Definition: explain.c:5450
void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:904
void ExplainQueryParameters(ExplainState *es, ParamListInfo params, int maxlen)
Definition: explain.c:1223
void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:981
@ EXPLAIN_FORMAT_XML
Definition: explain.h:30
@ EXPLAIN_FORMAT_YAML
Definition: explain.h:32
@ EXPLAIN_FORMAT_TEXT
Definition: explain.h:29
@ EXPLAIN_FORMAT_JSON
Definition: explain.h:31
void DefineCustomRealVariable(const char *name, const char *short_desc, const char *long_desc, double *valueAddr, double bootValue, double minValue, double maxValue, GucContext context, int flags, GucRealCheckHook check_hook, GucRealAssignHook assign_hook, GucShowHook show_hook)
Definition: guc.c:5188
void DefineCustomEnumVariable(const char *name, const char *short_desc, const char *long_desc, int *valueAddr, int bootValue, const struct config_enum_entry *options, GucContext context, int flags, GucEnumCheckHook check_hook, GucEnumAssignHook assign_hook, GucShowHook show_hook)
Definition: guc.c:5243
void DefineCustomBoolVariable(const char *name, const char *short_desc, const char *long_desc, bool *valueAddr, bool bootValue, GucContext context, int flags, GucBoolCheckHook check_hook, GucBoolAssignHook assign_hook, GucShowHook show_hook)
Definition: guc.c:5132
void MarkGUCPrefixReserved(const char *className)
Definition: guc.c:5279
void DefineCustomIntVariable(const char *name, const char *short_desc, const char *long_desc, int *valueAddr, int bootValue, int minValue, int maxValue, GucContext context, int flags, GucIntCheckHook check_hook, GucIntAssignHook assign_hook, GucShowHook show_hook)
Definition: guc.c:5158
#define GUC_UNIT_MS
Definition: guc.h:239
@ PGC_SUSET
Definition: guc.h:78
#define GUC_UNIT_BYTE
Definition: guc.h:236
#define IsParallelWorker()
Definition: parallel.h:60
void InstrEndLoop(Instrumentation *instr)
Definition: instrument.c:140
Instrumentation * InstrAlloc(int n, int instrument_options, bool async_mode)
Definition: instrument.c:31
@ INSTRUMENT_ALL
Definition: instrument.h:65
@ INSTRUMENT_TIMER
Definition: instrument.h:61
@ INSTRUMENT_BUFFERS
Definition: instrument.h:62
@ INSTRUMENT_WAL
Definition: instrument.h:64
@ INSTRUMENT_ROWS
Definition: instrument.h:63
static MemoryContext MemoryContextSwitchTo(MemoryContext context)
Definition: palloc.h:124
double pg_prng_double(pg_prng_state *state)
Definition: pg_prng.c:268
pg_prng_state pg_global_prng_state
Definition: pg_prng.c:34
ScanDirection
Definition: sdir.h:25
MemoryContext es_query_cxt
Definition: execnodes.h:700
bool verbose
Definition: explain.h:48
bool settings
Definition: explain.h:56
bool timing
Definition: explain.h:53
bool analyze
Definition: explain.h:49
StringInfo str
Definition: explain.h:46
ExplainFormat format
Definition: explain.h:59
bool wal
Definition: explain.h:52
bool summary
Definition: explain.h:54
bool costs
Definition: explain.h:50
bool buffers
Definition: explain.h:51
ParamListInfo params
Definition: execdesc.h:42
int instrument_options
Definition: execdesc.h:44
EState * estate
Definition: execdesc.h:48
struct Instrumentation * totaltime
Definition: execdesc.h:55
Definition: guc.h:174