PostgreSQL Source Code  git master
 All Data Structures Namespaces Files Functions Variables Typedefs Enumerations Enumerator Macros
auto_explain.c
Go to the documentation of this file.
1 /*-------------------------------------------------------------------------
2  *
3  * auto_explain.c
4  *
5  *
6  * Copyright (c) 2008-2017, 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 "commands/explain.h"
18 #include "executor/instrument.h"
19 #include "utils/guc.h"
20 
22 
23 /* GUC variables */
24 static int auto_explain_log_min_duration = -1; /* msec or -1 */
25 static bool auto_explain_log_analyze = false;
26 static bool auto_explain_log_verbose = false;
27 static bool auto_explain_log_buffers = false;
28 static bool auto_explain_log_triggers = false;
29 static bool auto_explain_log_timing = true;
32 static double auto_explain_sample_rate = 1;
33 
34 static const struct config_enum_entry format_options[] = {
35  {"text", EXPLAIN_FORMAT_TEXT, false},
36  {"xml", EXPLAIN_FORMAT_XML, false},
37  {"json", EXPLAIN_FORMAT_JSON, false},
38  {"yaml", EXPLAIN_FORMAT_YAML, false},
39  {NULL, 0, false}
40 };
41 
42 /* Current nesting depth of ExecutorRun calls */
43 static int nesting_level = 0;
44 
45 /* Saved hook values in case of unload */
50 
51 /* Is the current query sampled, per backend */
52 static bool current_query_sampled = true;
53 
54 #define auto_explain_enabled() \
55  (auto_explain_log_min_duration >= 0 && \
56  (nesting_level == 0 || auto_explain_log_nested_statements))
57 
58 void _PG_init(void);
59 void _PG_fini(void);
60 
61 static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
62 static void explain_ExecutorRun(QueryDesc *queryDesc,
63  ScanDirection direction,
64  uint64 count, bool execute_once);
65 static void explain_ExecutorFinish(QueryDesc *queryDesc);
66 static void explain_ExecutorEnd(QueryDesc *queryDesc);
67 
68 
69 /*
70  * Module load callback
71  */
72 void
73 _PG_init(void)
74 {
75  /* Define custom GUC variables. */
76  DefineCustomIntVariable("auto_explain.log_min_duration",
77  "Sets the minimum execution time above which plans will be logged.",
78  "Zero prints all plans. -1 turns this feature off.",
80  -1,
81  -1, INT_MAX / 1000,
82  PGC_SUSET,
84  NULL,
85  NULL,
86  NULL);
87 
88  DefineCustomBoolVariable("auto_explain.log_analyze",
89  "Use EXPLAIN ANALYZE for plan logging.",
90  NULL,
92  false,
93  PGC_SUSET,
94  0,
95  NULL,
96  NULL,
97  NULL);
98 
99  DefineCustomBoolVariable("auto_explain.log_verbose",
100  "Use EXPLAIN VERBOSE for plan logging.",
101  NULL,
103  false,
104  PGC_SUSET,
105  0,
106  NULL,
107  NULL,
108  NULL);
109 
110  DefineCustomBoolVariable("auto_explain.log_buffers",
111  "Log buffers usage.",
112  NULL,
114  false,
115  PGC_SUSET,
116  0,
117  NULL,
118  NULL,
119  NULL);
120 
121  DefineCustomBoolVariable("auto_explain.log_triggers",
122  "Include trigger statistics in plans.",
123  "This has no effect unless log_analyze is also set.",
125  false,
126  PGC_SUSET,
127  0,
128  NULL,
129  NULL,
130  NULL);
131 
132  DefineCustomEnumVariable("auto_explain.log_format",
133  "EXPLAIN format to be used for plan logging.",
134  NULL,
137  format_options,
138  PGC_SUSET,
139  0,
140  NULL,
141  NULL,
142  NULL);
143 
144  DefineCustomBoolVariable("auto_explain.log_nested_statements",
145  "Log nested statements.",
146  NULL,
148  false,
149  PGC_SUSET,
150  0,
151  NULL,
152  NULL,
153  NULL);
154 
155  DefineCustomBoolVariable("auto_explain.log_timing",
156  "Collect timing data, not just row counts.",
157  NULL,
159  true,
160  PGC_SUSET,
161  0,
162  NULL,
163  NULL,
164  NULL);
165 
166  DefineCustomRealVariable("auto_explain.sample_rate",
167  "Fraction of queries to process.",
168  NULL,
170  1.0,
171  0.0,
172  1.0,
173  PGC_SUSET,
174  0,
175  NULL,
176  NULL,
177  NULL);
178 
179  EmitWarningsOnPlaceholders("auto_explain");
180 
181  /* Install hooks. */
190 }
191 
192 /*
193  * Module unload callback
194  */
195 void
196 _PG_fini(void)
197 {
198  /* Uninstall hooks. */
203 }
204 
205 /*
206  * ExecutorStart hook: start up logging if needed
207  */
208 static void
209 explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
210 {
211  /*
212  * For rate sampling, randomly choose top-level statement. Either all
213  * nested statements will be explained or none will.
214  */
218 
220  {
221  /* Enable per-node instrumentation iff log_analyze is required. */
222  if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
223  {
225  queryDesc->instrument_options |= INSTRUMENT_TIMER;
226  else
227  queryDesc->instrument_options |= INSTRUMENT_ROWS;
230  }
231  }
232 
233  if (prev_ExecutorStart)
234  prev_ExecutorStart(queryDesc, eflags);
235  else
236  standard_ExecutorStart(queryDesc, eflags);
237 
239  {
240  /*
241  * Set up to track total elapsed time in ExecutorRun. Make sure the
242  * space is allocated in the per-query context so it will go away at
243  * ExecutorEnd.
244  */
245  if (queryDesc->totaltime == NULL)
246  {
247  MemoryContext oldcxt;
248 
249  oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
250  queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
251  MemoryContextSwitchTo(oldcxt);
252  }
253  }
254 }
255 
256 /*
257  * ExecutorRun hook: all we need do is track nesting depth
258  */
259 static void
261  uint64 count, bool execute_once)
262 {
263  nesting_level++;
264  PG_TRY();
265  {
266  if (prev_ExecutorRun)
267  prev_ExecutorRun(queryDesc, direction, count, execute_once);
268  else
269  standard_ExecutorRun(queryDesc, direction, count, execute_once);
270  nesting_level--;
271  }
272  PG_CATCH();
273  {
274  nesting_level--;
275  PG_RE_THROW();
276  }
277  PG_END_TRY();
278 }
279 
280 /*
281  * ExecutorFinish hook: all we need do is track nesting depth
282  */
283 static void
285 {
286  nesting_level++;
287  PG_TRY();
288  {
290  prev_ExecutorFinish(queryDesc);
291  else
292  standard_ExecutorFinish(queryDesc);
293  nesting_level--;
294  }
295  PG_CATCH();
296  {
297  nesting_level--;
298  PG_RE_THROW();
299  }
300  PG_END_TRY();
301 }
302 
303 /*
304  * ExecutorEnd hook: log results if needed
305  */
306 static void
308 {
310  {
311  double msec;
312 
313  /*
314  * Make sure stats accumulation is done. (Note: it's okay if several
315  * levels of hook all do this.)
316  */
317  InstrEndLoop(queryDesc->totaltime);
318 
319  /* Log plan if duration is exceeded. */
320  msec = queryDesc->totaltime->total * 1000.0;
321  if (msec >= auto_explain_log_min_duration)
322  {
324 
328  es->timing = (es->analyze && auto_explain_log_timing);
329  es->summary = es->analyze;
331 
332  ExplainBeginOutput(es);
333  ExplainQueryText(es, queryDesc);
334  ExplainPrintPlan(es, queryDesc);
336  ExplainPrintTriggers(es, queryDesc);
337  ExplainEndOutput(es);
338 
339  /* Remove last line break */
340  if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
341  es->str->data[--es->str->len] = '\0';
342 
343  /* Fix JSON to output an object */
345  {
346  es->str->data[0] = '{';
347  es->str->data[es->str->len - 1] = '}';
348  }
349 
350  /*
351  * Note: we rely on the existing logging of context or
352  * debug_query_string to identify just which statement is being
353  * reported. This isn't ideal but trying to do it here would
354  * often result in duplication.
355  */
356  ereport(LOG,
357  (errmsg("duration: %.3f ms plan:\n%s",
358  msec, es->str->data),
359  errhidestmt(true)));
360 
361  pfree(es->str->data);
362  }
363  }
364 
365  if (prev_ExecutorEnd)
366  prev_ExecutorEnd(queryDesc);
367  else
368  standard_ExecutorEnd(queryDesc);
369 }
static double auto_explain_sample_rate
Definition: auto_explain.c:32
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:7766
bool summary
Definition: explain.h:37
void standard_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: execMain.c:310
static ExecutorRun_hook_type prev_ExecutorRun
Definition: auto_explain.c:47
static bool current_query_sampled
Definition: auto_explain.c:52
ExplainState * NewExplainState(void)
Definition: explain.c:285
EState * estate
Definition: execdesc.h:48
Definition: guc.h:164
static bool auto_explain_log_verbose
Definition: auto_explain.c:26
PG_MODULE_MAGIC
Definition: auto_explain.c:21
long random(void)
Definition: random.c:22
static bool auto_explain_log_buffers
Definition: auto_explain.c:27
void standard_ExecutorStart(QueryDesc *queryDesc, int eflags)
Definition: execMain.c:156
void(* ExecutorEnd_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:84
static MemoryContext MemoryContextSwitchTo(MemoryContext context)
Definition: palloc.h:109
void(* ExecutorFinish_hook_type)(QueryDesc *queryDesc)
Definition: executor.h:80
void standard_ExecutorEnd(QueryDesc *queryDesc)
Definition: execMain.c:470
int errhidestmt(bool hide_stmt)
Definition: elog.c:1068
Instrumentation * InstrAlloc(int n, int instrument_options)
Definition: instrument.c:30
static bool auto_explain_log_nested_statements
Definition: auto_explain.c:31
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
Definition: auto_explain.c:209
static int auto_explain_log_format
Definition: auto_explain.c:30
#define LOG
Definition: elog.h:26
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:7796
void standard_ExecutorFinish(QueryDesc *queryDesc)
Definition: execMain.c:410
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:7851
int instrument_options
Definition: execdesc.h:44
ExecutorStart_hook_type ExecutorStart_hook
Definition: execMain.c:70
void InstrEndLoop(Instrumentation *instr)
Definition: instrument.c:114
void(* ExecutorStart_hook_type)(QueryDesc *queryDesc, int eflags)
Definition: executor.h:69
static ExecutorStart_hook_type prev_ExecutorStart
Definition: auto_explain.c:46
void ExplainEndOutput(ExplainState *es)
Definition: explain.c:3406
#define auto_explain_enabled()
Definition: auto_explain.c:54
void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:654
static void explain_ExecutorFinish(QueryDesc *queryDesc)
Definition: auto_explain.c:284
void pfree(void *pointer)
Definition: mcxt.c:950
MemoryContext es_query_cxt
Definition: execnodes.h:471
void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:617
static const struct config_enum_entry format_options[]
Definition: auto_explain.c:34
void ExplainBeginOutput(ExplainState *es)
Definition: explain.c:3375
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:43
Definition: guc.h:75
void EmitWarningsOnPlaceholders(const char *className)
Definition: guc.c:7879
void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc)
Definition: explain.c:701
ScanDirection
Definition: sdir.h:22
#define MAX_RANDOM_VALUE
#define ereport(elevel, rest)
Definition: elog.h:122
bool timing
Definition: explain.h:36
static int auto_explain_log_min_duration
Definition: auto_explain.c:24
static bool auto_explain_log_timing
Definition: auto_explain.c:29
static ExecutorFinish_hook_type prev_ExecutorFinish
Definition: auto_explain.c:48
static bool auto_explain_log_analyze
Definition: auto_explain.c:25
bool verbose
Definition: explain.h:32
static void explain_ExecutorEnd(QueryDesc *queryDesc)
Definition: auto_explain.c:307
#define PG_CATCH()
Definition: elog.h:293
struct Instrumentation * totaltime
Definition: execdesc.h:55
void _PG_fini(void)
Definition: auto_explain.c:196
#define NULL
Definition: c.h:229
static ExecutorEnd_hook_type prev_ExecutorEnd
Definition: auto_explain.c:49
ExplainFormat format
Definition: explain.h:38
#define PG_RE_THROW()
Definition: elog.h:314
static void explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: auto_explain.c:260
int errmsg(const char *fmt,...)
Definition: elog.c:797
bool buffers
Definition: explain.h:35
ExecutorFinish_hook_type ExecutorFinish_hook
Definition: execMain.c:72
#define PG_TRY()
Definition: elog.h:284
void(* ExecutorRun_hook_type)(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once)
Definition: executor.h:73
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:7740
StringInfo str
Definition: explain.h:30
#define EXEC_FLAG_EXPLAIN_ONLY
Definition: executor.h:58
void _PG_init(void)
Definition: auto_explain.c:73
#define PG_END_TRY()
Definition: elog.h:300
#define GUC_UNIT_MS
Definition: guc.h:224
static bool auto_explain_log_triggers
Definition: auto_explain.c:28