From: Tom Lane <tgl@sss.pgh.pa.us>
To: Noah Misch <noah@leadboat.com>
cc: Andrey Borodin <x4mmm@yandex-team.ru>,
        PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>,
        Michael Paquier <michael@paquier.xyz>, Peter Geoghegan <pg@bowt.ie>,
        Andres Freund <andres@anarazel.de>
Subject: Re: conchuela timeouts since 2021-10-09 system upgrade
In-reply-to: <20211026134500.GA128912@rfd.leadboat.com>
References: <20211019030212.GB3403374@rfd.leadboat.com>
 <20211024050028.GA3310519@rfd.leadboat.com>
 <64835CF9-D9AA-49BF-A685-01C23B1023C1@yandex-team.ru>
 <20211024161942.GB3945842@rfd.leadboat.com>
 <640FA6DC-A998-4499-B3B4-2773685B8C56@yandex-team.ru>
 <3792312.1635119599@sss.pgh.pa.us>
 <B5CC4C8F-1B73-4359-AF68-26A08A17BCD1@yandex-team.ru>
 <4170532.1635195582@sss.pgh.pa.us> <20211026015157.GA113335@rfd.leadboat.com>
 <52098.1635228234@sss.pgh.pa.us> <20211026134500.GA128912@rfd.leadboat.com>
Comments: In-reply-to Noah Misch <noah@leadboat.com>
	message dated "Tue, 26 Oct 2021 06:45:00 -0700"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <83445.1635258579.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Tue, 26 Oct 2021 10:29:39 -0400
Message-ID: <83446.1635258579@sss.pgh.pa.us>
Archived-At: 
 <https://www.postgresql.org/message-id/83446.1635258579%40sss.pgh.pa.us>
Precedence: bulk

Noah Misch <noah@leadboat.com> writes:
> On Tue, Oct 26, 2021 at 02:03:54AM -0400, Tom Lane wrote:
>> Or more
>> practically, use advisory locks in that script to enforce that only one
>> runs at once.

> The author did try that.

Hmm ... that ought to have done the trick, I'd think.  However:

> Both sound doable, but I don't expect either to fix prairiedog's trouble=
.

Yeah :-(.  I think this test is somehow stumbling over a pre-existing bug.

>> So what we have is that libpq thinks it's sent the next DROP INDEX,
>> but the backend hasn't seen it.

> Thanks for isolating that.

The plot thickens.  When I went back to look at that machine this morning,
I found this in the postmaster log:

2021-10-26 02:52:09.324 EDT [1013] 002_cic.pl LOG:  statement: DROP INDEX =
CONCURRENTLY idx;
2021-10-26 02:52:09.352 EDT [1013] 002_cic.pl LOG:  could not send data to=
 client: Broken pipe
2021-10-26 02:52:09.352 EDT [1013] 002_cic.pl FATAL:  connection to client=
 lost

The timestamps correspond (more or less anyway) to when I killed off the
stuck test run and went to bed.  So the DROP command *was* sent, and it
was eventually received by the backend, but it seems to have taken killing
the pgbench process to do it.

I think this probably exonerates the pgbench/libpq side of things, and
instead we have to wonder about a backend or kernel bug.  A kernel bug
could possibly explain the unexplainable connection to what's happening on
some other file descriptor.  I'd be prepared to believe that prairiedog's
ancient macOS version has some weird bug preventing kevent() from noticing
available data ... but (a) surely conchuela wouldn't share such a bug,
and (b) we've been using kevent() for a couple years now, so how come
we didn't see this before?

Still baffled.  I'm currently experimenting to see if the bug reproduces
when latch.c is made to use poll() instead of kevent().  But the failure
rate was low enough that it'll be hours before I can say confidently
that it doesn't (unless, of course, it does).

			regards, tom lane