fix-jit-statistics-in-EXPLAIN-for-non-parallel-queries-v1.patch

application/octet-stream

Filename: fix-jit-statistics-in-EXPLAIN-for-non-parallel-queries-v1.patch
Type: application/octet-stream
Part: 0
Message: Re: Query is over 2x slower with jit=on

Patch

Format: format-patch
Series: patch v1
Subject: Fix display of JIT statistics in EXPLAIN for non-parallel queries
File+
contrib/auto_explain/auto_explain.c 1 2
doc/src/sgml/jit.sgml 2 6
src/backend/commands/explain.c 28 2
src/backend/executor/execMain.c 0 15
src/include/commands/explain.h 1 0
From a60c742e4b3ede8676ad70b0e1657f12b8a0aa5e Mon Sep 17 00:00:00 2001
From: Lukas Fittl <lukas@fittl.com>
Date: Sun, 30 Sep 2018 22:24:20 -0700
Subject: [PATCH] Fix display of JIT statistics in EXPLAIN for non-parallel
 queries

This bug was introduced by e63441c3f5ca4a3cdb47f9c7fed9e61dde17b60d
since ExecutorEnd is only called after the query plan is being output
by EXPLAIN/auto_explain. Instead, introduce a new ExplainPrintJITSummary
method that takes care of the summarization and then outputs the stats.

In passing also fix outdated JIT documentation that was still using the
old JIT statistics format.
---
 contrib/auto_explain/auto_explain.c |  3 +--
 doc/src/sgml/jit.sgml               |  8 ++------
 src/backend/commands/explain.c      | 30 +++++++++++++++++++++++++++--
 src/backend/executor/execMain.c     | 15 ---------------
 src/include/commands/explain.h      |  1 +
 5 files changed, 32 insertions(+), 25 deletions(-)

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index b9c0896433..03be05129f 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -336,8 +336,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
 			if (es->analyze && auto_explain_log_triggers)
 				ExplainPrintTriggers(es, queryDesc);
 			if (es->costs)
-				ExplainPrintJIT(es, queryDesc->estate->es_jit_flags,
-								queryDesc->estate->es_jit_combined_instr, -1);
+				ExplainPrintJITSummary(es, queryDesc);
 			ExplainEndOutput(es);
 
 			/* Remove last line break */
diff --git a/doc/src/sgml/jit.sgml b/doc/src/sgml/jit.sgml
index 8387a4f6be..a21a07ef71 100644
--- a/doc/src/sgml/jit.sgml
+++ b/doc/src/sgml/jit.sgml
@@ -169,12 +169,8 @@ SET
  Planning Time: 0.133 ms
  JIT:
    Functions: 3
-   Generation Time: 1.259 ms
-   Inlining: false
-   Inlining Time: 0.000 ms
-   Optimization: false
-   Optimization Time: 0.797 ms
-   Emission Time: 5.048 ms
+   Options: Inlining false, Optimization false, Expressions true, Deforming true
+   Timing: Generation 1.259 ms, Inlining 0.000 ms, Optimization 0.797 ms, Emission 5.048 ms, Total 7.104 ms
  Execution Time: 7.416 ms
 </screen>
    As visible here, <acronym>JIT</acronym> was used, but inlining and
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index ed6afe79a9..32df216f2c 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -564,8 +564,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	 * at a later stage.
 	 */
 	if (es->costs)
-		ExplainPrintJIT(es, queryDesc->estate->es_jit_flags,
-						queryDesc->estate->es_jit_combined_instr, -1);
+		ExplainPrintJITSummary(es, queryDesc);
 
 	/*
 	 * Close down the query and free resources.  Include time for this in the
@@ -688,6 +687,33 @@ ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc)
 	ExplainCloseGroup("Triggers", "Triggers", false, es);
 }
 
+/*
+ * ExplainPrintJITSummary -
+ *    Print summarized JIT instrumentation from leader and workers
+ */
+void
+ExplainPrintJITSummary(ExplainState *es, QueryDesc *queryDesc)
+{
+	JitInstrumentation ji;
+
+	if (!queryDesc->estate->es_jit)
+		return;
+
+	memset(&ji, 0, sizeof(JitInstrumentation));
+
+	/*
+	 * Work with a copy instead of modifying the leader state, since this
+	 * function may be called twice
+	 */
+	InstrJitAgg(&ji, &queryDesc->estate->es_jit->instr);
+
+	/* If this process has done JIT in parallel workers, merge stats */
+	if (queryDesc->estate->es_jit_combined_instr)
+		InstrJitAgg(&ji, queryDesc->estate->es_jit_combined_instr);
+
+	ExplainPrintJIT(es, queryDesc->estate->es_jit_flags, &ji, -1);
+}
+
 /*
  * ExplainPrintJIT -
  *	  Append information about JITing to es->str.
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 04f14c9178..572506e7c2 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -495,21 +495,6 @@ standard_ExecutorEnd(QueryDesc *queryDesc)
 
 	ExecEndPlan(queryDesc->planstate, estate);
 
-	/*
-	 * If this process has done JIT, either merge stats into worker stats, or
-	 * use this process' stats as the global stats if no parallelism was used
-	 * / no workers did JIT.
-	 */
-	if (estate->es_instrument && queryDesc->estate->es_jit)
-	{
-		if (queryDesc->estate->es_jit_combined_instr)
-			InstrJitAgg(queryDesc->estate->es_jit_combined_instr,
-						&queryDesc->estate->es_jit->instr);
-		else
-			queryDesc->estate->es_jit_combined_instr =
-				&queryDesc->estate->es_jit->instr;
-	}
-
 	/* do away with our snapshots */
 	UnregisterSnapshot(estate->es_snapshot);
 	UnregisterSnapshot(estate->es_crosscheck_snapshot);
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index b0b6f1e15a..d3f70fda08 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -81,6 +81,7 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
 extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
 extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
 
+extern void ExplainPrintJITSummary(ExplainState *es, QueryDesc *queryDesc);
 extern void ExplainPrintJIT(ExplainState *es, int jit_flags,
 				struct JitInstrumentation *jit_instr, int worker_i);
 
-- 
2.19.0