Received: from malur.postgresql.org ([217.196.149.56])
	by arkaria.postgresql.org with esmtps
 (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256)
	(Exim 4.92)
	(envelope-from <pgsql-hackers-owner+archive@lists.postgresql.org>)
	id 1oy4iZ-0006pj-Is
	for pgsql-hackers@arkaria.postgresql.org; Thu, 24 Nov 2022 05:24:11 +0000
Received: from localhost ([127.0.0.1] helo=malur.postgresql.org)
	by malur.postgresql.org with esmtp (Exim 4.92)
	(envelope-from <pgsql-hackers-owner+archive@lists.postgresql.org>)
	id 1oy4iY-0006nU-5E
	for pgsql-hackers@arkaria.postgresql.org; Thu, 24 Nov 2022 05:24:10 +0000
Received: from makus.postgresql.org ([2001:4800:3e1:1::229])
	by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256)
	(Exim 4.92)
	(envelope-from <a.fakeev@postgrespro.ru>)
	id 1oy4iX-0006nL-Ro
	for pgsql-hackers@lists.postgresql.org; Thu, 24 Nov 2022 05:24:09 +0000
Received: from mail.postgrespro.ru ([93.174.131.139])
	by makus.postgresql.org with esmtp (Exim 4.92)
	(envelope-from <a.fakeev@postgrespro.ru>)
	id 1oy4iS-000540-Pa
	for pgsql-hackers@postgresql.org; Thu, 24 Nov 2022 05:24:08 +0000
