Recent failures in IsolationCheck deadlock-hard

Thomas Munro <thomas.munro@gmail.com> writes:

There have been five failures on three animals like this, over the
past couple of months:

Also worth noting is that anole failed its first try at the new
deadlock-parallel isolation test:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=anole&amp;dt=2019-08-01%2015%3A48%3A16

What that looks like is the queries got stuck and eventually
isolationtester gave up and canceled the test. So I'm suspicious
that there's a second bug in the parallel deadlock detection code.

Possibly relevant factoids: all three of the animals in question
run HEAD with force_parallel_mode = regress, and there's reason
to think that their timing behavior could be different from other
animals (anole and gharial run on HPUX, while hyrax uses
CLOBBER_CACHE_ALWAYS).

regards, tom lane

On Sat, Aug 3, 2019 at 2:11 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Thomas Munro <thomas.munro@gmail.com> writes:

There have been five failures on three animals like this, over the
past couple of months:

Also worth noting is that anole failed its first try at the new
deadlock-parallel isolation test:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=anole&amp;dt=2019-08-01%2015%3A48%3A16

And friarbird (also CLOBBER_CACHE_ALWAYS) fails every time.

animal | snapshot | branch | commit | result |
fail_stage | fail_tests
-----------+---------------------+--------+---------+---------+----------------+---------------------
lousyjack | 2019-08-05 11:33:02 | HEAD | a76cfba | FAILURE |
IsolationCheck | {deadlock-parallel}
gharial | 2019-08-05 10:30:37 | HEAD | a76cfba | FAILURE |
IsolationCheck | {deadlock-parallel}
friarbird | 2019-08-05 05:20:01 | HEAD | 8548ddc | FAILURE |
IsolationCheck | {deadlock-parallel}
friarbird | 2019-08-04 05:20:02 | HEAD | 69edf4f | FAILURE |
IsolationCheck | {deadlock-parallel}
hyrax | 2019-08-03 12:20:57 | HEAD | 2abd7ae | FAILURE |
IsolationCheck | {deadlock-parallel}
friarbird | 2019-08-03 05:20:01 | HEAD | 2abd7ae | FAILURE |
IsolationCheck | {deadlock-parallel}
friarbird | 2019-08-02 05:20:00 | HEAD | a9f301d | FAILURE |
IsolationCheck | {deadlock-parallel}
anole | 2019-08-01 15:48:16 | HEAD | da9456d | FAILURE |
IsolationCheck | {deadlock-parallel}

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=lousyjack&amp;dt=2019-08-05%2011:33:02
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=gharial&amp;dt=2019-08-05%2010:30:37
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=friarbird&amp;dt=2019-08-05%2005:20:01
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=friarbird&amp;dt=2019-08-04%2005:20:02
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hyrax&amp;dt=2019-08-03%2012:20:57
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=friarbird&amp;dt=2019-08-03%2005:20:01
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=friarbird&amp;dt=2019-08-02%2005:20:00
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=anole&amp;dt=2019-08-01%2015:48:16

 1
 step d2a1: <... completed>
-sum
-
-10000
+error in steps d1c e1l d2a1: ERROR:  canceling statement due to user request
 step e1c: COMMIT;
-step d2c: COMMIT;
 step e2l: <... completed>
 lock_excl

1
+step d2c: COMMIT;
step e2c: COMMIT;

--
Thomas Munro
https://enterprisedb.com

Thomas Munro <thomas.munro@gmail.com> writes:

On Sat, Aug 3, 2019 at 2:11 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Also worth noting is that anole failed its first try at the new
deadlock-parallel isolation test:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=anole&amp;dt=2019-08-01%2015%3A48%3A16

And friarbird (also CLOBBER_CACHE_ALWAYS) fails every time.

