1 /*-------------------------------------------------------------------------
2 *
3 * auto_explain.c
4 *
5 *
6 * Copyright (c) 2008-2016, 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);
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)273 explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count)
274 {
275 nesting_level++;
276 PG_TRY();
277 {
278 if (prev_ExecutorRun)
279 prev_ExecutorRun(queryDesc, direction, count);
280 else
281 standard_ExecutorRun(queryDesc, direction, count);
282 nesting_level--;
283 }
284 PG_CATCH();
285 {
286 nesting_level--;
287 PG_RE_THROW();
288 }
289 PG_END_TRY();
290 }
291
292 /*
293 * ExecutorFinish hook: all we need do is track nesting depth
294 */
295 static void
explain_ExecutorFinish(QueryDesc * queryDesc)296 explain_ExecutorFinish(QueryDesc *queryDesc)
297 {
298 nesting_level++;
299 PG_TRY();
300 {
301 if (prev_ExecutorFinish)
302 prev_ExecutorFinish(queryDesc);
303 else
304 standard_ExecutorFinish(queryDesc);
305 nesting_level--;
306 }
307 PG_CATCH();
308 {
309 nesting_level--;
310 PG_RE_THROW();
311 }
312 PG_END_TRY();
313 }
314
315 /*
316 * ExecutorEnd hook: log results if needed
317 */
318 static void
explain_ExecutorEnd(QueryDesc * queryDesc)319 explain_ExecutorEnd(QueryDesc *queryDesc)
320 {
321 if (queryDesc->totaltime && auto_explain_enabled())
322 {
323 MemoryContext oldcxt;
324 double msec;
325
326 /*
327 * Make sure we operate in the per-query context, so any cruft will be
328 * discarded later during ExecutorEnd.
329 */
330 oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
331
332 /*
333 * Make sure stats accumulation is done. (Note: it's okay if several
334 * levels of hook all do this.)
335 */
336 InstrEndLoop(queryDesc->totaltime);
337
338 /* Log plan if duration is exceeded. */
339 msec = queryDesc->totaltime->total * 1000.0;
340 if (msec >= auto_explain_log_min_duration)
341 {
342 ExplainState *es = NewExplainState();
343
344 es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
345 es->verbose = auto_explain_log_verbose;
346 es->buffers = (es->analyze && auto_explain_log_buffers);
347 es->timing = (es->analyze && auto_explain_log_timing);
348 es->summary = es->analyze;
349 es->format = auto_explain_log_format;
350
351 ExplainBeginOutput(es);
352 ExplainQueryText(es, queryDesc);
353 ExplainPrintPlan(es, queryDesc);
354 if (es->analyze && auto_explain_log_triggers)
355 ExplainPrintTriggers(es, queryDesc);
356 ExplainEndOutput(es);
357
358 /* Remove last line break */
359 if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
360 es->str->data[--es->str->len] = '\0';
361
362 /* Fix JSON to output an object */
363 if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
364 {
365 es->str->data[0] = '{';
366 es->str->data[es->str->len - 1] = '}';
367 }
368
369 /*
370 * Note: we rely on the existing logging of context or
371 * debug_query_string to identify just which statement is being
372 * reported. This isn't ideal but trying to do it here would
373 * often result in duplication.
374 */
375 ereport(LOG,
376 (errmsg("duration: %.3f ms plan:\n%s",
377 msec, es->str->data),
378 errhidestmt(true)));
379 }
380
381 MemoryContextSwitchTo(oldcxt);
382 }
383
384 if (prev_ExecutorEnd)
385 prev_ExecutorEnd(queryDesc);
386 else
387 standard_ExecutorEnd(queryDesc);
388 }
389