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 <pavel.stehule@gmail.com>
Reviewed-by: Daniel Gustafsson <daniel@yesql.se>
Discussion: https://postgr.es/m/20220612091253.eegstkufdsu4kfls@erthalion.local

diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile
index 5578a9dd4e3517a79dd4fabd06ba8845239aa113..eba4a95d91ac75427b39fc300515fc4f481b6ffd 100644 (file)
--- a/contrib/pg_stat_statements/Makefile
+++ b/contrib/pg_stat_statements/Makefile
@@ -7,6 +7,7 @@ OBJS = \
 
 EXTENSION = pg_stat_statements
 DATA = pg_stat_statements--1.4.sql \
+   pg_stat_statements--1.10--1.11.sql \
    pg_stat_statements--1.9--1.10.sql pg_stat_statements--1.8--1.9.sql \
    pg_stat_statements--1.7--1.8.sql pg_stat_statements--1.6--1.7.sql \
    pg_stat_statements--1.5--1.6.sql pg_stat_statements--1.4--1.5.sql \

diff --git a/contrib/pg_stat_statements/meson.build b/contrib/pg_stat_statements/meson.build
index 3e3062ada9cb97c568f8d50fa722986ccd523575..15b7c7f2b02006467d70bb03b775639bf0629d23 100644 (file)
--- a/contrib/pg_stat_statements/meson.build
+++ b/contrib/pg_stat_statements/meson.build
@@ -21,6 +21,7 @@ contrib_targets += pg_stat_statements
 install_data(
   'pg_stat_statements.control',
   'pg_stat_statements--1.4.sql',
+  'pg_stat_statements--1.10--1.11.sql',
   'pg_stat_statements--1.9--1.10.sql',
   'pg_stat_statements--1.8--1.9.sql',
   'pg_stat_statements--1.7--1.8.sql',

diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.10--1.11.sql b/contrib/pg_stat_statements/pg_stat_statements--1.10--1.11.sql
new file mode 100644 (file)
index 0000000..20bae80
--- /dev/null
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.10--1.11.sql
@@ -0,0 +1,69 @@
+/* contrib/pg_stat_statements/pg_stat_statements--1.10--1.11.sql */
+
+-- complain if script is sourced in psql, rather than via ALTER EXTENSION
+\echo Use "ALTER EXTENSION pg_stat_statements UPDATE TO '1.11'" to load this file. \quit
+
+/* First we have to remove them from the extension */
+ALTER EXTENSION pg_stat_statements DROP VIEW pg_stat_statements;
+ALTER EXTENSION pg_stat_statements DROP FUNCTION pg_stat_statements(boolean);
+
+/* Then we can drop them */
+DROP VIEW pg_stat_statements;
+DROP FUNCTION pg_stat_statements(boolean);
+
+/* Now redefine */
+CREATE FUNCTION pg_stat_statements(IN showtext boolean,
+    OUT userid oid,
+    OUT dbid oid,
+    OUT toplevel bool,
+    OUT queryid bigint,
+    OUT query text,
+    OUT plans int8,
+    OUT total_plan_time float8,
+    OUT min_plan_time float8,
+    OUT max_plan_time float8,
+    OUT mean_plan_time float8,
+    OUT stddev_plan_time float8,
+    OUT calls int8,
+    OUT total_exec_time float8,
+    OUT min_exec_time float8,
+    OUT max_exec_time float8,
+    OUT mean_exec_time float8,
+    OUT stddev_exec_time float8,
+    OUT rows int8,
+    OUT shared_blks_hit int8,
+    OUT shared_blks_read int8,
+    OUT shared_blks_dirtied int8,
+    OUT shared_blks_written int8,
+    OUT local_blks_hit int8,
+    OUT local_blks_read int8,
+    OUT local_blks_dirtied int8,
+    OUT local_blks_written int8,
+    OUT temp_blks_read int8,
+    OUT temp_blks_written int8,
+    OUT blk_read_time float8,
+    OUT blk_write_time float8,
+    OUT temp_blk_read_time float8,
+    OUT temp_blk_write_time float8,
+    OUT wal_records int8,
+    OUT wal_fpi int8,
+    OUT wal_bytes numeric,
+    OUT jit_functions int8,
+    OUT jit_generation_time float8,
+    OUT jit_inlining_count int8,
+    OUT jit_inlining_time float8,
+    OUT jit_optimization_count int8,
+    OUT jit_optimization_time float8,
+    OUT jit_emission_count int8,
+    OUT jit_emission_time float8,
+    OUT jit_deform_count int8,
+    OUT jit_deform_time float8
+)
+RETURNS SETOF record
+AS 'MODULE_PATHNAME', 'pg_stat_statements_1_11'
+LANGUAGE C STRICT VOLATILE PARALLEL SAFE;
+
+CREATE VIEW pg_stat_statements AS
+  SELECT * FROM pg_stat_statements(true);
+
+GRANT SELECT ON pg_stat_statements TO PUBLIC;

diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index 06b65aeef5ca3c7eab84ee6ba44f7b2ee50e7e56..a46f2db352b8bea8a8c69d1b04117b4757bc0875 100644 (file)
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -117,7 +117,8 @@ typedef enum pgssVersion
    PGSS_V1_3,
    PGSS_V1_8,
    PGSS_V1_9,
-   PGSS_V1_10
+   PGSS_V1_10,
+   PGSS_V1_11
 } pgssVersion;
 
 typedef enum pgssStoreKind
