mirrors
/
postgres
mirror of https://github.com/postgres/postgres
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

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
This commit is contained in:
Tom Lane 2023-11-08 12:01:28 -05:00
parent 1a5594b957
commit 76db9cb636
3 changed files with 242 additions and 47 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

110
contrib/pg_stat_statements/expected/level_tracking.out
View File

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

102
contrib/pg_stat_statements/pg_stat_statements.c
View File

@ -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();
@ -958,6 +950,14 @@ pgss_planner(Query *parse,
NULL);
}
else
{
/*
* 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,
@ -966,6 +966,12 @@ pgss_planner(Query *parse,
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();
@ -1205,6 +1214,26 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
NULL);
}
else
{
/*
* 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,
@ -1215,6 +1244,13 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString,
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);

53
contrib/pg_stat_statements/sql/level_tracking.sql
View File

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