From 5ff8c2d7d60d0084f577a920c9d614221bde283a Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Fri, 19 Sep 2014 13:19:05 -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 | 100 +++++++++++++++------------- 2 files changed, 57 insertions(+), 48 deletions(-) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index ad333b66447..63fc311835a 100644 --- 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 03b2309da8f..910cce1bd28 100644 --- a/doc/src/sgml/auto-explain.sgml +++ b/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 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) @@ -111,12 +96,55 @@ 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. + + + + + + + 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. @@ -139,27 +167,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 FALSE when only actual row counts, and not - exact times, are needed. - This parameter is only effective when auto_explain.log_analyze - is also enabled. It defaults to TRUE. - - - - 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;