| From: | Nazir Bilal Yavuz <byavuz81(at)gmail(dot)com> |
|---|---|
| To: | Fujii Masao <masao(dot)fujii(at)gmail(dot)com> |
| Cc: | PostgreSQL Hackers <pgsql-hackers(at)lists(dot)postgresql(dot)org> |
| Subject: | Re: Stabilize recovery conflict stats checks in 031_recovery_conflict.pl |
| Date: | 2026-09-02 08:57:01 |
| Message-ID: | CAN55FZ2zC8HR+Wc6XhkGDF4VCm9sLy8zy23pd++5YwSU_UYm3g@mail.gmail.com |
| Views: | Whole Thread | Raw Message | Download mbox | Resend email |
| Thread: | |
| Lists: | pgsql-hackers |
Hi,
Thank you for working on this!
On Wed, 2 Sept 2026 at 10:45, Fujii Masao <masao(dot)fujii(at)gmail(dot)com> 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
| Attachment | Content-Type | Size |
|---|---|---|
| nocfbot-Stabilize-test_custom_stats-001_custom_stats-test.patch | text/x-patch | 2.3 KB |
| From | Date | Subject | |
|---|---|---|---|
| Previous Message | Antonin Houska | 2026-09-02 08:47:26 | Re: REPACK (ANALYZE) within transaction block segfaults |