Horton

Thread

Commits

  1. Update oldextversions test for pg_stat_statements 1.11

  2. Add JIT deform_counter

  1. [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2022-06-12T09:12:53Z

    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?

  2. Re: [RFC] Add jit deform_counter

    Ian Lawrence Barwick <barwick@gmail.com> — 2022-12-11T00:14:42Z

    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

  3. Re: [RFC] Add jit deform_counter

    Pavel Stehule <pavel.stehule@gmail.com> — 2022-12-11T04:44:54Z

    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


>
> Regards
>
> Ian Barwick
>

  4. Re: [RFC] Add jit deform_counter

    Pavel Stehule <pavel.stehule@gmail.com> — 2022-12-25T17:55:02Z

    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


> Regards
>
> Pavel
>
>
>>
>> Regards
>>
>> Ian Barwick
>>
>

  5. Re: [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2023-01-02T16:55:50Z

    > 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.

  6. Re: [RFC] Add jit deform_counter

    Pavel Stehule <pavel.stehule@gmail.com> — 2023-01-06T08:42:09Z

    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

  7. Re: [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2023-01-07T15:47:05Z

    > 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.

  8. Re: [RFC] Add jit deform_counter

    Pavel Stehule <pavel.stehule@gmail.com> — 2023-01-07T18:09:11Z

    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.



> > 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.
>

  9. Re: [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2023-01-08T10:56:01Z

    > 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.

  10. Re: [RFC] Add jit deform_counter

    Pavel Stehule <pavel.stehule@gmail.com> — 2023-01-08T11:00:12Z

    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



>
> Otherwise addressed the rest of commentaries, thanks.
>

  11. Re: [RFC] Add jit deform_counter

    Pavel Stehule <pavel.stehule@gmail.com> — 2023-01-08T20:06:33Z

    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

  12. Re: [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2023-01-15T13:57:37Z

    > 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.

  13. Re: [RFC] Add jit deform_counter

    Pavel Stehule <pavel.stehule@gmail.com> — 2023-01-15T16:47:00Z

    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

  14. Re: [RFC] Add jit deform_counter

    David Rowley <dgrowleyml@gmail.com> — 2023-03-29T00:50:37Z

    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. Re: [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2023-03-31T17:39:27Z

    > 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. Re: [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2023-04-15T14:40:57Z

    > 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.

  17. Re: [RFC] Add jit deform_counter

    Daniel Gustafsson <daniel@yesql.se> — 2023-07-18T13:32:43Z

    > 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. Re: [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2023-07-19T15:18:29Z

    > 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. Re: [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2023-08-14T14:36:42Z

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

  20. Re: [RFC] Add jit deform_counter

    Daniel Gustafsson <daniel@yesql.se> — 2023-09-05T14:37:20Z

    > 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. Re: [RFC] Add jit deform_counter

    Daniel Gustafsson <daniel@yesql.se> — 2023-09-08T13:34:42Z

    > 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. Re: [RFC] Add jit deform_counter

    Dmitry Dolgov <9erthalion6@gmail.com> — 2023-09-08T13:45:27Z

    > 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. Re: [RFC] Add jit deform_counter

    Nazir Bilal Yavuz <byavuz81@gmail.com> — 2023-10-12T13:37:36Z

    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

  24. Re: [RFC] Add jit deform_counter

    Daniel Gustafsson <daniel@yesql.se> — 2023-10-12T13:40:00Z

    > 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. Re: [RFC] Add jit deform_counter

    Daniel Gustafsson <daniel@yesql.se> — 2023-10-13T12:20:52Z

    > On 12 Oct 2023, at 15:40, Daniel Gustafsson <daniel@yesql.se> wrote:
>> On 12 Oct 2023, at 15:37, Nazir Bilal Yavuz <byavuz81@gmail.com> wrote:

>> 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.

Applied, thanks!

--
Daniel Gustafsson