@@ -192,6 +193,10 @@ typedef struct Counters
    double      jit_generation_time;    /* total time to generate jit code */
    int64       jit_inlining_count; /* number of times inlining time has been
                                     * > 0 */
+   double      jit_deform_time;    /* total time to deform tuples in jit code */
+   int64       jit_deform_count;   /* number of times deform time has been >
+                                    * 0 */
+
    double      jit_inlining_time;  /* total time to inline jit code */
    int64       jit_optimization_count; /* number of times optimization time
                                         * has been > 0 */
@@ -312,6 +317,7 @@ PG_FUNCTION_INFO_V1(pg_stat_statements_1_3);
 PG_FUNCTION_INFO_V1(pg_stat_statements_1_8);
 PG_FUNCTION_INFO_V1(pg_stat_statements_1_9);
 PG_FUNCTION_INFO_V1(pg_stat_statements_1_10);
+PG_FUNCTION_INFO_V1(pg_stat_statements_1_11);
 PG_FUNCTION_INFO_V1(pg_stat_statements);
 PG_FUNCTION_INFO_V1(pg_stat_statements_info);
 
@@ -1398,6 +1404,10 @@ pgss_store(const char *query, uint64 queryId,
            e->counters.jit_functions += jitusage->created_functions;
            e->counters.jit_generation_time += INSTR_TIME_GET_MILLISEC(jitusage->generation_counter);
 
+           if (INSTR_TIME_GET_MILLISEC(jitusage->deform_counter))
+               e->counters.jit_deform_count++;
+           e->counters.jit_deform_time += INSTR_TIME_GET_MILLISEC(jitusage->deform_counter);
+
            if (INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter))
                e->counters.jit_inlining_count++;
            e->counters.jit_inlining_time += INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter);
@@ -1460,7 +1470,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
 #define PG_STAT_STATEMENTS_COLS_V1_8   32
 #define PG_STAT_STATEMENTS_COLS_V1_9   33
 #define PG_STAT_STATEMENTS_COLS_V1_10  43
-#define PG_STAT_STATEMENTS_COLS            43  /* maximum of above */
+#define PG_STAT_STATEMENTS_COLS_V1_11  45
+#define PG_STAT_STATEMENTS_COLS            45  /* maximum of above */
 
 /*
  * Retrieve statement statistics.
@@ -1472,6 +1483,16 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
  * expected API version is identified by embedding it in the C name of the
  * function.  Unfortunately we weren't bright enough to do that for 1.1.
  */
