From 5a3423ad8ee171fbf08317917981effe47d211eb Mon Sep 17 00:00:00 2001 From: Daniel Gustafsson Date: Fri, 8 Sep 2023 15:05:12 +0200 Subject: Add JIT deform_counter generation_counter includes time spent on both JIT:ing expressions and tuple deforming which are configured independently via options jit_expressions and jit_tuple_deforming. As they are combined in the same counter it's not apparent what fraction of time the tuple deforming takes. This adds deform_counter dedicated to tuple deforming, which allows seeing more directly the influence jit_tuple_deforming is having on the query. The counter is exposed in EXPLAIN and pg_stat_statements bumpin pg_stat_statements to 1.11. Author: Dmitry Dolgov <9erthalion6@gmail.com> Reviewed-by: Pavel Stehule Reviewed-by: Daniel Gustafsson Discussion: https://postgr.es/m/20220612091253.eegstkufdsu4kfls@erthalion.local --- src/backend/commands/explain.c | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) (limited to 'src/backend/commands/explain.c') diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 8570b14f621..13217807eed 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -893,6 +893,7 @@ ExplainPrintJIT(ExplainState *es, int jit_flags, JitInstrumentation *ji) /* calculate total time */ INSTR_TIME_SET_ZERO(total_time); + /* don't add deform_counter, it's included in generation_counter */ INSTR_TIME_ADD(total_time, ji->generation_counter); INSTR_TIME_ADD(total_time, ji->inlining_counter); INSTR_TIME_ADD(total_time, ji->optimization_counter); @@ -920,8 +921,9 @@ ExplainPrintJIT(ExplainState *es, int jit_flags, JitInstrumentation *ji) { ExplainIndentText(es); appendStringInfo(es->str, - "Timing: %s %.3f ms, %s %.3f ms, %s %.3f ms, %s %.3f ms, %s %.3f ms\n", + "Timing: %s %.3f ms (%s %.3f ms), %s %.3f ms, %s %.3f ms, %s %.3f ms, %s %.3f ms\n", "Generation", 1000.0 * INSTR_TIME_GET_DOUBLE(ji->generation_counter), + "Deform", 1000.0 * INSTR_TIME_GET_DOUBLE(ji->deform_counter), "Inlining", 1000.0 * INSTR_TIME_GET_DOUBLE(ji->inlining_counter), "Optimization", 1000.0 * INSTR_TIME_GET_DOUBLE(ji->optimization_counter), "Emission", 1000.0 * INSTR_TIME_GET_DOUBLE(ji->emission_counter), @@ -945,9 +947,15 @@ ExplainPrintJIT(ExplainState *es, int jit_flags, JitInstrumentation *ji) { ExplainOpenGroup("Timing", "Timing", true, es); - ExplainPropertyFloat("Generation", "ms", + ExplainOpenGroup("Generation", "Generation", true, es); + ExplainPropertyFloat("Deform", "ms", + 1000.0 * INSTR_TIME_GET_DOUBLE(ji->deform_counter), + 3, es); + ExplainPropertyFloat("Total", "ms", 1000.0 * INSTR_TIME_GET_DOUBLE(ji->generation_counter), 3, es); + ExplainCloseGroup("Generation", "Generation", true, es); + ExplainPropertyFloat("Inlining", "ms", 1000.0 * INSTR_TIME_GET_DOUBLE(ji->inlining_counter), 3, es); -- cgit v1.2.3