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