From 898f8a96ef9dfa79eac9ec1621a89e71fe16601c Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Fri, 19 Sep 2014 13:18:56 -0400 Subject: [PATCH] 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. --- contrib/auto_explain/auto_explain.c | 5 +- doc/src/sgml/auto-explain.sgml | 107 +++++++++++++++------------- 2 files changed, 61 insertions(+), 51 deletions(-) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index cbbd25753f..b33b2211ca 100644 --- 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 334996b0e6..d527208271 100644 --- a/doc/src/sgml/auto-explain.sgml +++ b/doc/src/sgml/auto-explain.sgml @@ -81,28 +81,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 auto_explain.log_timing ameliorates the + performance cost, at the price of obtaining less information. - - - auto_explain.log_verbose (boolean) - - auto_explain.log_verbose 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. - Only superusers can change this setting. - - - - auto_explain.log_buffers (boolean) @@ -112,12 +97,37 @@ LOAD 'auto_explain'; - 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_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. + + + + + + + auto_explain.log_timing (boolean) + + auto_explain.log_timing configuration parameter + + + + + 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,9 +143,28 @@ 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_verbose (boolean) + + auto_explain.log_verbose configuration parameter + + + + + 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. @@ -158,27 +187,6 @@ LOAD 'auto_explain'; - - - auto_explain.log_timing (boolean) - - auto_explain.log_timing 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. - 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;