+Datum
+pg_stat_statements_1_11(PG_FUNCTION_ARGS)
+{
+   bool        showtext = PG_GETARG_BOOL(0);
+
+   pg_stat_statements_internal(fcinfo, PGSS_V1_11, showtext);
+
+   return (Datum) 0;
+}
+
 Datum
 pg_stat_statements_1_10(PG_FUNCTION_ARGS)
 {
@@ -1602,6 +1623,10 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
            if (api_version != PGSS_V1_10)
                elog(ERROR, "incorrect number of output arguments");
            break;
+       case PG_STAT_STATEMENTS_COLS_V1_11:
+           if (api_version != PGSS_V1_11)
+               elog(ERROR, "incorrect number of output arguments");
+           break;
        default:
            elog(ERROR, "incorrect number of output arguments");
    }
@@ -1834,6 +1859,11 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
            values[i++] = Int64GetDatumFast(tmp.jit_emission_count);
            values[i++] = Float8GetDatumFast(tmp.jit_emission_time);
        }
+       if (api_version >= PGSS_V1_11)
+       {
+           values[i++] = Int64GetDatumFast(tmp.jit_deform_count);
+           values[i++] = Float8GetDatumFast(tmp.jit_deform_time);
+       }
 
        Assert(i == (api_version == PGSS_V1_0 ? PG_STAT_STATEMENTS_COLS_V1_0 :
                     api_version == PGSS_V1_1 ? PG_STAT_STATEMENTS_COLS_V1_1 :
@@ -1842,6 +1872,7 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
                     api_version == PGSS_V1_8 ? PG_STAT_STATEMENTS_COLS_V1_8 :
                     api_version == PGSS_V1_9 ? PG_STAT_STATEMENTS_COLS_V1_9 :
                     api_version == PGSS_V1_10 ? PG_STAT_STATEMENTS_COLS_V1_10 :
+                    api_version == PGSS_V1_11 ? PG_STAT_STATEMENTS_COLS_V1_11 :
                     -1 /* fail if you forget to update this assert */ ));
 
        tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls);

diff --git a/contrib/pg_stat_statements/pg_stat_statements.control b/contrib/pg_stat_statements/pg_stat_statements.control
index 0747e48138373377999693a1126a28b60e9aa92c..8a76106ec676378c6f57003b761635d4542093c8 100644 (file)
--- a/contrib/pg_stat_statements/pg_stat_statements.control
+++ b/contrib/pg_stat_statements/pg_stat_statements.control
@@ -1,5 +1,5 @@
 # pg_stat_statements extension
 comment = 'track planning and execution statistics of all SQL statements executed'
-default_version = '1.10'
+default_version = '1.11'
 module_pathname = '$libdir/pg_stat_statements'
 relocatable = true

diff --git a/doc/src/sgml/jit.sgml b/doc/src/sgml/jit.sgml
index 998c972e8ba08f50c1e50ab14bed646e857e9bb1..1921557cb826dacf96788270b25d445cbd31c8b9 100644 (file)
--- a/doc/src/sgml/jit.sgml
+++ b/doc/src/sgml/jit.sgml
@@ -170,7 +170,7 @@ SET
  JIT:
    Functions: 3
    Options: Inlining false, Optimization false, Expressions true, Deforming true
-   Timing: Generation 1.259 ms, Inlining 0.000 ms, Optimization 0.797 ms, Emission 5.048 ms, Total 7.104 ms
+   Timing: Generation 1.259 ms (Deform 0.000 ms), Inlining 0.000 ms, Optimization 0.797 ms, Emission 5.048 ms, Total 7.104 ms
  Execution Time: 7.416 ms
 </screen>
    As visible here, <acronym>JIT</acronym> was used, but inlining and

diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index b1214ee6453c9f4f1bc2a6aadcb7149478ca73fa..7e7c5c9ff826afdc98a52c3b7f41ca9706afe763 100644 (file)
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -420,6 +420,25 @@
       </para></entry>
      </row>
 
