Skip to content

Commit 5ff8c2d

Browse files
tglsfdctglsfdc
committed
Fix failure of contrib/auto_explain to print per-node timing information.
This has been broken since commit af7914c, which added the EXPLAIN (TIMING) option. Although that commit included updates to auto_explain, they evidently weren't tested very carefully, because the code failed to print node timings even when it should, due to failure to set es.timing in the ExplainState struct. Reported off-list by Neelakanth Nadgir of Salesforce. In passing, clean up the documentation for auto_explain's options a little bit, including re-ordering them into what seems to me a more logical order.
1 parent 8557a9f commit 5ff8c2d

File tree

2 files changed

+43
-34
lines changed

2 files changed

+43
-34
lines changed

‎contrib/auto_explain/auto_explain.c

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,7 @@ static int auto_explain_log_min_duration = -1; /* msec or -1 */
2323
static bool auto_explain_log_analyze = false;
2424
static bool auto_explain_log_verbose = false;
2525
static bool auto_explain_log_buffers = false;
26-
static bool auto_explain_log_timing = false;
26+
static bool auto_explain_log_timing = true;
2727
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
2828
static bool auto_explain_log_nested_statements = false;
2929

@@ -186,8 +186,6 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
186186
queryDesc->instrument_options |= INSTRUMENT_TIMER;
187187
else
188188
queryDesc->instrument_options |= INSTRUMENT_ROWS;
189-
190-
191189
if (auto_explain_log_buffers)
192190
queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
193191
}
@@ -288,6 +286,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
288286
es.analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
289287
es.verbose = auto_explain_log_verbose;
290288
es.buffers = (es.analyze && auto_explain_log_buffers);
289+
es.timing = (es.analyze && auto_explain_log_timing);
291290
es.format = auto_explain_log_format;
292291

293292
ExplainBeginOutput(&es);

‎doc/src/sgml/auto-explain.sgml

Lines changed: 41 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -80,86 +80,93 @@ LOAD 'auto_explain';
8080
When this parameter is on, per-plan-node timing occurs for all
8181
statements executed, whether or not they run long enough to actually
8282
get logged. This can have an extremely negative impact on performance.
83+
Turning off <varname>auto_explain.log_timing</varname> ameliorates the
84+
performance cost, at the price of obtaining less information.
8385
</para>
8486
</note>
8587
</listitem>
8688
</varlistentry>
8789

8890
<varlistentry>
8991
<term>
90-
<varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
92+
<varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
9193
</term>
9294
<indexterm>
93-
<primary><varname>auto_explain.log_verbose</> configuration parameter</primary>
95+
<primary><varname>auto_explain.log_buffers</> configuration parameter</primary>
9496
</indexterm>
9597
<listitem>
9698
<para>
97-
<varname>auto_explain.log_verbose</varname> causes <command>EXPLAIN VERBOSE</>
98-
output, rather than just <command>EXPLAIN</> output, to be printed
99-
when an execution plan is logged. This parameter is off by default.
99+
<varname>auto_explain.log_buffers</varname> controls whether buffer
100+
usage statistics are printed when an execution plan is logged; it's
101+
equivalent to the <literal>BUFFERS</> option of <command>EXPLAIN</>.
102+
This parameter has no effect
103+
unless <varname>auto_explain.log_analyze</varname> is enabled.
104+
This parameter is off by default.
100105
Only superusers can change this setting.
101106
</para>
102107
</listitem>
103108
</varlistentry>
104109

