open-dsi
/
postgres
mirror of https://github.com/postgres/postgres
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Make EXPLAIN output for JIT compilation more dense.

Browse Source 
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
pull/34/head
Andres Freund 7 years ago
parent 7636e5c60f
commit 52050ad8eb
1 changed files with 64 additions and 25 deletions
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Show Stats Download Patch File Download Diff File
  1. 89
      src/backend/commands/explain.c

89
src/backend/commands/explain.c
Unescape View File

@ -696,44 +696,83 @@ void
ExplainPrintJIT(ExplainState *es, QueryDesc *queryDesc) ExplainPrintJIT(ExplainState *es, QueryDesc *queryDesc)
{ {
JitContext *jc = queryDesc->estate->es_jit; 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); ExplainOpenGroup("JIT", "JIT", true, es);
/* for higher density, open code the text output format */
if (es->format == EXPLAIN_FORMAT_TEXT) if (es->format == EXPLAIN_FORMAT_TEXT)
{ {
es->indent += 1; appendStringInfoSpaces(es->str, es->indent * 2);
appendStringInfo(es->str, "JIT:\n"); appendStringInfo(es->str, "JIT:\n");
} es->indent += 1;
ExplainPropertyInteger("Functions", NULL, jc->created_functions, es); 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);
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) if (es->analyze && es->timing)
ExplainPropertyFloat("Inlining Time", "ms", {
1000.0 * INSTR_TIME_GET_DOUBLE(jc->inlining_counter), appendStringInfoSpaces(es->str, es->indent * 2);
3, es); 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); es->indent -= 1;
if (es->analyze && es->timing) }
ExplainPropertyFloat("Optimization Time", "ms", else
1000.0 * INSTR_TIME_GET_DOUBLE(jc->optimization_counter), {
3, es); ExplainPropertyInteger("Functions", NULL, jc->created_functions, es);
if (es->analyze && es->timing) ExplainOpenGroup("Options", "Options", true, es);
ExplainPropertyFloat("Emission Time", "ms", ExplainPropertyBool("Inlining", jc->flags & PGJIT_INLINE, es);
1000.0 * INSTR_TIME_GET_DOUBLE(jc->emission_counter), ExplainPropertyBool("Optimization", jc->flags & PGJIT_OPT3, es);
3, 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->analyze && es->timing)
if (es->format == EXPLAIN_FORMAT_TEXT) {
{ ExplainOpenGroup("Timing", "Timing", true, es);
es->indent -= 1;
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);
} }
/* /*

Write Preview
Loading…
Cancel
Save