On Tue, Mar 8, 2022 at 4:08 AM Julien Rouhaud <rjuju...@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/ <http://www.hagander.net/>
Work: https://www.redpill-linpro.com/ <http://www.redpill-linpro.com/>
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>
