Hi, On Tue, Oct 28, 2025 at 07:00:01AM +0200, Alexander Lakhin wrote: > One month later, fruitcrow has generated this failure too: > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=fruitcrow&dt=2025-10-25%2007%3A45%3A03
Thanks for noticing that, I was distracted with pgconf.eu last week... It hit again today on v17: https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=fruitcrow&dt=2025-10-30%2011%3A04%3A28 > pgsql.build/contrib/pg_stat_statements/regression.diffs > diff -U3 > /home/demo/client-code-REL_19_1/buildroot/HEAD/pgsql.build/contrib/pg_stat_statements/expected/entry_timestamp.out > > /home/demo/client-code-REL_19_1/buildroot/HEAD/pgsql.build/contrib/pg_stat_statements/results/entry_timestamp.out > --- > /home/demo/client-code-REL_19_1/buildroot/HEAD/pgsql.build/contrib/pg_stat_statements/expected/entry_timestamp.out > 2025-10-25 08:45:03.000000000 +0100 > +++ > /home/demo/client-code-REL_19_1/buildroot/HEAD/pgsql.build/contrib/pg_stat_statements/results/entry_timestamp.out > 2025-10-25 08:57:31.000000000 +0100 > @@ -147,7 +147,7 @@ > WHERE query LIKE '%STMTTS%'; > total | minmax_exec_zero | minmax_ts_after_ref | stats_since_after_ref > -------+------------------+---------------------+----------------------- > - 2 | 1 | 2 | 0 > + 2 | 2 | 2 | 0 > (1 row) > > -- Cleanup > > Thus, the "zero time difference" issue in general still exists. I checked this, if I just run the following excerpt of entry_timestamp.sql in a tight loop, I get a few (<10) occurrances out of 10000 iterations where min/max plan time is 0 (or rather minmax_plan_zero is non-zero): SELECT pg_stat_statements_reset(); SET pg_stat_statements.track_planning = TRUE; SELECT 1 AS "STMTTS1"; SELECT count(*) as total, count(*) FILTER ( WHERE min_plan_time + max_plan_time = 0 ) as minmax_plan_zero FROM pg_stat_statements WHERE query LIKE '%STMTTS%'; On the assumption that this isn't a general bug, but just a timing issue (planning 'SELECT 1' isn't complicated), I see two possibilities: 1. Ignore the plan times, and replace SELECT 1 with SELECT pg_sleep(1e-6), similar to e849bd551. I guess this would reduce test coverage so likely not be great? 2. Make the query a bit more complicated so that the plan time is likely to be non-negligable. I actually had to go quite a way to make it pretty failsafe, the attached made it fail less than 5 times out of 50000 iterations, not sure whether that is acceptable or still considered flaky? Any other ideas? Michael
>From e2b920d56b09cf438cd511c5a3dbe415586b68df Mon Sep 17 00:00:00 2001 From: Michael Banck <[email protected]> Date: Wed, 29 Oct 2025 23:10:30 +0100 Subject: [PATCH] Make pg_stat_statement's entry_timestamp test less flaky. On systems with relatively low timer precision (such as buildfarm animal fruitcrow), the combined min/max_plan_time and/or min/max_exec_time could be 0 as the executed query (SELECT 1 and similar) is very simple. Change this by making the query more complex, including call to pg_sleep and a join to a system table. --- .../expected/entry_timestamp.out | 32 +++++++++---------- .../sql/entry_timestamp.sql | 6 ++-- 2 files changed, 19 insertions(+), 19 deletions(-) diff --git a/contrib/pg_stat_statements/expected/entry_timestamp.out b/contrib/pg_stat_statements/expected/entry_timestamp.out index a10c4be6bac..d8cb712cb4e 100644 --- a/contrib/pg_stat_statements/expected/entry_timestamp.out +++ b/contrib/pg_stat_statements/expected/entry_timestamp.out @@ -3,17 +3,17 @@ -- -- planning time is needed during tests SET pg_stat_statements.track_planning = TRUE; -SELECT 1 AS "STMTTS1"; - STMTTS1 ---------- - 1 +SELECT pg_sleep(1e-6), 1 AS "STMTTS1" FROM pg_database GROUP BY "STMTTS1" ORDER BY "STMTTS1"; + pg_sleep | STMTTS1 +----------+--------- + | 1 (1 row) SELECT now() AS ref_ts \gset -SELECT 1,2 AS "STMTTS2"; - ?column? | STMTTS2 -----------+--------- - 1 | 2 +SELECT pg_sleep(1e-6), 1, 2 AS "STMTTS2" FROM pg_database GROUP BY "STMTTS2" ORDER BY "STMTTS2"; + pg_sleep | ?column? | STMTTS2 +----------+----------+--------- + | 1 | 2 (1 row) SELECT stats_since >= :'ref_ts', count(*) FROM pg_stat_statements @@ -80,10 +80,10 @@ query, minmax_stats_since = :'minmax_reset_ts' AS reset_ts_match FROM pg_stat_statements WHERE query LIKE '%STMTTS%' ORDER BY query COLLATE "C"; - query | reset_ts_match ----------------------------+---------------- - SELECT $1 AS "STMTTS1" | t - SELECT $1,$2 AS "STMTTS2" | f + query | reset_ts_match +------------------------------------------------------------------------------------------------+---------------- + SELECT pg_sleep($1), $2, 2 AS "STMTTS2" FROM pg_database GROUP BY "STMTTS2" ORDER BY "STMTTS2" | f + SELECT pg_sleep($1), 1 AS "STMTTS1" FROM pg_database GROUP BY "STMTTS1" ORDER BY "STMTTS1" | t (2 rows) -- check that minmax reset does not set stats_reset @@ -123,10 +123,10 @@ WHERE query LIKE '%STMTTS%'; (1 row) -- Execute first query once more to check stats update -SELECT 1 AS "STMTTS1"; - STMTTS1 ---------- - 1 +SELECT pg_sleep(1e-6), 1 AS "STMTTS1" FROM pg_database GROUP BY "STMTTS1" ORDER BY "STMTTS1"; + pg_sleep | STMTTS1 +----------+--------- + | 1 (1 row) -- check diff --git a/contrib/pg_stat_statements/sql/entry_timestamp.sql b/contrib/pg_stat_statements/sql/entry_timestamp.sql index d6d3027ab4f..61f7f39b9dd 100644 --- a/contrib/pg_stat_statements/sql/entry_timestamp.sql +++ b/contrib/pg_stat_statements/sql/entry_timestamp.sql @@ -5,9 +5,9 @@ -- planning time is needed during tests SET pg_stat_statements.track_planning = TRUE; -SELECT 1 AS "STMTTS1"; +SELECT pg_sleep(1e-6), 1 AS "STMTTS1" FROM pg_database GROUP BY "STMTTS1" ORDER BY "STMTTS1"; SELECT now() AS ref_ts \gset -SELECT 1,2 AS "STMTTS2"; +SELECT pg_sleep(1e-6), 1, 2 AS "STMTTS2" FROM pg_database GROUP BY "STMTTS2" ORDER BY "STMTTS2"; SELECT stats_since >= :'ref_ts', count(*) FROM pg_stat_statements WHERE query LIKE '%STMTTS%' GROUP BY stats_since >= :'ref_ts' @@ -91,7 +91,7 @@ FROM pg_stat_statements WHERE query LIKE '%STMTTS%'; -- Execute first query once more to check stats update -SELECT 1 AS "STMTTS1"; +SELECT pg_sleep(1e-6), 1 AS "STMTTS1" FROM pg_database GROUP BY "STMTTS1" ORDER BY "STMTTS1"; -- check -- we don't check planing times here to be independent of -- 2.39.5
