From 76db9cb6368eb553ec334fe05e1258f2439bf07f Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Wed, 8 Nov 2023 12:01:28 -0500 Subject: [PATCH] Fix some issues with tracking nesting level in pg_stat_statements. When we decide that we don't want to track execution time of a specific planner or ProcessUtility call, we still have to increment the nesting depth, or we'll make the wrong determination of whether we are at top level when considering nested statements. (PREPARE and EXECUTE are exceptions, for reasons explained in the code.) Counting planner nesting depth separately from executor nesting depth was a mistake: it causes us to make the wrong determination of whether we are at top level when considering nested statements that get executed during planning (as a result of constant-folding of functions, for example). Merge those counters into one. In passing, get rid of the PGSS_HANDLED_UTILITY macro in favor of explicitly listing statement types. It seems somewhat coincidental that PREPARE and EXECUTE are handled alike in each of the places where that was used: the reasoning tends to be different for each one. Thus, the macro seems as likely to encourage future bugs as prevent them, since it's quite unclear whether any future statement type that might need special-casing here would also need the same choices at each spot. Sergei Kornilov, Julien Rouhaud, and Tom Lane, per bug #17552 from Maxim Boguk. This is pretty clearly a bug fix, but it's also a behavioral change that might surprise somebody, so no back-patch. Discussion: https://postgr.es/m/17552-213b534c56ab5d02@postgresql.org --- .../expected/level_tracking.out | 110 ++++++++++++++- .../pg_stat_statements/pg_stat_statements.c | 126 +++++++++++------- .../pg_stat_statements/sql/level_tracking.sql | 53 +++++++- 3 files changed, 242 insertions(+), 47 deletions(-) diff --git a/contrib/pg_stat_statements/expected/level_tracking.out b/contrib/pg_stat_statements/expected/level_tracking.out index d924c87b41..0b94c71c9c 100644 --- a/contrib/pg_stat_statements/expected/level_tracking.out +++ b/contrib/pg_stat_statements/expected/level_tracking.out @@ -67,6 +67,61 @@ SELECT toplevel, calls, query FROM pg_stat_statements t | 1 | SET pg_stat_statements.track = 'all' (7 rows) +-- DO block - top-level tracking without utility. +SET pg_stat_statements.track = 'top'; +SET pg_stat_statements.track_utility = FALSE; +SELECT pg_stat_statements_reset(); + pg_stat_statements_reset +-------------------------- + +(1 row) + +DELETE FROM stats_track_tab; +DO $$ +BEGIN + DELETE FROM stats_track_tab; +END; $$; +DO LANGUAGE plpgsql $$ +BEGIN + -- this is a SELECT + PERFORM 'hello world'::TEXT; +END; $$; +SELECT toplevel, calls, query FROM pg_stat_statements + ORDER BY query COLLATE "C", toplevel; + toplevel | calls | query +----------+-------+----------------------------------- + t | 1 | DELETE FROM stats_track_tab + t | 1 | SELECT pg_stat_statements_reset() +(2 rows) + +-- DO block - all-level tracking without utility. +SET pg_stat_statements.track = 'all'; +SELECT pg_stat_statements_reset(); + pg_stat_statements_reset +-------------------------- + +(1 row) + +DELETE FROM stats_track_tab; +DO $$ +BEGIN + DELETE FROM stats_track_tab; +END; $$; +DO LANGUAGE plpgsql $$ +BEGIN + -- this is a SELECT + PERFORM 'hello world'::TEXT; +END; $$; +SELECT toplevel, calls, query FROM pg_stat_statements + ORDER BY query COLLATE "C", toplevel; + toplevel | calls | query +----------+-------+----------------------------------- + f | 1 | DELETE FROM stats_track_tab + t | 1 | DELETE FROM stats_track_tab + f | 1 | SELECT $1::TEXT + t | 1 | SELECT pg_stat_statements_reset() +(4 rows) + -- PL/pgSQL function - top-level tracking. SET pg_stat_statements.track = 'top'; SET pg_stat_statements.track_utility = FALSE; @@ -118,6 +173,31 @@ SELECT calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; 1 | 1 | SELECT pg_stat_statements_reset() (3 rows) +-- immutable SQL function --- can be executed at plan time +CREATE FUNCTION PLUS_THREE(i INTEGER) RETURNS INTEGER AS +$$ SELECT i + 3 LIMIT 1 $$ IMMUTABLE LANGUAGE SQL; +SELECT PLUS_THREE(8); + plus_three +------------ + 11 +(1 row) + +SELECT PLUS_THREE(10); + plus_three +------------ + 13 +(1 row) + +SELECT toplevel, calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; + toplevel | calls | rows | query +----------+-------+------+------------------------------------------------------------------------------ + t | 2 | 2 | SELECT PLUS_ONE($1) + t | 2 | 2 | SELECT PLUS_THREE($1) + t | 2 | 2 | SELECT PLUS_TWO($1) + t | 1 | 3 | SELECT calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C" + t | 1 | 1 | SELECT pg_stat_statements_reset() +(5 rows) + -- PL/pgSQL function - all-level tracking. SET pg_stat_statements.track = 'all'; SELECT pg_stat_statements_reset(); @@ -129,6 +209,7 @@ SELECT pg_stat_statements_reset(); -- we drop and recreate the functions to avoid any caching funnies DROP FUNCTION PLUS_ONE(INTEGER); DROP FUNCTION PLUS_TWO(INTEGER); +DROP FUNCTION PLUS_THREE(INTEGER); -- PL/pgSQL function CREATE FUNCTION PLUS_TWO(i INTEGER) RETURNS INTEGER AS $$ DECLARE @@ -174,7 +255,34 @@ SELECT calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; 1 | 1 | SELECT pg_stat_statements_reset() (5 rows) -DROP FUNCTION PLUS_ONE(INTEGER); +-- immutable SQL function --- can be executed at plan time +CREATE FUNCTION PLUS_THREE(i INTEGER) RETURNS INTEGER AS +$$ SELECT i + 3 LIMIT 1 $$ IMMUTABLE LANGUAGE SQL; +SELECT PLUS_THREE(8); + plus_three +------------ + 11 +(1 row) + +SELECT PLUS_THREE(10); + plus_three +------------ + 13 +(1 row) + +SELECT toplevel, calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; + toplevel | calls | rows | query +----------+-------+------+------------------------------------------------------------------------------ + f | 2 | 2 | SELECT (i + $2 + $3)::INTEGER + f | 2 | 2 | SELECT (i + $2)::INTEGER LIMIT $3 + t | 2 | 2 | SELECT PLUS_ONE($1) + t | 2 | 2 | SELECT PLUS_THREE($1) + t | 2 | 2 | SELECT PLUS_TWO($1) + t | 1 | 5 | SELECT calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C" + f | 2 | 2 | SELECT i + $2 LIMIT $3 + t | 1 | 1 | SELECT pg_stat_statements_reset() +(8 rows) + -- -- pg_stat_statements.track = none -- diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index 767b6ceb10..6c63acf989 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -99,13 +99,6 @@ static const uint32 PGSS_PG_MAJOR_VERSION = PG_VERSION_NUM / 100; #define USAGE_DEALLOC_PERCENT 5 /* free this % of entries at once */ #define IS_STICKY(c) ((c.calls[PGSS_PLAN] + c.calls[PGSS_EXEC]) == 0) -/* - * Utility statements that pgss_ProcessUtility and pgss_post_parse_analyze - * ignores. - */ -#define PGSS_HANDLED_UTILITY(n) (!IsA(n, ExecuteStmt) && \ - !IsA(n, PrepareStmt)) - /* * Extension version number, for supporting older extension versions' objects */ @@ -255,11 +248,8 @@ typedef struct pgssSharedState /*---- Local variables ----*/ -/* Current nesting depth of ExecutorRun+ProcessUtility calls */ -static int exec_nested_level = 0; - -/* Current nesting depth of planner calls */ -static int plan_nested_level = 0; +/* Current nesting depth of planner/ExecutorRun/ProcessUtility calls */ +static int nesting_level = 0; /* Saved hook values in case of unload */ static shmem_request_hook_type prev_shmem_request_hook = NULL; @@ -836,16 +826,18 @@ 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(exec_nested_level)) + if (!pgss || !pgss_hash || !pgss_enabled(nesting_level)) return; /* - * Clear queryId for prepared statements related utility, as those will - * inherit from the underlying statement's one. + * If it's EXECUTE, clear the queryId so that stats will accumulate for + * the underlying PREPARE. But don't do this if we're not tracking + * utility statements, to avoid messing up another extension that might be + * tracking them. */ if (query->utilityStmt) { - if (pgss_track_utility && !PGSS_HANDLED_UTILITY(query->utilityStmt)) + if (pgss_track_utility && IsA(query->utilityStmt, ExecuteStmt)) { query->queryId = UINT64CONST(0); return; @@ -897,7 +889,7 @@ pgss_planner(Query *parse, * So testing the planner nesting level only is not enough to detect real * top level planner call. */ - if (pgss_enabled(plan_nested_level + exec_nested_level) + if (pgss_enabled(nesting_level) && pgss_track_planning && query_string && parse->queryId != UINT64CONST(0)) { @@ -918,7 +910,7 @@ pgss_planner(Query *parse, walusage_start = pgWalUsage; INSTR_TIME_SET_CURRENT(start); - plan_nested_level++; + nesting_level++; PG_TRY(); { if (prev_planner_hook) @@ -930,7 +922,7 @@ pgss_planner(Query *parse, } PG_FINALLY(); { - plan_nested_level--; + nesting_level--; } PG_END_TRY(); @@ -959,12 +951,26 @@ pgss_planner(Query *parse, } else { - if (prev_planner_hook) - result = prev_planner_hook(parse, query_string, cursorOptions, - boundParams); - else - result = standard_planner(parse, query_string, cursorOptions, - boundParams); + /* + * Even though we're not tracking plan time for this statement, we + * must still increment the nesting level, to ensure that functions + * evaluated during planning are not seen as top-level calls. + */ + nesting_level++; + PG_TRY(); + { + if (prev_planner_hook) + result = prev_planner_hook(parse, query_string, cursorOptions, + boundParams); + else + result = standard_planner(parse, query_string, cursorOptions, + boundParams); + } + PG_FINALLY(); + { + nesting_level--; + } + PG_END_TRY(); } return result; @@ -986,7 +992,7 @@ pgss_ExecutorStart(QueryDesc *queryDesc, int eflags) * counting of optimizable statements that are directly contained in * utility statements. */ - if (pgss_enabled(exec_nested_level) && queryDesc->plannedstmt->queryId != UINT64CONST(0)) + if (pgss_enabled(nesting_level) && queryDesc->plannedstmt->queryId != UINT64CONST(0)) { /* * Set up to track total elapsed time in ExecutorRun. Make sure the @@ -1011,7 +1017,7 @@ static void pgss_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once) { - exec_nested_level++; + nesting_level++; PG_TRY(); { if (prev_ExecutorRun) @@ -1021,7 +1027,7 @@ pgss_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, } PG_FINALLY(); { - exec_nested_level--; + nesting_level--; } PG_END_TRY(); } @@ -1032,7 +1038,7 @@ pgss_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, static void pgss_ExecutorFinish(QueryDesc *queryDesc) { - exec_nested_level++; + nesting_level++; PG_TRY(); { if (prev_ExecutorFinish) @@ -1042,7 +1048,7 @@ pgss_ExecutorFinish(QueryDesc *queryDesc) } PG_FINALLY(); { - exec_nested_level--; + nesting_level--; } PG_END_TRY(); } @@ -1056,7 +1062,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) uint64 queryId = queryDesc->plannedstmt->queryId; if (queryId != UINT64CONST(0) && queryDesc->totaltime && - pgss_enabled(exec_nested_level)) + pgss_enabled(nesting_level)) { /* * Make sure stats accumulation is done. (Note: it's okay if several @@ -1097,6 +1103,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); /* * Force utility statements to get queryId zero. We do this even in cases @@ -1112,7 +1119,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, * that user configured another extension to handle utility statements * only. */ - if (pgss_enabled(exec_nested_level) && pgss_track_utility) + if (enabled) pstmt->queryId = UINT64CONST(0); /* @@ -1124,11 +1131,13 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, * hash table entry for the PREPARE (with hash calculated from the query * string), and then a different one with the same query string (but hash * calculated from the query tree) would be used to accumulate costs of - * ensuing EXECUTEs. This would be confusing, and inconsistent with other - * cases where planning time is not included at all. + * ensuing EXECUTEs. This would be confusing. Since PREPARE doesn't + * actually run the planner (only parse+rewrite), its costs are generally + * pretty negligible and it seems okay to just ignore it. */ - if (pgss_track_utility && pgss_enabled(exec_nested_level) && - PGSS_HANDLED_UTILITY(parsetree)) + if (enabled && + !IsA(parsetree, ExecuteStmt) && + !IsA(parsetree, PrepareStmt)) { instr_time start; instr_time duration; @@ -1142,7 +1151,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, walusage_start = pgWalUsage; INSTR_TIME_SET_CURRENT(start); - exec_nested_level++; + nesting_level++; PG_TRY(); { if (prev_ProcessUtility) @@ -1156,7 +1165,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, } PG_FINALLY(); { - exec_nested_level--; + nesting_level--; } PG_END_TRY(); @@ -1206,14 +1215,41 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, } else { - if (prev_ProcessUtility) - prev_ProcessUtility(pstmt, queryString, readOnlyTree, - context, params, queryEnv, - dest, qc); - else - standard_ProcessUtility(pstmt, queryString, readOnlyTree, + /* + * Even though we're not tracking execution time for this statement, + * we must still increment the nesting level, to ensure that functions + * evaluated within it are not seen as top-level calls. But don't do + * so for EXECUTE; that way, when control reaches pgss_planner or + * pgss_ExecutorStart, we will treat the costs as top-level if + * appropriate. Likewise, don't bump for PREPARE, so that parse + * analysis will treat the statement as top-level if appropriate. + * + * To be absolutely certain we don't mess up the nesting level, + * evaluate the bump_level condition just once. + */ + bool bump_level = + !IsA(parsetree, ExecuteStmt) && + !IsA(parsetree, PrepareStmt); + + if (bump_level) + nesting_level++; + PG_TRY(); + { + if (prev_ProcessUtility) + prev_ProcessUtility(pstmt, queryString, readOnlyTree, context, params, queryEnv, dest, qc); + else + standard_ProcessUtility(pstmt, queryString, readOnlyTree, + context, params, queryEnv, + dest, qc); + } + PG_FINALLY(); + { + if (bump_level) + nesting_level--; + } + PG_END_TRY(); } } @@ -1271,7 +1307,7 @@ pgss_store(const char *query, uint64 queryId, key.userid = GetUserId(); key.dbid = MyDatabaseId; key.queryid = queryId; - key.toplevel = (exec_nested_level == 0); + key.toplevel = (nesting_level == 0); /* Lookup the hash table entry with shared lock. */ LWLockAcquire(pgss->lock, LW_SHARED); diff --git a/contrib/pg_stat_statements/sql/level_tracking.sql b/contrib/pg_stat_statements/sql/level_tracking.sql index 0c20b8ce69..dcd0b04358 100644 --- a/contrib/pg_stat_statements/sql/level_tracking.sql +++ b/contrib/pg_stat_statements/sql/level_tracking.sql @@ -33,6 +33,39 @@ END; $$; SELECT toplevel, calls, query FROM pg_stat_statements ORDER BY query COLLATE "C", toplevel; +-- DO block - top-level tracking without utility. +SET pg_stat_statements.track = 'top'; +SET pg_stat_statements.track_utility = FALSE; +SELECT pg_stat_statements_reset(); +DELETE FROM stats_track_tab; +DO $$ +BEGIN + DELETE FROM stats_track_tab; +END; $$; +DO LANGUAGE plpgsql $$ +BEGIN + -- this is a SELECT + PERFORM 'hello world'::TEXT; +END; $$; +SELECT toplevel, calls, query FROM pg_stat_statements + ORDER BY query COLLATE "C", toplevel; + +-- DO block - all-level tracking without utility. +SET pg_stat_statements.track = 'all'; +SELECT pg_stat_statements_reset(); +DELETE FROM stats_track_tab; +DO $$ +BEGIN + DELETE FROM stats_track_tab; +END; $$; +DO LANGUAGE plpgsql $$ +BEGIN + -- this is a SELECT + PERFORM 'hello world'::TEXT; +END; $$; +SELECT toplevel, calls, query FROM pg_stat_statements + ORDER BY query COLLATE "C", toplevel; + -- PL/pgSQL function - top-level tracking. SET pg_stat_statements.track = 'top'; SET pg_stat_statements.track_utility = FALSE; @@ -57,6 +90,15 @@ SELECT PLUS_ONE(10); SELECT calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; +-- immutable SQL function --- can be executed at plan time +CREATE FUNCTION PLUS_THREE(i INTEGER) RETURNS INTEGER AS +$$ SELECT i + 3 LIMIT 1 $$ IMMUTABLE LANGUAGE SQL; + +SELECT PLUS_THREE(8); +SELECT PLUS_THREE(10); + +SELECT toplevel, calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; + -- PL/pgSQL function - all-level tracking. SET pg_stat_statements.track = 'all'; SELECT pg_stat_statements_reset(); @@ -64,6 +106,7 @@ SELECT pg_stat_statements_reset(); -- we drop and recreate the functions to avoid any caching funnies DROP FUNCTION PLUS_ONE(INTEGER); DROP FUNCTION PLUS_TWO(INTEGER); +DROP FUNCTION PLUS_THREE(INTEGER); -- PL/pgSQL function CREATE FUNCTION PLUS_TWO(i INTEGER) RETURNS INTEGER AS $$ @@ -85,7 +128,15 @@ SELECT PLUS_ONE(3); SELECT PLUS_ONE(1); SELECT calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; -DROP FUNCTION PLUS_ONE(INTEGER); + +-- immutable SQL function --- can be executed at plan time +CREATE FUNCTION PLUS_THREE(i INTEGER) RETURNS INTEGER AS +$$ SELECT i + 3 LIMIT 1 $$ IMMUTABLE LANGUAGE SQL; + +SELECT PLUS_THREE(8); +SELECT PLUS_THREE(10); + +SELECT toplevel, calls, rows, query FROM pg_stat_statements ORDER BY query COLLATE "C"; -- -- pg_stat_statements.track = none