Commit 898f8a96 authored by Tom Lane's avatar Tom Lane

Fix failure of contrib/auto_explain to print per-node timing information.

This has been broken since commit af7914c6,
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.
parent a92b5f96
...@@ -26,7 +26,7 @@ static bool auto_explain_log_analyze = false; ...@@ -26,7 +26,7 @@ static bool auto_explain_log_analyze = false;
static bool auto_explain_log_verbose = false; static bool auto_explain_log_verbose = false;
static bool auto_explain_log_buffers = false; static bool auto_explain_log_buffers = false;
static bool auto_explain_log_triggers = false; static bool auto_explain_log_triggers = false;
static bool auto_explain_log_timing = false; static bool auto_explain_log_timing = true;
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT; static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
static bool auto_explain_log_nested_statements = false; static bool auto_explain_log_nested_statements = false;
...@@ -200,8 +200,6 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags) ...@@ -200,8 +200,6 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
queryDesc->instrument_options |= INSTRUMENT_TIMER; queryDesc->instrument_options |= INSTRUMENT_TIMER;
else else
queryDesc->instrument_options |= INSTRUMENT_ROWS; queryDesc->instrument_options |= INSTRUMENT_ROWS;
if (auto_explain_log_buffers) if (auto_explain_log_buffers)
queryDesc->instrument_options |= INSTRUMENT_BUFFERS; queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
} }
...@@ -302,6 +300,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc) ...@@ -302,6 +300,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
es.analyze = (queryDesc->instrument_options && auto_explain_log_analyze); es.analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
es.verbose = auto_explain_log_verbose; es.verbose = auto_explain_log_verbose;
es.buffers = (es.analyze && auto_explain_log_buffers); es.buffers = (es.analyze && auto_explain_log_buffers);
es.timing = (es.analyze && auto_explain_log_timing);
es.format = auto_explain_log_format; es.format = auto_explain_log_format;
ExplainBeginOutput(&es); ExplainBeginOutput(&es);
......
...@@ -81,6 +81,8 @@ LOAD 'auto_explain'; ...@@ -81,6 +81,8 @@ LOAD 'auto_explain';
When this parameter is on, per-plan-node timing occurs for all When this parameter is on, per-plan-node timing occurs for all
statements executed, whether or not they run long enough to actually statements executed, whether or not they run long enough to actually
get logged. This can have an extremely negative impact on performance. get logged. This can have an extremely negative impact on performance.
Turning off <varname>auto_explain.log_timing</varname> ameliorates the
performance cost, at the price of obtaining less information.
</para> </para>
</note> </note>
</listitem> </listitem>
...@@ -88,16 +90,19 @@ LOAD 'auto_explain'; ...@@ -88,16 +90,19 @@ LOAD 'auto_explain';
<varlistentry> <varlistentry>
<term> <term>
<varname>auto_explain.log_verbose</varname> (<type>boolean</type>) <varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
<indexterm> <indexterm>
<primary><varname>auto_explain.log_verbose</> configuration parameter</primary> <primary><varname>auto_explain.log_buffers</> configuration parameter</primary>
</indexterm> </indexterm>
</term> </term>
<listitem> <listitem>
<para> <para>
<varname>auto_explain.log_verbose</varname> causes <command>EXPLAIN VERBOSE</> <varname>auto_explain.log_buffers</varname> controls whether buffer
output, rather than just <command>EXPLAIN</> output, to be printed usage statistics are printed when an execution plan is logged; it's
when an execution plan is logged. This parameter is off by default. equivalent to the <literal>BUFFERS</> option of <command>EXPLAIN</>.
This parameter has no effect
unless <varname>auto_explain.log_analyze</varname> is enabled.
This parameter is off by default.
Only superusers can change this setting. Only superusers can change this setting.
</para> </para>
</listitem> </listitem>
...@@ -105,19 +110,24 @@ LOAD 'auto_explain'; ...@@ -105,19 +110,24 @@ LOAD 'auto_explain';
<varlistentry> <varlistentry>
<term> <term>
<varname>auto_explain.log_buffers</varname> (<type>boolean</type>) <varname>auto_explain.log_timing</varname> (<type>boolean</type>)
<indexterm> <indexterm>
<primary><varname>auto_explain.log_buffers</> configuration parameter</primary> <primary><varname>auto_explain.log_timing</> configuration parameter</primary>
</indexterm> </indexterm>
</term> </term>
<listitem> <listitem>
<para> <para>
<varname>auto_explain.log_buffers</varname> causes <command>EXPLAIN <varname>auto_explain.log_timing</varname> controls whether per-node
(ANALYZE, BUFFERS)</> output, rather than just <command>EXPLAIN</> timing information is printed when an execution plan is logged; it's
output, to be printed when an execution plan is logged. This parameter is equivalent to the <literal>TIMING</> option of <command>EXPLAIN</>.
off by default. Only superusers can change this setting. This The overhead of repeatedly reading the system clock can slow down
parameter has no effect unless <varname>auto_explain.log_analyze</> queries significantly on some systems, so it may be useful to set this
parameter is set. parameter to off when only actual row counts, and not exact times, are
needed.
This parameter has no effect
unless <varname>auto_explain.log_analyze</varname> is enabled.
This parameter is on by default.
Only superusers can change this setting.
</para> </para>
</listitem> </listitem>
</varlistentry> </varlistentry>
...@@ -133,26 +143,27 @@ LOAD 'auto_explain'; ...@@ -133,26 +143,27 @@ LOAD 'auto_explain';
<para> <para>
<varname>auto_explain.log_triggers</varname> causes trigger <varname>auto_explain.log_triggers</varname> causes trigger
execution statistics to be included when an execution plan is logged. execution statistics to be included when an execution plan is logged.
This parameter is off by default. Only superusers can change this This parameter has no effect
setting. This parameter has no effect unless unless <varname>auto_explain.log_analyze</varname> is enabled.
<varname>auto_explain.log_analyze</> parameter is set. This parameter is off by default.
Only superusers can change this setting.
</para> </para>
</listitem> </listitem>
</varlistentry> </varlistentry>
<varlistentry> <varlistentry>
<term> <term>
<varname>auto_explain.log_format</varname> (<type>enum</type>) <varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
<indexterm> <indexterm>
<primary><varname>auto_explain.log_format</> configuration parameter</primary> <primary><varname>auto_explain.log_verbose</> configuration parameter</primary>
</indexterm> </indexterm>
</term> </term>
<listitem> <listitem>
<para> <para>
<varname>auto_explain.log_format</varname> selects the <varname>auto_explain.log_verbose</varname> controls whether verbose
<command>EXPLAIN</> output format to be used. details are printed when an execution plan is logged; it's
The allowed values are <literal>text</literal>, <literal>xml</literal>, equivalent to the <literal>VERBOSE</> option of <command>EXPLAIN</>.
<literal>json</literal>, and <literal>yaml</literal>. The default is text. This parameter is off by default.
Only superusers can change this setting. Only superusers can change this setting.
</para> </para>
</listitem> </listitem>
...@@ -160,25 +171,22 @@ LOAD 'auto_explain'; ...@@ -160,25 +171,22 @@ LOAD 'auto_explain';
<varlistentry> <varlistentry>
<term> <term>
<varname>auto_explain.log_timing</varname> (<type>boolean</type>) <varname>auto_explain.log_format</varname> (<type>enum</type>)
<indexterm> <indexterm>
<primary><varname>auto_explain.log_timing</> configuration parameter</primary> <primary><varname>auto_explain.log_format</> configuration parameter</primary>
</indexterm> </indexterm>
</term> </term>
<listitem> <listitem>
<para> <para>
<varname>auto_explain.log_timing</varname> causes <command>EXPLAIN <varname>auto_explain.log_format</varname> selects the
(ANALYZE, TIMING off)</> output, rather than just <command>EXPLAIN (ANALYZE)</> <command>EXPLAIN</> output format to be used.
output. The overhead of repeatedly reading the system clock can slow down the The allowed values are <literal>text</literal>, <literal>xml</literal>,
query significantly on some systems, so it may be useful to set this <literal>json</literal>, and <literal>yaml</literal>. The default is text.
parameter to off when only actual row counts, and not exact times, are needed.
This parameter is only effective when <varname>auto_explain.log_analyze</varname>
is also enabled. This parameter is on by default.
Only superusers can change this setting. Only superusers can change this setting.
</para> </para>
</listitem> </listitem>
</varlistentry> </varlistentry>
<varlistentry> <varlistentry>
<term> <term>
<varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>) <varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>)
...@@ -198,7 +206,9 @@ LOAD 'auto_explain'; ...@@ -198,7 +206,9 @@ LOAD 'auto_explain';
</variablelist> </variablelist>
<para> <para>
These parameters must be set in <filename>postgresql.conf</>. In ordinary usage, these parameters are set
in <filename>postgresql.conf</>, although superusers can alter them
on-the-fly within their own sessions.
Typical usage might be: Typical usage might be:
</para> </para>
...@@ -216,6 +226,7 @@ auto_explain.log_min_duration = '3s' ...@@ -216,6 +226,7 @@ auto_explain.log_min_duration = '3s'
<programlisting> <programlisting>
postgres=# LOAD 'auto_explain'; postgres=# LOAD 'auto_explain';
postgres=# SET auto_explain.log_min_duration = 0; postgres=# SET auto_explain.log_min_duration = 0;
postgres=# SET auto_explain.log_analyze = true;
postgres=# SELECT count(*) postgres=# SELECT count(*)
FROM pg_class, pg_index FROM pg_class, pg_index
WHERE oid = indrelid AND indisunique; WHERE oid = indrelid AND indisunique;
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment