[RFC] Add jit deform_counter

pavel.stehule@gmail.com

about 3 years ago

In reply to: Ian Lawrence Barwick (#2)

Re: [RFC] Add jit deform_counter

ne 11. 12. 2022 v 1:14 odesílatel Ian Lawrence Barwick <barwick@gmail.com>
napsal:

2022年6月12日(日) 18:14 Dmitry Dolgov <9erthalion6@gmail.com>:

Hi,

I've noticed that JIT performance counter generation_counter seems to

include

actions, relevant for both jit_expressions and jit_tuple_deforming

options. It

means one can't directly see what is the influence of jit_tuple_deforming
alone, which would be helpful when adjusting JIT options. To make it

better a

new counter can be introduced, does it make sense?

Hi Pavel

I see you are added as reviewer in the CF app; have you been able to take
a look
at this?

I hope so yes

Regards

Pavel

Show quoted text

Regards

Ian Barwick

http://cfbot.cputube.org/dmitry-dolgov.html

pavel.stehule@gmail.com

about 3 years ago

In reply to: Pavel Stehule (#3)

Re: [RFC] Add jit deform_counter

ne 11. 12. 2022 v 5:44 odesílatel Pavel Stehule <pavel.stehule@gmail.com>
napsal:

Hi

ne 11. 12. 2022 v 1:14 odesílatel Ian Lawrence Barwick <barwick@gmail.com>
napsal:

2022年6月12日(日) 18:14 Dmitry Dolgov <9erthalion6@gmail.com>:

Hi,

I've noticed that JIT performance counter generation_counter seems to

include

actions, relevant for both jit_expressions and jit_tuple_deforming

options. It

means one can't directly see what is the influence of

jit_tuple_deforming

alone, which would be helpful when adjusting JIT options. To make it

better a

new counter can be introduced, does it make sense?

Hi Pavel

I see you are added as reviewer in the CF app; have you been able to take
a look
at this?

I hope so yes

there are some problems with stability of regress tests

Regards

Pavel

Show quoted text

Regards

Pavel

Regards

Ian Barwick

9erthalion6@gmail.com

about 3 years ago

In reply to: Pavel Stehule (#4)

2 attachment(s)

Re: [RFC] Add jit deform_counter

On Sun, Dec 25, 2022 at 06:55:02PM +0100, Pavel Stehule wrote:
there are some problems with stability of regress tests

http://cfbot.cputube.org/dmitry-dolgov.html

Looks like this small change predates moving to meson, the attached
version should help.

Attachments:

v2-0001-Add-deform_counter.patchtext/plain; charset=us-asciiDownload

From 1b19af29b4a71e008d9d4ac7ca39d06dc89d6237 Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@gmail.com>
Date: Sat, 11 Jun 2022 11:54:40 +0200
Subject: [PATCH v2 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.31.1

v2-0002-Add-deform_counter-to-pg_stat_statements.patchtext/plain; charset=us-asciiDownload

From 072ce35efc53d9afbc9e7545a8065b5d2d63ebf0 Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@gmail.com>
Date: Sat, 11 Jun 2022 12:25:28 +0200
Subject: [PATCH v2 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            | 18 +++++
 6 files changed, 122 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..a2a68b15f2
--- /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_deform_count int8,
+    OUT jit_deform_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
+)
+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..6b4724d2fe 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++] = Float8GetDatumFast(tmp.jit_deform_time);
+			values[i++] = Int64GetDatumFast(tmp.jit_deform_count);
+		}
 
 		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..a378a2d752 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -420,6 +420,24 @@
       </para></entry>
      </row>
 
+     <row>
+      <entry role="catalog_table_entry"><para role="column_definition">
+       <structfield>jit_deform_count</structfield> <type>bigint</type>
+      </para>
+      <para>
+       Number of times tuples have been deformed
+      </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 deforming tuples, in milliseconds
+      </para></entry>
+     </row>
+
      <row>
       <entry role="catalog_table_entry"><para role="column_definition">
        <structfield>jit_inlining_count</structfield> <type>bigint</type>
-- 
2.31.1

pavel.stehule@gmail.com

about 3 years ago

In reply to: Dmitry Dolgov (#5)

Re: [RFC] Add jit deform_counter

po 2. 1. 2023 v 17:55 odesílatel Dmitry Dolgov <9erthalion6@gmail.com>
napsal:

On Sun, Dec 25, 2022 at 06:55:02PM +0100, Pavel Stehule wrote:
there are some problems with stability of regress tests

http://cfbot.cputube.org/dmitry-dolgov.html

Looks like this small change predates moving to meson, the attached
version should help.

The explain part is working, the part of pg_stat_statements doesn't

set jit_above_cost to 10;
set jit_optimize_above_cost to 10;
set jit_inline_above_cost to 10;

(2023-01-06 09:08:59) postgres=# explain analyze select
count(length(prosrc) > 0) from pg_proc;
┌────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN
│
╞════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
│ Aggregate (cost=154.10..154.11 rows=1 width=8) (actual
time=132.320..132.321 rows=1 loops=1) │
│ -> Seq Scan on pg_proc (cost=0.00..129.63 rows=3263 width=16) (actual
time=0.013..0.301 rows=3266 loops=1) │
│ Planning Time: 0.070 ms
│
│ JIT:
│
│ Functions: 3
│
│ Options: Inlining true, Optimization true, Expressions true, Deforming
true │
│ Timing: Generation 0.597 ms, Deforming 0.407 ms, Inlining 8.943 ms,
Optimization 79.403 ms, Emission 43.091 ms, Total 132.034 ms │
│ Execution Time: 132.986 ms
│
└────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(8 rows)

I see the result of deforming in explain analyze, but related values in
pg_stat_statements are 0.

Minimally, the values are assigned in wrong order

+       if (api_version >= PGSS_V1_11)
+       {
+           values[i++] = Float8GetDatumFast(tmp.jit_deform_time);
+           values[i++] = Int64GetDatumFast(tmp.jit_deform_count);
+       }

After reading the doc, I am confused what this metric means

+     <row>
+      <entry role="catalog_table_entry"><para role="column_definition">
+       <structfield>jit_deform_count</structfield> <type>bigint</type>
+      </para>
+      <para>
+       Number of times tuples have been deformed
+      </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 deforming tuples, in
milliseconds
+      </para></entry>
+     </row>

It is not clean so these times and these numbers are related just to the
compilation of the deforming process, not by own deforming.

Regards

Pavel

9erthalion6@gmail.com

about 3 years ago

In reply to: Pavel Stehule (#6)

Re: [RFC] Add jit deform_counter

On Fri, Jan 06, 2023 at 09:42:09AM +0100, Pavel Stehule wrote:
The explain part is working, the part of pg_stat_statements doesn't

set jit_above_cost to 10;
set jit_optimize_above_cost to 10;
set jit_inline_above_cost to 10;

(2023-01-06 09:08:59) postgres=# explain analyze select
count(length(prosrc) > 0) from pg_proc;
┌────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN
│
╞════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
│ Aggregate (cost=154.10..154.11 rows=1 width=8) (actual
time=132.320..132.321 rows=1 loops=1) │
│ -> Seq Scan on pg_proc (cost=0.00..129.63 rows=3263 width=16) (actual
time=0.013..0.301 rows=3266 loops=1) │
│ Planning Time: 0.070 ms
│
│ JIT:
│
│ Functions: 3
│
│ Options: Inlining true, Optimization true, Expressions true, Deforming
true │
│ Timing: Generation 0.597 ms, Deforming 0.407 ms, Inlining 8.943 ms,
Optimization 79.403 ms, Emission 43.091 ms, Total 132.034 ms │
│ Execution Time: 132.986 ms
│
└────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(8 rows)

I see the result of deforming in explain analyze, but related values in
pg_stat_statements are 0.

I'm not sure why, but pgss jit metrics are always nulls for explain
analyze queries. I have noticed this with surprise myself, when recently
was reviewing the lazy jit patch, but haven't yet figure out what is the
reason. Anyway, without "explain analyze" you'll get correct deforming
numbers in pgss.

Minimally, the values are assigned in wrong order

+       if (api_version >= PGSS_V1_11)
+       {
+           values[i++] = Float8GetDatumFast(tmp.jit_deform_time);
+           values[i++] = Int64GetDatumFast(tmp.jit_deform_count);
+       }

(facepalm) Yep, will fix the order.

After reading the doc, I am confused what this metric means

+     <row>
+      <entry role="catalog_table_entry"><para role="column_definition">
+       <structfield>jit_deform_count</structfield> <type>bigint</type>
+      </para>
+      <para>
+       Number of times tuples have been deformed
+      </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 deforming tuples, in
milliseconds
+      </para></entry>
+     </row>

It is not clean so these times and these numbers are related just to the
compilation of the deforming process, not by own deforming.

Good point, I need to formulate this more clearly.

pavel.stehule@gmail.com

about 3 years ago

In reply to: Dmitry Dolgov (#7)

Re: [RFC] Add jit deform_counter

so 7. 1. 2023 v 16:48 odesílatel Dmitry Dolgov <9erthalion6@gmail.com>
napsal:

On Fri, Jan 06, 2023 at 09:42:09AM +0100, Pavel Stehule wrote:
The explain part is working, the part of pg_stat_statements doesn't

set jit_above_cost to 10;
set jit_optimize_above_cost to 10;
set jit_inline_above_cost to 10;

(2023-01-06 09:08:59) postgres=# explain analyze select
count(length(prosrc) > 0) from pg_proc;

┌────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐

│ QUERY PLAN
│

╞════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡

│ Aggregate (cost=154.10..154.11 rows=1 width=8) (actual
time=132.320..132.321 rows=1 loops=1)

│

│ -> Seq Scan on pg_proc (cost=0.00..129.63 rows=3263 width=16)

(actual

time=0.013..0.301 rows=3266 loops=1) │
│ Planning Time: 0.070 ms
│
│ JIT:
│
│ Functions: 3
│
│ Options: Inlining true, Optimization true, Expressions true,

Deforming

true │
│ Timing: Generation 0.597 ms, Deforming 0.407 ms, Inlining 8.943 ms,
Optimization 79.403 ms, Emission 43.091 ms, Total 132.034 ms │
│ Execution Time: 132.986 ms
│

└────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘

(8 rows)

I see the result of deforming in explain analyze, but related values in
pg_stat_statements are 0.

I'm not sure why, but pgss jit metrics are always nulls for explain
analyze queries. I have noticed this with surprise myself, when recently
was reviewing the lazy jit patch, but haven't yet figure out what is the
reason. Anyway, without "explain analyze" you'll get correct deforming
numbers in pgss.

It was really strange, because I tested the queries without EXPLAIN ANALYZE
too, and new columns were always zero on my comp. Other jit columns were
filled. But I didn't do a deeper investigation.

Show quoted text

Minimally, the values are assigned in wrong order

+       if (api_version >= PGSS_V1_11)
+       {
+           values[i++] = Float8GetDatumFast(tmp.jit_deform_time);
+           values[i++] = Int64GetDatumFast(tmp.jit_deform_count);
+       }

(facepalm) Yep, will fix the order.

After reading the doc, I am confused what this metric means

+     <row>
+      <entry role="catalog_table_entry"><para role="column_definition">
+       <structfield>jit_deform_count</structfield> <type>bigint</type>
+      </para>
+      <para>
+       Number of times tuples have been deformed
+      </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 deforming tuples, in
milliseconds
+      </para></entry>
+     </row>

It is not clean so these times and these numbers are related just to the
compilation of the deforming process, not by own deforming.

Good point, I need to formulate this more clearly.

9erthalion6@gmail.com

about 3 years ago

In reply to: Pavel Stehule (#8)

2 attachment(s)

Re: [RFC] Add jit deform_counter

On Sat, Jan 07, 2023 at 07:09:11PM +0100, Pavel Stehule wrote:
so 7. 1. 2023 v 16:48 odesílatel Dmitry Dolgov <9erthalion6@gmail.com>
napsal:

On Fri, Jan 06, 2023 at 09:42:09AM +0100, Pavel Stehule wrote:
The explain part is working, the part of pg_stat_statements doesn't

set jit_above_cost to 10;
set jit_optimize_above_cost to 10;
set jit_inline_above_cost to 10;

(2023-01-06 09:08:59) postgres=# explain analyze select
count(length(prosrc) > 0) from pg_proc;

┌────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐

│ QUERY PLAN
│

╞════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡

│ Aggregate (cost=154.10..154.11 rows=1 width=8) (actual
time=132.320..132.321 rows=1 loops=1)

│

│ -> Seq Scan on pg_proc (cost=0.00..129.63 rows=3263 width=16)

(actual

time=0.013..0.301 rows=3266 loops=1) │
│ Planning Time: 0.070 ms
│
│ JIT:
│
│ Functions: 3
│
│ Options: Inlining true, Optimization true, Expressions true,

Deforming

true │
│ Timing: Generation 0.597 ms, Deforming 0.407 ms, Inlining 8.943 ms,
Optimization 79.403 ms, Emission 43.091 ms, Total 132.034 ms │
│ Execution Time: 132.986 ms
│

└────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘

(8 rows)

I see the result of deforming in explain analyze, but related values in
pg_stat_statements are 0.

I'm not sure why, but pgss jit metrics are always nulls for explain
analyze queries. I have noticed this with surprise myself, when recently
was reviewing the lazy jit patch, but haven't yet figure out what is the
reason. Anyway, without "explain analyze" you'll get correct deforming
numbers in pgss.

It was really strange, because I tested the queries without EXPLAIN ANALYZE
too, and new columns were always zero on my comp. Other jit columns were
filled. But I didn't do a deeper investigation.

Interesting. I've verified it once more with the query and the
parameters you've posted, got the following:

Maybe there is anything else special about how you run it?

Otherwise addressed the rest of commentaries, thanks.

Attachments:

v3-0001-Add-deform_counter.patchtext/x-diff; charset=us-asciiDownload

From 93d739e9258f79474df5644831a1f82fc97742dc Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@gmail.com>
Date: Sat, 11 Jun 2022 11:54:40 +0200
Subject: [PATCH v3 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

v3-0002-Add-deform_counter-to-pg_stat_statements.patchtext/x-diff; charset=us-asciiDownload

From 7bcd737fa3ae7976f619481b6ee8687cfe0fad2c Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@gmail.com>
Date: Sat, 11 Jun 2022 12:25:28 +0200
Subject: [PATCH v3 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..a2a68b15f2
--- /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_deform_count int8,
+    OUT jit_deform_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
+)
+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

#10

pavel.stehule@gmail.com

about 3 years ago

In reply to: Dmitry Dolgov (#9)

Re: [RFC] Add jit deform_counter

ne 8. 1. 2023 v 11:57 odesílatel Dmitry Dolgov <9erthalion6@gmail.com>
napsal:

On Sat, Jan 07, 2023 at 07:09:11PM +0100, Pavel Stehule wrote:
so 7. 1. 2023 v 16:48 odesílatel Dmitry Dolgov <9erthalion6@gmail.com>
napsal:

On Fri, Jan 06, 2023 at 09:42:09AM +0100, Pavel Stehule wrote:
The explain part is working, the part of pg_stat_statements doesn't

set jit_above_cost to 10;
set jit_optimize_above_cost to 10;
set jit_inline_above_cost to 10;

(2023-01-06 09:08:59) postgres=# explain analyze select
count(length(prosrc) > 0) from pg_proc;

┌────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐

│ QUERY

PLAN

│

╞════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡

│ Aggregate (cost=154.10..154.11 rows=1 width=8) (actual
time=132.320..132.321 rows=1 loops=1)

│

│ -> Seq Scan on pg_proc (cost=0.00..129.63 rows=3263 width=16)

(actual

time=0.013..0.301 rows=3266 loops=1) │
│ Planning Time: 0.070 ms
│
│ JIT:
│
│ Functions: 3
│
│ Options: Inlining true, Optimization true, Expressions true,

Deforming

true │
│ Timing: Generation 0.597 ms, Deforming 0.407 ms, Inlining 8.943

ms,

Optimization 79.403 ms, Emission 43.091 ms, Total 132.034 ms │
│ Execution Time: 132.986 ms
│

└────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘

(8 rows)

I see the result of deforming in explain analyze, but related values

in

pg_stat_statements are 0.

I'm not sure why, but pgss jit metrics are always nulls for explain
analyze queries. I have noticed this with surprise myself, when

recently

was reviewing the lazy jit patch, but haven't yet figure out what is

the

reason. Anyway, without "explain analyze" you'll get correct deforming
numbers in pgss.

It was really strange, because I tested the queries without EXPLAIN

ANALYZE

too, and new columns were always zero on my comp. Other jit columns were
filled. But I didn't do a deeper investigation.

Interesting. I've verified it once more with the query and the
parameters you've posted, got the following:

jit_functions | 3
jit_generation_time | 1.257522
jit_deform_count | 1
jit_deform_time | 10.381345
jit_inlining_count | 1
jit_inlining_time | 71.628168
jit_optimization_count | 1
jit_optimization_time | 48.146447
jit_emission_count | 1
jit_emission_time | 0.737822

Maybe there is anything else special about how you run it?

I hope not, but I'll see. I recheck updated patch

Show quoted text

Otherwise addressed the rest of commentaries, thanks.

#11

pavel.stehule@gmail.com

about 3 years ago

In reply to: Pavel Stehule (#10)

Re: [RFC] Add jit deform_counter

I'm not sure why, but pgss jit metrics are always nulls for explain

analyze queries. I have noticed this with surprise myself, when

recently

was reviewing the lazy jit patch, but haven't yet figure out what is

the

reason. Anyway, without "explain analyze" you'll get correct deforming
numbers in pgss.

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
│
└────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘

Regards

Pavel

#12

9erthalion6@gmail.com

almost 3 years ago

In reply to: Pavel Stehule (#11)

2 attachment(s)

Re: [RFC] Add jit deform_counter

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.

Attachments:

v4-0001-Add-deform_counter.patchtext/x-diff; charset=us-asciiDownload

From 93d739e9258f79474df5644831a1f82fc97742dc Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@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

v4-0002-Add-deform_counter-to-pg_stat_statements.patchtext/x-diff; charset=us-asciiDownload

From df5c3db54b9ce92bf6470ee1e8bd25fa4e90ecba Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@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

#13

pavel.stehule@gmail.com

almost 3 years ago

In reply to: Dmitry Dolgov (#12)

Re: [RFC] Add jit deform_counter

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.

I tested it and now looks well

check-world passed
make doc passed

I mark this patch as ready for committer

Regards

Pavel

#14

David Rowley

dgrowleyml@gmail.com

almost 3 years ago

In reply to: Dmitry Dolgov (#1)

Re: [RFC] Add jit deform_counter

On Sun, 12 Jun 2022 at 21:14, Dmitry Dolgov <9erthalion6@gmail.com> wrote:

I've noticed that JIT performance counter generation_counter seems to include
actions, relevant for both jit_expressions and jit_tuple_deforming options. It
means one can't directly see what is the influence of jit_tuple_deforming
alone, which would be helpful when adjusting JIT options. To make it better a
new counter can be introduced, does it make sense?

I'm not so sure about this idea. As of now, if I look at EXPLAIN
ANALYZE's JIT summary, the individual times add up to the total time.

If we add this deform time, then that's no longer going to be true as
the "Generation" time includes the newly added deform time.

master:
JIT:
Functions: 600
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 37.758 ms, Inlining 0.000 ms, Optimization 6.736
ms, Emission 172.244 ms, Total 216.738 ms

37.758 + 6.736 + 172.244 = 216.738

I think if I was a DBA wondering why JIT was taking so long, I'd
probably either be very astonished or I'd report a bug if I noticed
that all the individual component JIT times didn't add up to the total
time.

I don't think the solution is to subtract the deform time from the
generation time either.

Can't users just get this by looking at EXPLAIN ANALYZE with and
without jit_tuple_deforming?

David

#15

9erthalion6@gmail.com

almost 3 years ago

In reply to: David Rowley (#14)

Re: [RFC] Add jit deform_counter

On Wed, Mar 29, 2023 at 01:50:37PM +1300, David Rowley wrote:
On Sun, 12 Jun 2022 at 21:14, Dmitry Dolgov <9erthalion6@gmail.com> wrote:

I've noticed that JIT performance counter generation_counter seems to include
actions, relevant for both jit_expressions and jit_tuple_deforming options. It
means one can't directly see what is the influence of jit_tuple_deforming
alone, which would be helpful when adjusting JIT options. To make it better a
new counter can be introduced, does it make sense?

I'm not so sure about this idea. As of now, if I look at EXPLAIN
ANALYZE's JIT summary, the individual times add up to the total time.

If we add this deform time, then that's no longer going to be true as
the "Generation" time includes the newly added deform time.

master:
JIT:
Functions: 600
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 37.758 ms, Inlining 0.000 ms, Optimization 6.736
ms, Emission 172.244 ms, Total 216.738 ms

37.758 + 6.736 + 172.244 = 216.738

I think if I was a DBA wondering why JIT was taking so long, I'd
probably either be very astonished or I'd report a bug if I noticed
that all the individual component JIT times didn't add up to the total
time.

I don't think the solution is to subtract the deform time from the
generation time either.

Can't users just get this by looking at EXPLAIN ANALYZE with and
without jit_tuple_deforming?

It could be done this way, but then users need to know that tuple
deforming is included into generation time (I've skimmed through the
docs, there seems to be no direct statements about that, although it
could be guessed). At the same time I don't think it's very
user-friendly approach -- after all it could be the same for other
timings, i.e. only one counter for all JIT operations present,
expecting users to experiment how would it change if this or that option
will be different.

I agree about adding up to the total time though. What about changing
the format to something like this?

Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 37.758 ms (Deforming 1.234 ms), Inlining 0.000 ms, Optimization 6.736 ms, Emission 172.244 ms, Total 216.738 ms

This way it doesn't look like deforming timing is in the same category
as others, but rather a part of another value.

#16

9erthalion6@gmail.com

over 2 years ago

In reply to: Dmitry Dolgov (#15)

2 attachment(s)

Re: [RFC] Add jit deform_counter

On Fri, Mar 31, 2023 at 07:39:27PM +0200, Dmitry Dolgov wrote:

On Wed, Mar 29, 2023 at 01:50:37PM +1300, David Rowley wrote:
On Sun, 12 Jun 2022 at 21:14, Dmitry Dolgov <9erthalion6@gmail.com> wrote:

I've noticed that JIT performance counter generation_counter seems to include
actions, relevant for both jit_expressions and jit_tuple_deforming options. It
means one can't directly see what is the influence of jit_tuple_deforming
alone, which would be helpful when adjusting JIT options. To make it better a
new counter can be introduced, does it make sense?

I'm not so sure about this idea. As of now, if I look at EXPLAIN
ANALYZE's JIT summary, the individual times add up to the total time.

If we add this deform time, then that's no longer going to be true as
the "Generation" time includes the newly added deform time.

master:
JIT:
Functions: 600
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 37.758 ms, Inlining 0.000 ms, Optimization 6.736
ms, Emission 172.244 ms, Total 216.738 ms

37.758 + 6.736 + 172.244 = 216.738

I think if I was a DBA wondering why JIT was taking so long, I'd
probably either be very astonished or I'd report a bug if I noticed
that all the individual component JIT times didn't add up to the total
time.

I don't think the solution is to subtract the deform time from the
generation time either.

Can't users just get this by looking at EXPLAIN ANALYZE with and
without jit_tuple_deforming?

It could be done this way, but then users need to know that tuple
deforming is included into generation time (I've skimmed through the
docs, there seems to be no direct statements about that, although it
could be guessed). At the same time I don't think it's very
user-friendly approach -- after all it could be the same for other
timings, i.e. only one counter for all JIT operations present,
expecting users to experiment how would it change if this or that option
will be different.

I agree about adding up to the total time though. What about changing
the format to something like this?

Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 37.758 ms (Deforming 1.234 ms), Inlining 0.000 ms, Optimization 6.736 ms, Emission 172.244 ms, Total 216.738 ms

This way it doesn't look like deforming timing is in the same category
as others, but rather a part of another value.

Here is the patch with the proposed variation.

Attachments:

v5-0001-Add-deform_counter.patchtext/x-diff; charset=us-asciiDownload

From 963b9a31f2241cfff766544685709d813145f33a Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@gmail.com>
Date: Sat, 11 Jun 2022 11:54:40 +0200
Subject: [PATCH v5 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 5334c503e1..a134411209 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 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);
@@ -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),
+							 "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),
@@ -948,6 +950,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 fd1cf184c8..4da8fee20b 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 daefe66f40..e93b124863 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 14f2e36b37..ed381d8a1c 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

v5-0002-Add-deform_counter-to-pg_stat_statements.patchtext/x-diff; charset=us-asciiDownload

From 9d1b58fba2a2be6a786158496206b191d1edb9d6 Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@gmail.com>
Date: Sat, 11 Jun 2022 12:25:28 +0200
Subject: [PATCH v5 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 5578a9dd4e..eba4a95d91 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 3e3062ada9..15b7c7f2b0 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 68215bb2e3..ee2f60d6d8 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);
 
@@ -1402,6 +1407,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);
@@ -1464,7 +1473,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.
@@ -1476,6 +1486,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)
 {
@@ -1606,6 +1626,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");
 	}
@@ -1838,6 +1862,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 :
@@ -1846,6 +1875,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 b1214ee645..89ba13a7ed 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

#17

daniel@yesql.se

over 2 years ago

In reply to: Dmitry Dolgov (#16)

Re: [RFC] Add jit deform_counter

On 15 Apr 2023, at 16:40, Dmitry Dolgov <9erthalion6@gmail.com> wrote:

On Fri, Mar 31, 2023 at 07:39:27PM +0200, Dmitry Dolgov wrote:

On Wed, Mar 29, 2023 at 01:50:37PM +1300, David Rowley wrote:

I had a look at this patch today and I agree that it would be good to give the
user an easier way to gain insights into this since we make it configurable.

If we add this deform time, then that's no longer going to be true as
the "Generation" time includes the newly added deform time.

master:
JIT:
Functions: 600
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 37.758 ms, Inlining 0.000 ms, Optimization 6.736
ms, Emission 172.244 ms, Total 216.738 ms

37.758 + 6.736 + 172.244 = 216.738

I think if I was a DBA wondering why JIT was taking so long, I'd
probably either be very astonished or I'd report a bug if I noticed
that all the individual component JIT times didn't add up to the total
time.

While true, the current EXPLAIN output for JIT isn't without confusing details
as it is. The example above has "Optimization false" and "Optimization 6.736",
and it takes reading the very last line on a docs page commenting on an example
to understand why.

I don't think the solution is to subtract the deform time from the
generation time either.

Agreed.

I agree about adding up to the total time though. What about changing
the format to something like this?

Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 37.758 ms (Deforming 1.234 ms), Inlining 0.000 ms, Optimization 6.736 ms, Emission 172.244 ms, Total 216.738 ms

This way it doesn't look like deforming timing is in the same category
as others, but rather a part of another value.

I think this is a good trade-off, but the wording "deforming" makes it sound
like it's the act of tuple deforming and not that of compiling tuple deforming
code. I don't have too many better suggestions, but maybe "Deform" is enough
to differentiate it?

Here is the patch with the proposed variation.

This version still leaves non-text EXPLAIN formats with timing which doesn't
add up. Below are JSON and XML examples:

"Timing": { +
"Generation": 0.564, +
"Deforming": 0.111, +
"Inlining": 0.000, +
"Optimization": 0.358, +
"Emission": 6.505, +
"Total": 7.426 +
} +

<Timing> +
<Generation>0.598</Generation> +
<Deforming>0.117</Deforming> +
<Inlining>0.000</Inlining> +
<Optimization>0.367</Optimization> +
<Emission>6.400</Emission> +
<Total>7.365</Total> +
</Timing> +

It's less obvious how the additional level of details should be represented
here.

+     int64       jit_deform_count;   /* number of times deform time has been >
+                                      * 0 */
While not a new problem with this patch, the comments on this struct yields
pretty awkward reflows by pgindent.  I wonder if we should make a separate pass
over this at some point to clean it up?

The patch also fails to update doc/src/sgml/jit.sgml with the new EXPLAIN
output.

--
Daniel Gustafsson

#18

9erthalion6@gmail.com

over 2 years ago

In reply to: Daniel Gustafsson (#17)

Re: [RFC] Add jit deform_counter

On Tue, Jul 18, 2023, 3:32 PM Daniel Gustafsson <daniel@yesql.se> wrote

Here is the patch with the proposed variation.

This version still leaves non-text EXPLAIN formats with timing which

doesn't

add up. Below are JSON and XML examples:

Good point. For the structured formats it should be represented via a nested
level. I'll try to do this and other proposed changes as soon as I'll get
back.

#19

9erthalion6@gmail.com

over 2 years ago

In reply to: Dmitry Dolgov (#18)

2 attachment(s)

Re: [RFC] Add jit deform_counter

On Wed, Jul 19, 2023 at 05:18:29PM +0200, Dmitry Dolgov wrote:

On Tue, Jul 18, 2023, 3:32 PM Daniel Gustafsson <daniel@yesql.se> wrote

Here is the patch with the proposed variation.

This version still leaves non-text EXPLAIN formats with timing which

doesn't

add up. Below are JSON and XML examples:

Good point. For the structured formats it should be represented via a nested
level. I'll try to do this and other proposed changes as soon as I'll get
back.

And here is it. The json version of EXPLAIN now looks like this:

"JIT": {
[...]
"Timing": {
"Generation": {
"Deform": 0.000,
"Total": 0.205
},
"Inlining": 0.065,
"Optimization": 2.465,
"Emission": 2.337,
"Total": 5.072
}
},

Attachments:

v6-0001-Add-deform_counter.patchtext/x-diff; charset=us-asciiDownload

From 692ec7fb6c8132626e3597b753510dd1648ebeed Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@gmail.com>
Date: Sat, 11 Jun 2022 11:54:40 +0200
Subject: [PATCH v6 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.
---
 doc/src/sgml/jit.sgml               |  2 +-
 src/backend/commands/explain.c      | 14 +++++++++++---
 src/backend/jit/jit.c               |  1 +
 src/backend/jit/llvm/llvmjit_expr.c |  6 ++++++
 src/include/jit/jit.h               |  3 +++
 5 files changed, 22 insertions(+), 4 deletions(-)

diff --git a/doc/src/sgml/jit.sgml b/doc/src/sgml/jit.sgml
index 998c972e8ba..1921557cb82 100644
--- 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/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 8570b14f621..78cced83931 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 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);
@@ -914,14 +915,15 @@ ExplainPrintJIT(ExplainState *es, int jit_flags, JitInstrumentation *ji)
 						 "Inlining", jit_flags & PGJIT_INLINE ? "true" : "false",
 						 "Optimization", jit_flags & PGJIT_OPT3 ? "true" : "false",
 						 "Expressions", jit_flags & PGJIT_EXPR ? "true" : "false",
-						 "Deforming", jit_flags & PGJIT_DEFORM ? "true" : "false");
+						 "Deform", jit_flags & PGJIT_DEFORM ? "true" : "false");
 
 		if (es->analyze && es->timing)
 		{
 			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 fd1cf184c8e..4da8fee20b4 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 00d7b8110b9..2ac335e2389 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 14f2e36b371..ed381d8a1c8 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;
 

base-commit: 638d42a3c52081cf4882520f0622161bad69b40f
-- 
2.32.0

v6-0002-Add-deform_counter-to-pg_stat_statements.patchtext/x-diff; charset=us-asciiDownload

From 83d57c4b321579d6d01936b1db4149c23349abe6 Mon Sep 17 00:00:00 2001
From: Dmitrii Dolgov <9erthalion6@gmail.com>
Date: Sat, 11 Jun 2022 12:25:28 +0200
Subject: [PATCH v6 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   | 35 +++++++++-
 .../pg_stat_statements.control                |  2 +-
 doc/src/sgml/pgstatstatements.sgml            | 19 +++++
 6 files changed, 124 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 5578a9dd4e3..eba4a95d91a 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 3e3062ada9c..15b7c7f2b02 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 00000000000..20bae804582
--- /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 55b957d2515..5ea56dcbdaf 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,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 */
@@ -313,6 +318,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);
 
@@ -1402,6 +1408,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);
@@ -1464,7 +1474,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.
@@ -1476,6 +1487,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)
 {
@@ -1606,6 +1627,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");
 	}
@@ -1838,6 +1863,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 :
@@ -1846,6 +1876,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 0747e481383..8a76106ec67 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 b1214ee6453..89ba13a7ed5 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

#20

daniel@yesql.se

over 2 years ago

In reply to: Dmitry Dolgov (#19)

Re: [RFC] Add jit deform_counter

On 14 Aug 2023, at 16:36, Dmitry Dolgov <9erthalion6@gmail.com> wrote:

And here is it. The json version of EXPLAIN now looks like this:

"JIT": {
[...]
"Timing": {
"Generation": {
"Deform": 0.000,
"Total": 0.205
},
"Inlining": 0.065,
"Optimization": 2.465,
"Emission": 2.337,
"Total": 5.072
}
},

I've gone over this version of the patch and I think it's ready to go in. I'm
marking this Ready for Committer and will go ahead with it shortly barring any
objections.

--
Daniel Gustafsson

#21

daniel@yesql.se

over 2 years ago

In reply to: Daniel Gustafsson (#20)

Re: [RFC] Add jit deform_counter

On 5 Sep 2023, at 16:37, Daniel Gustafsson <daniel@yesql.se> wrote:

I've gone over this version of the patch and I think it's ready to go in. I'm
marking this Ready for Committer and will go ahead with it shortly barring any
objections.

Pushed, after another round of review with some minor fixes.

--
Daniel Gustafsson

#22

9erthalion6@gmail.com

over 2 years ago

In reply to: Daniel Gustafsson (#21)

Re: [RFC] Add jit deform_counter

On Fri, Sep 08, 2023 at 03:34:42PM +0200, Daniel Gustafsson wrote:

On 5 Sep 2023, at 16:37, Daniel Gustafsson <daniel@yesql.se> wrote:

I've gone over this version of the patch and I think it's ready to go in. I'm
marking this Ready for Committer and will go ahead with it shortly barring any
objections.

Pushed, after another round of review with some minor fixes.

Thanks!

#23

Nazir Bilal Yavuz

byavuz81@gmail.com

over 2 years ago

In reply to: Dmitry Dolgov (#22)

1 attachment(s)

Re: [RFC] Add jit deform_counter

Hi,

On Fri, 8 Sept 2023 at 20:22, Dmitry Dolgov <9erthalion6@gmail.com> wrote:

On Fri, Sep 08, 2023 at 03:34:42PM +0200, Daniel Gustafsson wrote:

On 5 Sep 2023, at 16:37, Daniel Gustafsson <daniel@yesql.se> wrote:

I've gone over this version of the patch and I think it's ready to go in. I'm
marking this Ready for Committer and will go ahead with it shortly barring any
objections.

Pushed, after another round of review with some minor fixes.

I realized that pg_stat_statements is bumped to 1.11 with this patch
but oldextversions test is not updated. So, I attached a patch for
updating oldextversions.

Regards,
Nazir Bilal Yavuz
Microsoft

Attachments:

v1-0001-Update-oldextversions-test-for-pg_stat_statements.patchtext/x-diff; charset=US-ASCII; name=v1-0001-Update-oldextversions-test-for-pg_stat_statements.patchDownload

From d3c63a5d68ed76257d110db6377bd3ec859d65a4 Mon Sep 17 00:00:00 2001
From: Nazir Bilal Yavuz <byavuz81@gmail.com>
Date: Thu, 12 Oct 2023 14:44:38 +0300
Subject: [PATCH v1] Update oldextversions test for pg_stat_statements 1.11

pg_stat_statements 1.11 is introduced at 5a3423ad8e but oldextversions
test is not updated. Add missing pg_stat_statements 1.11 test case to
oldextversions test.
---
 .../expected/oldextversions.out               | 58 +++++++++++++++++++
 .../pg_stat_statements/sql/oldextversions.sql |  5 ++
 2 files changed, 63 insertions(+)

diff --git a/contrib/pg_stat_statements/expected/oldextversions.out b/contrib/pg_stat_statements/expected/oldextversions.out
index efb2049ecff..64982aad601 100644
--- a/contrib/pg_stat_statements/expected/oldextversions.out
+++ b/contrib/pg_stat_statements/expected/oldextversions.out
@@ -250,4 +250,62 @@ SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
  t
 (1 row)
 
+-- New views for pg_stat_statements in 1.11
+AlTER EXTENSION pg_stat_statements UPDATE TO '1.11';
+\d pg_stat_statements
+                      View "public.pg_stat_statements"
+         Column         |       Type       | Collation | Nullable | Default 
+------------------------+------------------+-----------+----------+---------
+ userid                 | oid              |           |          | 
+ dbid                   | oid              |           |          | 
+ toplevel               | boolean          |           |          | 
+ queryid                | bigint           |           |          | 
+ query                  | text             |           |          | 
+ plans                  | bigint           |           |          | 
+ total_plan_time        | double precision |           |          | 
+ min_plan_time          | double precision |           |          | 
+ max_plan_time          | double precision |           |          | 
+ mean_plan_time         | double precision |           |          | 
+ stddev_plan_time       | double precision |           |          | 
+ calls                  | bigint           |           |          | 
+ total_exec_time        | double precision |           |          | 
+ min_exec_time          | double precision |           |          | 
+ max_exec_time          | double precision |           |          | 
+ mean_exec_time         | double precision |           |          | 
+ stddev_exec_time       | double precision |           |          | 
+ rows                   | bigint           |           |          | 
+ shared_blks_hit        | bigint           |           |          | 
+ shared_blks_read       | bigint           |           |          | 
+ shared_blks_dirtied    | bigint           |           |          | 
+ shared_blks_written    | bigint           |           |          | 
+ local_blks_hit         | bigint           |           |          | 
+ local_blks_read        | bigint           |           |          | 
+ local_blks_dirtied     | bigint           |           |          | 
+ local_blks_written     | bigint           |           |          | 
+ temp_blks_read         | bigint           |           |          | 
+ temp_blks_written      | bigint           |           |          | 
+ blk_read_time          | double precision |           |          | 
+ blk_write_time         | double precision |           |          | 
+ temp_blk_read_time     | double precision |           |          | 
+ temp_blk_write_time    | double precision |           |          | 
+ wal_records            | bigint           |           |          | 
+ wal_fpi                | bigint           |           |          | 
+ wal_bytes              | numeric          |           |          | 
+ jit_functions          | bigint           |           |          | 
+ jit_generation_time    | double precision |           |          | 
+ jit_inlining_count     | bigint           |           |          | 
+ jit_inlining_time      | double precision |           |          | 
+ jit_optimization_count | bigint           |           |          | 
+ jit_optimization_time  | double precision |           |          | 
+ jit_emission_count     | bigint           |           |          | 
+ jit_emission_time      | double precision |           |          | 
+ jit_deform_count       | bigint           |           |          | 
+ jit_deform_time        | double precision |           |          | 
+
+SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
+ has_data 
+----------
+ t
+(1 row)
+
 DROP EXTENSION pg_stat_statements;
diff --git a/contrib/pg_stat_statements/sql/oldextversions.sql b/contrib/pg_stat_statements/sql/oldextversions.sql
index e2a83106d4c..2435c0c576e 100644
--- a/contrib/pg_stat_statements/sql/oldextversions.sql
+++ b/contrib/pg_stat_statements/sql/oldextversions.sql
@@ -48,4 +48,9 @@ AlTER EXTENSION pg_stat_statements UPDATE TO '1.10';
 \d pg_stat_statements
 SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
 
+-- New views for pg_stat_statements in 1.11
+AlTER EXTENSION pg_stat_statements UPDATE TO '1.11';
+\d pg_stat_statements
+SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
+
 DROP EXTENSION pg_stat_statements;
-- 
2.42.0

#24

daniel@yesql.se

over 2 years ago

In reply to: Nazir Bilal Yavuz (#23)

Re: [RFC] Add jit deform_counter

On 12 Oct 2023, at 15:37, Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:

Hi,

On Fri, 8 Sept 2023 at 20:22, Dmitry Dolgov <9erthalion6@gmail.com> wrote:

On Fri, Sep 08, 2023 at 03:34:42PM +0200, Daniel Gustafsson wrote:

On 5 Sep 2023, at 16:37, Daniel Gustafsson <daniel@yesql.se> wrote:

I've gone over this version of the patch and I think it's ready to go in. I'm
marking this Ready for Committer and will go ahead with it shortly barring any
objections.

Pushed, after another round of review with some minor fixes.

I realized that pg_stat_statements is bumped to 1.11 with this patch
but oldextversions test is not updated. So, I attached a patch for
updating oldextversions.

Thanks for the patch, that was an oversight in the original commit for this.
From a quick look it seems correct, I'll have another look later today and will
then apply it.

--
Daniel Gustafsson

#25