1 /*-------------------------------------------------------------------------
6 * Copyright (c) 2008-2009, PostgreSQL Global Development Group
11 *-------------------------------------------------------------------------
15 #include "commands/explain.h"
16 #include "executor/instrument.h"
17 #include "utils/guc.h"
22 static int auto_explain_log_min_duration
= -1; /* msec or -1 */
23 static bool auto_explain_log_analyze
= false;
24 static bool auto_explain_log_verbose
= false;
25 static bool auto_explain_log_nested_statements
= false;
27 /* Current nesting depth of ExecutorRun calls */
28 static int nesting_level
= 0;
30 /* Saved hook values in case of unload */
31 static ExecutorStart_hook_type prev_ExecutorStart
= NULL
;
32 static ExecutorRun_hook_type prev_ExecutorRun
= NULL
;
33 static ExecutorEnd_hook_type prev_ExecutorEnd
= NULL
;
35 #define auto_explain_enabled() \
36 (auto_explain_log_min_duration >= 0 && \
37 (nesting_level == 0 || auto_explain_log_nested_statements))
42 static void explain_ExecutorStart(QueryDesc
*queryDesc
, int eflags
);
43 static void explain_ExecutorRun(QueryDesc
*queryDesc
,
44 ScanDirection direction
,
46 static void explain_ExecutorEnd(QueryDesc
*queryDesc
);
50 * Module load callback
55 /* Define custom GUC variables. */
56 DefineCustomIntVariable("auto_explain.log_min_duration",
57 "Sets the minimum execution time above which plans will be logged.",
58 "Zero prints all plans. -1 turns this feature off.",
59 &auto_explain_log_min_duration
,
67 DefineCustomBoolVariable("auto_explain.log_analyze",
68 "Use EXPLAIN ANALYZE for plan logging.",
70 &auto_explain_log_analyze
,
77 DefineCustomBoolVariable("auto_explain.log_verbose",
78 "Use EXPLAIN VERBOSE for plan logging.",
80 &auto_explain_log_verbose
,
87 DefineCustomBoolVariable("auto_explain.log_nested_statements",
88 "Log nested statements.",
90 &auto_explain_log_nested_statements
,
97 EmitWarningsOnPlaceholders("auto_explain");
100 prev_ExecutorStart
= ExecutorStart_hook
;
101 ExecutorStart_hook
= explain_ExecutorStart
;
102 prev_ExecutorRun
= ExecutorRun_hook
;
103 ExecutorRun_hook
= explain_ExecutorRun
;
104 prev_ExecutorEnd
= ExecutorEnd_hook
;
105 ExecutorEnd_hook
= explain_ExecutorEnd
;
109 * Module unload callback
114 /* Uninstall hooks. */
115 ExecutorStart_hook
= prev_ExecutorStart
;
116 ExecutorRun_hook
= prev_ExecutorRun
;
117 ExecutorEnd_hook
= prev_ExecutorEnd
;
121 * ExecutorStart hook: start up logging if needed
124 explain_ExecutorStart(QueryDesc
*queryDesc
, int eflags
)
126 if (auto_explain_enabled())
128 /* Enable per-node instrumentation iff log_analyze is required. */
129 if (auto_explain_log_analyze
&& (eflags
& EXEC_FLAG_EXPLAIN_ONLY
) == 0)
130 queryDesc
->doInstrument
= true;
133 if (prev_ExecutorStart
)
134 prev_ExecutorStart(queryDesc
, eflags
);
136 standard_ExecutorStart(queryDesc
, eflags
);
138 if (auto_explain_enabled())
141 * Set up to track total elapsed time in ExecutorRun. Make sure
142 * the space is allocated in the per-query context so it will go
143 * away at ExecutorEnd.
145 if (queryDesc
->totaltime
== NULL
)
147 MemoryContext oldcxt
;
149 oldcxt
= MemoryContextSwitchTo(queryDesc
->estate
->es_query_cxt
);
150 queryDesc
->totaltime
= InstrAlloc(1);
151 MemoryContextSwitchTo(oldcxt
);
157 * ExecutorRun hook: all we need do is track nesting depth
160 explain_ExecutorRun(QueryDesc
*queryDesc
, ScanDirection direction
, long count
)
165 if (prev_ExecutorRun
)
166 prev_ExecutorRun(queryDesc
, direction
, count
);
168 standard_ExecutorRun(queryDesc
, direction
, count
);
180 * ExecutorEnd hook: log results if needed
183 explain_ExecutorEnd(QueryDesc
*queryDesc
)
185 if (queryDesc
->totaltime
&& auto_explain_enabled())
190 * Make sure stats accumulation is done. (Note: it's okay if
191 * several levels of hook all do this.)
193 InstrEndLoop(queryDesc
->totaltime
);
195 /* Log plan if duration is exceeded. */
196 msec
= queryDesc
->totaltime
->total
* 1000.0;
197 if (msec
>= auto_explain_log_min_duration
)
201 initStringInfo(&buf
);
202 ExplainPrintPlan(&buf
, queryDesc
,
203 queryDesc
->doInstrument
&& auto_explain_log_analyze
,
204 auto_explain_log_verbose
);
206 /* Remove last line break */
207 if (buf
.len
> 0 && buf
.data
[buf
.len
- 1] == '\n')
208 buf
.data
[--buf
.len
] = '\0';
211 * Note: we rely on the existing logging of context or
212 * debug_query_string to identify just which statement is being
213 * reported. This isn't ideal but trying to do it here would
214 * often result in duplication.
217 (errmsg("duration: %.3f ms plan:\n%s",
224 if (prev_ExecutorEnd
)
225 prev_ExecutorEnd(queryDesc
);
227 standard_ExecutorEnd(queryDesc
);