Received: from sogo.postgrespro.ru (unknown [213.171.56.197])
	(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
	(Client did not present a certificate)
	by mail.postgrespro.ru (Postfix) with ESMTPS id 3385621C203F;
	Thu, 24 Nov 2022 08:24:02 +0300 (MSK)
From: =?utf-8?q?=D0=A4=D0=B0=D0=BA=D0=B5=D0=B5=D0=B2?=
 =?utf-8?q?_=D0=90=D0=BB=D0=B5=D0=BA=D1=81=D0=B5=D0=B9?=
 <a.fakeev@postgrespro.ru>
To: "'Andres Freund'" <andres@anarazel.de>,
	"'Tom Lane'" <tgl@sss.pgh.pa.us>
Cc: "'Robert Haas'" <robertmhaas@gmail.com>,
	<pgsql-hackers@postgresql.org>,
	"'Thomas Munro'" <thomas.munro@gmail.com>
References: <907760.1649790322@sss.pgh.pa.us>
 <20220413002626.udl7lll7f3o7nre7@alap3.anarazel.de>
 <20220429200809.uuuseakmhb57sppk@alap3.anarazel.de>
 <465685.1651274819@sss.pgh.pa.us>
 <20220503014803.uknu3cwahwhbgrak@alap3.anarazel.de>
 <1929823.1651549472@sss.pgh.pa.us>
 <20220503040557.eimbfibv4rsey3s5@alap3.anarazel.de>
 <1959496.1651555006@sss.pgh.pa.us>
 <20220503182025.wvbebs2ojk6vpi5f@alap3.anarazel.de>
 <2174975.1651602203@sss.pgh.pa.us>
 <20220503191305.htuzje6ldmic7skk@alap3.anarazel.de>
In-Reply-To: <20220503191305.htuzje6ldmic7skk@alap3.anarazel.de>
Subject: RE: failures in t/031_recovery_conflict.pl on CI
Date: Thu, 24 Nov 2022 09:24:01 +0400
Message-ID: <00cc01d8ffc4$f6169e60$e243db20$@postgrespro.ru>
MIME-Version: 1.0
Content-Type: text/plain;
	charset="US-ASCII"
Content-Transfer-Encoding: 7bit
X-Mailer: Microsoft Outlook 16.0
Content-Language: ru
Thread-Index: 
 AQHptZxQXbEJ/LwUxmznXFRMWXlDeQJmi8zvARKo+eoB8YOMVgIWYzVsAWwPiwgCMHum3AGxgimkActSQjkBtcV/gQIWr9+FrZjkuhA=
List-Id: <pgsql-hackers.lists.postgresql.org>
List-Help: <https://lists.postgresql.org/manage/>
List-Subscribe: <https://lists.postgresql.org/manage/>
List-Post: <mailto:pgsql-hackers@lists.postgresql.org>
List-Owner: <mailto:pgsql-hackers-owner@lists.postgresql.org>
List-Archive: <https://www.postgresql.org/list/pgsql-hackers>
Archived-At: 
 <https://www.postgresql.org/message-id/00cc01d8ffc4%24f6169e60%24e243db20%24%40postgrespro.ru>
Precedence: bulk

Hello.

Even after applying the patch, we are still facing an "ack Broken pipe"
problem. 
It occurs on the arm64 platform, presumably under high load. 
Here is a log snippet from buildfarm:
...
[19:08:12.150](0.394s) ok 13 - startup deadlock: cursor holding conflicting
pin, also waiting for lock, established
[19:08:12.208](0.057s) ok 14 - startup deadlock: lock acquisition is waiting
Waiting for replication conn standby's replay_lsn to pass 0/33F5FE0 on
primary
done
psql:<stdin>:8: ERROR:  canceling statement due to conflict with recovery
LINE 1: SELECT * FROM test_recovery_conflict_table2;
                      ^
DETAIL:  User transaction caused buffer deadlock with recovery.
[19:08:12.319](0.112s) ok 15 - startup deadlock: logfile contains terminated
connection due to recovery conflict
ack Broken pipe: write( 13, '\\q
' ) at /usr/share/perl5/IPC/Run/IO.pm line 550.
### Stopping node "primary" using mode immediate
# Running: pg_ctl -D
/home/bf/build/buildfarm-flaviventris/REL_15_STABLE/pgsql.build/src/test/rec
overy/tmp_check/t_031_recovery_conflict_primary_data/pgdata -m immediate
stop
waiting for server to shut down... done
server stopped
# No postmaster PID for node "primary"
### Stopping node "standby" using mode immediate
# Running: pg_ctl -D
/home/bf/build/buildfarm-flaviventris/REL_15_STABLE/pgsql.build/src/test/rec
overy/tmp_check/t_031_recovery_conflict_standby_data/pgdata -m immediate
stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "standby"
[19:08:12.450](0.131s) # Tests were run but no plan was declared and
done_testing() was not seen.
[19:08:12.450](0.000s) # Looks like your test exited with 32 just after 15.
...

Below is a test report:
... 
[20:46:35] t/030_stats_cleanup_replica.pl ....... ok     9956 ms ( 0.01 usr
0.00 sys +  3.49 cusr  2.49 csys =  5.99 CPU)
# Tests were run but no plan was declared and done_testing() was not seen.
# Looks like your test exited with 32 just after 15.
[20:46:43] t/031_recovery_conflict.pl ........... 
Dubious, test returned 32 (wstat 8192, 0x2000)
All 15 subtests passed 
[20:46:56] t/032_relfilenode_reuse.pl ........... ok    13625 ms ( 0.01 usr
0.00 sys +  3.53 cusr  2.39 csys =  5.93 CPU)
[20:47:03] t/110_wal_sender_check_crc.pl ........ ok     6421 ms ( 0.00 usr
0.00 sys +  3.20 cusr  1.87 csys =  5.07 CPU)
[20:47:03]

Test Summary Report
-------------------
t/031_recovery_conflict.pl         (Wstat: 8192 Tests: 15 Failed: 0)
  Non-zero exit status: 32
  Parse errors: No plan found in TAP output




-----Original Message-----
From: Andres Freund <andres@anarazel.de> 
Sent: Tuesday, May 3, 2022 11:13 PM
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Robert Haas <robertmhaas@gmail.com>; pgsql-hackers@postgresql.org;
Thomas Munro <thomas.munro@gmail.com>
Subject: Re: failures in t/031_recovery_conflict.pl on CI

Hi,

On 2022-05-03 14:23:23 -0400, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> >> So it's almost surely a timing issue, and your theory here seems
plausible.
> 
> > Unfortunately I don't think my theory holds, because I actually had 
> > added a defense against this into the test that I forgot about
momentarily...
> 
> Oh, hm.  I can try harder to repro it.

I've now reproduced it a couple times here running under rr, so it's
probably not worth putting too much effort into that.

Attached is a fix for the test that I think should avoid the problem.
Couldn't repro it with it applied, under both rr and valgrind.


My current problem is that I'm running into some IPC::Run issues (bug?). I
get "ack Broken pipe:" iff I add "SELECT pg_sleep(1);" after
"-- wait for lock held by prepared transaction"

It doesn't happen without that debugging thing, but it makes me worried that
it's something that'll come up in random situations.

It looks to me like it's a bug in IPC::Run - with a few changes I get the
failure to happen inside pump_nb(), which seems like it shouldn't error out
just because the child process exited...


I *think* it might not happen without the sleep. But I'm not at all
confident.

In general I'm kinda worried on how much effectively unmaintained perl stuff
we're depending :(

Greetings,

Andres Freund