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 57dfbe2887a7b250b7ab9f95e63585d5ff6c60a1..1d97c82de6ad294e6472501ecbdb8eaf6baa11ab 100644 (file)
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -25,7 +25,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;
 
@@ -188,8 +188,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;
        }
@@ -290,6 +288,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 d3957e3de6ff3e506c11e5e6e3bcfeae91c0c1a5..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 auto_explain.log_timing ameliorates the
+       performance cost, at the price of obtaining less information.
       
      
     
@@ -87,16 +89,19 @@ LOAD 'auto_explain';
 
    
     
-     auto_explain.log_verbose (boolean)
+     auto_explain.log_buffers (boolean)
     
     
-     auto_explain.log_verbose configuration parameter
+     auto_explain.log_buffers configuration parameter
     
     
      
-      auto_explain.log_verbose causes EXPLAIN VERBOSE
-      output, rather than just EXPLAIN output, to be printed
-      when an execution plan is logged. This parameter is off by default.
+      auto_explain.log_buffers controls whether buffer
+      usage statistics are printed when an execution plan is logged; it's
+      equivalent to the BUFFERS option of EXPLAIN.
+      This parameter has no effect
+      unless auto_explain.log_analyze is enabled.
+      This parameter is off by default.
       Only superusers can change this setting.
      
     
@@ -104,36 +109,41 @@ LOAD 'auto_explain';
 
    
     
-     auto_explain.log_buffers (boolean)
+     auto_explain.log_timing (boolean)
     
     
-     auto_explain.log_buffers configuration parameter
+     auto_explain.log_timing configuration parameter
     
     
      
-      auto_explain.log_buffers causes EXPLAIN
-      (ANALYZE, BUFFERS) output, rather than just 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 auto_explain.log_analyze
-      parameter is set.
+      auto_explain.log_timing controls whether per-node
+      timing information is printed when an execution plan is logged; it's
+      equivalent to the TIMING option of 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 auto_explain.log_analyze is enabled.
+      This parameter is on by default.
+      Only superusers can change this setting.
      
     
    
 
    
     
-     auto_explain.log_format (enum)
+     auto_explain.log_verbose (boolean)
     
     
-     auto_explain.log_format configuration parameter
+     auto_explain.log_verbose configuration parameter
     
     
      
-      auto_explain.log_format selects the
-      EXPLAIN output format to be used.
-      The allowed values are text, xml,
-      json, and yaml.  The default is text.
+      auto_explain.log_verbose controls whether verbose
+      details are printed when an execution plan is logged; it's
+      equivalent to the VERBOSE option of EXPLAIN.
+      This parameter is off by default.
       Only superusers can change this setting.
      
     
@@ -141,25 +151,22 @@ LOAD 'auto_explain';
 
    
     
-     auto_explain.log_timing (boolean)
+     auto_explain.log_format (enum)
     
     
-     auto_explain.log_timing configuration parameter
+     auto_explain.log_format configuration parameter
     
     
      
-      auto_explain.log_timing causes EXPLAIN
-      (ANALYZE, TIMING off) output, rather than just 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 off when only actual row counts, and not exact times, are needed.
-      This parameter is only effective when auto_explain.log_analyze
-      is also enabled.  This parameter is on by default.
+      auto_explain.log_format selects the
+      EXPLAIN output format to be used.
+      The allowed values are text, xml,
+      json, and yaml.  The default is text.
       Only superusers can change this setting.
      
     
    
-   
+
    
     
      auto_explain.log_nested_statements (boolean)
@@ -179,7 +186,9 @@ LOAD 'auto_explain';
   
 
   
-   These parameters must be set in postgresql.conf.
+   In ordinary usage, these parameters are set
+   in postgresql.conf, although superusers can alter them
+   on-the-fly within their own sessions.
    Typical usage might be:
   
 
@@ -197,6 +206,7 @@ auto_explain.log_min_duration = '3s'
 
 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;