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

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

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);

doc/src/sgml/auto-explain.sgml

@@ -80,28 +80,13 @@ 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>
    </varlistentry>
 
-   <varlistentry>
-    <term>
-     <varname>auto_explain.log_verbose</varname> (<type>boolean</type>)
-    </term>
-    <indexterm>
-     <primary><varname>auto_explain.log_verbose</> 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.
-      Only superusers can change this setting.
-     </para>
-    </listitem>
-   </varlistentry>
-
    <varlistentry>
     <term>
      <varname>auto_explain.log_buffers</varname> (<type>boolean</type>)
@@ -111,12 +96,55 @@ LOAD 'auto_explain';
     </indexterm>
     <listitem>
      <para>
-      <varname>auto_explain.log_buffers</varname> causes <command>EXPLAIN
+      <varname>auto_explain.log_buffers</varname> controls whether buffer
-      (ANALYZE, BUFFERS)</> output, rather than just <command>EXPLAIN</>
+      usage statistics are 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>BUFFERS</> option of <command>EXPLAIN</>.
-      off by default. Only superusers can change this setting. This
+      This parameter has no effect
-      parameter has no effect unless <varname>auto_explain.log_analyze</>
+      unless <varname>auto_explain.log_analyze</varname> is enabled.
-      parameter is set.
+      This parameter is off by default.
+      Only superusers can change this setting.
+     </para>
+    </listitem>
+   </varlistentry>
+
+   <varlistentry>
+    <term>
+     <varname>auto_explain.log_timing</varname> (<type>boolean</type>)
+    </term>
+    <indexterm>
+     <primary><varname>auto_explain.log_timing</> configuration parameter</primary>
+    </indexterm>
+    <listitem>
+     <para>
+      <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_verbose</varname> (<type>boolean</type>)
+    </term>
+    <indexterm>
+     <primary><varname>auto_explain.log_verbose</> configuration parameter</primary>
+    </indexterm>
+    <listitem>
+     <para>
+      <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>
    </varlistentry>
@@ -139,27 +167,6 @@ LOAD 'auto_explain';
     </listitem>
    </varlistentry>
 
-   <varlistentry>
-    <term>
-     <varname>auto_explain.log_timing</varname> (<type>boolean</type>)
-    </term>
-    <indexterm>
-     <primary><varname>auto_explain.log_timing</> 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>.
-     </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;