Add TIMING option to EXPLAIN, to allow eliminating of timing overhead.

Sometimes it may be useful to get actual row counts out of EXPLAIN
(ANALYZE) without paying the cost of timing every node entry/exit.
With this patch, you can say EXPLAIN (ANALYZE, TIMING OFF) to get that.

Tomas Vondra, reviewed by Eric Theise, with minor doc changes by me.

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 61da6a27dec6e59d70987d6ce7b1056f4f794119..9fc0ae1d92338417c416fe79f44a84332b4a9735 100644 (file)
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -23,6 +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 int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
 static bool auto_explain_log_nested_statements = false;
 
@@ -133,6 +134,17 @@ _PG_init(void)
                             NULL,
                             NULL);
 
+   DefineCustomBoolVariable("auto_explain.log_timing",
+                            "Collect timing data, not just row counts.",
+                            NULL,
+                            &auto_explain_log_timing,
+                            true,
+                            PGC_SUSET,
+                            0,
+                            NULL,
+                            NULL,
+                            NULL);
+
    EmitWarningsOnPlaceholders("auto_explain");
 
    /* Install hooks. */
@@ -170,7 +182,12 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
        /* Enable per-node instrumentation iff log_analyze is required. */
        if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
        {
-           queryDesc->instrument_options |= INSTRUMENT_TIMER;
+           if (auto_explain_log_timing)
+               queryDesc->instrument_options |= INSTRUMENT_TIMER;
+           else
+               queryDesc->instrument_options |= INSTRUMENT_ROWS;
+
+
            if (auto_explain_log_buffers)
                queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
        }

diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 8a9c9defcacad2765583b76a535d3b6bdad42faa..419b72cad348fe8d2e522a78eee981a121e8c402 100644 (file)
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -40,6 +40,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replac
     VERBOSE [ <replaceable class="parameter">boolean</replaceable> ]
     COSTS [ <replaceable class="parameter">boolean</replaceable> ]
     BUFFERS [ <replaceable class="parameter">boolean</replaceable> ]
+    TIMING [ <replaceable class="parameter">boolean</replaceable> ]
     FORMAT { TEXT | XML | JSON | YAML }
 </synopsis>
  </refsynopsisdiv>
@@ -171,6 +172,21 @@ ROLLBACK;
     </listitem>
    </varlistentry>
 
+   <varlistentry>
+    <term><literal>TIMING</literal></term>
+    <listitem>
+     <para>
+      Include the actual startup time and time spent in the node in the 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 may only be used when <literal>ANALYZE</literal> is also
+      enabled.  It defaults to <literal>TRUE</literal>.
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry>
     <term><literal>FORMAT</literal></term>
     <listitem>

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index e57580e8addb24e9e203bdc47d4858c0db80a86e..a1692f82ae85ae06cdfcf4dc7e00acd707155d72 100644 (file)
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -116,6 +116,7 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
    TupOutputState *tstate;
    List       *rewritten;
    ListCell   *lc;
+   bool        timing_set = false;
 
    /* Initialize ExplainState. */
    ExplainInitState(&es);
@@ -133,6 +134,11 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
            es.costs = defGetBoolean(opt);
        else if (strcmp(opt->defname, "buffers") == 0)
            es.buffers = defGetBoolean(opt);
