From 913064b68d79487680625c19b1b09e5ff520c5ca Mon Sep 17 00:00:00 2001 From: Muhammad Usama Date: Wed, 7 Dec 2022 15:40:13 +0500 Subject: [PATCH] PG-435: Adding new counters that are available in PG15 (#329) In line with pg_stat_statments for PG15, This commit adds eight new cumulative counters for jit operations, making it easier to diagnose how JIT is used in an installation. And two new columns, temp_blk_read_time, and temp_blk_write_time, respectively, show the time spent reading and writing temporary file blocks on disk. Moreover, The commit also contains a few indentations and API adjustments. --- pg_stat_monitor--1.0--2.0.sql | 110 +++++++++++++++++++++++++++++++--- pg_stat_monitor--2.0.sql | 104 ++++++++++++++++++++++++++++++-- pg_stat_monitor.c | 89 ++++++++++++++++++++++----- pg_stat_monitor.h | 23 ++++++- t/018_column_names.pl | 10 +++- 5 files changed, 303 insertions(+), 33 deletions(-) diff --git a/pg_stat_monitor--1.0--2.0.sql b/pg_stat_monitor--1.0--2.0.sql index 89cdc98..b8ac5f3 100644 --- a/pg_stat_monitor--1.0--2.0.sql +++ b/pg_stat_monitor--1.0--2.0.sql @@ -62,15 +62,28 @@ CREATE FUNCTION pg_stat_monitor_internal( OUT temp_blks_written int8, OUT blk_read_time float8, OUT blk_write_time float8, + OUT temp_blk_read_time float8, + OUT temp_blk_write_time float8, + OUT resp_calls text, -- 41 OUT cpu_user_time float8, OUT cpu_sys_time float8, - OUT wal_records int8, - OUT wal_fpi int8, - OUT wal_bytes numeric, - OUT comments TEXT, - OUT toplevel BOOLEAN, - OUT bucket_done BOOLEAN + OUT wal_records int8, + OUT wal_fpi int8, + OUT wal_bytes numeric, + OUT comments TEXT, + + 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, + + OUT toplevel BOOLEAN, + OUT bucket_done BOOLEAN ) RETURNS SETOF record AS 'MODULE_PATHNAME', 'pg_stat_monitor_2_0' @@ -258,18 +271,97 @@ RETURN 0; END; $$ LANGUAGE plpgsql; +CREATE FUNCTION pgsm_create_15_view() RETURNS INT AS +$$ +BEGIN +CREATE VIEW pg_stat_monitor AS SELECT + bucket, + bucket_start_time AS bucket_start_time, + userid::regrole, + datname, + '0.0.0.0'::inet + client_ip AS client_ip, + queryid, + toplevel, + top_queryid, + query, + comments, + planid, + query_plan, + top_query, + application_name, + string_to_array(relations, ',') AS relations, + cmd_type, + get_cmd_type(cmd_type) AS cmd_type_text, + elevel, + sqlcode, + message, + calls, + total_exec_time, + min_exec_time, + max_exec_time, + mean_exec_time, + stddev_exec_time, + rows_retrieved, + shared_blks_hit, + shared_blks_read, + shared_blks_dirtied, + shared_blks_written, + local_blks_hit, + local_blks_read, + local_blks_dirtied, + local_blks_written, + temp_blks_read, + temp_blks_written, + blk_read_time, + blk_write_time, + temp_blk_read_time, + temp_blk_write_time, + + (string_to_array(resp_calls, ',')) resp_calls, + cpu_user_time, + cpu_sys_time, + wal_records, + wal_fpi, + wal_bytes, + bucket_done, + + plans_calls, + total_plan_time, + min_plan_time, + max_plan_time, + mean_plan_time, + stddev_plan_time, + + jit_functions, + jit_generation_time, + jit_inlining_count, + jit_inlining_time, + jit_optimization_count, + jit_optimization_time, + jit_emission_count, + jit_emission_time + +FROM pg_stat_monitor_internal(TRUE) p, pg_database d WHERE dbid = oid +ORDER BY bucket_start_time; +RETURN 0; +END; +$$ LANGUAGE plpgsql; + CREATE FUNCTION pgsm_create_view() RETURNS INT AS $$ DECLARE ver integer; BEGIN SELECT current_setting('server_version_num') INTO ver; - IF (ver >= 14000) THEN + IF (ver >= 150000) THEN + return pgsm_create_15_view(); + END IF; + IF (ver >= 140000) THEN return pgsm_create_14_view(); END IF; - IF (ver >= 13000) THEN + IF (ver >= 130000) THEN return pgsm_create_13_view(); END IF; - IF (ver >= 11000) THEN + IF (ver >= 110000) THEN return pgsm_create_11_view(); END IF; RETURN 0; diff --git a/pg_stat_monitor--2.0.sql b/pg_stat_monitor--2.0.sql index b98876a..4104cc0 100644 --- a/pg_stat_monitor--2.0.sql +++ b/pg_stat_monitor--2.0.sql @@ -116,7 +116,6 @@ CREATE FUNCTION pg_stat_monitor_internal( OUT planid text, OUT query text, OUT query_plan text, - OUT state_code int8, OUT top_queryid text, OUT top_query text, OUT application_name text, @@ -158,15 +157,29 @@ CREATE FUNCTION pg_stat_monitor_internal( OUT temp_blks_written int8, OUT blk_read_time float8, OUT blk_write_time float8, + + OUT temp_blk_read_time float8, + OUT temp_blk_write_time float8, + OUT resp_calls text, -- 41 OUT cpu_user_time float8, OUT cpu_sys_time float8, - OUT wal_records int8, - OUT wal_fpi int8, - OUT wal_bytes numeric, - OUT comments TEXT, + OUT wal_records int8, + OUT wal_fpi int8, + OUT wal_bytes numeric, + OUT comments TEXT, + + 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, + OUT toplevel BOOLEAN, - OUT bucket_done BOOLEAN + OUT bucket_done BOOLEAN ) RETURNS SETOF record AS 'MODULE_PATHNAME', 'pg_stat_monitor_2_0' @@ -355,11 +368,90 @@ RETURN 0; END; $$ LANGUAGE plpgsql; +CREATE FUNCTION pgsm_create_15_view() RETURNS INT AS +$$ +BEGIN +CREATE VIEW pg_stat_monitor AS SELECT + bucket, + bucket_start_time AS bucket_start_time, + userid::regrole, + datname, + '0.0.0.0'::inet + client_ip AS client_ip, + queryid, + toplevel, + top_queryid, + query, + comments, + planid, + query_plan, + top_query, + application_name, + string_to_array(relations, ',') AS relations, + cmd_type, + get_cmd_type(cmd_type) AS cmd_type_text, + elevel, + sqlcode, + message, + calls, + total_exec_time, + min_exec_time, + max_exec_time, + mean_exec_time, + stddev_exec_time, + rows_retrieved, + shared_blks_hit, + shared_blks_read, + shared_blks_dirtied, + shared_blks_written, + local_blks_hit, + local_blks_read, + local_blks_dirtied, + local_blks_written, + temp_blks_read, + temp_blks_written, + blk_read_time, + blk_write_time, + temp_blk_read_time, + temp_blk_write_time, + + (string_to_array(resp_calls, ',')) resp_calls, + cpu_user_time, + cpu_sys_time, + wal_records, + wal_fpi, + wal_bytes, + bucket_done, + + plans_calls, + total_plan_time, + min_plan_time, + max_plan_time, + mean_plan_time, + stddev_plan_time, + + jit_functions, + jit_generation_time, + jit_inlining_count, + jit_inlining_time, + jit_optimization_count, + jit_optimization_time, + jit_emission_count, + jit_emission_time + +FROM pg_stat_monitor_internal(TRUE) p, pg_database d WHERE dbid = oid +ORDER BY bucket_start_time; +RETURN 0; +END; +$$ LANGUAGE plpgsql; + CREATE FUNCTION pgsm_create_view() RETURNS INT AS $$ DECLARE ver integer; BEGIN SELECT current_setting('server_version_num') INTO ver; + IF (ver >= 150000) THEN + return pgsm_create_15_view(); + END IF; IF (ver >= 140000) THEN return pgsm_create_14_view(); END IF; diff --git a/pg_stat_monitor.c b/pg_stat_monitor.c index 59c88c9..ddf1765 100644 --- a/pg_stat_monitor.c +++ b/pg_stat_monitor.c @@ -36,7 +36,12 @@ PG_MODULE_MAGIC; #define BUILD_VERSION "2.0.0-dev" -#define PG_STAT_STATEMENTS_COLS 53 /* maximum of above */ + +/* Number of output arguments (columns) for various API versions */ +#define PG_STAT_MONITOR_COLS_V1_0 52 +#define PG_STAT_MONITOR_COLS_V2_0 61 +#define PG_STAT_MONITOR_COLS 61 /* maximum of above */ + #define PGSM_TEXT_FILE PGSTAT_STAT_PERMANENT_DIRECTORY "pg_stat_monitor_query" #define roundf(x,d) ((floor(((x)*pow(10,d))+.5))/pow(10,d)) @@ -186,6 +191,7 @@ static void pgss_store(uint64 queryid, uint64 rows, BufferUsage *bufusage, WalUsage *walusage, + const struct JitInstrumentation *jitusage, JumbleState *jstate, pgssStoreKind kind); @@ -241,7 +247,7 @@ _PG_init(void) * In order to create our shared memory area, we have to be loaded via * shared_preload_libraries. If not, fall out without hooking into any of * the main system. (We don't throw error here because it seems useful to - * allow the pg_stat_statements functions to be created even when the + * allow the pg_stat_monitor functions to be created even when the * module isn't active. The functions must protect themselves against * being called then, however.) */ @@ -432,6 +438,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query, JumbleState *jstate) 0, /* rows */ NULL, /* bufusage */ NULL, /* walusage */ + NULL, /* jitusage */ jstate, /* JumbleState */ PGSS_PARSE); /* pgssStoreKind */ } @@ -490,6 +497,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query) 0, /* rows */ NULL, /* bufusage */ NULL, /* walusage */ + NULL, /* jitusage */ &jstate, /* JumbleState */ PGSS_PARSE); /* pgssStoreKind */ } @@ -661,6 +669,11 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) &queryDesc->totaltime->walusage, /* walusage */ #else NULL, +#endif +#if PG_VERSION_NUM >= 150000 + queryDesc->estate->es_jit ? &queryDesc->estate->es_jit->instr : NULL, +#else + NULL, #endif NULL, PGSS_FINISHED); /* pgssStoreKind */ @@ -804,6 +817,7 @@ pgss_planner_hook(Query *parse, const char *query_string, int cursorOptions, Par &bufusage, /* bufusage */ &walusage, /* walusage */ NULL, /* JumbleState */ + NULL, PGSS_PLAN); /* pgssStoreKind */ } else @@ -993,6 +1007,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, #else NULL, /* walusage, NULL for PG <= 12 */ #endif + NULL, NULL, /* JumbleState */ PGSS_FINISHED); /* pgssStoreKind */ } @@ -1139,7 +1154,7 @@ pg_get_client_addr(bool *ok) static void pgss_update_entry(pgssEntry *entry, - int bucketid, + uint64 bucketid, uint64 queryid, const char *query, const char *comments, @@ -1151,6 +1166,7 @@ pgss_update_entry(pgssEntry *entry, uint64 rows, BufferUsage *bufusage, WalUsage *walusage, + const struct JitInstrumentation *jitusage, bool reset, pgssStoreKind kind, const char *app_name, @@ -1272,6 +1288,10 @@ pgss_update_entry(pgssEntry *entry, e->counters.blocks.temp_blks_written += bufusage->temp_blks_written; e->counters.blocks.blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_read_time); e->counters.blocks.blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_write_time); + #if PG_VERSION_NUM >= 150000 + e->counters.blocks.temp_blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->temp_blk_read_time); + e->counters.blocks.temp_blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->temp_blk_write_time); + #endif } e->counters.calls.usage += USAGE_EXEC(total_time); if (sys_info) @@ -1285,6 +1305,23 @@ pgss_update_entry(pgssEntry *entry, e->counters.walusage.wal_fpi += walusage->wal_fpi; e->counters.walusage.wal_bytes += walusage->wal_bytes; } + if (jitusage) + { + e->counters.jitinfo.jit_functions += jitusage->created_functions; + e->counters.jitinfo.jit_generation_time += INSTR_TIME_GET_MILLISEC(jitusage->generation_counter); + + if (INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter)) + e->counters.jitinfo.jit_inlining_count++; + e->counters.jitinfo.jit_inlining_time += INSTR_TIME_GET_MILLISEC(jitusage->inlining_counter); + + if (INSTR_TIME_GET_MILLISEC(jitusage->optimization_counter)) + e->counters.jitinfo.jit_optimization_count++; + e->counters.jitinfo.jit_optimization_time += INSTR_TIME_GET_MILLISEC(jitusage->optimization_counter); + + if (INSTR_TIME_GET_MILLISEC(jitusage->emission_counter)) + e->counters.jitinfo.jit_emission_count++; + e->counters.jitinfo.jit_emission_time += INSTR_TIME_GET_MILLISEC(jitusage->emission_counter); + } SpinLockRelease(&e->mutex); } } @@ -1313,6 +1350,7 @@ pgss_store_error(uint64 queryid, NULL, /* bufusage */ NULL, /* walusage */ NULL, /* JumbleState */ + NULL, PGSS_ERROR); /* pgssStoreKind */ } @@ -1339,6 +1377,7 @@ pgss_store(uint64 queryid, uint64 rows, BufferUsage *bufusage, WalUsage *walusage, + const struct JitInstrumentation *jitusage, JumbleState *jstate, pgssStoreKind kind) { @@ -1553,6 +1592,7 @@ pgss_store(uint64 queryid, rows, /* rows */ bufusage, /* bufusage */ walusage, /* walusage */ + jitusage, reset, /* reset */ kind, /* kind */ app_name_ptr, @@ -1627,7 +1667,7 @@ IsBucketValid(uint64 bucketid) return true; } -/* Common code for all versions of pg_stat_statements() */ +/* Common code for all versions of pg_stat_monitor() */ static void pg_stat_monitor_internal(FunctionCallInfo fcinfo, pgsmVersion api_version, @@ -1645,6 +1685,7 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, HTAB *pgss_hash = pgsm_get_hash(); char *query_txt = (char *) palloc0(PGSM_QUERY_MAX_LEN + 1); char *parent_query_txt = (char *) palloc0(PGSM_QUERY_MAX_LEN + 1); + int expected_columns = (api_version >= PGSM_V2_0)?PG_STAT_MONITOR_COLS_V2_0:PG_STAT_MONITOR_COLS_V1_0; /* Safety check... */ if (!IsSystemInitialized()) @@ -1671,7 +1712,7 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE) elog(ERROR, "pg_stat_monitor: return type must be a row type"); - if (tupdesc->natts != 52) + if (tupdesc->natts != expected_columns) elog(ERROR, "pg_stat_monitor: incorrect number of output arguments, required %d", tupdesc->natts); tupstore = tuplestore_begin_heap(true, false, work_mem); @@ -1686,18 +1727,18 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, hash_seq_init(&hash_seq, pgss_hash); while ((entry = hash_seq_search(&hash_seq)) != NULL) { - Datum values[PG_STAT_STATEMENTS_COLS] = {0}; - bool nulls[PG_STAT_STATEMENTS_COLS] = {0}; + Datum values[PG_STAT_MONITOR_COLS] = {0}; + bool nulls[PG_STAT_MONITOR_COLS] = {0}; int i = 0; Counters tmp; double stddev; char queryid_text[32] = {0}; char planid_text[32] = {0}; uint64 queryid = entry->key.queryid; - uint64 bucketid = entry->key.bucket_id; + int64 bucketid = entry->key.bucket_id; uint64 dbid = entry->key.dbid; uint64 userid = entry->key.userid; - uint64 ip = entry->key.ip; + int64 ip = entry->key.ip; uint64 planid = entry->key.planid; #if PG_VERSION_NUM < 140000 bool toplevel = 1; @@ -1816,8 +1857,9 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, values[i++] = CStringGetTextDatum(""); } - /* state at column number 8 */ - values[i++] = Int64GetDatumFast(tmp.state); + /* state at column number 8 for V1.0 API*/ + if (api_version <= PGSM_V1_0) + values[i++] = Int64GetDatumFast(tmp.state); /* parentid at column number 9 */ if (tmp.info.parentid != UINT64CONST(0)) @@ -1871,7 +1913,7 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, if (tmp.info.cmd_type == CMD_NOTHING) nulls[i++] = true; else - values[i++] = Int64GetDatumFast(tmp.info.cmd_type); + values[i++] = Int64GetDatumFast((int64)tmp.info.cmd_type); /* elevel at column number 12 */ values[i++] = Int64GetDatumFast(tmp.error.elevel); @@ -1969,6 +2011,12 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, values[i++] = Float8GetDatumFast(tmp.blocks.blk_read_time); values[i++] = Float8GetDatumFast(tmp.blocks.blk_write_time); + if (api_version >= PGSM_V2_0) + { + values[i++] = Float8GetDatumFast(tmp.blocks.temp_blk_read_time); + values[i++] = Float8GetDatumFast(tmp.blocks.temp_blk_write_time); + } + /* resp_calls at column number 41 */ values[i++] = IntArrayGetTextDatum(tmp.resp_calls, PGSM_HISTOGRAM_BUCKETS); @@ -2002,6 +2050,19 @@ pg_stat_monitor_internal(FunctionCallInfo fcinfo, values[i++] = CStringGetTextDatum(tmp.info.comments); else nulls[i++] = true; + + if (api_version >= PGSM_V2_0) + { + values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_functions); + values[i++] = Float8GetDatumFast(tmp.jitinfo.jit_generation_time); + values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_inlining_count); + values[i++] = Float8GetDatumFast(tmp.jitinfo.jit_inlining_time); + values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_optimization_count); + values[i++] = Float8GetDatumFast(tmp.jitinfo.jit_optimization_time); + values[i++] = Int64GetDatumFast(tmp.jitinfo.jit_emission_count); + values[i++] = Float8GetDatumFast(tmp.jitinfo.jit_emission_time); + } + } values[i++] = BoolGetDatum(toplevel); values[i++] = BoolGetDatum(pg_atomic_read_u64(&pgss->current_wbucket) != bucketid); @@ -3343,8 +3404,8 @@ pg_stat_monitor_settings(PG_FUNCTION_ARGS) } else { - values[j++] = Int64GetDatumFast(get_conf(i)->guc_min); - values[j++] = Int64GetDatumFast(get_conf(i)->guc_max); + values[j++] = Int32GetDatum(get_conf(i)->guc_min); + values[j++] = Int32GetDatum(get_conf(i)->guc_max); } if (conf->type == PGC_ENUM) diff --git a/pg_stat_monitor.h b/pg_stat_monitor.h index e816ca3..dd66c9d 100644 --- a/pg_stat_monitor.h +++ b/pg_stat_monitor.h @@ -31,6 +31,7 @@ #include "catalog/pg_authid.h" #include "executor/instrument.h" #include "common/ip.h" +#include "jit/jit.h" #include "funcapi.h" #include "access/twophase.h" #include "mb/pg_wchar.h" @@ -255,8 +256,27 @@ typedef struct Blocks int64 temp_blks_written; /* # of temp blocks written */ double blk_read_time; /* time spent reading, in msec */ double blk_write_time; /* time spent writing, in msec */ + + double temp_blk_read_time; /* time spent reading temp blocks, in msec */ + double temp_blk_write_time; /* time spent writing temp blocks, in + * msec */ } Blocks; +typedef struct JitInfo +{ + 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 */ +} JitInfo; + typedef struct SysInfo { float utime; /* user cpu time */ @@ -283,11 +303,12 @@ typedef struct Counters Blocks blocks; SysInfo sysinfo; + JitInfo jitinfo; ErrorInfo error; Wal_Usage walusage; int resp_calls[MAX_RESPONSE_BUCKET]; /* execution time's in * msec */ - uint64 state; /* query state */ + int64 state; /* query state */ } Counters; /* Some global structure to get the cpu usage, really don't like the idea of global variable */ diff --git a/t/018_column_names.pl b/t/018_column_names.pl index e67320b..eedade4 100644 --- a/t/018_column_names.pl +++ b/t/018_column_names.pl @@ -26,14 +26,18 @@ close $conf; my %pg_versions_pgsm_columns = ( 15 => "application_name,blk_read_time," . "blk_write_time,bucket,bucket_done,bucket_start_time,calls," . "client_ip,cmd_type,cmd_type_text,comments,cpu_sys_time,cpu_user_time," . - "datname,elevel,local_blks_dirtied,local_blks_hit,local_blks_read," . + "datname,elevel,jit_emission_count,jit_emission_time,jit_functions," . + "jit_generation_time,jit_inlining_count,jit_inlining_time," . + "jit_optimization_count,jit_optimization_time," . + "local_blks_dirtied,local_blks_hit,local_blks_read," . "local_blks_written,max_exec_time,max_plan_time,mean_exec_time," . "mean_plan_time,message,min_exec_time,min_plan_time,planid," . "plans_calls,query,query_plan,queryid,relations,resp_calls," . "rows_retrieved,shared_blks_dirtied,shared_blks_hit,shared_blks_read," . "shared_blks_written,sqlcode,stddev_exec_time,stddev_plan_time," . - "temp_blks_read,temp_blks_written,top_query,top_queryid,toplevel," . - "total_exec_time,total_plan_time,userid,wal_bytes,wal_fpi,wal_records", + "temp_blk_read_time,temp_blk_write_time,temp_blks_read,temp_blks_written," . + "top_query,top_queryid,toplevel,total_exec_time,total_plan_time," . + "userid,wal_bytes,wal_fpi,wal_records", 14 => "application_name,blk_read_time," . "blk_write_time,bucket,bucket_done,bucket_start_time,calls," . "client_ip,cmd_type,cmd_type_text,comments,cpu_sys_time,cpu_user_time," .