ProcSignalBarrier waits behind a session stuck writing to its client: which change clears which case ===================================================================== Which change clears which case, measured. Same base for every column: master master at f2edf5dd00d, unpatched note the docs note for 19 (no code change); its two remedies, measured on master: (a) pg_terminate_backend() on the logged PID, (b) tcp_user_timeout set ahead of time (10s here; TCP clients only) v6 master + v6_fix_masahiko.patch (applies cleanly) v2 master + v2-0001 (option 2), procsignal_barrier_timeout = 2s All builds: --enable-cassert --enable-debug --enable-tap-tests --enable-injection-points. The stuck session is a client that is alive but has stopped reading, so its backend sits in ClientWrite. 3 runs per cell unless stated. Times are in ms from the start of the operation unless stated; the "hung" cells are bounded by the observation window (12 s for promotion, 15 s otherwise), not by the server. row master note (a) / (b) v6 v2 -------------------------------------------------------------------------------- Standby, wal_level = replica on both nodes 1 failover slot at start hung 4-6 / 10.5 s 20-24 2024-2031 2 local slot at start hung 6-7 9-26 2011-2019 3 slot made in recovery(6) hung 4-6 12-26 2010-2038 4 toggled in recovery hung 6 9-25 2013-2021 5 stuck, then first slot replay 15s+ 4-6 / 10.5 s replay 15s+ 2040-2063 9 crash, then promotion hung not measured 23-24 2021-2031 Primary 6 enable data checksums hung 70-121 (*) hung 2066-2074 7 DROP DATABASE, other db hung 5-6 (*) hung 2008-2012 8 DROP DATABASE, walsender hung 4-6 (*) hung 2009-2013 Negative controls (DROP DATABASE as the barrier; must survive) idle session 8-9 - 7-9 7-10 pg_sleep(600) 9-10 - 9 8-10 slow reader (keeps reading) 8-9 - 8-10 8-10 sync rep waiter, no standby waits 15s+ - waits 15s+ waits 15s+ COPY FROM STDIN, paused waits 15s+ - waits 15s+ waits 15s+ -------------------------------------------------------------------------------- (a) ms from pg_terminate_backend() of the stuck backend to completion. (b) total time from the moment the backend blocked (see "tcp_user_timeout"). (*) the note is about promotion and does not cover rows 6-8; (a) still works. "replay 15s+": replay of the record that enables logical decoding did not reach it within 15 s. Row 3 is 3 runs with a synced failover slot plus 3 with a slot made on the standby. Rows ---- 1 Failover slot created on the primary before the base backup, synced to the standby by the slot sync worker. Logical decoding is on from standby start. 2 Same status, but the logical slot is created on the standby itself. 3 The primary creates its first logical slot after the standby started (a replayed enable record); synced failover slot, or a slot on the standby. 4 On at start, off (last primary slot dropped, checkpoint), on again, all while the standby is in recovery. 5 The backend gets stuck first; then the primary creates its first logical slot. Measured: does replay of the enable record pass the stuck backend? 9 Row 1 setup plus a slot on the standby; kill -9 of a standby backend (crash restart), then the stuck session and promotion. 6-8 On a primary: pg_enable_data_checksums(); DROP DATABASE of another database while the session is connected elsewhere; DROP DATABASE while a walsender is stuck sending a base backup. In every promotion row, after promotion 5 rows inserted on the new primary were decoded through the logical slot, in every run of every column. How it was measured ------------------- Rows 1-5, 9: repro-standby.sh (with stall.py). Primary and standby on 127.0.0.1, both wal_level = replica. The stuck session runs COPY ... TO STDOUT from stall.py, which never reads. Before acting, the script waits until the backend stays blocked: its socket's bytes_acked stops moving, and a wakeup with pg_log_backend_memory_contexts() no longer makes it log (a woken backend can fit one more send and absorb a pending barrier otherwise). Then pg_promote(false); "hung" = not promoted in 12 s, after which the script terminates the stuck backend and records the release time. Rows 6-8: t/090_barrier_primary_rows.pl; controls: t/091_barrier_controls.pl. Both are TAP tests run inside the source tree of each build. The controls set synchronous_commit = local and only the sync rep control session turns it on, so CREATE/DROP DATABASE never wait for the missing standby. For the two "waits" controls, the barrier wait was logged ("still waiting for backend with PID ...") in every run, and DROP DATABASE finished 9-20 ms after the control was released (standby names reset / end of COPY data sent). 45 control runs (5 controls x 3 runs x 3 builds): every session survived, none was terminated. In every v2 cell that cleared, the stuck backend was terminated by the timeout ("terminating process ... within 2000 ms"; checked in the log for rows 6-8, 9/9). Every "hung" cell was released by pg_terminate_backend() of the stuck backend in 4-175 ms. tcp_user_timeout (column note, (b)) ----------------------------------- tcp_user_timeout = 10s in postgresql.conf, measured with the attached script (repro-standby.sh, which waits until the backend is blocked for good before acting; WINDOW=40 RWAIT=40). Promotion (row 1): promoted 10.49 s after the backend blocked (10489-10493 ms), 3/3. Replay (row 5): caught up 10.52-10.56 s after the backend blocked, 3/3. Every run logged "could not send data to client: Connection timed out". Not measured: clients on a Unix-domain socket (tcp_user_timeout does not apply to them), rows 6-8 and row 9 with (b). Stale caches (XLogLogicalInfo) ------------------------------ With CENSUS=1, repro-standby.sh reads the process-local XLogLogicalInfo of every standby child with gdb (needs gdb, debug symbols and permission to attach), just before pg_promote() and again after promotion. Rows 1-2 (status on since standby start): master and v2 had 5 stale processes (checkpointer, background writer, both io workers, startup) out of 7-8 in 12/12 runs; v6 had none, 6/6. Row 9, after the crash restart: master and v2 5/7, v6 0/7. Rows 3-5: no stale process in any column. After promotion: no stale process in any run of any column. Discarded runs -------------- tcp_user_timeout = 3s: the backend had already timed out before the operation started, so those runs (all "promoted in 8-25 ms") do not measure the bound. One replay run that acted as soon as the backend first showed ClientWrite: the backend was not blocked yet and absorbed the barrier (caught up in 60 ms). Three earlier promotion runs without the settle step (10.50-10.52 s after the backend blocked) agree with the numbers above but used a different method; they are superseded by the runs made with the attached script. One row 1 run on master: setup timed out (slot never synced within 170 s); replaced. A first controls run hung in the harness (CREATE DATABASE waited for the missing sync standby); fixed as described above. Related, measured on other setups --------------------------------- - REL_19_STABLE at 2dc899f780f + v6: 25/25 promotions cleared over the same setups (unpatched 22/22 hung); row 5 stalled 15 s with and without v6. - v2's own test (recovery/061): 11/11 runs, 11/11 pinned to one CPU. - v2 limit: a session sending one 100 MB value to a client reading 2 MB/s is terminated at the timeout (30.05 s with the default 30s); master waits until the value is out (50.5 s). - Recovery conflicts against such a backend are not cleared by any column.