Fix performance issue in EXPLAIN (ANALYZE, TIMING OFF).

Commit af7914c6627bcf0b0ca614e9ce95d3f8056602bf, which added the TIMING
option to EXPLAIN, had an oversight: if the TIMING option is disabled
then control in InstrStartNode() goes through an elog(DEBUG2) call, which
typically does nothing but takes a noticeable amount of time to do it.
Tweak the logic to avoid that.

In HEAD, also change the elog(DEBUG2)'s in instrument.c to elog(ERROR).
It's not very clear why they weren't like that to begin with, but this
episode shows that not complaining more vociferously about misuse is
likely to do little except allow bugs to remain hidden.

While at it, adjust some code that was making possibly-dangerous
assumptions about flag bits being in the rightmost byte of the
instrument_options word.

Problem reported by Pavel Stehule (via Tomas Vondra).

diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index c58ee3d3002fa4ba1705cfef72c56d1307093664..2b4ce751f5efbb7715f5a28a3a61e637c1a9a775 100644 (file)
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -33,9 +33,9 @@ InstrAlloc(int n, int instrument_options)
        instr = palloc0(n * sizeof(Instrumentation));
        if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER))
        {
+               bool            need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0;
+               bool            need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
                int                     i;
-               bool            need_buffers = instrument_options & INSTRUMENT_BUFFERS;
-               bool            need_timer = instrument_options & INSTRUMENT_TIMER;
 
                for (i = 0; i < n; i++)
                {
@@ -51,10 +51,13 @@ InstrAlloc(int n, int instrument_options)
 void
 InstrStartNode(Instrumentation *instr)
 {
-       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");
+       if (instr->need_timer)
+       {
+               if (INSTR_TIME_IS_ZERO(instr->starttime))
+                       INSTR_TIME_SET_CURRENT(instr->starttime);
+               else
+                       elog(DEBUG2, "InstrStartNode called twice in a row");
+       }
 
        /* save buffer usage totals at node entry, if needed */
        if (instr->need_bufusage)
@@ -73,7 +76,6 @@ InstrStopNode(Instrumentation *instr, double nTuples)
        /* let's update the time only if the timer was requested */
        if (instr->need_timer)
        {
-
                if (INSTR_TIME_IS_ZERO(instr->starttime))
                {
                        elog(DEBUG2, "InstrStopNode called without start");
@@ -84,7 +86,6 @@ InstrStopNode(Instrumentation *instr, double nTuples)
                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 */