From b8f88dcd4d44a11301776455cc133bb3e859d000 Mon Sep 17 00:00:00 2001 From: Ilia Evdokimov Date: Thu, 20 Feb 2025 01:29:55 +0300 Subject: [PATCH v18] Allow setting execution time threshold for pg_stat_statements New configuration parameter pg_stat_statements.track_min_duration makes it possible to track statements whose execution time is greater than threshold, to reduce the amount of tracking. --- contrib/pg_stat_statements/Makefile | 2 +- .../expected/min_duration.out | 174 ++++++++++++++++++ contrib/pg_stat_statements/meson.build | 1 + .../pg_stat_statements/pg_stat_statements.c | 59 ++++-- .../pg_stat_statements/sql/min_duration.sql | 50 +++++ doc/src/sgml/pgstatstatements.sgml | 22 +++ 6 files changed, 287 insertions(+), 21 deletions(-) create mode 100644 contrib/pg_stat_statements/expected/min_duration.out create mode 100644 contrib/pg_stat_statements/sql/min_duration.sql diff --git a/contrib/pg_stat_statements/Makefile b/contrib/pg_stat_statements/Makefile index 241c02587b..df512e428e 100644 --- a/contrib/pg_stat_statements/Makefile +++ b/contrib/pg_stat_statements/Makefile @@ -20,7 +20,7 @@ LDFLAGS_SL += $(filter -lm, $(LIBS)) REGRESS_OPTS = --temp-config $(top_srcdir)/contrib/pg_stat_statements/pg_stat_statements.conf REGRESS = select dml cursors utility level_tracking planning \ user_activity wal entry_timestamp privileges extended \ - parallel cleanup oldextversions + parallel min_duration cleanup oldextversions # Disabled because these tests require "shared_preload_libraries=pg_stat_statements", # which typical installcheck users do not have (e.g. buildfarm clients). NO_INSTALLCHECK = 1 diff --git a/contrib/pg_stat_statements/expected/min_duration.out b/contrib/pg_stat_statements/expected/min_duration.out new file mode 100644 index 0000000000..ef6f2a4437 --- /dev/null +++ b/contrib/pg_stat_statements/expected/min_duration.out @@ -0,0 +1,174 @@ +-- +-- track_min_duration +-- +-- top-level tracking - simple query protocol +SHOW pg_stat_statements.track; + pg_stat_statements.track +-------------------------- + top +(1 row) + +SET pg_stat_statements.track_min_duration = -1; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + t +--- + t +(1 row) + +SELECT 1 AS "int"; + int +----- + 1 +(1 row) + +SELECT query, calls FROM pg_stat_statements ORDER BY query COLLATE "C"; + query | calls +-------+------- +(0 rows) + +SET pg_stat_statements.track_min_duration = 0; +SELECT 1 AS "int"; + int +----- + 1 +(1 row) + +SELECT query, calls FROM pg_stat_statements ORDER BY query COLLATE "C"; + query | calls +--------------------+------- + SELECT $1 AS "int" | 1 +(1 row) + +-- top-level tracking - extended query protocol +SET pg_stat_statements.track_min_duration = -1; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + t +--- + t +(1 row) + +SELECT 1 \parse stmt +\bind_named stmt \g + ?column? +---------- + 1 +(1 row) + +SELECT query, calls FROM pg_stat_statements ORDER BY query COLLATE "C"; + query | calls +-------+------- +(0 rows) + +SET pg_stat_statements.track_min_duration = 0; +\bind_named stmt \g + ?column? +---------- + 1 +(1 row) + +SELECT query, calls FROM pg_stat_statements ORDER BY query COLLATE "C"; + query | calls +-----------+------- + SELECT $1 | 1 +(1 row) + +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + t +--- + t +(1 row) + +DEALLOCATE stmt; +-- nested tracking - simple query protocol +SET pg_stat_statements.track = "all"; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + t +--- + t +(1 row) + +SET pg_stat_statements.track_min_duration = 0; +EXPLAIN (COSTS OFF) SELECT 1; + QUERY PLAN +------------ + Result +(1 row) + +EXPLAIN (COSTS OFF) SELECT 1; + QUERY PLAN +------------ + Result +(1 row) + +SET pg_stat_statements.track_min_duration = -1; +EXPLAIN (COSTS OFF) SELECT 1; + QUERY PLAN +------------ + Result +(1 row) + +EXPLAIN (COSTS OFF) SELECT 1; + QUERY PLAN +------------ + Result +(1 row) + +SELECT toplevel, calls, query FROM pg_stat_statements + ORDER BY query COLLATE "C"; + toplevel | calls | query +----------+-------+---------------------------------------------------- + t | 2 | EXPLAIN (COSTS OFF) SELECT $1 + f | 2 | SELECT $1 + t | 1 | SELECT pg_stat_statements_reset() IS NOT NULL AS t + t | 2 | SET pg_stat_statements.track_min_duration = $1 +(4 rows) + +-- nested tracking - extended query protocol +SET pg_stat_statements.track = "all"; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; + t +--- + t +(1 row) + +SET pg_stat_statements.track_min_duration = 0; +EXPLAIN (COSTS OFF) SELECT 1; \parse stmt + QUERY PLAN +------------ + Result +(1 row) + +\bind_named stmt \g + QUERY PLAN +------------ + Result +(1 row) + +\bind_named stmt \g + QUERY PLAN +------------ + Result +(1 row) + +SET pg_stat_statements.track_min_duration = -1; +\bind_named stmt \g + QUERY PLAN +------------ + Result +(1 row) + +\bind_named stmt \g + QUERY PLAN +------------ + Result +(1 row) + +SELECT toplevel, calls, query FROM pg_stat_statements + ORDER BY query COLLATE "C"; + toplevel | calls | query +----------+-------+------------------------------------------------ + t | 2 | EXPLAIN (COSTS OFF) SELECT $1 + f | 3 | SELECT $1 + t | 1 | SET pg_stat_statements.track_min_duration = $1 +(3 rows) + diff --git a/contrib/pg_stat_statements/meson.build b/contrib/pg_stat_statements/meson.build index 4446af58c5..6427665ee1 100644 --- a/contrib/pg_stat_statements/meson.build +++ b/contrib/pg_stat_statements/meson.build @@ -54,6 +54,7 @@ tests += { 'privileges', 'extended', 'parallel', + 'min_duration', 'cleanup', 'oldextversions', ], diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index 4a3e855ce9..00ac11aed0 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -291,16 +291,18 @@ static const struct config_enum_entry track_options[] = static int pgss_max = 5000; /* max # statements to track */ static int pgss_track = PGSS_TRACK_TOP; /* tracking level */ +static int pgss_track_min_duration = 0; /* msec or -1 */ static bool pgss_track_utility = true; /* whether to track utility commands */ static bool pgss_track_planning = false; /* whether to track planning * duration */ static bool pgss_save = true; /* whether to save stats across shutdown */ -#define pgss_enabled(level) \ +#define pgss_enabled(level, skip_sample_check) \ (!IsParallelWorker() && \ (pgss_track == PGSS_TRACK_ALL || \ - (pgss_track == PGSS_TRACK_TOP && (level) == 0))) + (pgss_track == PGSS_TRACK_TOP && (level) == 0)) && \ + (skip_sample_check == PGSS_INVALID || pgss_track_min_duration >= 0)) #define record_gc_qtexts() \ do { \ @@ -415,6 +417,18 @@ _PG_init(void) NULL, NULL); + DefineCustomIntVariable("pg_stat_statements.track_min_duration", + "Sets the minimum execution time above which statements will be tracked.", + " -1 turns this feature off. 0 tracks all statements.", + &pgss_track_min_duration, + 0, + -1, INT_MAX, + PGC_SUSET, + GUC_UNIT_MS, + NULL, + NULL, + NULL); + DefineCustomEnumVariable("pg_stat_statements.track", "Selects which statements are tracked by pg_stat_statements.", NULL, @@ -837,7 +851,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query, JumbleState *jstate) prev_post_parse_analyze_hook(pstate, query, jstate); /* Safety check... */ - if (!pgss || !pgss_hash || !pgss_enabled(nesting_level)) + if (!pgss || !pgss_hash || !pgss_enabled(nesting_level, PGSS_INVALID)) return; /* @@ -895,7 +909,7 @@ pgss_planner(Query *parse, * pgss_store needs it. We also ignore query without queryid, as it would * be treated as a utility statement, which may not be the case. */ - if (pgss_enabled(nesting_level) + if (pgss_enabled(nesting_level, PGSS_PLAN) && pgss_track_planning && query_string && parse->queryId != UINT64CONST(0)) { @@ -1000,7 +1014,8 @@ pgss_ExecutorStart(QueryDesc *queryDesc, int eflags) * counting of optimizable statements that are directly contained in * utility statements. */ - if (pgss_enabled(nesting_level) && queryDesc->plannedstmt->queryId != UINT64CONST(0)) + if (pgss_enabled(nesting_level, PGSS_EXEC) && + queryDesc->plannedstmt->queryId != UINT64CONST(0)) { /* * Set up to track total elapsed time in ExecutorRun. Make sure the @@ -1069,27 +1084,31 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) uint64 queryId = queryDesc->plannedstmt->queryId; if (queryId != UINT64CONST(0) && queryDesc->totaltime && - pgss_enabled(nesting_level)) + pgss_enabled(nesting_level, PGSS_EXEC)) { + double msec; /* * Make sure stats accumulation is done. (Note: it's okay if several * levels of hook all do this.) */ InstrEndLoop(queryDesc->totaltime); - pgss_store(queryDesc->sourceText, - queryId, - queryDesc->plannedstmt->stmt_location, - queryDesc->plannedstmt->stmt_len, - PGSS_EXEC, - queryDesc->totaltime->total * 1000.0, /* convert to msec */ - queryDesc->estate->es_total_processed, - &queryDesc->totaltime->bufusage, - &queryDesc->totaltime->walusage, - queryDesc->estate->es_jit ? &queryDesc->estate->es_jit->instr : NULL, - NULL, - queryDesc->estate->es_parallel_workers_to_launch, - queryDesc->estate->es_parallel_workers_launched); + /* convert to msec */ + msec = queryDesc->totaltime->total * 1000.0; + if (msec >= pgss_track_min_duration) + pgss_store(queryDesc->sourceText, + queryId, + queryDesc->plannedstmt->stmt_location, + queryDesc->plannedstmt->stmt_len, + PGSS_EXEC, + msec, + queryDesc->estate->es_total_processed, + &queryDesc->totaltime->bufusage, + &queryDesc->totaltime->walusage, + queryDesc->estate->es_jit ? &queryDesc->estate->es_jit->instr : NULL, + NULL, + queryDesc->estate->es_parallel_workers_to_launch, + queryDesc->estate->es_parallel_workers_launched); } if (prev_ExecutorEnd) @@ -1112,7 +1131,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, uint64 saved_queryId = pstmt->queryId; int saved_stmt_location = pstmt->stmt_location; int saved_stmt_len = pstmt->stmt_len; - bool enabled = pgss_track_utility && pgss_enabled(nesting_level); + bool enabled = pgss_track_utility && pgss_enabled(nesting_level, PGSS_EXEC); /* * Force utility statements to get queryId zero. We do this even in cases diff --git a/contrib/pg_stat_statements/sql/min_duration.sql b/contrib/pg_stat_statements/sql/min_duration.sql new file mode 100644 index 0000000000..63903cc388 --- /dev/null +++ b/contrib/pg_stat_statements/sql/min_duration.sql @@ -0,0 +1,50 @@ +-- +-- track_min_duration +-- + +-- top-level tracking - simple query protocol +SHOW pg_stat_statements.track; +SET pg_stat_statements.track_min_duration = -1; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; +SELECT 1 AS "int"; +SELECT query, calls FROM pg_stat_statements ORDER BY query COLLATE "C"; +SET pg_stat_statements.track_min_duration = 0; +SELECT 1 AS "int"; +SELECT query, calls FROM pg_stat_statements ORDER BY query COLLATE "C"; + +-- top-level tracking - extended query protocol +SET pg_stat_statements.track_min_duration = -1; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; +SELECT 1 \parse stmt +\bind_named stmt \g +SELECT query, calls FROM pg_stat_statements ORDER BY query COLLATE "C"; +SET pg_stat_statements.track_min_duration = 0; +\bind_named stmt \g +SELECT query, calls FROM pg_stat_statements ORDER BY query COLLATE "C"; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; +DEALLOCATE stmt; + +-- nested tracking - simple query protocol +SET pg_stat_statements.track = "all"; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; +SET pg_stat_statements.track_min_duration = 0; +EXPLAIN (COSTS OFF) SELECT 1; +EXPLAIN (COSTS OFF) SELECT 1; +SET pg_stat_statements.track_min_duration = -1; +EXPLAIN (COSTS OFF) SELECT 1; +EXPLAIN (COSTS OFF) SELECT 1; +SELECT toplevel, calls, query FROM pg_stat_statements + ORDER BY query COLLATE "C"; + +-- nested tracking - extended query protocol +SET pg_stat_statements.track = "all"; +SELECT pg_stat_statements_reset() IS NOT NULL AS t; +SET pg_stat_statements.track_min_duration = 0; +EXPLAIN (COSTS OFF) SELECT 1; \parse stmt +\bind_named stmt \g +\bind_named stmt \g +SET pg_stat_statements.track_min_duration = -1; +\bind_named stmt \g +\bind_named stmt \g +SELECT toplevel, calls, query FROM pg_stat_statements + ORDER BY query COLLATE "C"; \ No newline at end of file diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml index e2ac1c2d50..1c5f57425f 100644 --- a/doc/src/sgml/pgstatstatements.sgml +++ b/doc/src/sgml/pgstatstatements.sgml @@ -945,6 +945,28 @@ + + + pg_stat_statements.track_min_duration (real) + + pg_stat_statements.track_min_duration configuration parameter + + + + + + pg_stat_statements.track_min_duration is the minimum statement + execution time, in milliseconds, that will cause the statement to + be tracked. Setting this to 0 tracks all statements. + -1 (the default) disables tracking of statements. + The same as setting pg_stat_statements.track to none. + For example, if you set it to 250ms then all statements + that run 250ms or longer will be tracked. Only superusers can change this + setting. + + + + pg_stat_statements.save (boolean) -- 2.34.1