Thread: Expose JIT counters/timing in pg_stat_statements
Here's a patch to add the sum of timings for JIT counters to pg_stat_statements, as a way to follow-up on if JIT is doing a good or a bad job in a configuration. I decided to only store the total time for the timings, since there are 4 different timings and storing max/min/etc for each one of them would lead to a bit too much data. This can of course be reconsidered, but I think that's a reasonable tradeoff. Another option I guess could be to store the max/min/etc, but only store for the total jit time instead of for each individual one. Maybe that'd actually be more useful? -- Magnus Hagander Me: https://www.hagander.net/ Work: https://www.redpill-linpro.com/
Attachment
Hi, On Fri, Feb 25, 2022 at 02:06:29PM +0100, Magnus Hagander wrote: > Here's a patch to add the sum of timings for JIT counters to > pg_stat_statements, as a way to follow-up on if JIT is doing a good or > a bad job in a configuration. +1, it seems like something quite useful. > I decided to only store the total time for the timings, since there > are 4 different timings and storing max/min/etc for each one of them > would lead to a bit too much data. This can of course be reconsidered, > but I think that's a reasonable tradeoff. I think the cumulated total time is enough. Looking at the patch, I think we should also cumulate the number of time jit was triggered, and probably the same for each other main operation (optimization and inlining). Otherwise the values may be wrong and look artificially low.
On Fri, Feb 25, 2022 at 2:33 PM Julien Rouhaud <rjuju123@gmail.com> wrote: > > Hi, > > On Fri, Feb 25, 2022 at 02:06:29PM +0100, Magnus Hagander wrote: > > Here's a patch to add the sum of timings for JIT counters to > > pg_stat_statements, as a way to follow-up on if JIT is doing a good or > > a bad job in a configuration. > > +1, it seems like something quite useful. Given the amount of time often spent debugging JIT -- getting more insight is going to make it easier to tune it instead of like what unfortunately many people do and just turn it off.. > > I decided to only store the total time for the timings, since there > > are 4 different timings and storing max/min/etc for each one of them > > would lead to a bit too much data. This can of course be reconsidered, > > but I think that's a reasonable tradeoff. > > I think the cumulated total time is enough. Looking at the patch, I think we > should also cumulate the number of time jit was triggered, and > probably the same for each other main operation (optimization and inlining). > Otherwise the values may be wrong and look artificially low. So just to be clear, you're basically thinking: jit_count = count of entries where jit_functions>0 jit_functions = <same as now> jit_optimizatinos = count of entries where time spent on jit_optimizations > 0 etc? So we count the times with min/max like other times for the total one, but instead add a counter for each of the details? -- Magnus Hagander Me: https://www.hagander.net/ Work: https://www.redpill-linpro.com/
On Fri, Feb 25, 2022 at 04:19:27PM +0100, Magnus Hagander wrote: > > So just to be clear, you're basically thinking: > > jit_count = count of entries where jit_functions>0 > jit_functions = <same as now> > jit_optimizatinos = count of entries where time spent on jit_optimizations > 0 > > etc? Yes exactly, so 3 new fields on top of the one you already added. > So we count the times with min/max like other times for the total one, > but instead add a counter for each of the details? I don't understand this one. Did you mean we *don't* count times with min/max? If that's the case then yes :)
On Fri, Feb 25, 2022 at 4:40 PM Julien Rouhaud <rjuju123@gmail.com> wrote: > > On Fri, Feb 25, 2022 at 04:19:27PM +0100, Magnus Hagander wrote: > > > > So just to be clear, you're basically thinking: > > > > jit_count = count of entries where jit_functions>0 > > jit_functions = <same as now> > > jit_optimizatinos = count of entries where time spent on jit_optimizations > 0 > > > > etc? > > Yes exactly, so 3 new fields on top of the one you already added. > > > So we count the times with min/max like other times for the total one, > > but instead add a counter for each of the details? > > I don't understand this one. Did you mean we *don't* count times with min/max? > If that's the case then yes :) Hmm. Yeah, that was a bit unclear. I mean we track total time with min/max, and detailed time not at all. For details, we only track count, not time. -- Magnus Hagander Me: https://www.hagander.net/ Work: https://www.redpill-linpro.com/
On Fri, Feb 25, 2022 at 4:41 PM Magnus Hagander <magnus@hagander.net> wrote: > > On Fri, Feb 25, 2022 at 4:40 PM Julien Rouhaud <rjuju123@gmail.com> wrote: > > > > On Fri, Feb 25, 2022 at 04:19:27PM +0100, Magnus Hagander wrote: > > > > > > So just to be clear, you're basically thinking: > > > > > > jit_count = count of entries where jit_functions>0 > > > jit_functions = <same as now> > > > jit_optimizatinos = count of entries where time spent on jit_optimizations > 0 > > > > > > etc? > > > > Yes exactly, so 3 new fields on top of the one you already added. > > > > > So we count the times with min/max like other times for the total one, > > > but instead add a counter for each of the details? > > > > I don't understand this one. Did you mean we *don't* count times with min/max? > > If that's the case then yes :) > > Hmm. Yeah, that was a bit unclear. I mean we track total time with > min/max, and detailed time not at all. For details, we only track > count, not time. Per some off-list discussion with Julien, we have clearly been talking in slightly different terms. So let's summarize the options into what theÿ́d actually be: Option 0: what is int he patch now Option 1: jit_count - number of executions using jit total_jit_time - for sum of functions+inlining+optimization+emission time min_jit_time - for sum of functions+inlining+optimization+emission time max_jit_time - for sum of functions+inlining+optimization+emission time mean_jit_time - for sum of functions+inlining+optimization+emission time stddev_jit_time - for sum of functions+inlining+optimization+emission time jit_functions - number of functions jit_inlining_count - number of executions where inlining happened jit_optimization_count - number of executions where optimization happened jit_emission_count - number of executions where emission happened Option 2: jit_count jit_functions jit_generation_time jit_inlining_count jit_inlining_time jit_optimization_count jit_optimization_time jit_emission_count jit_emission_time (We can bikeshed on the exact names of the fields once we have decided which option is preferred) -- Magnus Hagander Me: https://www.hagander.net/ Work: https://www.redpill-linpro.com/
> On Fri, Feb 25, 2022 at 04:19:27PM +0100, Magnus Hagander wrote: > On Fri, Feb 25, 2022 at 2:33 PM Julien Rouhaud <rjuju123@gmail.com> wrote: > > > > Hi, > > > > On Fri, Feb 25, 2022 at 02:06:29PM +0100, Magnus Hagander wrote: > > > Here's a patch to add the sum of timings for JIT counters to > > > pg_stat_statements, as a way to follow-up on if JIT is doing a good or > > > a bad job in a configuration. > > > > +1, it seems like something quite useful. > > Given the amount of time often spent debugging JIT -- getting more > insight is going to make it easier to tune it instead of like what > unfortunately many people do and just turn it off.. Indeed, sounds convenient, although I wonder how exactly one would use it to tune JIT? I'm curious, because I got used to situations when one single long query takes much longer than expected due to JIT issues -- but it seems the target of this patch are situations when there are a lot of long queries using JIT, and it's easier to analyze them via pgss? > > > I decided to only store the total time for the timings, since there > > > are 4 different timings and storing max/min/etc for each one of them > > > would lead to a bit too much data. This can of course be reconsidered, > > > but I think that's a reasonable tradeoff. > > > > I think the cumulated total time is enough. Looking at the patch, I think we > > should also cumulate the number of time jit was triggered, and > > probably the same for each other main operation (optimization and inlining). > > Otherwise the values may be wrong and look artificially low. > > So just to be clear, you're basically thinking: > > jit_count = count of entries where jit_functions>0 > jit_functions = <same as now> > jit_optimizatinos = count of entries where time spent on jit_optimizations > 0 One interesting not-very-relevant for the patch thing I've noticed while reading it, is that there seems to be no way to find out what fraction of time jit_tuple_deforming is taking alone, it's sort of merged together with jit_expressions in generation_counter.
On Fri, Feb 25, 2022 at 05:38:45PM +0100, Magnus Hagander wrote: > > Per some off-list discussion with Julien, we have clearly been talking > in slightly different terms. So let's summarize the options into what > theÿ́d actually be: > > Option 0: what is int he patch now > > Option 1: > jit_count - number of executions using jit > total_jit_time - for sum of functions+inlining+optimization+emission time > min_jit_time - for sum of functions+inlining+optimization+emission time > max_jit_time - for sum of functions+inlining+optimization+emission time > mean_jit_time - for sum of functions+inlining+optimization+emission time > stddev_jit_time - for sum of functions+inlining+optimization+emission time > jit_functions - number of functions > jit_inlining_count - number of executions where inlining happened > jit_optimization_count - number of executions where optimization happened > jit_emission_count - number of executions where emission happened > > Option 2: > jit_count > jit_functions > jit_generation_time > jit_inlining_count > jit_inlining_time > jit_optimization_count > jit_optimization_time > jit_emission_count > jit_emission_time I'm for option 2, I think it's important to have the timing details for inlining and optimization and be able to compute correct stats.
On 25.02.22 14:06, Magnus Hagander wrote: > + OUT jit_generation_time float8, > + OUT jit_inlining_time float8, > + OUT jit_optimization_time float8, > + OUT jit_emission_time float8 Perhaps those should be of type interval?
On Mon, Feb 28, 2022 at 05:00:05PM +0100, Peter Eisentraut wrote: > On 25.02.22 14:06, Magnus Hagander wrote: > > + OUT jit_generation_time float8, > > + OUT jit_inlining_time float8, > > + OUT jit_optimization_time float8, > > + OUT jit_emission_time float8 > > Perhaps those should be of type interval? The rest of the "time" fields are declared as float8, so I think it's better to keep things consistent. And changing the type of existing fields, even in a major version, seems like a bit too much trouble.
On Fri, Feb 25, 2022 at 5:40 PM Dmitry Dolgov <9erthalion6@gmail.com> wrote: > > > On Fri, Feb 25, 2022 at 04:19:27PM +0100, Magnus Hagander wrote: > > On Fri, Feb 25, 2022 at 2:33 PM Julien Rouhaud <rjuju123@gmail.com> wrote: > > > > > > Hi, > > > > > > On Fri, Feb 25, 2022 at 02:06:29PM +0100, Magnus Hagander wrote: > > > > Here's a patch to add the sum of timings for JIT counters to > > > > pg_stat_statements, as a way to follow-up on if JIT is doing a good or > > > > a bad job in a configuration. > > > > > > +1, it seems like something quite useful. > > > > Given the amount of time often spent debugging JIT -- getting more > > insight is going to make it easier to tune it instead of like what > > unfortunately many people do and just turn it off.. > > Indeed, sounds convenient, although I wonder how exactly one would use it > to tune JIT? I'm curious, because I got used to situations when one > single long query takes much longer than expected due to JIT issues -- > but it seems the target of this patch are situations when there are a > lot of long queries using JIT, and it's easier to analyze them via pgss? "tune jit" might be a bad wording. But tune the values of jit_above_cost for example, and in particular figure specific queries where it needs adapting. And like most things with pgss, just getting proper insight into what your system is actually doing and spending it's time on. It might be spending a huge amount of time on JITting many relatively simple queries, and it may still be a win -- but this lets you know that this was the case. > > > > I decided to only store the total time for the timings, since there > > > > are 4 different timings and storing max/min/etc for each one of them > > > > would lead to a bit too much data. This can of course be reconsidered, > > > > but I think that's a reasonable tradeoff. > > > > > > I think the cumulated total time is enough. Looking at the patch, I think we > > > should also cumulate the number of time jit was triggered, and > > > probably the same for each other main operation (optimization and inlining). > > > Otherwise the values may be wrong and look artificially low. > > > > So just to be clear, you're basically thinking: > > > > jit_count = count of entries where jit_functions>0 > > jit_functions = <same as now> > > jit_optimizatinos = count of entries where time spent on jit_optimizations > 0 > > One interesting not-very-relevant for the patch thing I've noticed while > reading it, is that there seems to be no way to find out what fraction > of time jit_tuple_deforming is taking alone, it's sort of merged > together with jit_expressions in generation_counter. That's missing att a deeper level though, right? We don't have it in EXPLAIN ANALYZE either. So while I agree that's useful, I think that's the job of another patch, and these two sets of counters should be the same. -- Magnus Hagander Me: https://www.hagander.net/ Work: https://www.redpill-linpro.com/
On Fri, Feb 25, 2022 at 5:43 PM Julien Rouhaud <rjuju123@gmail.com> wrote: > > On Fri, Feb 25, 2022 at 05:38:45PM +0100, Magnus Hagander wrote: > > > > Per some off-list discussion with Julien, we have clearly been talking > > in slightly different terms. So let's summarize the options into what > > theÿ́d actually be: > > > > Option 0: what is int he patch now > > > > Option 1: > > jit_count - number of executions using jit > > total_jit_time - for sum of functions+inlining+optimization+emission time > > min_jit_time - for sum of functions+inlining+optimization+emission time > > max_jit_time - for sum of functions+inlining+optimization+emission time > > mean_jit_time - for sum of functions+inlining+optimization+emission time > > stddev_jit_time - for sum of functions+inlining+optimization+emission time > > jit_functions - number of functions > > jit_inlining_count - number of executions where inlining happened > > jit_optimization_count - number of executions where optimization happened > > jit_emission_count - number of executions where emission happened > > > > Option 2: > > jit_count > > jit_functions > > jit_generation_time > > jit_inlining_count > > jit_inlining_time > > jit_optimization_count > > jit_optimization_time > > jit_emission_count > > jit_emission_time > > I'm for option 2, I think it's important to have the timing details for > inlining and optimization and be able to compute correct stats. I wonder if there might be an interesting middle ground, or if that is making it too much. That is, we could have an Option 3: jit_count total_jit_time - for sum of functions+inlining+optimization+emission time min_jit_time - for sum of functions+inlining+optimization+emission time max_jit_time - for sum of functions+inlining+optimization+emission time mean_jit_time - for sum of functions+inlining+optimization+emission time stddev_jit_time - for sum of functions+inlining+optimization+emission time jit_functions jit_generation_time jit_inlining_count jit_inlining_time jit_optimization_count jit_optimization_time jit_emission_count jit_emission_time That is, we'd get the more detailed timings across the total time, but not on the details. But that might be overkill. But -- here's an updated patched based on Option 2. -- Magnus Hagander Me: https://www.hagander.net/ Work: https://www.redpill-linpro.com/
Attachment
> On Mon, Mar 07, 2022 at 01:27:02PM +0100, Magnus Hagander wrote: > On Fri, Feb 25, 2022 at 5:40 PM Dmitry Dolgov <9erthalion6@gmail.com> wrote: > > One interesting not-very-relevant for the patch thing I've noticed while > > reading it, is that there seems to be no way to find out what fraction > > of time jit_tuple_deforming is taking alone, it's sort of merged > > together with jit_expressions in generation_counter. > > That's missing att a deeper level though, right? We don't have it in > EXPLAIN ANALYZE either. So while I agree that's useful, I think that's > the job of another patch, and these two sets of counters should be the > same. Right, it's missing on the instrumentation level, I was just surprised to notice that.
On Mon, Mar 07, 2022 at 01:40:34PM +0100, Magnus Hagander wrote: > > I wonder if there might be an interesting middle ground, or if that is > making it too much. That is, we could have an > Option 3: > jit_count > total_jit_time - for sum of functions+inlining+optimization+emission time > min_jit_time - for sum of functions+inlining+optimization+emission time > max_jit_time - for sum of functions+inlining+optimization+emission time > mean_jit_time - for sum of functions+inlining+optimization+emission time > stddev_jit_time - for sum of functions+inlining+optimization+emission time > jit_functions > jit_generation_time > jit_inlining_count > jit_inlining_time > jit_optimization_count > jit_optimization_time > jit_emission_count > jit_emission_time > > That is, we'd get the more detailed timings across the total time, but > not on the details. But that might be overkill. I also thought about it but it seems overkill. pg_stat_statements view is already very big, and I think that the JIT time should be somewhat stable, at least compared to how much a query execution time can vary depending on the parameters. This approach would also be a bit useless if you change the costing of underlying JIT operation. > But -- here's an updated patched based on Option 2. Thanks! Code-wide, the patch looks good. For the doc, it seems that you documented jit_inlining_count three times rather than documenting jit_optimization_count and jit_emission_count. I don't think we can add tests there, and having a test for every new counter being >= 0 seems entirely useless, however there should be a new test added for the "oldextversions" test to make sure that there's no issue with old SQL / new shlib compatibility. And looking at it I see that it was already missed for version 1.9 :(
On Tue, Mar 8, 2022 at 4:08 AM Julien Rouhaud <rjuju123@gmail.com> wrote:
On Mon, Mar 07, 2022 at 01:40:34PM +0100, Magnus Hagander wrote:
>
> I wonder if there might be an interesting middle ground, or if that is
> making it too much. That is, we could have an
> Option 3:
> jit_count
> total_jit_time - for sum of functions+inlining+optimization+emission time
> min_jit_time - for sum of functions+inlining+optimization+emission time
> max_jit_time - for sum of functions+inlining+optimization+emission time
> mean_jit_time - for sum of functions+inlining+optimization+emission time
> stddev_jit_time - for sum of functions+inlining+optimization+emission time
> jit_functions
> jit_generation_time
> jit_inlining_count
> jit_inlining_time
> jit_optimization_count
> jit_optimization_time
> jit_emission_count
> jit_emission_time
>
> That is, we'd get the more detailed timings across the total time, but
> not on the details. But that might be overkill.
I also thought about it but it seems overkill. pg_stat_statements view is
already very big, and I think that the JIT time should be somewhat stable, at
least compared to how much a query execution time can vary depending on the
parameters. This approach would also be a bit useless if you change the
costing of underlying JIT operation.
> But -- here's an updated patched based on Option 2.
Thanks!
Code-wide, the patch looks good. For the doc, it seems that you documented
jit_inlining_count three times rather than documenting jit_optimization_count
and jit_emission_count.
Oops, thanks and fixed.
I don't think we can add tests there, and having a test for every new counter
being >= 0 seems entirely useless, however there should be a new test added for
the "oldextversions" test to make sure that there's no issue with old SQL / new
shlib compatibility. And looking at it I see that it was already missed for
version 1.9 :(
Indeed. Fixed here.
Michael had already applied a patch that took us to 1.10 and added that test, so I've just updated it here. I don't think we normally bump the version twice int he same day, so I just mergd the SQL script changes as well.
PFA a "final" version for the CI to run.
Attachment
RE: Expose JIT counters/timing in pg_stat_statements
From
"Shinoda, Noriyoshi (PN Japan FSIP)"
Date:
Hi,
thank you for the great features.
The attached small patch changes the data type in the document.
The following columns are actually double precision but bigint in the docs.
jit_generation_time
jit_inlining_time
jit_optimization_time
jit_emission_count
Regards,
Noriyoshi Shinoda
From: Magnus Hagander <magnus@hagander.net>
Sent: Friday, April 8, 2022 8:47 PM
To: Julien Rouhaud <rjuju123@gmail.com>
Cc: PostgreSQL Developers <pgsql-hackers@lists.postgresql.org>
Subject: Re: Expose JIT counters/timing in pg_stat_statements
On Tue, Mar 8, 2022 at 4:08 AM Julien Rouhaud <rjuju123@gmail.com> wrote:
On Mon, Mar 07, 2022 at 01:40:34PM +0100, Magnus Hagander wrote:
>
> I wonder if there might be an interesting middle ground, or if that is
> making it too much. That is, we could have an
> Option 3:
> jit_count
> total_jit_time - for sum of functions+inlining+optimization+emission time
> min_jit_time - for sum of functions+inlining+optimization+emission time
> max_jit_time - for sum of functions+inlining+optimization+emission time
> mean_jit_time - for sum of functions+inlining+optimization+emission time
> stddev_jit_time - for sum of functions+inlining+optimization+emission time
> jit_functions
> jit_generation_time
> jit_inlining_count
> jit_inlining_time
> jit_optimization_count
> jit_optimization_time
> jit_emission_count
> jit_emission_time
>
> That is, we'd get the more detailed timings across the total time, but
> not on the details. But that might be overkill.
I also thought about it but it seems overkill. pg_stat_statements view is
already very big, and I think that the JIT time should be somewhat stable, at
least compared to how much a query execution time can vary depending on the
parameters. This approach would also be a bit useless if you change the
costing of underlying JIT operation.
> But -- here's an updated patched based on Option 2.
Thanks!
Code-wide, the patch looks good. For the doc, it seems that you documented
jit_inlining_count three times rather than documenting jit_optimization_count
and jit_emission_count.
Oops, thanks and fixed.
I don't think we can add tests there, and having a test for every new counter
being >= 0 seems entirely useless, however there should be a new test added for
the "oldextversions" test to make sure that there's no issue with old SQL / new
shlib compatibility. And looking at it I see that it was already missed for
version 1.9 :(
Indeed. Fixed here.
Michael had already applied a patch that took us to 1.10 and added that test, so I've just updated it here. I don't think we normally bump the version twice int he same day, so I just mergd the SQL script changes as well.
PFA a "final" version for the CI to run.
--
Magnus Hagander
Me: https://www.hagander.net/
Work: https://www.redpill-linpro.com/
Attachment
Hi, On Sat, Apr 09, 2022 at 01:51:21AM +0000, Shinoda, Noriyoshi (PN Japan FSIP) wrote: > Hi, > thank you for the great features. > > The attached small patch changes the data type in the document. > The following columns are actually double precision but bigint in the docs. > jit_generation_time > jit_inlining_time > jit_optimization_time > jit_emission_count Indeed! The patch looks good to me, I didn't find any other discrepancy.