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
This commit is contained in:
Magnus Hagander 2022-04-08 13:51:01 +02:00
parent dad9ba1c82
commit 57d6aea00f
4 changed files with 175 additions and 41 deletions

View File

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

View File

@ -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'

View File

@ -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 :

View File

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