Prevent auto_explain from changing the output of a user's EXPLAIN.

tglsfdc · tglsfdc · commit 0266a9c78139 · 2014-05-20T12:20:52.000-04:00
Commit af7914c, which introduced the EXPLAIN (TIMING) option, for some reason coded explain.c to look at planstate->instrument->need_timer rather than es->timing to decide whether to print timing info. However, the former flag might get set as a result of contrib/auto_explain wanting timing information. We certainly don't want activation of auto_explain to change user-visible statement behavior, so fix that. Also fix an independent bug introduced in the same patch: in the code path for a never-executed node with a machine-friendly output format, if timing was selected, it would fail to print the Actual Rows and Actual Loops items. Per bug #10404 from Tomonari Katsumata. Back-patch to 9.2 where the faulty code was introduced.
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
@@ -1145,11 +1145,18 @@ ExplainNode(PlanState *planstate, List *ancestors,
 	/*
 	 * We have to forcibly clean up the instrumentation state because we
 	 * haven't done ExecutorEnd yet.  This is pretty grotty ...
+	 *
+	 * Note: contrib/auto_explain could cause instrumentation to be set up
+	 * even though we didn't ask for it here.  Be careful not to print any
+	 * instrumentation results the user didn't ask for.  But we do the
+	 * InstrEndLoop call anyway, if possible, to reduce the number of cases
+	 * auto_explain has to contend with.
 	 */
 	if (planstate->instrument)
 		InstrEndLoop(planstate->instrument);
 
-	if (planstate->instrument && planstate->instrument->nloops > 0)
+	if (es->analyze &&
+		planstate->instrument && planstate->instrument->nloops > 0)
 	{
 		double		nloops = planstate->instrument->nloops;
 		double		startup_sec = 1000.0 * planstate->instrument->startup / nloops;
@@ -1158,7 +1165,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 
 		if (es->format == EXPLAIN_FORMAT_TEXT)
 		{
-			if (planstate->instrument->need_timer)
+			if (es->timing)
 				appendStringInfo(es->str,
 							" (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
 								 startup_sec, total_sec, rows, nloops);
@@ -1169,7 +1176,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 		}
 		else
 		{
-			if (planstate->instrument->need_timer)
+			if (es->timing)
 			{
 				ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
 				ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
@@ -1180,20 +1187,18 @@ ExplainNode(PlanState *planstate, List *ancestors,
 	}
 	else if (es->analyze)
 	{
-
 		if (es->format == EXPLAIN_FORMAT_TEXT)
 			appendStringInfo(es->str, " (never executed)");
-		else if (planstate->instrument->need_timer)
-		{
-			ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es);
-			ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);
-		}
 		else
 		{
+			if (es->timing)
+			{
+				ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es);
+				ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);
+			}
 			ExplainPropertyFloat("Actual Rows", 0.0, 0, es);
 			ExplainPropertyFloat("Actual Loops", 0.0, 0, es);
 		}
-
 	}
 
 	/* in text format, first line ends here */
@@ -1362,7 +1367,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
 	}
 
 	/* Show buffer usage */
-	if (es->buffers)
+	if (es->buffers && planstate->instrument)
 	{
 		const BufferUsage *usage = &planstate->instrument->bufusage;
 

Original file line number	Diff line number	Diff line change
`@@ -1145,11 +1145,18 @@ ExplainNode(PlanState planstate, List ancestors,`
`1145`	`1145`	`/*`
`1146`	`1146`	`* We have to forcibly clean up the instrumentation state because we`
`1147`	`1147`	`* haven't done ExecutorEnd yet. This is pretty grotty ...`
	`1148`	`+ *`
	`1149`	`+ * Note: contrib/auto_explain could cause instrumentation to be set up`
	`1150`	`+ * even though we didn't ask for it here. Be careful not to print any`
	`1151`	`+ * instrumentation results the user didn't ask for. But we do the`
	`1152`	`+ * InstrEndLoop call anyway, if possible, to reduce the number of cases`
	`1153`	`+ * auto_explain has to contend with.`
`1148`	`1154`	`*/`
`1149`	`1155`	`if (planstate->instrument)`
`1150`	`1156`	`InstrEndLoop(planstate->instrument);`
`1151`	`1157`
`1152`		`- if (planstate->instrument && planstate->instrument->nloops > 0)`
	`1158`	`+ if (es->analyze &&`
	`1159`	`+ planstate->instrument && planstate->instrument->nloops > 0)`
`1153`	`1160`	`{`
`1154`	`1161`	`double nloops = planstate->instrument->nloops;`
`1155`	`1162`	`double startup_sec = 1000.0 * planstate->instrument->startup / nloops;`
`@@ -1158,7 +1165,7 @@ ExplainNode(PlanState planstate, List ancestors,`
`1158`	`1165`
`1159`	`1166`	`if (es->format == EXPLAIN_FORMAT_TEXT)`
`1160`	`1167`	`{`
`1161`		`- if (planstate->instrument->need_timer)`
	`1168`	`+ if (es->timing)`
`1162`	`1169`	`appendStringInfo(es->str,`
`1163`	`1170`	`" (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",`
`1164`	`1171`	`startup_sec, total_sec, rows, nloops);`
`@@ -1169,7 +1176,7 @@ ExplainNode(PlanState planstate, List ancestors,`
`1169`	`1176`	`}`
`1170`	`1177`	`else`
`1171`	`1178`	`{`
`1172`		`- if (planstate->instrument->need_timer)`
	`1179`	`+ if (es->timing)`
`1173`	`1180`	`{`
`1174`	`1181`	`ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);`
`1175`	`1182`	`ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);`
`@@ -1180,20 +1187,18 @@ ExplainNode(PlanState planstate, List ancestors,`
`1180`	`1187`	`}`
`1181`	`1188`	`else if (es->analyze)`
`1182`	`1189`	`{`
`1183`		`-`
`1184`	`1190`	`if (es->format == EXPLAIN_FORMAT_TEXT)`
`1185`	`1191`	`appendStringInfo(es->str, " (never executed)");`
`1186`		`- else if (planstate->instrument->need_timer)`
`1187`		`- {`
`1188`		`- ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es);`
`1189`		`- ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);`
`1190`		`- }`
`1191`	`1192`	`else`
`1192`	`1193`	`{`
	`1194`	`+ if (es->timing)`
	`1195`	`+ {`
	`1196`	`+ ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es);`
	`1197`	`+ ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);`
	`1198`	`+ }`
`1193`	`1199`	`ExplainPropertyFloat("Actual Rows", 0.0, 0, es);`
`1194`	`1200`	`ExplainPropertyFloat("Actual Loops", 0.0, 0, es);`
`1195`	`1201`	`}`
`1196`		`-`
`1197`	`1202`	`}`
`1198`	`1203`
`1199`	`1204`	`/* in text format, first line ends here */`
`@@ -1362,7 +1367,7 @@ ExplainNode(PlanState planstate, List ancestors,`
`1362`	`1367`	`}`
`1363`	`1368`
`1364`	`1369`	`/* Show buffer usage */`
`1365`		`- if (es->buffers)`
	`1370`	`+ if (es->buffers && planstate->instrument)`
`1366`	`1371`	`{`
`1367`	`1372`	`const BufferUsage *usage = &planstate->instrument->bufusage;`
`1368`	`1373`