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

This has been broken since commit af7914c6627bcf0b0ca614e9ce95d3f8056602bf,
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.

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index ad333b664471aee25c15ff6dd4dcde5ac702845c..63fc311835a4f255cab5b225f747c04cb7f3e55a 100644 (file)
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -23,7 +23,7 @@ static int    auto_explain_log_min_duration = -1; /* msec or -1 */
 static bool auto_explain_log_analyze = false;
 static bool auto_explain_log_verbose = false;
 static bool auto_explain_log_buffers = 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 bool auto_explain_log_nested_statements = false;
 
@@ -186,8 +186,6 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
                                queryDesc->instrument_options |= INSTRUMENT_TIMER;
                        else
                                queryDesc->instrument_options |= INSTRUMENT_ROWS;
-
-
                        if (auto_explain_log_buffers)
                                queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
                }
@@ -288,6 +286,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
                        es.analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
                        es.verbose = auto_explain_log_verbose;
                        es.buffers = (es.analyze && auto_explain_log_buffers);
+                       es.timing = (es.analyze && auto_explain_log_timing);
                        es.format = auto_explain_log_format;
 
                        ExplainBeginOutput(&es);

diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index 03b2309da8f99bf54b2a71af4d3172e14e349f84..910cce1bd288e259f50daa51a038167e25e18796 100644 (file)
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -80,6 +80,8 @@ LOAD 'auto_explain';
        When this parameter is on, per-plan-node timing occurs for all
        statements executed, whether or not they run long enough to actually
        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>
      </note>
     </listitem>
@@ -87,16 +89,19 @@ LOAD 'auto_explain';
 
    <varlistentry>
     <term>
-     <varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
+     <varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
     </term>
     <indexterm>
-     <primary><varname>auto_explain.log_verbose</> configuration parameter</primary>
+     <primary><varname>auto_explain.log_buffers</> configuration parameter</primary>
     </indexterm>
     <listitem>
      <para>
-      <varname>auto_explain.log_verbose</varname> causes <command>EXPLAIN VERBOSE</>
-      output, rather than just <command>EXPLAIN</> output, to be printed
-      when an execution plan is logged. This parameter is off by default.
+      <varname>auto_explain.log_buffers</varname> controls whether buffer
+      usage statistics are printed when an execution plan is logged; it's
+      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.
      </para>
     </listitem>
@@ -104,36 +109,41 @@ LOAD 'auto_explain';
 
    <varlistentry>
     <term>
-     <varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
+     <varname>auto_explain.log_timing</varname> (<type>boolean</type>)
     </term>
     <indexterm>
-     <primary><varname>auto_explain.log_buffers</> configuration parameter</primary>
+     <primary><varname>auto_explain.log_timing</> configuration parameter</primary>
     </indexterm>
     <listitem>
      <para>
-      <varname>auto_explain.log_buffers</varname> causes <command>EXPLAIN
-      (ANALYZE, BUFFERS)</> output, rather than just <command>EXPLAIN</>
-      output, to be printed when an execution plan is logged. This parameter is
-      off by default. Only superusers can change this setting. This
-      parameter has no effect unless <varname>auto_explain.log_analyze</>
-      parameter is set.
+      <varname>auto_explain.log_timing</varname> controls whether per-node
+      timing information is printed when an execution plan is logged; it's
+      equivalent to the <literal>TIMING</> option of <command>EXPLAIN</>.
+      The overhead of repeatedly reading the system clock can slow down
+      queries significantly on some systems, so it may be useful to set this
+      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>
     </listitem>
    </varlistentry>
 
    <varlistentry>
     <term>
-     <varname>auto_explain.log_format</varname> (<type>enum</type>)
+     <varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
     </term>
     <indexterm>
-     <primary><varname>auto_explain.log_format</> configuration parameter</primary>
+     <primary><varname>auto_explain.log_verbose</> configuration parameter</primary>
     </indexterm>
     <listitem>
      <para>
-      <varname>auto_explain.log_format</varname> selects the
-      <command>EXPLAIN</> output format to be used.
-      The allowed values are <literal>text</literal>, <literal>xml</literal>,
-      <literal>json</literal>, and <literal>yaml</literal>.  The default is text.
+      <varname>auto_explain.log_verbose</varname> controls whether verbose
+      details are printed when an execution plan is logged; it's
+      equivalent to the <literal>VERBOSE</> option of <command>EXPLAIN</>.
+      This parameter is off by default.
       Only superusers can change this setting.
      </para>
     </listitem>
@@ -141,25 +151,22 @@ LOAD 'auto_explain';
 
    <varlistentry>
     <term>
-     <varname>auto_explain.log_timing</varname> (<type>boolean</type>)
+     <varname>auto_explain.log_format</varname> (<type>enum</type>)
     </term>
     <indexterm>
-     <primary><varname>auto_explain.log_timing</> configuration parameter</primary>
+     <primary><varname>auto_explain.log_format</> configuration parameter</primary>
     </indexterm>
     <listitem>
      <para>
-      <varname>auto_explain.log_timing</varname> causes <command>EXPLAIN
-      (ANALYZE, TIMING off)</> output, rather than just <command>EXPLAIN (ANALYZE)</>
-      output. The overhead of repeatedly reading the system clock can slow down the
-      query significantly on some systems, so it may be useful to set this
-      parameter to <literal>FALSE</literal> 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.  It defaults to <literal>TRUE</literal>.
+      <varname>auto_explain.log_format</varname> selects the
+      <command>EXPLAIN</> output format to be used.
+      The allowed values are <literal>text</literal>, <literal>xml</literal>,
+      <literal>json</literal>, and <literal>yaml</literal>.  The default is text.
+      Only superusers can change this setting.
      </para>
     </listitem>
    </varlistentry>
-   
+
    <varlistentry>
     <term>
      <varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>)
@@ -179,7 +186,9 @@ LOAD 'auto_explain';
   </variablelist>
 
   <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:
   </para>
 
@@ -197,6 +206,7 @@ auto_explain.log_min_duration = '3s'
 <programlisting>
 postgres=# LOAD 'auto_explain';
 postgres=# SET auto_explain.log_min_duration = 0;
+postgres=# SET auto_explain.log_analyze = true;
 postgres=# SELECT count(*)
            FROM pg_class, pg_index
            WHERE oid = indrelid AND indisunique;