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-2020, 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 "executor/instrument.h"
20 #include "jit/jit.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 bool auto_explain_log_analyze = false;
28 static bool auto_explain_log_verbose = false;
29 static bool auto_explain_log_buffers = false;
30 static bool auto_explain_log_wal = false;
31 static bool auto_explain_log_triggers = false;
32 static bool auto_explain_log_timing = true;
33 static bool auto_explain_log_settings = false;
37 static double auto_explain_sample_rate = 1;
38 
39 static const struct config_enum_entry format_options[] = {
40  {"text", EXPLAIN_FORMAT_TEXT, false},
41  {"xml", EXPLAIN_FORMAT_XML, false},
42  {"json", EXPLAIN_FORMAT_JSON, false},
43  {"yaml", EXPLAIN_FORMAT_YAML, false},
44  {NULL, 0, false}
45 };
46 
47 static const struct config_enum_entry loglevel_options[] = {
48  {"debug5", DEBUG5, false},
49  {"debug4", DEBUG4, false},
50  {"debug3", DEBUG3, false},
51  {"debug2", DEBUG2, false},
52  {"debug1", DEBUG1, false},
53  {"debug", DEBUG2, true},
54  {"info", INFO, false},
55  {"notice", NOTICE, false},
56  {"warning", WARNING, false},
57  {"log", LOG, false},
58  {NULL, 0, false}
59 };
60 
61 /* Current nesting depth of ExecutorRun calls */
62 static int nesting_level = 0;
63 
64 /* Is the current top-level query to be sampled? */
65 static bool current_query_sampled = false;
66 
67 #define auto_explain_enabled() \
68  (auto_explain_log_min_duration >= 0 && \
69  (nesting_level == 0 || auto_explain_log_nested_statements) && \
70  current_query_sampled)
71 
72 /* Saved hook values in case of unload */
77 
78 void _PG_init(void);
79 void _PG_fini(void);
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  DefineCustomBoolVariable("auto_explain.log_analyze",
109  "Use EXPLAIN ANALYZE for plan logging.",
110  NULL,
112  false,
113  PGC_SUSET,
114  0,
115  NULL,
116  NULL,
117  NULL);
118 
119  DefineCustomBoolVariable("auto_explain.log_settings",
120  "Log modified configuration parameters affecting query planning.",
121  NULL,
123  false,
124  PGC_SUSET,
125  0,
126  NULL,
127  NULL,
128  NULL);
129 
130  DefineCustomBoolVariable("auto_explain.log_verbose",
131  "Use EXPLAIN VERBOSE for plan logging.",
132  NULL,
134  false,
135  PGC_SUSET,
136  0,
137  NULL,
138  NULL,
139  NULL);
140 
141  DefineCustomBoolVariable("auto_explain.log_buffers",
142  "Log buffers usage.",
143  NULL,
145  false,
146  PGC_SUSET,
147  0,
148  NULL,
149  NULL,
150  NULL);
151 
152  DefineCustomBoolVariable("auto_explain.log_wal",
153  "Log WAL usage.",
154  NULL,
156  false,
157  PGC_SUSET,
158  0,
159  NULL,
160  NULL,
161  NULL);
162 
163  DefineCustomBoolVariable("auto_explain.log_triggers",
164  "Include trigger statistics in plans.",
165  "This has no effect unless log_analyze is also set.",
167  false,
168  PGC_SUSET,
169  0,
170  NULL,
171  NULL,
172  NULL);
173 
174  DefineCustomEnumVariable("auto_explain.log_format",
175  "EXPLAIN format to be used for plan logging.",
176  NULL,
179  format_options,
180  PGC_SUSET,
181  0,
182  NULL,
183  NULL,
184  NULL);
185 
186  DefineCustomEnumVariable("auto_explain.log_level",
187  "Log level for the plan.",
188  NULL,
190  LOG,
191  loglevel_options,
192  PGC_SUSET,
193  0,
194  NULL,
195  NULL,
196  NULL);
197 
198  DefineCustomBoolVariable("auto_explain.log_nested_statements",
199  "Log nested statements.",
200  NULL,
202  false,
203  PGC_SUSET,
204  0,
205  NULL,
206  NULL,
207  NULL);
208 
209  DefineCustomBoolVariable("auto_explain.log_timing",
210  "Collect timing data, not just row counts.",
211  NULL,
213  true,
214  PGC_SUSET,
215  0,
216  NULL,
217  NULL,
218  NULL);
219 
220  DefineCustomRealVariable("auto_explain.sample_rate",
221  "Fraction of queries to process.",
222  NULL,
224  1.0,
225  0.0,
226  1.0,
227  PGC_SUSET,
228  0,
229  NULL,
230  NULL,
231  NULL);
232 
233  EmitWarningsOnPlaceholders("auto_explain");
234 
235  /* Install hooks. */
244 }
245 
246 /*
247  * Module unload callback
248  */
249 void
250 _PG_fini(void)
251 {
252  /* Uninstall hooks. */
257 }
258 
259 /*
260  * ExecutorStart hook: start up logging if needed
261  */
262 static void
263 explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
264 {
265  /*
266  * At the beginning of each top-level statement, decide whether we'll
267  * sample this statement. If nested-statement explaining is enabled,
268  * either all nested statements will be explained or none will.
269  *
270  * When in a parallel worker, we should do nothing, which we can implement
271  * cheaply by pretending we decided not to sample the current statement.
272  * If EXPLAIN is active in the parent session, data will be collected and
273  * reported back to the parent, and it's no business of ours to interfere.
274  */
275  if (nesting_level == 0)
276  {
279  ((double) MAX_RANDOM_VALUE + 1));
280  else
281  current_query_sampled = false;
282  }
283 
284  if (auto_explain_enabled())
285  {
286  /* Enable per-node instrumentation iff log_analyze is required. */
287  if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
288  {
290  queryDesc->instrument_options |= INSTRUMENT_TIMER;
291  else
292  queryDesc->instrument_options |= INSTRUMENT_ROWS;
296  queryDesc->instrument_options |= INSTRUMENT_WAL;
297  }
298  }
299 
300  if (prev_ExecutorStart)
301  prev_ExecutorStart(queryDesc, eflags);
302  else
303  standard_ExecutorStart(queryDesc, eflags);
304 
305  if (auto_explain_enabled())
306  {
307  /*
308  * Set up to track total elapsed time in ExecutorRun. Make sure the
309  * space is allocated in the per-query context so it will go away at
310  * ExecutorEnd.
311  */
312  if (queryDesc->totaltime == NULL)
313  {
314  MemoryContext oldcxt;
315 
316  oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
317  queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
318  MemoryContextSwitchTo(oldcxt);
319  }
320  }
321 }
322 
323 /*
324  * ExecutorRun hook: all we need do is track nesting depth
325  */
326 static void
328  uint64 count, bool execute_once)
329 {
330  nesting_level++;
331  PG_TRY();
332  {
333  if (prev_ExecutorRun)
334  prev_ExecutorRun(queryDesc, direction, count, execute_once);
335  else
336  standard_ExecutorRun(queryDesc, direction, count, execute_once);
337  }
338  PG_FINALLY();
339  {
340  nesting_level--;
341  }
342  PG_END_TRY();
343 }
344 
345 /*
346  * ExecutorFinish hook: all we need do is track nesting depth
347  */
348 static void
350 {
351  nesting_level++;
352  PG_TRY();
353  {
355  prev_ExecutorFinish(queryDesc);
356  else
357  standard_ExecutorFinish(queryDesc);
358  }
359  PG_FINALLY();
360  {
361  nesting_level--;
362  }
363  PG_END_TRY();
364 }
365 
366 /*
367  * ExecutorEnd hook: log results if needed
368  */
369 static void
371 {
372  if (queryDesc->totaltime && auto_explain_enabled())
373  {
374  double msec;
375 
376  /*
377  * Make sure stats accumulation is done. (Note: it's okay if several
378  * levels of hook all do this.)
379  */
380  InstrEndLoop(queryDesc->totaltime);
381 
382  /* Log plan if duration is exceeded. */
383  msec = queryDesc->totaltime->total * 1000.0;
384  if (msec >= auto_explain_log_min_duration)
385  {
387 
391  es->wal = (es->analyze && auto_explain_log_wal);
392  es->timing = (es->analyze && auto_explain_log_timing);
393  es->summary = es->analyze;
396 
397  ExplainBeginOutput(es);
398  ExplainQueryText(es, queryDesc);
399  ExplainPrintPlan(es, queryDesc);
401  ExplainPrintTriggers(es, queryDesc);
402  if (es->costs)
403  ExplainPrintJITSummary(es, queryDesc);
404  ExplainEndOutput(es);
405 
406  /* Remove last line break */
407  if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
408  es->str->data[--es->str->len] = '\0';
409 
410  /* Fix JSON to output an object */
412  {
413  es->str->data[0] = '{';
414  es->str->data[es->str->len - 1] = '}';
415  }
416 
417  /*
418  * Note: we rely on the existing logging of context or
419  * debug_query_string to identify just which statement is being
420  * reported. This isn't ideal but trying to do it here would
421  * often result in duplication.
422  */
424  (errmsg("duration: %.3f ms plan:\n%s",
425  msec, es->str->data),
426  errhidestmt(true)));
427 
428  pfree(es->str->data);
429  }
430  }
431 
432  if (prev_ExecutorEnd)
433  prev_ExecutorEnd(queryDesc);
434  else
435  standard_ExecutorEnd(queryDesc);
436 }
static double auto_explain_sample_rate
Definition: auto_explain.c:37
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:8797
bool summary
Definition: explain.h:47
void(* ExecutorRun_hook_type)(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: executor.h:69
void standard_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: execMain.c:312
static int auto_explain_log_level
Definition: auto_explain.c:35
static ExecutorRun_hook_type prev_ExecutorRun
Definition: auto_explain.c:74
static bool current_query_sampled
Definition: auto_explain.c:65
ExplainState * NewExplainState(void)
Definition: explain.c:309
#define DEBUG1
Definition: elog.h:25
EState * estate
Definition: execdesc.h:48
Definition: guc.h:164
#define DEBUG3
Definition: elog.h:23
static bool auto_explain_log_verbose
Definition: auto_explain.c:28
PG_MODULE_MAGIC
Definition: auto_explain.c:23
long random(void)
Definition: random.c:22
static bool auto_explain_log_buffers
Definition: auto_explain.c:29
void standard_ExecutorStart(QueryDesc *queryDesc, int eflags)
Definition: execMain.c:152
static MemoryContext MemoryContextSwitchTo(MemoryContext context)
Definition: palloc.h:109
void standard_ExecutorEnd(QueryDesc *queryDesc)
Definition: execMain.c:471
int errhidestmt(bool hide_stmt)
Definition: elog.c:1142
Instrumentation * InstrAlloc(int n, int instrument_options)
Definition: instrument.c:31
void(* ExecutorFinish_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:76
#define INFO
Definition: elog.h:33
static bool auto_explain_log_nested_statements
Definition: auto_explain.c:36
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
Definition: auto_explain.c:263
static int auto_explain_log_format
Definition: auto_explain.c:34
#define LOG
Definition: elog.h:26
bool costs
Definition: explain.h:43
#define DEBUG4
Definition: elog.h:22
bool analyze
Definition: explain.h:42
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:8827
void standard_ExecutorFinish(QueryDesc *queryDesc)
Definition: execMain.c:411
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:8882
int instrument_options
Definition: execdesc.h:44
ExecutorStart_hook_type ExecutorStart_hook
Definition: execMain.c:70
void InstrEndLoop(Instrumentation *instr)
Definition: instrument.c:121
static ExecutorStart_hook_type prev_ExecutorStart
Definition: auto_explain.c:73
void ExplainEndOutput(ExplainState *es)
Definition: explain.c:4568
#define auto_explain_enabled()
Definition: auto_explain.c:67
void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:780
static void explain_ExecutorFinish(QueryDesc *queryDesc)
Definition: auto_explain.c:349
void pfree(void *pointer)
Definition: mcxt.c:1056
MemoryContext es_query_cxt
Definition: execnodes.h:555
void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:731
static const struct config_enum_entry format_options[]
Definition: auto_explain.c:39
void ExplainBeginOutput(ExplainState *es)
Definition: explain.c:4537
ExecutorRun_hook_type ExecutorRun_hook
Definition: execMain.c:71
ExecutorEnd_hook_type ExecutorEnd_hook
Definition: execMain.c:73
static int nesting_level
Definition: auto_explain.c:62
Definition: guc.h:75
void EmitWarningsOnPlaceholders(const char *className)
Definition: guc.c:8910
#define DEBUG2
Definition: elog.h:24
void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:946
ScanDirection
Definition: sdir.h:22
#define MAX_RANDOM_VALUE
#define IsParallelWorker()
Definition: parallel.h:61
bool timing
Definition: explain.h:46
#define WARNING
Definition: elog.h:40
static int auto_explain_log_min_duration
Definition: auto_explain.c:26
#define PG_FINALLY()
Definition: elog.h:312
static bool auto_explain_log_timing
Definition: auto_explain.c:32
static ExecutorFinish_hook_type prev_ExecutorFinish
Definition: auto_explain.c:75
static const struct config_enum_entry loglevel_options[]
Definition: auto_explain.c:47
static bool auto_explain_log_wal
Definition: auto_explain.c:30
static bool auto_explain_log_analyze
Definition: auto_explain.c:27
bool verbose
Definition: explain.h:41
#define ereport(elevel,...)
Definition: elog.h:144
static void explain_ExecutorEnd(QueryDesc *queryDesc)
Definition: auto_explain.c:370
#define NOTICE
Definition: elog.h:37
struct Instrumentation * totaltime
Definition: execdesc.h:55
void(* ExecutorEnd_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:80
void _PG_fini(void)
Definition: auto_explain.c:250
static ExecutorEnd_hook_type prev_ExecutorEnd
Definition: auto_explain.c:76
bool wal
Definition: explain.h:45
ExplainFormat format
Definition: explain.h:49
static void explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: auto_explain.c:327
int errmsg(const char *fmt,...)
Definition: elog.c:824
void(* ExecutorStart_hook_type)(QueryDesc *queryDesc, int eflags)
Definition: executor.h:65
bool buffers
Definition: explain.h:44
ExecutorFinish_hook_type ExecutorFinish_hook
Definition: execMain.c:72
void ExplainPrintJITSummary(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:826
#define DEBUG5
Definition: elog.h:20
static bool auto_explain_log_settings
Definition: auto_explain.c:33
#define PG_TRY()
Definition: elog.h:295
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:8771
StringInfo str
Definition: explain.h:39
#define EXEC_FLAG_EXPLAIN_ONLY
Definition: executor.h:56
void _PG_init(void)
Definition: auto_explain.c:93
bool settings
Definition: explain.h:48
#define PG_END_TRY()
Definition: elog.h:320
#define GUC_UNIT_MS
Definition: guc.h:225
static bool auto_explain_log_triggers
Definition: auto_explain.c:31