105110
<varlistentry>
106111
<term>
107-
<varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
112+
<varname>auto_explain.log_timing</varname> (<type>boolean</type>)
108113
</term>
109114
<indexterm>
110-
<primary><varname>auto_explain.log_buffers</> configuration parameter</primary>
115+
<primary><varname>auto_explain.log_timing</> configuration parameter</primary>
111116
</indexterm>
112117
<listitem>
113118
<para>
114-
<varname>auto_explain.log_buffers</varname> causes <command>EXPLAIN
115-
(ANALYZE, BUFFERS)</> output, rather than just <command>EXPLAIN</>
116-
output, to be printed when an execution plan is logged. This parameter is
117-
off by default. Only superusers can change this setting. This
118-
parameter has no effect unless <varname>auto_explain.log_analyze</>
119-
parameter is set.
119+
<varname>auto_explain.log_timing</varname> controls whether per-node
120+
timing information is printed when an execution plan is logged; it's
121+
equivalent to the <literal>TIMING</> option of <command>EXPLAIN</>.
122+
The overhead of repeatedly reading the system clock can slow down
123+
queries significantly on some systems, so it may be useful to set this
124+
parameter to off when only actual row counts, and not exact times, are
125+
needed.
126+
This parameter has no effect
127+
unless <varname>auto_explain.log_analyze</varname> is enabled.
128+
This parameter is on by default.
129+
Only superusers can change this setting.
120130
</para>
121131
</listitem>
122132
</varlistentry>
123133

124134
<varlistentry>
125135
<term>
126-
<varname>auto_explain.log_format</varname> (<type>enum</type>)
136+
<varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
127137
</term>
128138
<indexterm>
129-
<primary><varname>auto_explain.log_format</> configuration parameter</primary>
139+
<primary><varname>auto_explain.log_verbose</> configuration parameter</primary>
130140
</indexterm>
131141
<listitem>
132142
<para>
133-
<varname>auto_explain.log_format</varname> selects the
134-
<command>EXPLAIN</> output format to be used.
135-
The allowed values are <literal>text</literal>, <literal>xml</literal>,
136-
<literal>json</literal>, and <literal>yaml</literal>. The default is text.
143+
<varname>auto_explain.log_verbose</varname> controls whether verbose
144+
details are printed when an execution plan is logged; it's
145+
equivalent to the <literal>VERBOSE</> option of <command>EXPLAIN</>.
146+
This parameter is off by default.
137147
Only superusers can change this setting.
138148
</para>
139149
</listitem>
140150
</varlistentry>
141151

142152
<varlistentry>
143153
<term>
144-
<varname>auto_explain.log_timing</varname> (<type>boolean</type>)
154+
<varname>auto_explain.log_format</varname> (<type>enum</type>)
145155
</term>
146156
<indexterm>
147-
<primary><varname>auto_explain.log_timing</> configuration parameter</primary>
157+
<primary><varname>auto_explain.log_format</> configuration parameter</primary>
148158
</indexterm>
149159
<listitem>
150160
<para>
151-
<varname>auto_explain.log_timing</varname> causes <command>EXPLAIN
152-
(ANALYZE, TIMING off)</> output, rather than just <command>EXPLAIN (ANALYZE)</>
153-
output. The overhead of repeatedly reading the system clock can slow down the
154-
query significantly on some systems, so it may be useful to set this
155-
parameter to <literal>FALSE</literal> when only actual row counts, and not
156-
exact times, are needed.
157-
This parameter is only effective when <varname>auto_explain.log_analyze</varname>
158-
is also enabled. It defaults to <literal>TRUE</literal>.
161+
<varname>auto_explain.log_format</varname> selects the
162+
<command>EXPLAIN</> output format to be used.
163+
The allowed values are <literal>text</literal>, <literal>xml</literal>,
164+
<literal>json</literal>, and <literal>yaml</literal>. The default is text.
165+
Only superusers can change this setting.
159166
</para>
160167
</listitem>
161168
</varlistentry>
162-
169+
163170
<varlistentry>
164171
<term>
165172
<varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>)
@@ -179,7 +186,9 @@ LOAD 'auto_explain';
179186
</variablelist>
180187

181188
<para>
182-
These parameters must be set in <filename>postgresql.conf</>.
189+
In ordinary usage, these parameters are set
190+
in <filename>postgresql.conf</>, although superusers can alter them
191+
on-the-fly within their own sessions.
183192
Typical usage might be:
184193
</para>
185194

@@ -197,6 +206,7 @@ auto_explain.log_min_duration = '3s'
197206
<programlisting>
198207
postgres=# LOAD 'auto_explain';
199208
postgres=# SET auto_explain.log_min_duration = 0;
209+
postgres=# SET auto_explain.log_analyze = true;
200210
postgres=# SELECT count(*)
201211
FROM pg_class, pg_index
202212
WHERE oid = indrelid AND indisunique;

0 commit comments

Comments
 (0)