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