+     <row>
+      <entry role="catalog_table_entry"><para role="column_definition">
+       <structfield>jit_deform_count</structfield> <type>bigint</type>
+      </para>
+      <para>
+       Total number of tuple deform functions JIT-compiled by the statement
+      </para></entry>
+     </row>
+
+     <row>
+      <entry role="catalog_table_entry"><para role="column_definition">
+       <structfield>jit_deform_time</structfield> <type>double precision</type>
+      </para>
+      <para>
+        Total time spent by the statement on JIT-compiling tuple deform
+        functions, in milliseconds
+      </para></entry>
+     </row>
+
      <row>
       <entry role="catalog_table_entry"><para role="column_definition">
        <structfield>jit_inlining_count</structfield> <type>bigint</type>

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 8570b14f6217bc1e8f193578f433d8aa2a7b4eaa..13217807eed794274ecc23acb8d732ce1ce7ed4f 100644 (file)
--- 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);

diff --git a/src/backend/jit/jit.c b/src/backend/jit/jit.c
index fd1cf184c8e58587d79caaa83ee16400a738ff95..4da8fee20b4a52ad592ebd4ebe9cd9663cf510ae 100644 (file)
--- a/src/backend/jit/jit.c
+++ b/src/backend/jit/jit.c
@@ -185,6 +185,7 @@ InstrJitAgg(JitInstrumentation *dst, JitInstrumentation *add)
 {
    dst->created_functions += add->created_functions;
    INSTR_TIME_ADD(dst->generation_counter, add->generation_counter);
+   INSTR_TIME_ADD(dst->deform_counter, add->deform_counter);
    INSTR_TIME_ADD(dst->inlining_counter, add->inlining_counter);
    INSTR_TIME_ADD(dst->optimization_counter, add->optimization_counter);
    INSTR_TIME_ADD(dst->emission_counter, add->emission_counter);

diff --git a/src/backend/jit/llvm/llvmjit_expr.c b/src/backend/jit/llvm/llvmjit_expr.c
index 00d7b8110b9ebe281edaf9cb5bd5eb4ddfdd8e7d..2ac335e23899e7620701bb0aa890dd2d2eca9d9e 100644 (file)
--- a/src/backend/jit/llvm/llvmjit_expr.c
+++ b/src/backend/jit/llvm/llvmjit_expr.c
@@ -121,7 +121,9 @@ llvm_compile_expr(ExprState *state)
    LLVMValueRef v_aggnulls;
 
    instr_time  starttime;
+   instr_time  deform_starttime;
    instr_time  endtime;
+   instr_time  deform_endtime;
 
    llvm_enter_fatal_on_oom();
 
@@ -315,10 +317,14 @@ llvm_compile_expr(ExprState *state)
                     */
                    if (tts_ops && desc && (context->base.flags & PGJIT_DEFORM))
                    {
+                       INSTR_TIME_SET_CURRENT(deform_starttime);
                        l_jit_deform =
                            slot_compile_deform(context, desc,
                                                tts_ops,
                                                op->d.fetch.last_var);
+                       INSTR_TIME_SET_CURRENT(deform_endtime);
+                       INSTR_TIME_ACCUM_DIFF(context->base.instr.deform_counter,
+                                             deform_endtime, deform_starttime);
                    }
 
                    if (l_jit_deform)

diff --git a/src/include/jit/jit.h b/src/include/jit/jit.h
index 14f2e36b3711b55557ec4270d5a22ee28a384d72..ed381d8a1c8f62ff3c0bd8f1b9d306dc8303852d 100644 (file)
--- a/src/include/jit/jit.h
+++ b/src/include/jit/jit.h
@@ -32,6 +32,9 @@ typedef struct JitInstrumentation
    /* accumulated time to generate code */
    instr_time  generation_counter;
 
+   /* accumulated time to deform tuples, included into generation_counter */
+   instr_time  deform_counter;
+
    /* accumulated time for inlining */
    instr_time  inlining_counter;