8000 Make EXPLAIN output for JIT compilation more dense. · postgrespro/postgres@52050ad · GitHub
[go: up one dir, main page]
Skip to content
8000
< 8000 div class="prc-PageLayout-PageLayoutWrapper-s2ao4" data-width="full">

Commit 52050ad

Browse files
anarazelanarazel
committed
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
1 parent 7636e5c commit 52050ad

File tree

1 file changed

+64
-25
lines changed

1 file changed

+64
-25
lines changed

‎src/backend/commands/explain.c

Lines changed: 64 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -696,44 +696,83 @@ void
696696
ExplainPrintJIT(ExplainState *es, QueryDesc *queryDesc)
697697
{
698698
JitContext *jc = queryDesc->estate->es_jit;
699+
instr_time total_time;
700+
701+
/* calculate total time */
702+
INSTR_TIME_SET_ZERO(total_time);
703+
INSTR_TIME_ADD(total_time, jc->generation_counter);
704+
INSTR_TIME_ADD(total_time, jc->inlining_counter);
705+
INSTR_TIME_ADD(total_time, jc->optimization_counter);
706+
INSTR_TIME_ADD(total_time, jc->emission_counter);
699707

700708
ExplainOpenGroup("JIT", "JIT", true, es);
701709

710+
/* for higher density, open code the text output format */
702711
if (es->format == EXPLAIN_FORMAT_TEXT)
703712
{
704-
es->indent += 1;
713+
appendStringInfoSpaces(es->str, es->indent * 2);
705714
appendStringInfo(es->str, "JIT:\n");
706-
}
715+
es->indent += 1;
707716

708-
ExplainPropertyInteger("Functions", NULL, jc->created_functions, es);
709-
if (es->analyze && es->timing)
710-
ExplainPropertyFloat("Generation Time", "ms",
711-
1000.0 * INSTR_TIME_GET_DOUBLE(jc->generation_counter),
712-
3, es);
717+
ExplainPropertyInteger("Functions", NULL, jc->created_functions, es);
713718

714-
ExplainPropertyBool("Inlining", jc->flags & PGJIT_INLINE, es);
719+
appendStringInfoSpaces(es->str, es->indent * 2);
720+
appendStringInfo(es->str, "Options: %s %s, %s %s, %s %s, %s %s\n",
721+
"Inlining", jc->flags & PGJIT_INLINE ? "true" : "false",
722+
"Optimization", jc->flags & PGJIT_OPT3 ? "true" : "false",
723+
"Expressions", jc->flags & PGJIT_EXPR ? "true" : "false",
724+
"Deforming", jc->flags & PGJIT_DEFORM ? "true" : "false");
715725

716-
if (es->analyze && es->timing)
717-
ExplainPropertyFloat("Inlining Time", "ms",
718-
1000.0 * INSTR_TIME_GET_DOUBLE(jc->inlining_counter),
719-
3, es);
726+
if (es->analyze && es->timing)
727+
{
728+
appendStringInfoSpaces(es->str, es->indent * 2);
729+
appendStringInfo(es->str,
730+
"Timing: %s %.3f ms, %s %.3f ms, %s %.3f ms, %s %.3f ms, %s %.3f ms\n",
731+
"Generation", 1000.0 * INSTR_TIME_GET_DOUBLE(jc->generation_counter),
732+
"Inlining", 1000.0 * INSTR_TIME_GET_DOUBLE(jc->inlining_counter),
733+
"Optimization", 1000.0 * INSTR_TIME_GET_DOUBLE(jc->optimization_counter),
734+
"Emission", 1000.0 * INSTR_TIME_GET_DOUBLE(jc->emission_counter),
735+
"Total", 1000.0 * INSTR_TIME_GET_DOUBLE(total_time));
736+
}
720737

721-
ExplainPropertyBool("Optimization", jc->flags & PGJIT_OPT3, es);
722-
if (es->analyze && es->timing)
723-
ExplainPropertyFloat("Optimization Time", "ms",
724-
1000.0 * INSTR_TIME_GET_DOUBLE(jc->optimization_counter),
725-
3, es);
738+
es->indent -= 1;
739+
}
740+
else
741+
{
742+
ExplainPropertyInteger("Functions", NULL, jc->created_functions, es);
726743

727-
if (es->analyze && es->timing)
728-
ExplainPropertyFloat("Emission Time", "ms",
729-
1000.0 * INSTR_TIME_GET_DOUBLE(jc->emission_counter),
730-
3, es);
744+
ExplainOpenGroup("Options", "Options", true, es);
745+
ExplainPropertyBool("Inlining", jc->flags & PGJIT_INLINE, es);
746+
ExplainPropertyBool("Optimization", jc->flags & PGJIT_OPT3, es);
747+
ExplainPropertyBool("Expressions", jc->flags & PGJIT_EXPR, es);
748+
ExplainPropertyBool("Deforming", jc->flags & PGJIT_DEFORM, es);
749+
ExplainCloseGroup("Options", "Options", true, es);
731750

732-
ExplainCloseGroup("JIT", "JIT", true, es);
733-
if (es->format == EXPLAIN_FORMAT_TEXT)
734-
{
735-
es->indent -= 1;
751+
if (es->analyze && es->timing)
752+
{
753+
ExplainOpenGroup("Timing", "Timing", true, es);
754+
755+
ExplainPropertyFloat("Generation", "ms",
756+
1000.0 * INSTR_TIME_GET_DOUBLE(jc->generation_counter),
757+
3, es);
758+
ExplainPropertyFloat("Inlining", "ms",
759+
1000.0 * INSTR_TIME_GET_DOUBLE(jc->inlining_counter),
760+
3, es);
761+
ExplainPropertyFloat("Optimization", "ms",
762+
1000.0 * INSTR_TIME_GET_DOUBLE(jc->optimization_counter),
763+
3, es);
764+
ExplainPropertyFloat("Emission", "ms",
765+
1000.0 * INSTR_TIME_GET_DOUBLE(jc->emission_counter),
766+
3, es);
767+
ExplainPropertyFloat("Total", "ms",
768+
1000.0 * INSTR_TIME_GET_DOUBLE(total_time),
769+
3, es);
770+
771+
ExplainCloseGroup("Timing", "Timing", true, es);
772+
}
736773
}
774+
775+
ExplainCloseGroup("JIT", "JIT", true, es);
737776
}
738777

739778
/*

0 commit comments

Comments
 (0)
0