> On Sun, Jan 08, 2023 at 09:06:33PM +0100, Pavel Stehule wrote:
> It is working although I am not sure if it is correctly
>
> when I run EXPLAIN ANALYZE for query `explain analyze select
> count(length(prosrc) > 0) from pg_proc;`
>
> I got plan and times
>
> ┌─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
> │ QUERY PLAN
> │
> ╞═════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
> │ Aggregate (cost=154.10..154.11 rows=1 width=8) (actual
> time=134.450..134.451 rows=1 loops=1)
> │
> │ -> Seq Scan on pg_proc (cost=0.00..129.63 rows=3263 width=16) (actual
> time=0.013..0.287 rows=3266 loops=1) │
> │ Planning Time: 0.088 ms
> │
> │ JIT:
> │
> │ Functions: 3
> │
> │ Options: Inlining true, Optimization true, Expressions true, Deforming
> true │
> │ Timing: Generation 0.631 ms, Deforming 0.396 ms, Inlining 10.026 ms,
> Optimization 78.608 ms, Emission 44.915 ms, Total 134.181 ms │
> │ Execution Time: 135.173 ms
> │
> └─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
> (8 rows)
>
> Deforming is 0.396ms
>
> When I run mentioned query, and when I look to pg_stat_statements table, I
> see different times
>
> deforming is about 10ms
>
> wal_bytes │ 0
> jit_functions │ 9
> jit_generation_time │ 1.9040409999999999
> jit_deform_count │ 3
> jit_deform_time │ 36.395131
> jit_inlining_count │ 3
> jit_inlining_time │ 256.104205
> jit_optimization_count │ 3
> jit_optimization_time │ 132.45361300000002
> jit_emission_count │ 3
> jit_emission_time │ 1.210633
>
> counts are correct, but times are strange - there is not consistency with
> values from EXPLAIN
>
> When I run this query on master, the values are correct
>
> jit_functions │ 6
> jit_generation_time │ 1.350521
> jit_inlining_count │ 2
> jit_inlining_time │ 24.018382000000003
> jit_optimization_count │ 2
> jit_optimization_time │ 173.405792
> jit_emission_count │ 2
> jit_emission_time │ 91.226655
> ────────────────────────┴───────────────────
>
> │ JIT:
> │
> │ Functions: 3
> │
> │ Options: Inlining true, Optimization true, Expressions true, Deforming
> true │
> │ Timing: Generation 0.636 ms, Inlining 9.309 ms, Optimization 89.653 ms,
> Emission 45.812 ms, Total 145.410 ms │
> │ Execution Time: 146.410 ms
> │
> └────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
Thanks for noticing. Similarly to the previous issue, the order of
columns was incorrect -- deform counters have to be the last columns in
the view.
>From 93d739e9258f79474df5644831a1f82fc97742dc Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthali...@gmail.com>
Date: Sat, 11 Jun 2022 11:54:40 +0200
Subject: [PATCH v4 1/2] Add deform_counter
At the moment generation_counter includes time spent on both JITing
expressions and tuple deforming. Those are configured independently via
corresponding options (jit_expressions and jit_tuple_deforming), which
means there is no way to find out what fraction of time tuple deforming
alone is taking.
Add deform_counter dedicated to tuple deforming, which allows seeing
more directly the influence jit_tuple_deforming is having on the query.
---
src/backend/commands/explain.c | 7 ++++++-
src/backend/jit/jit.c | 1 +
src/backend/jit/llvm/llvmjit_expr.c | 6 ++++++
src/include/jit/jit.h | 3 +++
4 files changed, 16 insertions(+), 1 deletion(-)
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index f86983c660..2f23602a87 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -882,6 +882,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 into 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);
@@ -909,8 +910,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),
+ "Deforming", 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),
@@ -937,6 +939,9 @@ ExplainPrintJIT(ExplainState *es, int jit_flags, JitInstrumentation *ji)
ExplainPropertyFloat("Generation", "ms",
1000.0 * INSTR_TIME_GET_DOUBLE(ji->generation_counter),
3, es);
+ ExplainPropertyFloat("Deforming", "ms",
+ 1000.0 * INSTR_TIME_GET_DOUBLE(ji->deform_counter),
+ 3, 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 91a6b2b63a..a6bdf03718 100644
--- 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 f114337f8e..1ad384f15e 100644
--- 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 600ddfc753..2c8e20d9cf 100644
--- 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;
--
2.32.0
>From df5c3db54b9ce92bf6470ee1e8bd25fa4e90ecba Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthali...@gmail.com>
Date: Sat, 11 Jun 2022 12:25:28 +0200
Subject: [PATCH v4 2/2] Add deform_counter to pg_stat_statements
Similar to other JIT counters, expose deform_counter via
pg_stat_statements. Includes bumping its version to 1.11.
---
contrib/pg_stat_statements/Makefile | 1 +
contrib/pg_stat_statements/meson.build | 1 +
.../pg_stat_statements--1.10--1.11.sql | 69 +++++++++++++++++++
.../pg_stat_statements/pg_stat_statements.c | 34 ++++++++-
.../pg_stat_statements.control | 2 +-
doc/src/sgml/pgstatstatements.sgml | 19 +++++
6 files changed, 123 insertions(+), 3 deletions(-)
create mode 100644 contrib/pg_stat_statements/pg_stat_statements--1.10--1.11.sql
diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile
index edc40c8bbf..8d787970e7 100644
--- 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 7537e1cf64..e224cd764c 100644
--- 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
index 0000000000..20bae80458
--- /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 8567cc0ca2..f2650b691b 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -118,7 +118,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
@@ -193,6 +194,9 @@ 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 */
@@ -313,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);
@@ -1400,6 +1405,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);
@@ -1462,7 +1471,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.
@@ -1474,6 +1484,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)
{
@@ -1604,6 +1624,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");
}
@@ -1836,6 +1860,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 :
@@ -1844,6 +1873,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 0747e48138..8a76106ec6 100644
--- 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/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index ea90365c7f..62b29c48b5 100644
--- 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 deform tuple
+ functions, in milliseconds
+ </para></entry>
+ </row>
+
<row>
<entry role="catalog_table_entry"><para role="column_definition">
<structfield>jit_inlining_count</structfield> <type>bigint</type>
--
2.32.0
