Re: Is RecoveryConflictInterrupt() entirely safe in a signal handler?

HHi,

On 2022-07-01 13:14:23 -0700, Andres Freund wrote:
> I saw a couple failures of 031 on CI for the meson patch - which obviously
> doesn't change anything around this. However it adds a lot more distributions,
> and the added ones run in docker containers on a shared host, presumably
> adding a lot of noise. I saw this more frequently when I accidentally had the
> test runs at the number of CPUs in the host, rather than the allotted CPUs in
> the container.
>
> That made me look more into these issues. I played with adding a pg_usleep()
> to RecoveryConflictInterrupt() to simulate slow signal delivery.
>
> Found a couple things:
>
> - the pg_usleep(5000) in ResolveRecoveryConflictWithVirtualXIDs() can
> completely swamp the target(s) on a busy system. This surely is exascerbated
> by the usleep I added RecoveryConflictInterrupt() but a 5ms signalling pace
> does seem like a bad idea.

This one is also implicated in
https://postgr.es/m/20220701154105.jjfutmngoedgiad3%40alvherre.pgsql
and related issues.

Besides being very short, it also seems like a bad idea to wait when we might
not need to? Seems we should only wait if we subsequently couldn't get the
lock?

Misleadingly WaitExceedsMaxStandbyDelay() also contains a usleep, which at
least I wouldn't expect given its name.

A minimal fix would be to increase the wait time, similar how it is done with
standbyWait_us?

Medium term it seems we ought to set the startup process's latch when handling
a conflict, and use a latch wait. But avoiding races probably isn't quite
trivial.

> - we process the same recovery conflict (not a single signal, but a single
> "real conflict") multiple times in the target of a conflict, presumably
> while handling the error. That includes handling the same interrupt once as
> an ERROR and once as FATAL.
>
> E.g.
>
> 2022-07-01 12:19:14.428 PDT [2000572] LOG: recovery still waiting after 10.032 ms: recovery conflict on buffer pin
> 2022-07-01 12:19:14.428 PDT [2000572] CONTEXT: WAL redo at 0/344E098 for Heap2/PRUNE: latestRemovedXid 0 nredirected 0 ndead 100; blkref #0: rel 1663/16385/1>
> 2022-07-01 12:19:54.597 PDT [2000578] 031_recovery_conflict.pl ERROR: canceling statement due to conflict with recovery at character 15
> 2022-07-01 12:19:54.597 PDT [2000578] 031_recovery_conflict.pl DETAIL: User transaction caused buffer deadlock with recovery.
> 2022-07-01 12:19:54.597 PDT [2000578] 031_recovery_conflict.pl STATEMENT: SELECT * FROM test_recovery_conflict_table2;
> 2022-07-01 12:19:54.778 PDT [2000572] LOG: recovery finished waiting after 40359.937 ms: recovery conflict on buffer pin
> 2022-07-01 12:19:54.778 PDT [2000572] CONTEXT: WAL redo at 0/344E098 for Heap2/PRUNE: latestRemovedXid 0 nredirected 0 ndead 100; blkref #0: rel 1663/16385/1>
> 2022-07-01 12:19:54.788 PDT [2000578] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery
> 2022-07-01 12:19:54.788 PDT [2000578] 031_recovery_conflict.pl DETAIL: User transaction caused buffer deadlock with recovery.
> 2022-07-01 12:19:54.788 PDT [2000578] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command.
> 2022-07-01 12:19:54.837 PDT [2001389] 031_recovery_conflict.pl LOG: statement: SELECT 1;
>
> note that the startup process considers the conflict resolved by the time
> the backend handles the interrupt.

I guess the reason we first get an ERROR and then a FATAL is that the second
iteration hits the if (RecoveryConflictPending && DoingCommandRead) bit,
because we end up there after handling the first error? And that's a FATAL.

I suspect that Thomas' fix will address at least part of this, as the check
whether we're still waiting for a lock will be made just before the error is
thrown.

