postgrespro.git / summary / log / commit / refs

commit    52050ad8ebec8d831902f587314aa4f6aaa6d2c5
Author:   Andres Freund <andres@anarazel.de>
Date:     Mon Sep 24 20:27:08 2018 +0000

    Make EXPLAIN output for JIT compilation more dense.
    
    A discussion about also reporting JIT compilation overhead on workers
    brought unhappiness with the verbosity of the current explain format
    to light.  Make the text format more dense, and restructure the
    structured output to mirror that more closely.
    
    As we're re-jiggering the output format anyway: The denser format
    allows us to report all flags for JIT compilation (now also reporting
    PGJIT_EXPR and PGJIT_DEFORM), and report the total time in addition to
    the individual times.
    
    Per complaint from Tom Lane.
    
    Author: Andres Freund
    Discussion: https://postgr.es/m/27812.1537221015@sss.pgh.pa.us
    Backpatch: 11-, where JIT compilation was introduced


 src/backend/commands/explain.c | 89 ++++++++++++++++++++++++++++++------------
 1 file changed, 64 insertions(+), 25 deletions(-)

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 16a80a0ea1..01520154e4 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -696,44 +696,83 @@ void
 ExplainPrintJIT(ExplainState *es, QueryDesc *queryDesc)
 {
 	JitContext *jc = queryDesc->estate->es_jit;
+	instr_time	total_time;
+
+	/* calculate total time */
+	INSTR_TIME_SET_ZERO(total_time);
+	INSTR_TIME_ADD(total_time, jc->generation_counter);
+	INSTR_TIME_ADD(total_time, jc->inlining_counter);
+	INSTR_TIME_ADD(total_time, jc->optimization_counter);
+	INSTR_TIME_ADD(total_time, jc->emission_counter);
 
 	ExplainOpenGroup("JIT", "JIT", true, es);
 
+	/* for higher density, open code the text output format */
 	if (es->format == EXPLAIN_FORMAT_TEXT)
 	{
-		es->indent += 1;
+		appendStringInfoSpaces(es->str, es->indent * 2);
 		appendStringInfo(es->str, "JIT:\n");
-	}
+		es->indent += 1;
 
-	ExplainPropertyInteger("Functions", NULL, jc->created_functions, es);
-	if (es->analyze && es->timing)
-		ExplainPropertyFloat("Generation Time", "ms",
-							 1000.0 * INSTR_TIME_GET_DOUBLE(jc->generation_counter),
-							 3, es);
+		ExplainPropertyInteger("Functions", NULL, jc->created_functions, es);
 
-	ExplainPropertyBool("Inlining", jc->flags & PGJIT_INLINE, es);
+		appendStringInfoSpaces(es->str, es->indent * 2);
+		appendStringInfo(es->str, "Options: %s %s, %s %s, %s %s, %s %s\n",
+						 "Inlining", jc->flags & PGJIT_INLINE ? "true" : "false",
+						 "Optimization", jc->flags & PGJIT_OPT3 ? "true" : "false",
+						 "Expressions", jc->flags & PGJIT_EXPR ? "true" : "false",
+						 "Deforming", jc->flags & PGJIT_DEFORM ? "true" : "false");
 
-	if (es->analyze && es->timing)
-		ExplainPropertyFloat("Inlining Time", "ms",
-							 1000.0 * INSTR_TIME_GET_DOUBLE(jc->inlining_counter),
-							 3, es);
+		if (es->analyze && es->timing)
+		{
+			appendStringInfoSpaces(es->str, es->indent * 2);
+			appendStringInfo(es->str,
+							 "Timing: %s %.3f ms, %s %.3f ms, %s %.3f ms, %s %.3f ms, %s %.3f ms\n",
+							 "Generation", 1000.0 * INSTR_TIME_GET_DOUBLE(jc->generation_counter),
+							 "Inlining", 1000.0 * INSTR_TIME_GET_DOUBLE(jc->inlining_counter),
+							 "Optimization", 1000.0 * INSTR_TIME_GET_DOUBLE(jc->optimization_counter),
+							 "Emission", 1000.0 * INSTR_TIME_GET_DOUBLE(jc->emission_counter),
+							 "Total", 1000.0 * INSTR_TIME_GET_DOUBLE(total_time));
+		}
 
-	ExplainPropertyBool("Optimization", jc->flags & PGJIT_OPT3, es);
-	if (es->analyze && es->timing)
-		ExplainPropertyFloat("Optimization Time", "ms",
-							 1000.0 * INSTR_TIME_GET_DOUBLE(jc->optimization_counter),
-							 3, es);
+		es->indent -= 1;
+	}
+	else
+	{
+		ExplainPropertyInteger("Functions", NULL, jc->created_functions, es);
 
-	if (es->analyze && es->timing)
-		ExplainPropertyFloat("Emission Time", "ms",
-							 1000.0 * INSTR_TIME_GET_DOUBLE(jc->emission_counter),
-							 3, es);
+		ExplainOpenGroup("Options", "Options", true, es);
+		ExplainPropertyBool("Inlining", jc->flags & PGJIT_INLINE, es);
+		ExplainPropertyBool("Optimization", jc->flags & PGJIT_OPT3, es);
+		ExplainPropertyBool("Expressions", jc->flags & PGJIT_EXPR, es);
+		ExplainPropertyBool("Deforming", jc->flags & PGJIT_DEFORM, es);
+		ExplainCloseGroup("Options", "Options", true, es);
 
-	ExplainCloseGroup("JIT", "JIT", true, es);
-	if (es->format == EXPLAIN_FORMAT_TEXT)
-	{
-		es->indent -= 1;
+		if (es->analyze && es->timing)
+		{
+			ExplainOpenGroup("Timing", "Timing", true, es);
+
+			ExplainPropertyFloat("Generation", "ms",
+								 1000.0 * INSTR_TIME_GET_DOUBLE(jc->generation_counter),
+								 3, es);
+			ExplainPropertyFloat("Inlining", "ms",
+								 1000.0 * INSTR_TIME_GET_DOUBLE(jc->inlining_counter),
+								 3, es);
+			ExplainPropertyFloat("Optimization", "ms",
+								 1000.0 * INSTR_TIME_GET_DOUBLE(jc->optimization_counter),
+								 3, es);
+			ExplainPropertyFloat("Emission", "ms",
+								 1000.0 * INSTR_TIME_GET_DOUBLE(jc->emission_counter),
+								 3, es);
+			ExplainPropertyFloat("Total", "ms",
+								 1000.0 * INSTR_TIME_GET_DOUBLE(total_time),
+								 3, es);
+
+			ExplainCloseGroup("Timing", "Timing", true, es);
+		}
 	}
+
+	ExplainCloseGroup("JIT", "JIT", true, es);
 }
 
 /*


[parent: 7636e5c60fea]