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-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 
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;
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 */
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 _PG_init(void)
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,
101  GUC_UNIT_MS,
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  */
259 static void
260 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  if (nesting_level == 0)
273  {
276  else
277  current_query_sampled = false;
278  }
279 
280  if (auto_explain_enabled())
281  {
282  /* Enable per-node instrumentation iff log_analyze is required. */
283  if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
284  {
286  queryDesc->instrument_options |= INSTRUMENT_TIMER;
287  else
288  queryDesc->instrument_options |= INSTRUMENT_ROWS;
292  queryDesc->instrument_options |= INSTRUMENT_WAL;
293  }
294  }
295 
296  if (prev_ExecutorStart)
297  prev_ExecutorStart(queryDesc, eflags);
298  else
299  standard_ExecutorStart(queryDesc, eflags);
300 
301  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  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  */
322 static void
324  uint64 count, bool execute_once)
325 {
326  nesting_level++;
327  PG_TRY();
328  {
329  if (prev_ExecutorRun)
330  prev_ExecutorRun(queryDesc, direction, count, execute_once);
331  else
332  standard_ExecutorRun(queryDesc, direction, count, execute_once);
333  }
334  PG_FINALLY();
335  {
336  nesting_level--;
337  }
338  PG_END_TRY();
339 }
340 
341 /*
342  * ExecutorFinish hook: all we need do is track nesting depth
343  */
344 static void
346 {
347  nesting_level++;
348  PG_TRY();
349  {
351  prev_ExecutorFinish(queryDesc);
352  else
353  standard_ExecutorFinish(queryDesc);
354  }
355  PG_FINALLY();
356  {
357  nesting_level--;
358  }
359  PG_END_TRY();
360 }
361 
362 /*
363  * ExecutorEnd hook: log results if needed
364  */
365 static 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;
387  if (msec >= auto_explain_log_min_duration)
388  {
390 
394  es->wal = (es->analyze && auto_explain_log_wal);
395  es->timing = (es->analyze && auto_explain_log_timing);
396  es->summary = es->analyze;
397  /* No support for MEMORY */
398  /* es->memory = false; */
401 
402  ExplainBeginOutput(es);
403  ExplainQueryText(es, queryDesc);
405  ExplainPrintPlan(es, queryDesc);
407  ExplainPrintTriggers(es, queryDesc);
408  if (es->costs)
409  ExplainPrintJITSummary(es, queryDesc);
410  ExplainEndOutput(es);
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 
438  if (prev_ExecutorEnd)
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_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 void explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: auto_explain.c:323
static ExecutorFinish_hook_type prev_ExecutorFinish
Definition: auto_explain.c:76
static bool auto_explain_log_settings
Definition: auto_explain.c:34
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:69
ExecutorFinish_hook_type ExecutorFinish_hook
Definition: execMain.c:68
ExecutorStart_hook_type ExecutorStart_hook
Definition: execMain.c:66
void standard_ExecutorStart(QueryDesc *queryDesc, int eflags)
Definition: execMain.c:139
void standard_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: execMain.c:306
ExecutorRun_hook_type ExecutorRun_hook
Definition: execMain.c:67
void standard_ExecutorEnd(QueryDesc *queryDesc)
Definition: execMain.c:474
void standard_ExecutorFinish(QueryDesc *queryDesc)
Definition: execMain.c:414
void(* ExecutorRun_hook_type)(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: executor.h:79
void(* ExecutorFinish_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:86
void(* ExecutorStart_hook_type)(QueryDesc *queryDesc, int eflags)
Definition: executor.h:75
void(* ExecutorEnd_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:90
#define EXEC_FLAG_EXPLAIN_ONLY
Definition: executor.h:65
void ExplainEndOutput(ExplainState *es)
Definition: explain.c:5474
void ExplainPrintJITSummary(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:1017
void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:1201
void ExplainBeginOutput(ExplainState *es)
Definition: explain.c:5443
ExplainState * NewExplainState(void)
Definition: explain.c:380
void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:897
void ExplainQueryParameters(ExplainState *es, ParamListInfo params, int maxlen)
Definition: explain.c:1216
void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:974
@ 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:5147
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:5202
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:5091
void MarkGUCPrefixReserved(const char *className)
Definition: guc.c:5238
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:5117
#define GUC_UNIT_MS
Definition: guc.h:235
@ PGC_SUSET
Definition: guc.h:74
#define GUC_UNIT_BYTE
Definition: guc.h:232
#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
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
MemoryContextSwitchTo(old_ctx)
ScanDirection
Definition: sdir.h:25
MemoryContext es_query_cxt
Definition: execnodes.h:675
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:170