> I also see cases where a FATAL is repeated:
>
> 2022-07-01 12:43:18.190 PDT [2054721] LOG: recovery still waiting after 15.410 ms: recovery conflict on snapshot
> 2022-07-01 12:43:18.190 PDT [2054721] DETAIL: Conflicting process: 2054753.
> 2022-07-01 12:43:18.190 PDT [2054721] CONTEXT: WAL redo at 0/344AB90 for Heap2/PRUNE: latestRemovedXid 732 nredirected 18 ndead 0; blkref #0: rel 1663/16385/>
> 2054753: reporting recovery conflict 9
> 2022-07-01 12:43:18.482 PDT [2054753] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery
> 2022-07-01 12:43:18.482 PDT [2054753] 031_recovery_conflict.pl DETAIL: User query might have needed to see row versions that must be removed.
> 2022-07-01 12:43:18.482 PDT [2054753] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command.
> ...
> 2054753: reporting recovery conflict 9
> 2022-07-01 12:43:19.068 PDT [2054753] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery
> 2022-07-01 12:43:19.068 PDT [2054753] 031_recovery_conflict.pl DETAIL: User query might have needed to see row versions that must be removed.
> 2022-07-01 12:43:19.068 PDT [2054753] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command.
>
> the FATAL one seems like it might at least partially be due to
> RecoveryConflictPending not being reset in at least some of the FATAL
> recovery conflict paths.
>
> It seems pretty obvious that the proc_exit_inprogress check in
> RecoveryConflictInterrupt() is misplaced, and needs to be where the errors
> are thrown. But that won't help, because it turns out, we don't yet set that
> necessarily.
>
> Look at this stack from an assertion in ProcessInterrupts() ensuring that
> the same FATAL isn't raised twice:
>
> #0 __GI_raise (sig=sig(at)entry=6) at ../sysdeps/unix/sysv/linux/raise.c:49
> #1 0x00007fd47897b546 in __GI_abort () at abort.c:79
> #2 0x00005594c150b27a in ExceptionalCondition (conditionName=0x5594c16fe746 "!in_fatal", errorType=0x5594c16fd8f6 "FailedAssertion",
> fileName=0x5594c16fdac0 "/home/andres/src/postgresql/src/backend/tcop/postgres.c", lineNumber=3259)
> at /home/andres/src/postgresql/src/backend/utils/error/assert.c:69
> #3 0x00005594c134f6d2 in ProcessInterrupts () at /home/andres/src/postgresql/src/backend/tcop/postgres.c:3259
> #4 0x00005594c150c671 in errfinish (filename=0x5594c16b8f2e "pqcomm.c", lineno=1393, funcname=0x5594c16b95e0 <__func__.8> "internal_flush")
> at /home/andres/src/postgresql/src/backend/utils/error/elog.c:683
> #5 0x00005594c115e059 in internal_flush () at /home/andres/src/postgresql/src/backend/libpq/pqcomm.c:1393
> #6 0x00005594c115df49 in socket_flush () at /home/andres/src/postgresql/src/backend/libpq/pqcomm.c:1340
> #7 0x00005594c15121af in send_message_to_frontend (edata=0x5594c18a5740 <errordata>) at /home/andres/src/postgresql/src/backend/utils/error/elog.c:3283
> #8 0x00005594c150f00e in EmitErrorReport () at /home/andres/src/postgresql/src/backend/utils/error/elog.c:1541
> #9 0x00005594c150c42e in errfinish (filename=0x5594c16fdaed "postgres.c", lineno=3266, funcname=0x5594c16ff5b0 <__func__.9> "ProcessInterrupts")
> at /home/andres/src/postgresql/src/backend/utils/error/elog.c:592
> #10 0x00005594c134f770 in ProcessInterrupts () at /home/andres/src/postgresql/src/backend/tcop/postgres.c:3266
> #11 0x00005594c134b995 in ProcessClientReadInterrupt (blocked=true) at /home/andres/src/postgresql/src/backend/tcop/postgres.c:497
> #12 0x00005594c1153417 in secure_read (port=0x5594c2e7d620, ptr=0x5594c189ba60 <PqRecvBuffer>, len=8192)
>
> reporting a FATAL error in process of reporting a FATAL error. Yeha.
>
> I assume this could lead to sending out the same message quite a few
> times.

This seems like it needs to be fixed in elog.c. ISTM that at the very least we
ought to HOLD_INTERRUPTS() before the EmitErrorReport() for FATAL.

Greetings,

Andres Freund