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

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 16a80a0ea14bec0db4c5814212f679cd5b78252f..01520154e4867db180992c3ed67c037d29dd9c8d 100644 (file)
--- 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);
 }
 
 /*