+       else if (strcmp(opt->defname, "timing") == 0)
+       {
+           timing_set = true;
+           es.timing = defGetBoolean(opt);
+       }
        else if (strcmp(opt->defname, "format") == 0)
        {
            char       *p = defGetString(opt);
@@ -162,6 +168,15 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
        ereport(ERROR,
                (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
                 errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
+   
+   /* if the timing was not set explicitly, set default value */
+   es.timing = (timing_set) ? es.timing : es.analyze;
+
+   /* check that timing is used with EXPLAIN ANALYZE */
+   if (es.timing && !es.analyze)
+       ereport(ERROR,
+               (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+                errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
    /*
     * Parse analysis was done already, but we still have to run the rule
@@ -360,8 +375,11 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es,
    int         eflags;
    int         instrument_option = 0;
 
-   if (es->analyze)
+   if (es->analyze && es->timing)
        instrument_option |= INSTRUMENT_TIMER;
+   else if (es->analyze)
+       instrument_option |= INSTRUMENT_ROWS;
+
    if (es->buffers)
        instrument_option |= INSTRUMENT_BUFFERS;
 
@@ -956,29 +974,42 @@ ExplainNode(PlanState *planstate, List *ancestors,
 
        if (es->format == EXPLAIN_FORMAT_TEXT)
        {
-           appendStringInfo(es->str,
-                            " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
-                            startup_sec, total_sec, rows, nloops);
+           if (planstate->instrument->need_timer)
+               appendStringInfo(es->str,
+                                " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
+                                startup_sec, total_sec, rows, nloops);
+           else
+               appendStringInfo(es->str,
+                                " (actual rows=%.0f loops=%.0f)",
+                                rows, nloops);
        }
        else
        {
-           ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
-           ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
+           if (planstate->instrument->need_timer)
+           {
+               ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
+               ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
+           }
            ExplainPropertyFloat("Actual Rows", rows, 0, es);
            ExplainPropertyFloat("Actual Loops", nloops, 0, es);
        }
    }
    else if (es->analyze)
    {
+
        if (es->format == EXPLAIN_FORMAT_TEXT)
            appendStringInfo(es->str, " (never executed)");
-       else
+       else if (planstate->instrument->need_timer)
        {
            ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es);
            ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);
+       }
+       else
+       {
            ExplainPropertyFloat("Actual Rows", 0.0, 0, es);
            ExplainPropertyFloat("Actual Loops", 0.0, 0, es);
        }
+
    }
 
    /* in text format, first line ends here */

diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index dde73b7919263233ef3e258be570360a737bfd43..2c749b13cd8b4c3761df4c8fae6a2538f225fb56 100644 (file)
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -29,17 +29,19 @@ InstrAlloc(int n, int instrument_options)
 {
    Instrumentation *instr;
 
-   /* timer is always required for now */
-   Assert(instrument_options & INSTRUMENT_TIMER);
-
    /* initialize all fields to zeroes, then modify as needed */
    instr = palloc0(n * sizeof(Instrumentation));
-   if (instrument_options & INSTRUMENT_BUFFERS)
+   if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER))
    {
        int         i;
+       bool        need_buffers = instrument_options & INSTRUMENT_BUFFERS;
+       bool        need_timer = instrument_options & INSTRUMENT_TIMER;
 
        for (i = 0; i < n; i++)
-           instr[i].need_bufusage = true;
+       {
+           instr[i].need_bufusage = need_buffers;
+           instr[i].need_timer = need_timer;
+       }
    }
 
    return instr;
@@ -49,7 +51,7 @@ InstrAlloc(int n, int instrument_options)
 void
 InstrStartNode(Instrumentation *instr)
 {
-   if (INSTR_TIME_IS_ZERO(instr->starttime))
+   if (instr->need_timer && INSTR_TIME_IS_ZERO(instr->starttime))
        INSTR_TIME_SET_CURRENT(instr->starttime);
    else
        elog(DEBUG2, "InstrStartNode called twice in a row");
@@ -68,16 +70,22 @@ InstrStopNode(Instrumentation *instr, double nTuples)
    /* count the returned tuples */
    instr->tuplecount += nTuples;
 
-   if (INSTR_TIME_IS_ZERO(instr->starttime))
+   /* let's update the time only if the timer was requested */
+   if (instr->need_timer)
    {
-       elog(DEBUG2, "InstrStopNode called without start");
-       return;
-   }
 
-   INSTR_TIME_SET_CURRENT(endtime);
-   INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
+       if (INSTR_TIME_IS_ZERO(instr->starttime))
+       {
+           elog(DEBUG2, "InstrStopNode called without start");
+           return;
+       }
 
-   INSTR_TIME_SET_ZERO(instr->starttime);
+       INSTR_TIME_SET_CURRENT(endtime);
+       INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
+
+       INSTR_TIME_SET_ZERO(instr->starttime);
+
+   }
 
    /* Add delta of buffer usage since entry to node's totals */
    if (instr->need_bufusage)

diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3443259b009e475154f887fa3eeeab381de659a6..a987c4312420a2bbbf277b58e7266f03c989e85d 100644 (file)
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -31,6 +31,7 @@ typedef struct ExplainState
    bool        analyze;        /* print actual times */
    bool        costs;          /* print costs */
    bool        buffers;        /* print buffer usage */
+   bool        timing;         /* print timing */
    ExplainFormat format;       /* output format */
    /* other states */
    PlannedStmt *pstmt;         /* top of plan */

diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 9ecb5445f38edc065b90ab68d1771779bfd8dda6..084302e4e7efef8be05ff9983bc2467cd8595e21 100644 (file)
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -31,14 +31,16 @@ typedef struct BufferUsage
 /* Flag bits included in InstrAlloc's instrument_options bitmask */
 typedef enum InstrumentOption
 {
-   INSTRUMENT_TIMER = 1 << 0,  /* needs timer */
+   INSTRUMENT_TIMER = 1 << 0,  /* needs timer (and row counts) */
    INSTRUMENT_BUFFERS = 1 << 1,    /* needs buffer usage */
+   INSTRUMENT_ROWS = 1 << 2,   /* needs row count */
    INSTRUMENT_ALL = 0x7FFFFFFF
 } InstrumentOption;
 
 typedef struct Instrumentation
 {
    /* Parameters set at node creation: */
+   bool        need_timer;     /* TRUE if we need timer data */
    bool        need_bufusage;  /* TRUE if we need buffer usage data */
    /* Info about current plan cycle: */
    bool        running;        /* TRUE if we've completed first tuple */