Re: Recent 027_streaming_regress.pl hangs

On 2024-07-25 Th 5:14 PM, Tom Lane wrote:
> I wrote:
>> I'm confused by crake's buildfarm logs.  AFAICS it is not running
>> recovery-check at all in most of the runs; at least there is no
>> mention of that step, for example here:
>> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=crake&dt=2024-07-25%2013%3A27%3A02
> Oh, I see it: the log file that is called recovery-check in a
> failing run is called misc-check if successful.  That seems
> mighty bizarre, and it's not how my own animals behave.
> Something weird about the meson code path, perhaps?


Yes, it was discussed some time ago. As suggested by Andres, we run the 
meson test suite more or less all together (in effect like "make 
checkworld" but without the main regression suite, which is run on its 
own first), rather than in the separate (and serialized) way we do with 
the configure/make tests. That results in significant speedup. If the 
tests fail we report the failure as happening at the first failure we 
encounter, which is possibly less than ideal, but I haven't got a better 
idea.


>
> Anyway, in this successful run:
>
> https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=crake&dt=2024-07-25%2018%3A57%3A02&stg=misc-check
>
> here are some salient test timings:
>
>    1/297 postgresql:pg_upgrade / pg_upgrade/001_basic                                    OK                0.18s   9 subtests passed
>    2/297 postgresql:pg_upgrade / pg_upgrade/003_logical_slots                            OK               15.95s   12 subtests passed
>    3/297 postgresql:pg_upgrade / pg_upgrade/004_subscription                             OK               16.29s   14 subtests passed
>   17/297 postgresql:isolation / isolation/isolation                                      OK               71.60s   119 subtests passed
>   41/297 postgresql:pg_upgrade / pg_upgrade/002_pg_upgrade                               OK              169.13s   18 subtests passed
> 140/297 postgresql:initdb / initdb/001_initdb                                           OK               41.34s   52 subtests passed
> 170/297 postgresql:recovery / recovery/027_stream_regress                               OK              469.49s   9 subtests passed
>
> while in the next, failing run
>
> https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=crake&dt=2024-07-25%2020%3A18%3A05&stg=recovery-check
>
> the same tests took:
>
>    1/297 postgresql:pg_upgrade / pg_upgrade/001_basic                                    OK                0.22s   9 subtests passed
>    2/297 postgresql:pg_upgrade / pg_upgrade/003_logical_slots                            OK               56.62s   12 subtests passed
>    3/297 postgresql:pg_upgrade / pg_upgrade/004_subscription                             OK               71.92s   14 subtests passed
>   21/297 postgresql:isolation / isolation/isolation                                      OK              299.12s   119 subtests passed
>   31/297 postgresql:pg_upgrade / pg_upgrade/002_pg_upgrade                               OK              344.42s   18 subtests passed
> 159/297 postgresql:initdb / initdb/001_initdb                                           OK              344.46s   52 subtests passed
> 162/297 postgresql:recovery / recovery/027_stream_regress                               ERROR           840.84s   exit status 29
>
> Based on this, it seems fairly likely that crake is simply timing out
> as a consequence of intermittent heavy background activity.
>


The latest failure is this:


Waiting for replication conn standby_1's replay_lsn to pass 2/88E4E260 on primary
[16:40:29.481](208.545s) # poll_query_until timed out executing this query:
# SELECT '2/88E4E260' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('standby_1', 'walreceiver')
# expecting this output:
# t
# last actual query output:
# f
# with stderr:
timed out waiting for catchup at /home/andrew/bf/root/HEAD/pgsql/src/test/recovery/t/027_stream_regress.pl line 103.


Maybe it's a case where the system is overloaded, I dunno. I wouldn't bet my house on it. Pretty much nothing else runs on this machine.

I have added a mild throttle to the buildfarm config so it doesn't try 
to run every branch at once. Maybe I also need to bring down the number 
or meson jobs too? But I suspect there's something deeper. Prior to the 
failure of this test 10 days ago it hadn't failed in a very long time. 
The OS was upgraded a month ago. Eight or so days ago I changed 
PG_TEST_EXTRA. I can't think of anything else.


cheers


andrew

--
Andrew Dunstan
EDB:https://www.enterprisedb.com