Hi, Thank you for working on this!
On Wed, 2 Sept 2026 at 10:45, Fujii Masao <[email protected]> wrote: > > I investigated the 031_recovery_conflict.pl test failure reported by > buildfarm member akepa [1], since it occurred just after the commit > I pushed. But that seems unrelated to that commit. I saw 031_recovery_conflict.pl failure on CI at least a couple times, but I am not sure if they originated from the same problem, though. > [01:46:23.473](0.028s) not ok 12 - tablespace conflict: stats show > conflict on standby > [01:46:23.474](0.001s) # Failed test 'tablespace conflict: stats > show conflict on standby' > # at > /home/buildfarm/build-farm-21/buildroot/REL_19_STABLE/pgsql/src/test/recovery/t/031_recovery_conflict.pl > line 332. > [01:46:23.474](0.000s) # got: '0' > # expected: '1' > > The test saw a recovery conflict counter of 0 when it expected 1. > Since the standby log contained the expected tablespace conflict > message, the conflict itself had already occurred. But, ISTM that > the counter in pg_stat_database_conflicts had not been updated yet > when the test checked it immediately afterward, causing the failure. > That is, there seems no guarantee that the conflict counter has been > flushed and become visible even after the conflict message has been > logged. I am able to reproduce your test case by adding sleep before pgstat_report_stat(true): ``` diff --git a/src/backend/utils/activity/pgstat.c b/src/backend/utils/activity/pgstat.c index 4615f610106..325092008d7 100644 --- a/src/backend/utils/activity/pgstat.c +++ b/src/backend/utils/activity/pgstat.c @@ -659,6 +659,7 @@ pgstat_shutdown_hook(int code, Datum arg) if (OidIsValid(MyDatabaseId)) pgstat_report_disconnect(MyDatabaseId); + pg_usleep(100000); pgstat_report_stat(true); /* there shouldn't be any pending changes left * ``` Then 'recovery/031_recovery_conflict' test is failed with: ``` # test failed ----------------------------------- stderr ----------------------------------- # Failed test 'snapshot conflict: stats show conflict on standby' # at /home/nbyavuz/Desktop/projects/postgres/src/test/recovery/t/031_recovery_conflict.pl line 332. # got: '0' # expected: '1' # Failed test 'lock conflict: stats show conflict on standby' # at /home/nbyavuz/Desktop/projects/postgres/src/test/recovery/t/031_recovery_conflict.pl line 332. # got: '0' # expected: '1' # Failed test 'tablespace conflict: stats show conflict on standby' # at /home/nbyavuz/Desktop/projects/postgres/src/test/recovery/t/031_recovery_conflict.pl line 332. # got: '0' # expected: '1' # Failed test 'startup deadlock: stats show conflict on standby' # at /home/nbyavuz/Desktop/projects/postgres/src/test/recovery/t/031_recovery_conflict.pl line 332. # got: '0' # expected: '1' # Looks like you failed 4 tests of 18. (test program exited with status code 4) ``` > > To fix this issue, I'd like to propose the attached patch that changes > the test to poll until the expected counter becomes visible instead of > checking it only once. I confirm that your patch fixes the problem and LGTM. In addition to that, 'test_custom_stats/001_custom_stats' started to fail with similar race condition when I increased timeout from 100000 to 1000000: ``` # Failed test 'report for variable-sized data of entry1' # at /home/nbyavuz/Desktop/projects/postgres/src/test/modules/test_custom_stats/t/001_custom_stats.pl line 80. # got: 'entry1|0|Test entry 1' # expected: 'entry1|2|Test entry 1' # Failed test 'report for variable-sized data of entry2' # at /home/nbyavuz/Desktop/projects/postgres/src/test/modules/test_custom_stats/t/001_custom_stats.pl line 86. # got: 'entry2|0|Test entry 2' # expected: 'entry2|3|Test entry 2' # Failed test 'report for variable-sized data of entry3' # at /home/nbyavuz/Desktop/projects/postgres/src/test/modules/test_custom_stats/t/001_custom_stats.pl line 92. # got: 'entry3|0|Test entry 3' # expected: 'entry3|2|Test entry 3' # Failed test 'report for variable-sized data of entry4' # at /home/nbyavuz/Desktop/projects/postgres/src/test/modules/test_custom_stats/t/001_custom_stats.pl line 98. # got: 'entry4|0|Test entry 4' # expected: 'entry4|3|Test entry 4' # Looks like you failed 4 tests of 16. ``` I attached a patch for fixing this problem by using poll_query_until() like you did. I am not sure if 'test_custom_stats/001_custom_stats' is the real problem since you need quite a big sleep time to reproduce it, but I wanted to mention it just in case. Renamed that patch as a nocfbot-* so it won't affect CI. -- Regards, Nazir Bilal Yavuz Microsoft
From 5bcb76299860631cb4c319b9e02679fa057d0387 Mon Sep 17 00:00:00 2001 From: Nazir Bilal Yavuz <[email protected]> Date: Wed, 2 Sep 2026 11:37:41 +0300 Subject: [PATCH v1] Stabilize test_custom_stats/001_custom_stats test --- .../test_custom_stats/t/001_custom_stats.pl | 35 ++++++++++--------- 1 file changed, 18 insertions(+), 17 deletions(-) diff --git a/src/test/modules/test_custom_stats/t/001_custom_stats.pl b/src/test/modules/test_custom_stats/t/001_custom_stats.pl index 69f2284229e..b2b895c008e 100644 --- a/src/test/modules/test_custom_stats/t/001_custom_stats.pl +++ b/src/test/modules/test_custom_stats/t/001_custom_stats.pl @@ -74,29 +74,30 @@ $node->safe_psql('postgres', q(select test_custom_stats_fixed_update())); $node->safe_psql('postgres', q(select test_custom_stats_fixed_update())); $node->safe_psql('postgres', q(select test_custom_stats_fixed_update())); -# Test data reports. -$result = $node->safe_psql('postgres', - q(select * from test_custom_stats_var_report('entry1'))); -is( $result, - "entry1|2|Test entry 1", +# Test data reports. The variable-sized updates are flushed by their backends +# during process exit, so wait until they are visible. +ok( $node->poll_query_until( + 'postgres', + q(select * from test_custom_stats_var_report('entry1')), + "entry1|2|Test entry 1"), "report for variable-sized data of entry1"); -$result = $node->safe_psql('postgres', - q(select * from test_custom_stats_var_report('entry2'))); -is( $result, - "entry2|3|Test entry 2", +ok( $node->poll_query_until( + 'postgres', + q(select * from test_custom_stats_var_report('entry2')), + "entry2|3|Test entry 2"), "report for variable-sized data of entry2"); -$result = $node->safe_psql('postgres', - q(select * from test_custom_stats_var_report('entry3'))); -is( $result, - "entry3|2|Test entry 3", +ok( $node->poll_query_until( + 'postgres', + q(select * from test_custom_stats_var_report('entry3')), + "entry3|2|Test entry 3"), "report for variable-sized data of entry3"); -$result = $node->safe_psql('postgres', - q(select * from test_custom_stats_var_report('entry4'))); -is( $result, - "entry4|3|Test entry 4", +ok( $node->poll_query_until( + 'postgres', + q(select * from test_custom_stats_var_report('entry4')), + "entry4|3|Test entry 4"), "report for variable-sized data of entry4"); $result = $node->safe_psql('postgres', -- 2.47.3
