From 57d6aea00fcefec3825a5948ce05cf2b4941097b Mon Sep 17 00:00:00 2001 From: Magnus Hagander Date: Fri, 8 Apr 2022 13:51:01 +0200 Subject: [PATCH] Add JIT counters to pg_stat_statements This adds cumulative counters for jit operations to pg_stat_statements, making it easier to diagnose how JIT is used in an installation. These changes merge into the 1.10 changes applied in 76cbf7edb6 without creating a new version. Reviewed-By: Julien Rouhaud Discussion: https://www.postgresql.org/message-id/flat/CABUevEySt4NTYqvWzwyAW_0-jG1bjN-y+tykapAnA0FALOs+Lw@mail.gmail.com --- .../expected/oldextversions.out | 84 ++++++++++--------- .../pg_stat_statements--1.9--1.10.sql | 10 ++- .../pg_stat_statements/pg_stat_statements.c | 50 ++++++++++- doc/src/sgml/pgstatstatements.sgml | 72 ++++++++++++++++ 4 files changed, 175 insertions(+), 41 deletions(-) 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 + + + + jit_functions bigint + + + Total number of functions JIT-compiled by the statement + + + + + + jit_generation_time bigint + + + Total time spent by the statement on generating JIT code, in milliseconds + + + + + + jit_inlining_count bigint + + + Number of times functions have been inlined + + + + + + jit_inlining_time bigint + + + Total time spent by the statement on inlining functions, in milliseconds + + + + + + jit_optimization_count bigint + + + Number of times the statement has been optimized + + + + + + jit_optimization_time bigint + + + Total time spent by the statement on optimizing, in milliseconds + + + + + + jit_emission_count bigint + + + Number of times code has been emitted + + + + + + jit_emission_time bigint + + + Total time spent by the statement on emitting code, in milliseconds + +