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

tglsfdc · tglsfdc · commit bcc6c4c2914a · 2013-02-07T22:53:00.000-05:00
Commit af7914c, 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
@@ -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(ERROR, "InstrStartNode called twice in a row");
+	}
 
 	/* save buffer usage totals at node entry, if needed */
 	if (instr->need_bufusage)
@@ -73,18 +76,13 @@ 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");
-			return;
-		}
+			elog(ERROR, "InstrStopNode called without start");
 
 		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 */
@@ -111,7 +109,7 @@ InstrEndLoop(Instrumentation *instr)
 		return;
 
 	if (!INSTR_TIME_IS_ZERO(instr->starttime))
-		elog(DEBUG2, "InstrEndLoop called on running node");
+		elog(ERROR, "InstrEndLoop called on running node");
 
 	/* Accumulate per-cycle statistics into totals */
 	totaltime = INSTR_TIME_GET_DOUBLE(instr->counter);
