[RFC] Add jit deform_counter

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?

Regards

Ian Barwick

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

Regards

Pavel

Hi

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

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

Regards

Pavel

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.

Hi

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

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.

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.

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?

Otherwise addressed the rest of commentaries, thanks.

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

Hi

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

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.

Hi

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

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

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.

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.

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

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.

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
}
},

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