From bea0ae9fd062ee1810c9ff2d5f1be98a19114d84 Mon Sep 17 00:00:00 2001 From: Andrei Zubkov Date: Fri, 3 Dec 2021 16:25:17 +0300 Subject: [PATCH] pg_stat_statements: Track statement entry timestamp This patch adds stats_since column to the pg_stat_statements view. This column is populated with the current timestamp when a new statement is added to the pg_stat_statements hashtable. This column provides clean information about statistics collection time interval for each statement. Besides it can be used by sampling solutions to detect situations when a statement was evicted and returned back between two samples. Such sampling solution could derive any pg_stat_statements statistic value for an interval between two samples with except of all min/max statistics. To address this issue this patch adds the following columns: min_plan_time_local float8, max_plan_time_local float8, min_exec_time_local float8, max_exec_time_local float8 And a function to reset those statistics during a sample: CREATE FUNCTION pg_stat_statements_reset_local(IN userid Oid DEFAULT 0, IN dbid Oid DEFAULT 0, IN queryid bigint DEFAULT 0 ) The timestamp of last local statistics reset is stored for every statement in a column: local_stats_since timestamp with time zone Discussion: https://www.postgresql.org/message-id/flat/72e80e7b160a6eb189df9ef6f068cce3765d37f8.camel%40moonset.ru --- contrib/pg_stat_statements/Makefile | 3 +- .../expected/pg_stat_statements.out | 29 +++ .../pg_stat_statements--1.9--1.10.sql | 72 +++++++ .../pg_stat_statements/pg_stat_statements.c | 200 +++++++++++++++++- .../pg_stat_statements.control | 2 +- .../sql/pg_stat_statements.sql | 9 + doc/src/sgml/pgstatstatements.sgml | 111 +++++++++- 7 files changed, 419 insertions(+), 7 deletions(-) create mode 100644 contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile index 7fabd96f38..edc40c8bbf 100644 --- a/contrib/pg_stat_statements/Makefile +++ b/contrib/pg_stat_statements/Makefile @@ -6,7 +6,8 @@ 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/expected/pg_stat_statements.out b/contrib/pg_stat_statements/expected/pg_stat_statements.out index e0abe34bb6..9388490073 100644 --- a/contrib/pg_stat_statements/expected/pg_stat_statements.out +++ b/contrib/pg_stat_statements/expected/pg_stat_statements.out @@ -1077,4 +1077,33 @@ SELECT COUNT(*) FROM pg_stat_statements WHERE query LIKE '%SELECT GROUPING%'; 2 (1 row) +-- +-- statement timestamps +-- +SELECT pg_stat_statements_reset(); + pg_stat_statements_reset +-------------------------- + +(1 row) + +SELECT 1 AS "STMTTS1"; + STMTTS1 +--------- + 1 +(1 row) + +SELECT now() AS ref_ts \gset +SELECT 1,2 AS "STMTTS2"; + ?column? | STMTTS2 +----------+--------- + 1 | 2 +(1 row) + +SELECT first_seen >= :'ref_ts', count(*) FROM pg_stat_statements WHERE query LIKE '%STMTTS%' GROUP BY first_seen >= :'ref_ts' ORDER BY first_seen >= :'ref_ts'; + ?column? | count +----------+------- + f | 1 + t | 1 +(2 rows) + DROP EXTENSION pg_stat_statements; 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..00f5f1c933 --- /dev/null +++ b/contrib/pg_stat_statements/pg_stat_statements--1.9--1.10.sql @@ -0,0 +1,72 @@ +/* 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 + +/* We need to redefine a view and a function */ +/* 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 min_plan_time_local float8, + OUT max_plan_time_local 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 min_exec_time_local float8, + OUT max_exec_time_local 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 stats_since timestamp with time zone, + OUT local_stats_since timestamp with time zone +) +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); + +CREATE FUNCTION pg_stat_statements_reset_local(IN userid Oid DEFAULT 0, + IN dbid Oid DEFAULT 0, + IN queryid bigint DEFAULT 0 +) +RETURNS void +AS 'MODULE_PATHNAME', 'pg_stat_statements_reset_local_1_10' +LANGUAGE C STRICT PARALLEL SAFE; + +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 726ba59e2b..43467da0eb 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -88,7 +88,7 @@ PG_MODULE_MAGIC; #define PGSS_TEXT_FILE PG_STAT_TMP_DIR "/pgss_query_texts.stat" /* Magic number identifying the stats file format */ -static const uint32 PGSS_FILE_HEADER = 0x20201227; +static const uint32 PGSS_FILE_HEADER = 0x20210322; /* PostgreSQL major version number, changes in which invalidate all entries */ static const uint32 PGSS_PG_MAJOR_VERSION = PG_VERSION_NUM / 100; @@ -121,7 +121,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 @@ -168,6 +169,10 @@ typedef struct Counters * msec */ double max_time[PGSS_NUMKIND]; /* maximum planning/execution time in * msec */ + double min_time_local[PGSS_NUMKIND]; /* minimum planning/execution time + * since local reset in msec */ + double max_time_local[PGSS_NUMKIND]; /* maximum planning/execution time + * since local reset in msec */ double mean_time[PGSS_NUMKIND]; /* mean planning/execution time in * msec */ double sum_var_time[PGSS_NUMKIND]; /* sum of variances in @@ -214,6 +219,8 @@ typedef struct pgssEntry Size query_offset; /* query text offset in external file */ int query_len; /* # of valid bytes in query string, or -1 */ int encoding; /* query text encoding */ + TimestampTz gstats_since; /* timestamp of entry allocation moment */ + TimestampTz lstats_since; /* timestamp of last local statistics reset */ slock_t mutex; /* protects the counters only */ } pgssEntry; @@ -298,10 +305,12 @@ void _PG_fini(void); PG_FUNCTION_INFO_V1(pg_stat_statements_reset); PG_FUNCTION_INFO_V1(pg_stat_statements_reset_1_7); +PG_FUNCTION_INFO_V1(pg_stat_statements_reset_local_1_10); 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); @@ -345,6 +354,7 @@ static char *qtext_fetch(Size query_offset, int query_len, char *buffer, Size buffer_size); static bool need_gc_qtexts(void); static void gc_qtexts(void); +static void entry_reset_local(Oid userid, Oid dbid, uint64 queryid); static void entry_reset(Oid userid, Oid dbid, uint64 queryid); static char *generate_normalized_query(JumbleState *jstate, const char *query, int query_loc, int *query_len_p); @@ -649,6 +659,8 @@ pgss_shmem_startup(void) /* copy in the actual stats */ entry->counters = temp.counters; + entry->gstats_since = temp.gstats_since; + entry->lstats_since = temp.lstats_since; } /* Read global statistics for pg_stat_statements */ @@ -1340,6 +1352,8 @@ pgss_store(const char *query, uint64 queryId, e->counters.min_time[kind] = total_time; e->counters.max_time[kind] = total_time; e->counters.mean_time[kind] = total_time; + e->counters.min_time_local[kind] = total_time; + e->counters.max_time_local[kind] = total_time; } else { @@ -1359,6 +1373,23 @@ pgss_store(const char *query, uint64 queryId, e->counters.min_time[kind] = total_time; if (e->counters.max_time[kind] < total_time) e->counters.max_time[kind] = total_time; + + /* + * Calculate local min and max time. min_local > max_local + * means that local reset was happen + */ + if (e->counters.min_time_local[kind] > e->counters.max_time_local[kind]) + { + e->counters.min_time_local[kind] = total_time; + e->counters.max_time_local[kind] = total_time; + } + else + { + if (e->counters.min_time_local[kind] > total_time) + e->counters.min_time_local[kind] = total_time; + if (e->counters.max_time_local[kind] < total_time) + e->counters.max_time_local[kind] = total_time; + } } e->counters.rows += rows; e->counters.shared_blks_hit += bufusage->shared_blks_hit; @@ -1389,6 +1420,25 @@ done: pfree(norm_query); } +/* + * Reset local statement statistics corresponding to userid, dbid, and queryid. + */ +Datum +pg_stat_statements_reset_local_1_10(PG_FUNCTION_ARGS) +{ + Oid userid; + Oid dbid; + uint64 queryid; + + userid = PG_GETARG_OID(0); + dbid = PG_GETARG_OID(1); + queryid = (uint64) PG_GETARG_INT64(2); + + entry_reset_local(userid, dbid, queryid); + + PG_RETURN_VOID(); +} + /* * Reset statement statistics corresponding to userid, dbid, and queryid. */ @@ -1426,7 +1476,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 39 +#define PG_STAT_STATEMENTS_COLS 39 /* maximum of above */ /* * Retrieve statement statistics. @@ -1438,6 +1489,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) { @@ -1571,6 +1632,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"); } @@ -1656,6 +1721,8 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo, Counters tmp; double stddev; int64 queryid = entry->key.queryid; + TimestampTz gstats_since; + TimestampTz lstats_since; memset(values, 0, sizeof(values)); memset(nulls, 0, sizeof(nulls)); @@ -1724,6 +1791,8 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo, SpinLockAcquire(&e->mutex); tmp = e->counters; + gstats_since = e->gstats_since; + lstats_since = e->lstats_since; SpinLockRelease(&e->mutex); } @@ -1758,6 +1827,21 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo, else stddev = 0.0; values[i++] = Float8GetDatumFast(stddev); + + if (tmp.max_time_local[kind] < tmp.min_time_local[kind]) + { + /* + * There was not executions since last local min/max reset + * so, we should return nulls. + */ + nulls[i++] = true; + nulls[i++] = true; + } + else + { + values[i++] = Float8GetDatumFast(tmp.min_time_local[kind]); + values[i++] = Float8GetDatumFast(tmp.max_time_local[kind]); + } } } values[i++] = Int64GetDatumFast(tmp.rows); @@ -1795,6 +1879,11 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo, Int32GetDatum(-1)); values[i++] = wal_bytes; } + if (api_version >= PGSS_V1_10) + { + values[i++] = TimestampTzGetDatum(gstats_since); + values[i++] = TimestampTzGetDatum(lstats_since); + } Assert(i == (api_version == PGSS_V1_0 ? PG_STAT_STATEMENTS_COLS_V1_0 : api_version == PGSS_V1_1 ? PG_STAT_STATEMENTS_COLS_V1_1 : @@ -1802,6 +1891,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); @@ -1917,6 +2007,8 @@ entry_alloc(pgssHashKey *key, Size query_offset, int query_len, int encoding, entry->query_offset = query_offset; entry->query_len = query_len; entry->encoding = encoding; + entry->gstats_since = GetCurrentTimestamp(); + entry->lstats_since = entry->gstats_since; } return entry; @@ -2463,6 +2555,106 @@ gc_fail: record_gc_qtexts(); } +/* + * Reset local statistic values of specified entries + */ +static void +entry_reset_local(Oid userid, Oid dbid, uint64 queryid) +{ + HASH_SEQ_STATUS hash_seq; + pgssEntry *entry; + Counters *entry_counters; + pgssHashKey key; + TimestampTz stats_reset_local; + + if (!pgss || !pgss_hash) + ereport(ERROR, + (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE), + errmsg("pg_stat_statements must be loaded via shared_preload_libraries"))); + + LWLockAcquire(pgss->lock, LW_EXCLUSIVE); + + stats_reset_local = GetCurrentTimestamp(); + + if (userid != 0 && dbid != 0 && queryid != UINT64CONST(0)) + { + /* If all the parameters are available, use the fast path. */ + memset(&key, 0, sizeof(pgssHashKey)); + key.userid = userid; + key.dbid = dbid; + key.queryid = queryid; + + /* + * Reset locals, starting with the nested-level entry + * For min/max values reset sign is min > max + */ + key.toplevel = false; + entry = (pgssEntry *) hash_search(pgss_hash, &key, HASH_FIND, NULL); + if (entry) /* found */ + { + entry_counters = &entry->counters; + for (int kind = 0; kind < PGSS_NUMKIND; kind++) + { + entry_counters->max_time_local[kind] = 0; + entry_counters->min_time_local[kind] = 1; + } + entry->lstats_since = stats_reset_local; + } + + /* Reset locals for top level statements */ + key.toplevel = true; + + entry = (pgssEntry *) hash_search(pgss_hash, &key, HASH_FIND, NULL); + if (entry) /* found */ + { + entry_counters = &entry->counters; + for (int kind = 0; kind < PGSS_NUMKIND; kind++) + { + entry_counters->max_time_local[kind] = 0; + entry_counters->min_time_local[kind] = 1; + } + entry->lstats_since = stats_reset_local; + } + } + else if (userid != 0 || dbid != 0 || queryid != UINT64CONST(0)) + { + /* Reset locals for entries corresponding to valid parameters. */ + hash_seq_init(&hash_seq, pgss_hash); + while ((entry = hash_seq_search(&hash_seq)) != NULL) + { + if ((!userid || entry->key.userid == userid) && + (!dbid || entry->key.dbid == dbid) && + (!queryid || entry->key.queryid == queryid)) + { + entry_counters = &entry->counters; + for (int kind = 0; kind < PGSS_NUMKIND; kind++) + { + entry_counters->max_time_local[kind] = 0; + entry_counters->min_time_local[kind] = 1; + } + entry->lstats_since = stats_reset_local; + } + } + } + else + { + /* Reset locals for all entries. */ + hash_seq_init(&hash_seq, pgss_hash); + while ((entry = hash_seq_search(&hash_seq)) != NULL) + { + entry_counters = &entry->counters; + for (int kind = 0; kind < PGSS_NUMKIND; kind++) + { + entry_counters->max_time_local[kind] = 0; + entry_counters->min_time_local[kind] = 1; + } + entry->lstats_since = stats_reset_local; + } + } + + LWLockRelease(pgss->lock); +} + /* * Release entries corresponding to parameters passed. */ @@ -2492,7 +2684,7 @@ entry_reset(Oid userid, Oid dbid, uint64 queryid) key.dbid = dbid; key.queryid = queryid; - /* Remove the key if it exists, starting with the top-level entry */ + /* Remove the key if it exists, starting with the nested-level entry */ key.toplevel = false; entry = (pgssEntry *) hash_search(pgss_hash, &key, HASH_REMOVE, NULL); if (entry) /* found */ 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/contrib/pg_stat_statements/sql/pg_stat_statements.sql b/contrib/pg_stat_statements/sql/pg_stat_statements.sql index dffd2c8c18..44a766c9a8 100644 --- a/contrib/pg_stat_statements/sql/pg_stat_statements.sql +++ b/contrib/pg_stat_statements/sql/pg_stat_statements.sql @@ -442,4 +442,13 @@ SELECT ( SELECT COUNT(*) FROM pg_stat_statements WHERE query LIKE '%SELECT GROUPING%'; +-- +-- statement timestamps +-- +SELECT pg_stat_statements_reset(); +SELECT 1 AS "STMTTS1"; +SELECT now() AS ref_ts \gset +SELECT 1,2 AS "STMTTS2"; +SELECT first_seen >= :'ref_ts', count(*) FROM pg_stat_statements WHERE query LIKE '%STMTTS%' GROUP BY first_seen >= :'ref_ts' ORDER BY first_seen >= :'ref_ts'; + DROP EXTENSION pg_stat_statements; diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml index bc9d5bdbe3..b10c24d212 100644 --- a/doc/src/sgml/pgstatstatements.sgml +++ b/doc/src/sgml/pgstatstatements.sgml @@ -30,7 +30,8 @@ these statistics, the module provides views pg_stat_statements and pg_stat_statements_info, - and the utility functions pg_stat_statements_reset and + and the utility functions pg_stat_statements_reset, + pg_stat_statements_reset_local and pg_stat_statements. These are not available globally but can be enabled for a specific database with CREATE EXTENSION pg_stat_statements. @@ -180,6 +181,38 @@ + + + min_plan_time_local double precision + + + Minimum time spent planning the statement since + local_stats_since, in milliseconds + (if pg_stat_statements.track_planning is enabled, + otherwise zero) + + + Function pg_stat_statements_reset_local resets this + value + + + + + + max_plan_time_local double precision + + + Maximum time spent planning the statement since + local_stats_since, in milliseconds + (if pg_stat_statements.track_planning is enabled, + otherwise zero) + + + Function pg_stat_statements_reset_local resets this + value + + + calls bigint @@ -234,6 +267,34 @@ + + + min_exec_time_local double precision + + + Minimum time spent executing the statement since + local_stats_since, in milliseconds + + + Function pg_stat_statements_reset_local resets this + value + + + + + + max_exec_time_local double precision + + + Maximum time spent executing the statement since + local_stats_since, in milliseconds + + + Function pg_stat_statements_reset_local resets this + value + + + rows bigint @@ -379,6 +440,23 @@ Total amount of WAL generated by the statement in bytes + + + + stats_since timestamp with time zone + + + Timestamp of statistics gathering start for the statement + + + + + local_stats_since timestamp with time zone + + + Timestamp of local statistics gathering start for the statement. + + @@ -595,6 +673,37 @@ + + + pg_stat_statements_reset_local(userid Oid, dbid Oid, queryid bigint) returns void + + pg_stat_statements_reset_local + + + + + + pg_stat_statements_reset_local discards only the local + statistics (min_plan_time_local, + max_plan_time_local, + min_exec_time_local and + max_exec_time_local) + gathered so far by pg_stat_statements corresponding + to the specified userid, dbid + and queryid. If any of the parameters are not + specified, the default value 0(invalid) is used for + each of them and the local statistics that match with other parameters will be + reset. If no parameter is specified or all the specified parameters are + 0(invalid), it will discard all local statistics. + Discarding the local statistics of a statement this function will update + the value of local_stats_since with the current + timestamp. + By default, this function can only be executed by superusers. + Access may be granted to others using GRANT. + + + + pg_stat_statements(showtext boolean) returns setof record -- 2.30.2