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-2022, 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 
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;
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 */
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 _PG_init(void)
94 {
95  /* Define custom GUC variables. */
96  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.",
100  -1,
101  -1, INT_MAX,
102  PGC_SUSET,
103  GUC_UNIT_MS,
104  NULL,
105  NULL,
106  NULL);
107 
108  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.",
112  -1,
113  -1, INT_MAX,
114  PGC_SUSET,
116  NULL,
117  NULL,
118  NULL);
119 
120  DefineCustomBoolVariable("auto_explain.log_analyze",
121  "Use EXPLAIN ANALYZE for plan logging.",
122  NULL,
124  false,
125  PGC_SUSET,
126  0,
127  NULL,
128  NULL,
129  NULL);
130 
131  DefineCustomBoolVariable("auto_explain.log_settings",
132  "Log modified configuration parameters affecting query planning.",
133  NULL,
135  false,
136  PGC_SUSET,
137  0,
138  NULL,
139  NULL,
140  NULL);
141 
142  DefineCustomBoolVariable("auto_explain.log_verbose",
143  "Use EXPLAIN VERBOSE for plan logging.",
144  NULL,
146  false,
147  PGC_SUSET,
148  0,
149  NULL,
150  NULL,
151  NULL);
152 
153  DefineCustomBoolVariable("auto_explain.log_buffers",
154  "Log buffers usage.",
155  NULL,
157  false,
158  PGC_SUSET,
159  0,
160  NULL,
161  NULL,
162  NULL);
163 
164  DefineCustomBoolVariable("auto_explain.log_wal",
165  "Log WAL usage.",
166  NULL,
168  false,
169  PGC_SUSET,
170  0,
171  NULL,
172  NULL,
173  NULL);
174 
175  DefineCustomBoolVariable("auto_explain.log_triggers",
176  "Include trigger statistics in plans.",
177  "This has no effect unless log_analyze is also set.",
179  false,
180  PGC_SUSET,
181  0,
182  NULL,
183  NULL,
184  NULL);
185 
186  DefineCustomEnumVariable("auto_explain.log_format",
187  "EXPLAIN format to be used for plan logging.",
188  NULL,
192  PGC_SUSET,
193  0,
194  NULL,
195  NULL,
196  NULL);
197 
198  DefineCustomEnumVariable("auto_explain.log_level",
199  "Log level for the plan.",
200  NULL,
202  LOG,
204  PGC_SUSET,
205  0,
206  NULL,
207  NULL,
208  NULL);
209 
210  DefineCustomBoolVariable("auto_explain.log_nested_statements",
211  "Log nested statements.",
212  NULL,
214  false,
215  PGC_SUSET,
216  0,
217  NULL,
218  NULL,
219  NULL);
220 
221  DefineCustomBoolVariable("auto_explain.log_timing",
222  "Collect timing data, not just row counts.",
223  NULL,
225  true,
226  PGC_SUSET,
227  0,
228  NULL,
229  NULL,
230  NULL);
231 
232  DefineCustomRealVariable("auto_explain.sample_rate",
233  "Fraction of queries to process.",
234  NULL,
236  1.0,
237  0.0,
238  1.0,
239  PGC_SUSET,
240  0,
241  NULL,
242  NULL,
243  NULL);
244 
245  MarkGUCPrefixReserved("auto_explain");
246 
247  /* Install hooks. */
256 }
257 
258 /*
259  * ExecutorStart hook: start up logging if needed
260  */
261 static void
262 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  if (nesting_level == 0)
275  {
278  else
279  current_query_sampled = false;
280  }
281 
282  if (auto_explain_enabled())
283  {
284  /* Enable per-node instrumentation iff log_analyze is required. */
285  if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
286  {
288  queryDesc->instrument_options |= INSTRUMENT_TIMER;
289  else
290  queryDesc->instrument_options |= INSTRUMENT_ROWS;
294  queryDesc->instrument_options |= INSTRUMENT_WAL;
295  }
296  }
297 
298  if (prev_ExecutorStart)
299  prev_ExecutorStart(queryDesc, eflags);
300  else
301  standard_ExecutorStart(queryDesc, eflags);
302 
303  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  if (queryDesc->totaltime == NULL)
311  {
312  MemoryContext oldcxt;
313 
314  oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
315  queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
316  MemoryContextSwitchTo(oldcxt);
317  }
318  }
319 }
320 
321 /*
322  * ExecutorRun hook: all we need do is track nesting depth
323  */
324 static void
326  uint64 count, bool execute_once)
327 {
328  nesting_level++;
329  PG_TRY();
330  {
331  if (prev_ExecutorRun)
332  prev_ExecutorRun(queryDesc, direction, count, execute_once);
333  else
334  standard_ExecutorRun(queryDesc, direction, count, execute_once);
335  }
336  PG_FINALLY();
337  {
338  nesting_level--;
339  }
340  PG_END_TRY();
341 }
342 
343 /*
344  * ExecutorFinish hook: all we need do is track nesting depth
345  */
346 static void
348 {
349  nesting_level++;
350  PG_TRY();
351  {
353  prev_ExecutorFinish(queryDesc);
354  else
355  standard_ExecutorFinish(queryDesc);
356  }
357  PG_FINALLY();
358  {
359  nesting_level--;
360  }
361  PG_END_TRY();
362 }
363 
364 /*
365  * ExecutorEnd hook: log results if needed
366  */
367 static void
369 {
370  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  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  InstrEndLoop(queryDesc->totaltime);
386 
387  /* Log plan if duration is exceeded. */
388  msec = queryDesc->totaltime->total * 1000.0;
389  if (msec >= auto_explain_log_min_duration)
390  {
392 
396  es->wal = (es->analyze && auto_explain_log_wal);
397  es->timing = (es->analyze && auto_explain_log_timing);
398  es->summary = es->analyze;
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:77
static int auto_explain_log_min_duration
Definition: auto_explain.c:28
static bool auto_explain_log_analyze
Definition: auto_explain.c:30
static void explain_ExecutorEnd(QueryDesc *queryDesc)
Definition: auto_explain.c:368
void _PG_init(void)
Definition: auto_explain.c:93
static bool auto_explain_log_wal
Definition: auto_explain.c:33
#define auto_explain_enabled()
Definition: auto_explain.c:70
PG_MODULE_MAGIC
Definition: auto_explain.c:25
static double auto_explain_sample_rate
Definition: auto_explain.c:40
static bool auto_explain_log_nested_statements
Definition: auto_explain.c:39
static int auto_explain_log_parameter_max_length
Definition: auto_explain.c:29
static bool auto_explain_log_verbose
Definition: auto_explain.c:31
static void explain_ExecutorFinish(QueryDesc *queryDesc)
Definition: auto_explain.c:347
static int nesting_level
Definition: auto_explain.c:65
static bool current_query_sampled
Definition: auto_explain.c:68
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
Definition: auto_explain.c:262
static ExecutorStart_hook_type prev_ExecutorStart
Definition: auto_explain.c:76
static const struct config_enum_entry loglevel_options[]
Definition: auto_explain.c:50
static bool auto_explain_log_timing
Definition: auto_explain.c:35
static int auto_explain_log_format
Definition: auto_explain.c:37
static bool auto_explain_log_buffers
Definition: auto_explain.c:32
static bool auto_explain_log_triggers
Definition: auto_explain.c:34
static const struct config_enum_entry format_options[]
Definition: auto_explain.c:42
static ExecutorEnd_hook_type prev_ExecutorEnd
Definition: auto_explain.c:79
static int auto_explain_log_level
Definition: auto_explain.c:38
static void explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: auto_explain.c:325
static ExecutorFinish_hook_type prev_ExecutorFinish
Definition: auto_explain.c:78
static bool auto_explain_log_settings
Definition: auto_explain.c:36
int errhidestmt(bool hide_stmt)
Definition: elog.c:1287
int errmsg(const char *fmt,...)
Definition: elog.c:946
#define LOG
Definition: elog.h:27
#define DEBUG3
Definition: elog.h:24
#define PG_TRY(...)
Definition: elog.h:309
#define WARNING
Definition: elog.h:32
#define DEBUG2
Definition: elog.h:25
#define PG_END_TRY(...)
Definition: elog.h:334
#define DEBUG1
Definition: elog.h:26
#define NOTICE
Definition: elog.h:31
#define PG_FINALLY(...)
Definition: elog.h:326
#define INFO
Definition: elog.h:30
#define ereport(elevel,...)
Definition: elog.h:145
#define DEBUG5
Definition: elog.h:22
#define DEBUG4
Definition: elog.h:23
ExecutorEnd_hook_type ExecutorEnd_hook
Definition: execMain.c:76
ExecutorFinish_hook_type ExecutorFinish_hook
Definition: execMain.c:75
ExecutorStart_hook_type ExecutorStart_hook
Definition: execMain.c:73
void standard_ExecutorStart(QueryDesc *queryDesc, int eflags)
Definition: execMain.c:149
void standard_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: execMain.c:312
ExecutorRun_hook_type ExecutorRun_hook
Definition: execMain.c:74
void standard_ExecutorEnd(QueryDesc *queryDesc)
Definition: execMain.c:471
void standard_ExecutorFinish(QueryDesc *queryDesc)
Definition: execMain.c:411
void(* ExecutorRun_hook_type)(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: executor.h:69
void(* ExecutorFinish_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:76
void(* ExecutorStart_hook_type)(QueryDesc *queryDesc, int eflags)
Definition: executor.h:65
void(* ExecutorEnd_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:80
#define EXEC_FLAG_EXPLAIN_ONLY
Definition: executor.h:56
void ExplainEndOutput(ExplainState *es)
Definition: explain.c:4895
void ExplainPrintJITSummary(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:849
void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:969
void ExplainBeginOutput(ExplainState *es)
Definition: explain.c:4864
ExplainState * NewExplainState(void)
Definition: explain.c:311
void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:757
void ExplainQueryParameters(ExplainState *es, ParamListInfo params, int maxlen)
Definition: explain.c:984
void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:806
@ EXPLAIN_FORMAT_XML
Definition: explain.h:23
@ EXPLAIN_FORMAT_YAML
Definition: explain.h:25
@ EXPLAIN_FORMAT_TEXT
Definition: explain.h:22
@ EXPLAIN_FORMAT_JSON
Definition: explain.h:24
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:4996
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:5051
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:4940
void MarkGUCPrefixReserved(const char *className)
Definition: guc.c:5087
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:4966
#define GUC_UNIT_MS
Definition: guc.h:232
@ PGC_SUSET
Definition: guc.h:74
#define GUC_UNIT_BYTE
Definition: guc.h:229
#define IsParallelWorker()
Definition: parallel.h:61
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:63
@ INSTRUMENT_TIMER
Definition: instrument.h:59
@ INSTRUMENT_BUFFERS
Definition: instrument.h:60
@ INSTRUMENT_WAL
Definition: instrument.h:62
@ INSTRUMENT_ROWS
Definition: instrument.h:61
static MemoryContext MemoryContextSwitchTo(MemoryContext context)
Definition: palloc.h:135
double pg_prng_double(pg_prng_state *state)
Definition: pg_prng.c:226
pg_prng_state pg_global_prng_state
Definition: pg_prng.c:28
ScanDirection
Definition: sdir.h:23
MemoryContext es_query_cxt
Definition: execnodes.h:653
bool verbose
Definition: explain.h:41
bool settings
Definition: explain.h:48
bool timing
Definition: explain.h:46
bool analyze
Definition: explain.h:42
StringInfo str
Definition: explain.h:39
ExplainFormat format
Definition: explain.h:49
bool wal
Definition: explain.h:45
bool summary
Definition: explain.h:47
bool costs
Definition: explain.h:43
bool buffers
Definition: explain.h:44
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:168