Thread: [RFC] Add jit deform_counter

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?

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

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

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

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

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

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

> 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

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

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

> 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

> 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