Yeah, there have been half a dozen failures since deadlock-parallel
went in, mostly on critters that are slowed by CLOBBER_CACHE_ALWAYS
or valgrind. I've tried repeatedly to reproduce that here, without
success :-(. It's unclear whether the failures represent a real
code bug or just a problem in the test case, so I don't really want
to speculate about fixes till I can reproduce it.

regards, tom lane

On Tue, Aug 6, 2019 at 6:18 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Thomas Munro <thomas.munro@gmail.com> writes:

On Sat, Aug 3, 2019 at 2:11 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Also worth noting is that anole failed its first try at the new
deadlock-parallel isolation test:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=anole&amp;dt=2019-08-01%2015%3A48%3A16

And friarbird (also CLOBBER_CACHE_ALWAYS) fails every time.

Yeah, there have been half a dozen failures since deadlock-parallel
went in, mostly on critters that are slowed by CLOBBER_CACHE_ALWAYS
or valgrind. I've tried repeatedly to reproduce that here, without
success :-(. It's unclear whether the failures represent a real
code bug or just a problem in the test case, so I don't really want
to speculate about fixes till I can reproduce it.

I managed to reproduce a failure that looks a lot like lousyjack's
(note that there are two slightly different failure modes):

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=lousyjack&amp;dt=2019-08-05%2011:33:02

I did that by changing the deadlock_timeout values for sessions d1 and
d2 to just a few milliseconds on my slowest computer, guessing that
this might be a race involving the deadlock timeout and the time it
takes for workers to fork and join a lock queue. While normally
deadlock.c with DEBUG_DEADLOCK defined prints out something like this
during this test:

DeadLockCheck: lock 0x80a2812d0 queue 33087 33088 33089 33090 33091
rearranged to: lock 0x80a2812d0 queue 33091 33090 33089 33088 33087

... when it failed like lousyjack my run printed out:

DeadLockCheck: lock 0x80a2721f8 queue 33108 33114
rearranged to: lock 0x80a2721f8 queue 33114 33108

... and then it hung for a while, so I could inspect the lock table
and see that PID 33108 was e1l (not granted), and PID 33114 was gone
but was almost certainly the first worker for d2a1 (I can tell because
33110-33113 are the workers for d1a2 and they're still waiting and
d2a1's first worker should have had the next sequential PID, on my
OS).

Another thing I noticed is that all 4 times I managed to reproduce
this, the "rearranged to" queue had only two entries; I can understand
that d1's workers might not feature yet due to bad timing, but it's
not clear to me why there should always be only one d2a1 worker and
not more. I don't have time to study this further today and I might
be way off, but my first guess is that in theory we need a way to make
sure that the d1-e2 edge exists before d2's deadlock timer expires,
no? That's pretty tricky though, so maybe we just need to crank the
times up.

--
Thomas Munro
https://enterprisedb.com

Thomas Munro <thomas.munro@gmail.com> writes:

On Tue, Aug 6, 2019 at 6:18 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Yeah, there have been half a dozen failures since deadlock-parallel
went in, mostly on critters that are slowed by CLOBBER_CACHE_ALWAYS
or valgrind. I've tried repeatedly to reproduce that here, without
success :-(. It's unclear whether the failures represent a real
code bug or just a problem in the test case, so I don't really want
to speculate about fixes till I can reproduce it.

I managed to reproduce a failure that looks a lot like lousyjack's
(note that there are two slightly different failure modes):
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=lousyjack&amp;dt=2019-08-05%2011:33:02

I did that by changing the deadlock_timeout values for sessions d1 and
d2 to just a few milliseconds on my slowest computer, guessing that
this might be a race involving the deadlock timeout and the time it
takes for workers to fork and join a lock queue.

Yeah, I eventually managed to reproduce it (not too reliably) by
introducing a randomized delay into parallel worker startup.

The scenario seems to be: some d1a2 worker arrives so late that it's not
accounted for in the initial DeadLockCheck performed by some d2a1 worker.
The other d1a2 workers are released, and run and finish, but the late one
goes to sleep, with a long deadlock_timeout. If the next DeadLockCheck is
run by e1l's worker, that prefers to release d2a1 workers, which then all
run to completion. When the late d1a2 worker finally wakes up and runs
DeadLockCheck, *there is no deadlock to resolve*: the d2 session is idle,
not waiting for any lock. So the worker goes back to sleep, and we sit
till isolationtester times out.

Another way to look at it is that there is a deadlock condition, but
one of the waits-for constraints is on the client side where DeadLockCheck
can't see it. isolationtester is waiting for d1a2 to complete before it
will execute d1c which would release session d2, so that d2 is effectively
waiting for d1, but DeadLockCheck doesn't know that and thinks that it's
equally good to unblock either d1 or d2.

The attached proposed patch resolves this by introducing another lock
that is held by d1 and then d2 tries to take it, ensuring that the
deadlock detector will recognize that d1 must be released.

I've run several thousand iterations of the test this way without a
problem, where before the MTBF was maybe a hundred or two iterations
with the variable startup delay active. So I think this fix is good,
but I could be wrong. One notable thing is that every so often the
test takes ~10s to complete instead of a couple hundred msec. I think
that what's happening there is that the last deadlock condition doesn't
form until after all of session d2's DeadLockChecks have run, meaning
that we don't spot the deadlock until some other session runs it. The
test still passes, though. This is probably fine given that it would
never happen except with platforms that are horridly slow anyway.
Possibly we could shorten the 10s values to make that case complete
quicker, but I'm afraid of maybe breaking things on slow machines.

Another thing I noticed is that all 4 times I managed to reproduce
this, the "rearranged to" queue had only two entries; I can understand
that d1's workers might not feature yet due to bad timing, but it's
not clear to me why there should always be only one d2a1 worker and
not more.

I noticed that too, and eventually realized that it's a
max_worker_processes constraint: we have two parallel workers waiting
in e1l and e2l, so if d1a2 takes four, there are only two slots left for
d2a1; and for reasons that aren't totally clear, we don't get to use the
last slot. (Not sure if that's a bug in itself.)

The attached patch therefore also knocks max_parallel_workers_per_gather
down to 3 in this test, so that we have room for at least 2 d2a1 workers.

regards, tom lane