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 cbbd25753f72deb33123b47508d732e57f1cb247..b33b2211ca09f2fd67d2e793e95db3897c3196bd 100644 (file)
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -26,7 +26,7 @@ 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_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 bool auto_explain_log_nested_statements = false;
 
@@ -200,8 +200,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;
        }
@@ -302,6 +300,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 334996b0e668b78845216ba876818d4351dd4585..d527208271f003fd5c1744755c7754bb4d5c1791 100644 (file)
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -81,6 +81,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.
       
      
     
@@ -88,16 +90,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.
      
     
@@ -105,19 +110,24 @@ 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.
      
     
    
@@ -133,26 +143,27 @@ LOAD 'auto_explain';
      
       auto_explain.log_triggers causes trigger
       execution statistics to be included 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.
+      This parameter has no effect
+      unless auto_explain.log_analyze is enabled.
+      This parameter is off 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.
      
     
@@ -160,25 +171,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)
@@ -198,7 +206,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:
   
 
@@ -216,6 +226,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;