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/
Attachments:
pg_stat_statements_jit.patchtext/x-patch; charset=US-ASCII; name=pg_stat_statements_jit.patchDownload
diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile
index 7fabd96f38..d9eacfb364 100644
--- a/contrib/pg_stat_statements/Makefile
+++ b/contrib/pg_stat_statements/Makefile
@@ -6,7 +6,7 @@ OBJS = \
pg_stat_statements.o
EXTENSION = pg_stat_statements
-DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.8--1.9.sql \
+DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.9--1.10.sql pg_stat_statements--1.8--1.9.sql \
pg_stat_statements--1.7--1.8.sql pg_stat_statements--1.6--1.7.sql \
pg_stat_statements--1.5--1.6.sql pg_stat_statements--1.4--1.5.sql \
pg_stat_statements--1.3--1.4.sql pg_stat_statements--1.2--1.3.sql \
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
new file mode 100644
index 0000000000..19b16874b4
--- /dev/null
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
@@ -0,0 +1,62 @@
+/* contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql */
+
+-- complain if script is sourced in psql, rather than via ALTER EXTENSION
+\echo Use "ALTER EXTENSION pg_stat_statements UPDATE TO '1.10'" to load this file. \quit
+
+/* First we have to remove them from the extension */
+ALTER EXTENSION pg_stat_statements DROP VIEW pg_stat_statements;
+ALTER EXTENSION pg_stat_statements DROP FUNCTION pg_stat_statements(boolean);
+
+/* Then we can drop them */
+DROP VIEW pg_stat_statements;
+DROP FUNCTION pg_stat_statements(boolean);
+
+/* Now redefine */
+CREATE FUNCTION pg_stat_statements(IN showtext boolean,
+ OUT userid oid,
+ OUT dbid oid,
+ OUT toplevel bool,
+ OUT queryid bigint,
+ OUT query text,
+ OUT plans int8,
+ OUT total_plan_time float8,
+ OUT min_plan_time float8,
+ OUT max_plan_time float8,
+ OUT mean_plan_time float8,
+ OUT stddev_plan_time float8,
+ OUT calls int8,
+ OUT total_exec_time float8,
+ OUT min_exec_time float8,
+ OUT max_exec_time float8,
+ OUT mean_exec_time float8,
+ OUT stddev_exec_time float8,
+ OUT rows int8,
+ OUT shared_blks_hit int8,
+ OUT shared_blks_read int8,
+ OUT shared_blks_dirtied int8,
+ OUT shared_blks_written int8,
+ OUT local_blks_hit int8,
+ OUT local_blks_read int8,
+ OUT local_blks_dirtied int8,
+ OUT local_blks_written int8,
+ OUT temp_blks_read int8,
+ OUT temp_blks_written int8,
+ OUT blk_read_time float8,
+ OUT blk_write_time float8,
+ OUT wal_records int8,
+ OUT wal_fpi int8,
+ OUT wal_bytes numeric,
+ OUT jit_functions int8,
+ OUT jit_generation_time float8,
+ OUT jit_inlining_time float8,
+ OUT jit_optimization_time float8,
+ OUT jit_emission_time float8
+)
+RETURNS SETOF record
+AS 'MODULE_PATHNAME', 'pg_stat_statements_1_10'
+LANGUAGE C STRICT VOLATILE PARALLEL SAFE;
+
+CREATE VIEW pg_stat_statements AS
+ SELECT * FROM pg_stat_statements(true);
+
+GRANT SELECT ON pg_stat_statements TO PUBLIC;
diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index 38d92a89cc..b802f67db2 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -52,6 +52,7 @@
#include "common/hashfn.h"
#include "executor/instrument.h"
#include "funcapi.h"
+#include "jit/jit.h"
#include "mb/pg_wchar.h"
#include "miscadmin.h"
#include "optimizer/planner.h"
@@ -121,7 +122,8 @@ typedef enum pgssVersion
PGSS_V1_2,
PGSS_V1_3,
PGSS_V1_8,
- PGSS_V1_9
+ PGSS_V1_9,
+ PGSS_V1_10
} pgssVersion;
typedef enum pgssStoreKind
@@ -189,6 +191,11 @@ typedef struct Counters
int64 wal_records; /* # of WAL records generated */
int64 wal_fpi; /* # of WAL full page images generated */
uint64 wal_bytes; /* total amount of WAL generated in bytes */
+ int64 jit_functions; /* total number of JIT functions emitted */
+ double jit_generation_time; /* total time to generate jit code */
+ double jit_inlining_time; /* total time to inline jit code */
+ double jit_optimization_time; /* total time to optimize jit code */
+ double jit_emission_time; /* total time to emit jit code */
} Counters;
/*
@@ -302,6 +309,7 @@ PG_FUNCTION_INFO_V1(pg_stat_statements_1_2);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_3);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_8);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_9);
+PG_FUNCTION_INFO_V1(pg_stat_statements_1_10);
PG_FUNCTION_INFO_V1(pg_stat_statements);
PG_FUNCTION_INFO_V1(pg_stat_statements_info);
@@ -330,6 +338,7 @@ static void pgss_store(const char *query, uint64 queryId,
double total_time, uint64 rows,
const BufferUsage *bufusage,
const WalUsage *walusage,
+ const struct JitInstrumentation *jitusage,
JumbleState *jstate);
static void pg_stat_statements_internal(FunctionCallInfo fcinfo,
pgssVersion api_version,
@@ -854,6 +863,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query, JumbleState *jstate)
0,
NULL,
NULL,
+ NULL,
jstate);
}
@@ -938,6 +948,7 @@ pgss_planner(Query *parse,
0,
&bufusage,
&walusage,
+ NULL,
NULL);
}
else
@@ -1056,6 +1067,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc)
queryDesc->estate->es_processed,
&queryDesc->totaltime->bufusage,
&queryDesc->totaltime->walusage,
+ queryDesc->estate->es_jit ? &queryDesc->estate->es_jit->instr : NULL,
NULL);
}
@@ -1173,6 +1185,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
rows,
&bufusage,
&walusage,
+ NULL,
NULL);
}
else
@@ -1206,6 +1219,7 @@ pgss_store(const char *query, uint64 queryId,
double total_time, uint64 rows,
const BufferUsage *bufusage,
const WalUsage *walusage,
+ const struct JitInstrumentation *jitusage,
JumbleState *jstate)
{
pgssHashKey key;
@@ -1373,6 +1387,14 @@ pgss_store(const char *query, uint64 queryId,
e->counters.wal_records += walusage->wal_records;
e->counters.wal_fpi += walusage->wal_fpi;
e->counters.wal_bytes += walusage->wal_bytes;
+ if (jitusage)
+ {
+ e->counters.jit_functions += jitusage->created_functions;
+ e->counters.jit_generation_time += INSTR_TIME_GET_MILLISEC(jitusage->generation_counter);
+ e->counters.jit_inlining_time += INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter);
+ e->counters.jit_optimization_time += INSTR_TIME_GET_MILLISEC(jitusage->optimization_counter);
+ e->counters.jit_emission_time += INSTR_TIME_GET_MILLISEC(jitusage->emission_counter);
+ }
SpinLockRelease(&e->mutex);
}
@@ -1422,7 +1444,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
#define PG_STAT_STATEMENTS_COLS_V1_3 23
#define PG_STAT_STATEMENTS_COLS_V1_8 32
#define PG_STAT_STATEMENTS_COLS_V1_9 33
-#define PG_STAT_STATEMENTS_COLS 33 /* maximum of above */
+#define PG_STAT_STATEMENTS_COLS_V1_10 38
+#define PG_STAT_STATEMENTS_COLS 38 /* maximum of above */
/*
* Retrieve statement statistics.
@@ -1434,6 +1457,16 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
* expected API version is identified by embedding it in the C name of the
* function. Unfortunately we weren't bright enough to do that for 1.1.
*/
+Datum
+pg_stat_statements_1_10(PG_FUNCTION_ARGS)
+{
+ bool showtext = PG_GETARG_BOOL(0);
+
+ pg_stat_statements_internal(fcinfo, PGSS_V1_10, showtext);
+
+ return (Datum) 0;
+}
+
Datum
pg_stat_statements_1_9(PG_FUNCTION_ARGS)
{
@@ -1567,6 +1600,10 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
if (api_version != PGSS_V1_9)
elog(ERROR, "incorrect number of output arguments");
break;
+ case PG_STAT_STATEMENTS_COLS_V1_10:
+ if (api_version != PGSS_V1_10)
+ elog(ERROR, "incorrect number of output arguments");
+ break;
default:
elog(ERROR, "incorrect number of output arguments");
}
@@ -1791,6 +1828,14 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
Int32GetDatum(-1));
values[i++] = wal_bytes;
}
+ if (api_version >= PGSS_V1_10)
+ {
+ values[i++] = Int64GetDatumFast(tmp.jit_functions);
+ values[i++] = Float8GetDatumFast(tmp.jit_generation_time);
+ values[i++] = Float8GetDatumFast(tmp.jit_inlining_time);
+ values[i++] = Float8GetDatumFast(tmp.jit_optimization_time);
+ values[i++] = Float8GetDatumFast(tmp.jit_emission_time);
+ }
Assert(i == (api_version == PGSS_V1_0 ? PG_STAT_STATEMENTS_COLS_V1_0 :
api_version == PGSS_V1_1 ? PG_STAT_STATEMENTS_COLS_V1_1 :
@@ -1798,6 +1843,7 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
api_version == PGSS_V1_3 ? PG_STAT_STATEMENTS_COLS_V1_3 :
api_version == PGSS_V1_8 ? PG_STAT_STATEMENTS_COLS_V1_8 :
api_version == PGSS_V1_9 ? PG_STAT_STATEMENTS_COLS_V1_9 :
+ api_version == PGSS_V1_10 ? PG_STAT_STATEMENTS_COLS_V1_10 :
-1 /* fail if you forget to update this assert */ ));
tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/contrib/pg_stat_statements/pg_stat_statements.control b/contrib/pg_stat_statements/pg_stat_statements.control
index 2f1ce6ed50..0747e48138 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.control
+++ b/contrib/pg_stat_statements/pg_stat_statements.control
@@ -1,5 +1,5 @@
# pg_stat_statements extension
comment = 'track planning and execution statistics of all SQL statements executed'
-default_version = '1.9'
+default_version = '1.10'
module_pathname = '$libdir/pg_stat_statements'
relocatable = true
diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index bc9d5bdbe3..11dfcb5f98 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -379,6 +379,51 @@
Total amount of WAL generated by the statement in bytes
</para></entry>
</row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_functions</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total number of functions JIT-compiled by the statement
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_generation_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on generating JIT code, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on inlining functions, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_optimization_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on optimizing, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_emission_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on emitting code, in milliseconds
+ </para></entry>
+ </row>
</tbody>
</tgroup>
</table>
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 > 0etc?
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 > 0etc?
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 > 0etc?
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 happenedOption 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 float8Perhaps 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 > 0One 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 happenedOption 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_timeI'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/
Attachments:
pg_stat_statements_jit_v2.patchtext/x-patch; charset=US-ASCII; name=pg_stat_statements_jit_v2.patchDownload
diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile
index 7fabd96f38..d9eacfb364 100644
--- a/contrib/pg_stat_statements/Makefile
+++ b/contrib/pg_stat_statements/Makefile
@@ -6,7 +6,7 @@ OBJS = \
pg_stat_statements.o
EXTENSION = pg_stat_statements
-DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.8--1.9.sql \
+DATA = pg_stat_statements--1.4.sql pg_stat_statements--1.9--1.10.sql pg_stat_statements--1.8--1.9.sql \
pg_stat_statements--1.7--1.8.sql pg_stat_statements--1.6--1.7.sql \
pg_stat_statements--1.5--1.6.sql pg_stat_statements--1.4--1.5.sql \
pg_stat_statements--1.3--1.4.sql pg_stat_statements--1.2--1.3.sql \
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
new file mode 100644
index 0000000000..8924df2715
--- /dev/null
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
@@ -0,0 +1,65 @@
+/* contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql */
+
+-- complain if script is sourced in psql, rather than via ALTER EXTENSION
+\echo Use "ALTER EXTENSION pg_stat_statements UPDATE TO '1.10'" to load this file. \quit
+
+/* First we have to remove them from the extension */
+ALTER EXTENSION pg_stat_statements DROP VIEW pg_stat_statements;
+ALTER EXTENSION pg_stat_statements DROP FUNCTION pg_stat_statements(boolean);
+
+/* Then we can drop them */
+DROP VIEW pg_stat_statements;
+DROP FUNCTION pg_stat_statements(boolean);
+
+/* Now redefine */
+CREATE FUNCTION pg_stat_statements(IN showtext boolean,
+ OUT userid oid,
+ OUT dbid oid,
+ OUT toplevel bool,
+ OUT queryid bigint,
+ OUT query text,
+ OUT plans int8,
+ OUT total_plan_time float8,
+ OUT min_plan_time float8,
+ OUT max_plan_time float8,
+ OUT mean_plan_time float8,
+ OUT stddev_plan_time float8,
+ OUT calls int8,
+ OUT total_exec_time float8,
+ OUT min_exec_time float8,
+ OUT max_exec_time float8,
+ OUT mean_exec_time float8,
+ OUT stddev_exec_time float8,
+ OUT rows int8,
+ OUT shared_blks_hit int8,
+ OUT shared_blks_read int8,
+ OUT shared_blks_dirtied int8,
+ OUT shared_blks_written int8,
+ OUT local_blks_hit int8,
+ OUT local_blks_read int8,
+ OUT local_blks_dirtied int8,
+ OUT local_blks_written int8,
+ OUT temp_blks_read int8,
+ OUT temp_blks_written int8,
+ OUT blk_read_time float8,
+ OUT blk_write_time float8,
+ OUT wal_records int8,
+ OUT wal_fpi int8,
+ OUT wal_bytes numeric,
+ OUT jit_functions int8,
+ OUT jit_generation_time float8,
+ OUT jit_inlining_count int8,
+ OUT jit_inlining_time float8,
+ OUT jit_optimization_count int8,
+ OUT jit_optimization_time float8,
+ OUT jit_emission_count int8,
+ OUT jit_emission_time float8
+)
+RETURNS SETOF record
+AS 'MODULE_PATHNAME', 'pg_stat_statements_1_10'
+LANGUAGE C STRICT VOLATILE PARALLEL SAFE;
+
+CREATE VIEW pg_stat_statements AS
+ SELECT * FROM pg_stat_statements(true);
+
+GRANT SELECT ON pg_stat_statements TO PUBLIC;
diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index d803253cea..99b9db37b1 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -52,6 +52,7 @@
#include "common/hashfn.h"
#include "executor/instrument.h"
#include "funcapi.h"
+#include "jit/jit.h"
#include "mb/pg_wchar.h"
#include "miscadmin.h"
#include "optimizer/planner.h"
@@ -121,7 +122,8 @@ typedef enum pgssVersion
PGSS_V1_2,
PGSS_V1_3,
PGSS_V1_8,
- PGSS_V1_9
+ PGSS_V1_9,
+ PGSS_V1_10
} pgssVersion;
typedef enum pgssStoreKind
@@ -189,6 +191,17 @@ typedef struct Counters
int64 wal_records; /* # of WAL records generated */
int64 wal_fpi; /* # of WAL full page images generated */
uint64 wal_bytes; /* total amount of WAL generated in bytes */
+ int64 jit_functions; /* total number of JIT functions emitted */
+ double jit_generation_time; /* total time to generate jit code */
+ int64 jit_inlining_count; /* number of times inlining time has been
+ * > 0 */
+ double jit_inlining_time; /* total time to inline jit code */
+ int64 jit_optimization_count; /* number of times optimization time
+ * has been > 0 */
+ double jit_optimization_time; /* total time to optimize jit code */
+ int64 jit_emission_count; /* number of times emission time has been
+ * > 0 */
+ double jit_emission_time; /* total time to emit jit code */
} Counters;
/*
@@ -302,6 +315,7 @@ PG_FUNCTION_INFO_V1(pg_stat_statements_1_2);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_3);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_8);
PG_FUNCTION_INFO_V1(pg_stat_statements_1_9);
+PG_FUNCTION_INFO_V1(pg_stat_statements_1_10);
PG_FUNCTION_INFO_V1(pg_stat_statements);
PG_FUNCTION_INFO_V1(pg_stat_statements_info);
@@ -330,6 +344,7 @@ static void pgss_store(const char *query, uint64 queryId,
double total_time, uint64 rows,
const BufferUsage *bufusage,
const WalUsage *walusage,
+ const struct JitInstrumentation *jitusage,
JumbleState *jstate);
static void pg_stat_statements_internal(FunctionCallInfo fcinfo,
pgssVersion api_version,
@@ -854,6 +869,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query, JumbleState *jstate)
0,
NULL,
NULL,
+ NULL,
jstate);
}
@@ -938,6 +954,7 @@ pgss_planner(Query *parse,
0,
&bufusage,
&walusage,
+ NULL,
NULL);
}
else
@@ -1056,6 +1073,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc)
queryDesc->estate->es_processed,
&queryDesc->totaltime->bufusage,
&queryDesc->totaltime->walusage,
+ queryDesc->estate->es_jit ? &queryDesc->estate->es_jit->instr : NULL,
NULL);
}
@@ -1173,6 +1191,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
rows,
&bufusage,
&walusage,
+ NULL,
NULL);
}
else
@@ -1206,6 +1225,7 @@ pgss_store(const char *query, uint64 queryId,
double total_time, uint64 rows,
const BufferUsage *bufusage,
const WalUsage *walusage,
+ const struct JitInstrumentation *jitusage,
JumbleState *jstate)
{
pgssHashKey key;
@@ -1373,6 +1393,23 @@ pgss_store(const char *query, uint64 queryId,
e->counters.wal_records += walusage->wal_records;
e->counters.wal_fpi += walusage->wal_fpi;
e->counters.wal_bytes += walusage->wal_bytes;
+ if (jitusage)
+ {
+ e->counters.jit_functions += jitusage->created_functions;
+ e->counters.jit_generation_time += INSTR_TIME_GET_MILLISEC(jitusage->generation_counter);
+
+ if (INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter))
+ e->counters.jit_inlining_count++;
+ e->counters.jit_inlining_time += INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter);
+
+ if (INSTR_TIME_GET_MILLISEC(jitusage->optimization_counter))
+ e->counters.jit_optimization_count++;
+ e->counters.jit_optimization_time += INSTR_TIME_GET_MILLISEC(jitusage->optimization_counter);
+
+ if (INSTR_TIME_GET_MILLISEC(jitusage->emission_counter))
+ e->counters.jit_emission_count++;
+ e->counters.jit_emission_time += INSTR_TIME_GET_MILLISEC(jitusage->emission_counter);
+ }
SpinLockRelease(&e->mutex);
}
@@ -1422,7 +1459,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
#define PG_STAT_STATEMENTS_COLS_V1_3 23
#define PG_STAT_STATEMENTS_COLS_V1_8 32
#define PG_STAT_STATEMENTS_COLS_V1_9 33
-#define PG_STAT_STATEMENTS_COLS 33 /* maximum of above */
+#define PG_STAT_STATEMENTS_COLS_V1_10 41
+#define PG_STAT_STATEMENTS_COLS 41 /* maximum of above */
/*
* Retrieve statement statistics.
@@ -1434,6 +1472,16 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
* expected API version is identified by embedding it in the C name of the
* function. Unfortunately we weren't bright enough to do that for 1.1.
*/
+Datum
+pg_stat_statements_1_10(PG_FUNCTION_ARGS)
+{
+ bool showtext = PG_GETARG_BOOL(0);
+
+ pg_stat_statements_internal(fcinfo, PGSS_V1_10, showtext);
+
+ return (Datum) 0;
+}
+
Datum
pg_stat_statements_1_9(PG_FUNCTION_ARGS)
{
@@ -1567,6 +1615,10 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
if (api_version != PGSS_V1_9)
elog(ERROR, "incorrect number of output arguments");
break;
+ case PG_STAT_STATEMENTS_COLS_V1_10:
+ if (api_version != PGSS_V1_10)
+ elog(ERROR, "incorrect number of output arguments");
+ break;
default:
elog(ERROR, "incorrect number of output arguments");
}
@@ -1791,6 +1843,17 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
Int32GetDatum(-1));
values[i++] = wal_bytes;
}
+ if (api_version >= PGSS_V1_10)
+ {
+ values[i++] = Int64GetDatumFast(tmp.jit_functions);
+ values[i++] = Float8GetDatumFast(tmp.jit_generation_time);
+ values[i++] = Int64GetDatumFast(tmp.jit_inlining_count);
+ values[i++] = Float8GetDatumFast(tmp.jit_inlining_time);
+ values[i++] = Int64GetDatumFast(tmp.jit_optimization_count);
+ values[i++] = Float8GetDatumFast(tmp.jit_optimization_time);
+ values[i++] = Int64GetDatumFast(tmp.jit_emission_count);
+ values[i++] = Float8GetDatumFast(tmp.jit_emission_time);
+ }
Assert(i == (api_version == PGSS_V1_0 ? PG_STAT_STATEMENTS_COLS_V1_0 :
api_version == PGSS_V1_1 ? PG_STAT_STATEMENTS_COLS_V1_1 :
@@ -1798,6 +1861,7 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
api_version == PGSS_V1_3 ? PG_STAT_STATEMENTS_COLS_V1_3 :
api_version == PGSS_V1_8 ? PG_STAT_STATEMENTS_COLS_V1_8 :
api_version == PGSS_V1_9 ? PG_STAT_STATEMENTS_COLS_V1_9 :
+ api_version == PGSS_V1_10 ? PG_STAT_STATEMENTS_COLS_V1_10 :
-1 /* fail if you forget to update this assert */ ));
tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/contrib/pg_stat_statements/pg_stat_statements.control b/contrib/pg_stat_statements/pg_stat_statements.control
index 2f1ce6ed50..0747e48138 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.control
+++ b/contrib/pg_stat_statements/pg_stat_statements.control
@@ -1,5 +1,5 @@
# pg_stat_statements extension
comment = 'track planning and execution statistics of all SQL statements executed'
-default_version = '1.9'
+default_version = '1.10'
module_pathname = '$libdir/pg_stat_statements'
relocatable = true
diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index bc9d5bdbe3..f3d65cfe2a 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -379,6 +379,78 @@
Total amount of WAL generated by the statement in bytes
</para></entry>
</row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_functions</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total number of functions JIT-compiled by the statement
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_generation_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on generating JIT code, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_count</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times functions have been inlined
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on inlining functions, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_count</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times the statement has been inlined
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_optimization_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on optimizing, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_count</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times code has been emitted
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_emission_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on emitting code, in milliseconds
+ </para></entry>
+ </row>
</tbody>
</tgroup>
</table>
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_timeThat 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+emissiontime
jit_functions
jit_generation_time
jit_inlining_count
jit_inlining_time
jit_optimization_count
jit_optimization_time
jit_emission_count
jit_emission_timeThat 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/ <http://www.hagander.net/>
Work: https://www.redpill-linpro.com/ <http://www.redpill-linpro.com/>
Attachments:
pg_stat_statements_jit_v3.patchtext/x-patch; charset=US-ASCII; name=pg_stat_statements_jit_v3.patchDownload
diff --git a/contrib/pg_stat_statements/expected/oldextversions.out b/contrib/pg_stat_statements/expected/oldextversions.out
index 2813eb16cb..efb2049ecf 100644
--- a/contrib/pg_stat_statements/expected/oldextversions.out
+++ b/contrib/pg_stat_statements/expected/oldextversions.out
@@ -197,44 +197,52 @@ SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
-- New functions and views for pg_stat_statements in 1.10
AlTER EXTENSION pg_stat_statements UPDATE TO '1.10';
\d pg_stat_statements
- View "public.pg_stat_statements"
- Column | Type | Collation | Nullable | Default
----------------------+------------------+-----------+----------+---------
- userid | oid | | |
- dbid | oid | | |
- toplevel | boolean | | |
- queryid | bigint | | |
- query | text | | |
- plans | bigint | | |
- total_plan_time | double precision | | |
- min_plan_time | double precision | | |
- max_plan_time | double precision | | |
- mean_plan_time | double precision | | |
- stddev_plan_time | double precision | | |
- calls | bigint | | |
- total_exec_time | double precision | | |
- min_exec_time | double precision | | |
- max_exec_time | double precision | | |
- mean_exec_time | double precision | | |
- stddev_exec_time | double precision | | |
- rows | bigint | | |
- shared_blks_hit | bigint | | |
- shared_blks_read | bigint | | |
- shared_blks_dirtied | bigint | | |
- shared_blks_written | bigint | | |
- local_blks_hit | bigint | | |
- local_blks_read | bigint | | |
- local_blks_dirtied | bigint | | |
- local_blks_written | bigint | | |
- temp_blks_read | bigint | | |
- temp_blks_written | bigint | | |
- blk_read_time | double precision | | |
- blk_write_time | double precision | | |
- temp_blk_read_time | double precision | | |
- temp_blk_write_time | double precision | | |
- wal_records | bigint | | |
- wal_fpi | bigint | | |
- wal_bytes | numeric | | |
+ View "public.pg_stat_statements"
+ Column | Type | Collation | Nullable | Default
+------------------------+------------------+-----------+----------+---------
+ userid | oid | | |
+ dbid | oid | | |
+ toplevel | boolean | | |
+ queryid | bigint | | |
+ query | text | | |
+ plans | bigint | | |
+ total_plan_time | double precision | | |
+ min_plan_time | double precision | | |
+ max_plan_time | double precision | | |
+ mean_plan_time | double precision | | |
+ stddev_plan_time | double precision | | |
+ calls | bigint | | |
+ total_exec_time | double precision | | |
+ min_exec_time | double precision | | |
+ max_exec_time | double precision | | |
+ mean_exec_time | double precision | | |
+ stddev_exec_time | double precision | | |
+ rows | bigint | | |
+ shared_blks_hit | bigint | | |
+ shared_blks_read | bigint | | |
+ shared_blks_dirtied | bigint | | |
+ shared_blks_written | bigint | | |
+ local_blks_hit | bigint | | |
+ local_blks_read | bigint | | |
+ local_blks_dirtied | bigint | | |
+ local_blks_written | bigint | | |
+ temp_blks_read | bigint | | |
+ temp_blks_written | bigint | | |
+ blk_read_time | double precision | | |
+ blk_write_time | double precision | | |
+ temp_blk_read_time | double precision | | |
+ temp_blk_write_time | double precision | | |
+ wal_records | bigint | | |
+ wal_fpi | bigint | | |
+ wal_bytes | numeric | | |
+ jit_functions | bigint | | |
+ jit_generation_time | double precision | | |
+ jit_inlining_count | bigint | | |
+ jit_inlining_time | double precision | | |
+ jit_optimization_count | bigint | | |
+ jit_optimization_time | double precision | | |
+ jit_emission_count | bigint | | |
+ jit_emission_time | double precision | | |
SELECT count(*) > 0 AS has_data FROM pg_stat_statements;
has_data
diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
index ca777f14e8..811813c491 100644
--- a/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
+++ b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql
@@ -47,7 +47,15 @@ CREATE FUNCTION pg_stat_statements(IN showtext boolean,
OUT temp_blk_write_time float8,
OUT wal_records int8,
OUT wal_fpi int8,
- OUT wal_bytes numeric
+ OUT wal_bytes numeric,
+ OUT jit_functions int8,
+ OUT jit_generation_time float8,
+ OUT jit_inlining_count int8,
+ OUT jit_inlining_time float8,
+ OUT jit_optimization_count int8,
+ OUT jit_optimization_time float8,
+ OUT jit_emission_count int8,
+ OUT jit_emission_time float8
)
RETURNS SETOF record
AS 'MODULE_PATHNAME', 'pg_stat_statements_1_10'
diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c
index 42ac001053..1ca67ef623 100644
--- a/contrib/pg_stat_statements/pg_stat_statements.c
+++ b/contrib/pg_stat_statements/pg_stat_statements.c
@@ -52,6 +52,7 @@
#include "common/hashfn.h"
#include "executor/instrument.h"
#include "funcapi.h"
+#include "jit/jit.h"
#include "mb/pg_wchar.h"
#include "miscadmin.h"
#include "optimizer/planner.h"
@@ -188,6 +189,17 @@ typedef struct Counters
int64 wal_records; /* # of WAL records generated */
int64 wal_fpi; /* # of WAL full page images generated */
uint64 wal_bytes; /* total amount of WAL generated in bytes */
+ int64 jit_functions; /* total number of JIT functions emitted */
+ double jit_generation_time; /* total time to generate jit code */
+ int64 jit_inlining_count; /* number of times inlining time has been
+ * > 0 */
+ double jit_inlining_time; /* total time to inline jit code */
+ int64 jit_optimization_count; /* number of times optimization time
+ * has been > 0 */
+ double jit_optimization_time; /* total time to optimize jit code */
+ int64 jit_emission_count; /* number of times emission time has been
+ * > 0 */
+ double jit_emission_time; /* total time to emit jit code */
} Counters;
/*
@@ -330,6 +342,7 @@ static void pgss_store(const char *query, uint64 queryId,
double total_time, uint64 rows,
const BufferUsage *bufusage,
const WalUsage *walusage,
+ const struct JitInstrumentation *jitusage,
JumbleState *jstate);
static void pg_stat_statements_internal(FunctionCallInfo fcinfo,
pgssVersion api_version,
@@ -854,6 +867,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query, JumbleState *jstate)
0,
NULL,
NULL,
+ NULL,
jstate);
}
@@ -938,6 +952,7 @@ pgss_planner(Query *parse,
0,
&bufusage,
&walusage,
+ NULL,
NULL);
}
else
@@ -1056,6 +1071,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc)
queryDesc->estate->es_processed,
&queryDesc->totaltime->bufusage,
&queryDesc->totaltime->walusage,
+ queryDesc->estate->es_jit ? &queryDesc->estate->es_jit->instr : NULL,
NULL);
}
@@ -1173,6 +1189,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
rows,
&bufusage,
&walusage,
+ NULL,
NULL);
}
else
@@ -1206,6 +1223,7 @@ pgss_store(const char *query, uint64 queryId,
double total_time, uint64 rows,
const BufferUsage *bufusage,
const WalUsage *walusage,
+ const struct JitInstrumentation *jitusage,
JumbleState *jstate)
{
pgssHashKey key;
@@ -1375,6 +1393,23 @@ pgss_store(const char *query, uint64 queryId,
e->counters.wal_records += walusage->wal_records;
e->counters.wal_fpi += walusage->wal_fpi;
e->counters.wal_bytes += walusage->wal_bytes;
+ if (jitusage)
+ {
+ e->counters.jit_functions += jitusage->created_functions;
+ e->counters.jit_generation_time += INSTR_TIME_GET_MILLISEC(jitusage->generation_counter);
+
+ if (INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter))
+ e->counters.jit_inlining_count++;
+ e->counters.jit_inlining_time += INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter);
+
+ if (INSTR_TIME_GET_MILLISEC(jitusage->optimization_counter))
+ e->counters.jit_optimization_count++;
+ e->counters.jit_optimization_time += INSTR_TIME_GET_MILLISEC(jitusage->optimization_counter);
+
+ if (INSTR_TIME_GET_MILLISEC(jitusage->emission_counter))
+ e->counters.jit_emission_count++;
+ e->counters.jit_emission_time += INSTR_TIME_GET_MILLISEC(jitusage->emission_counter);
+ }
SpinLockRelease(&e->mutex);
}
@@ -1424,8 +1459,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS)
#define PG_STAT_STATEMENTS_COLS_V1_3 23
#define PG_STAT_STATEMENTS_COLS_V1_8 32
#define PG_STAT_STATEMENTS_COLS_V1_9 33
-#define PG_STAT_STATEMENTS_COLS_V1_10 35
-#define PG_STAT_STATEMENTS_COLS 35 /* maximum of above */
+#define PG_STAT_STATEMENTS_COLS_V1_10 43
+#define PG_STAT_STATEMENTS_COLS 43 /* maximum of above */
/*
* Retrieve statement statistics.
@@ -1786,6 +1821,17 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo,
Int32GetDatum(-1));
values[i++] = wal_bytes;
}
+ if (api_version >= PGSS_V1_10)
+ {
+ values[i++] = Int64GetDatumFast(tmp.jit_functions);
+ values[i++] = Float8GetDatumFast(tmp.jit_generation_time);
+ values[i++] = Int64GetDatumFast(tmp.jit_inlining_count);
+ values[i++] = Float8GetDatumFast(tmp.jit_inlining_time);
+ values[i++] = Int64GetDatumFast(tmp.jit_optimization_count);
+ values[i++] = Float8GetDatumFast(tmp.jit_optimization_time);
+ values[i++] = Int64GetDatumFast(tmp.jit_emission_count);
+ values[i++] = Float8GetDatumFast(tmp.jit_emission_time);
+ }
Assert(i == (api_version == PGSS_V1_0 ? PG_STAT_STATEMENTS_COLS_V1_0 :
api_version == PGSS_V1_1 ? PG_STAT_STATEMENTS_COLS_V1_1 :
diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index 0ead2464d8..45e720e995 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -401,6 +401,78 @@
Total amount of WAL generated by the statement in bytes
</para></entry>
</row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_functions</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total number of functions JIT-compiled by the statement
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_generation_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on generating JIT code, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_count</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times functions have been inlined
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_inlining_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on inlining functions, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_optimization_count</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times the statement has been optimized
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_optimization_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on optimizing, in milliseconds
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_emission_count</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Number of times code has been emitted
+ </para></entry>
+ </row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>jit_emission_time</structfield> <type>bigint</type>
+ </para>
+ <para>
+ Total time spent by the statement on emitting code, in milliseconds
+ </para></entry>
+ </row>
</tbody>
</tgroup>
</table>
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<mailto: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_timeThat 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/<http://www.hagander.net/>
Work: https://www.redpill-linpro.com/<http://www.redpill-linpro.com/>
Attachments:
pg_stat_statements_jit_doc_v1.diffapplication/octet-stream; name=pg_stat_statements_jit_doc_v1.diffDownload
diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml
index 45e720e..4fd9e74 100644
--- a/doc/src/sgml/pgstatstatements.sgml
+++ b/doc/src/sgml/pgstatstatements.sgml
@@ -413,7 +413,7 @@
<row>
<entry role="catalog_table_entry"><para role="column_definition">
- <structfield>jit_generation_time</structfield> <type>bigint</type>
+ <structfield>jit_generation_time</structfield> <type>double precision</type>
</para>
<para>
Total time spent by the statement on generating JIT code, in milliseconds
@@ -431,7 +431,7 @@
<row>
<entry role="catalog_table_entry"><para role="column_definition">
- <structfield>jit_inlining_time</structfield> <type>bigint</type>
+ <structfield>jit_inlining_time</structfield> <type>double precision</type>
</para>
<para>
Total time spent by the statement on inlining functions, in milliseconds
@@ -449,7 +449,7 @@
<row>
<entry role="catalog_table_entry"><para role="column_definition">
- <structfield>jit_optimization_time</structfield> <type>bigint</type>
+ <structfield>jit_optimization_time</structfield> <type>double precision</type>
</para>
<para>
Total time spent by the statement on optimizing, in milliseconds
@@ -467,7 +467,7 @@
<row>
<entry role="catalog_table_entry"><para role="column_definition">
- <structfield>jit_emission_time</structfield> <type>bigint</type>
+ <structfield>jit_emission_time</structfield> <type>double precision</type>
</para>
<para>
Total time spent by the statement on emitting code, in milliseconds
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.