Hi Shihao,
> 8. Standby promotion waits until every process has accepted a
> ProcSignalBarrier, even with wal_level=replica and no slots. A backend
> blocked sending a result to a client does not accept it. [...] promotion
> hung in 8 of 8 runs on Linux. [...] 18.6 promotes in 0.1 seconds.
I reproduced this on 19rc1 (0b8bff042a9) against 18.6, and tracked down why
it isn't always 8/8.
On promotion the startup process emits a ProcSignalBarrier (generation 1,
from UpdateLogicalDecodingStatusEndOfRecovery), even with wal_level=replica
and no slots. A backend blocked in secure_write() never accepts it: the
latch wakes the write and ProcessClientWriteInterrupt(true) runs, but it only
acts on ProcDiePending, so CHECK_FOR_INTERRUPTS() is never reached. The fix
looks like it belongs in that wait rather than in promotion.
Whether a given stalled backend blocks promotion depends on its local send
buffer, which is why it isn't 8/8 for everyone: unsaturated I got 28/28 hung
pinned to one CPU core but 0/11 on another, and there gdb shows the backend
absorbing the barrier after the kernel freed buffer space. Saturating the
send buffer first -- the state of a client that stalled a while ago -- gives
10/10 hung on 19rc1 and 0/10 on 18.6, on any core.
It is any backend blocked in a socket write, not only a SELECT: COPY ... TO
STDOUT left unread, a stalled pg_basebackup, and a crash failover all hang
too, while idle and idle-in-transaction clients do not. The same wait also
stops plain replay when the first logical slot is created on the primary,
which then blocks synchronous_commit=remote_apply commits there;
max_standby_streaming_delay does not help.
Your 949 s looks like the client's TCP retries running out. With a client
that stays connected but paused (an app thread, a psql in a pager) nothing on
the TCP side ends it: a promotion here was still hung at 450 s, zero-window
persist timer backing off, connection alive. tcp_user_timeout bounds the
wait.
Full write-up with the backtraces and the repro is attached. Happy to help
on the thread when you open it.
Regards,
Manu
# PG19: standby promotion (and standby replay) waits on a client that stopped
reading
Independent reproduction of item 8 (High) in Shihao Zhong's list
"[PG19] Bugs found comparing 19 with 18, list before I open threads"
(<cagrkxqsfdjqzp_kwrz7dv6lhx-csrkdnynnxgntrscenqtk...@mail.gmail.com>,
2026-10-13),
plus blast-radius checks he did not mention.
Builds: REL_19_STABLE at 0b8bff042a9 (19rc1) and REL_18_6 (724edf9bde9), both
`--enable-cassert --enable-debug --with-icu -O1`, Linux 7.2 x86_64. All
clusters are
throwaway pairs on tmpfs, ports 5618x/5629x. Timings come from cassert builds
and are only
there for the order of magnitude; what counts is the HUNG/PROMOTED outcome.
Everything below comes from the third full pass (`results/*.csv`). Earlier
passes are kept
in `results/run1/` and `results/run2/`. Section 2 explains why the third pass
changed the
harness.
## 1. Reproduction
Per run: a fresh primary and hot standby, `wal_level = replica`, **no
replication slots**.
One client on the standby sends
`select repeat('x', 8000) from generate_series(1, 100000000)` and never reads
again
(`repro/stall_client.py`, a ~70-line v3 protocol client that stays connected
and keeps
ACKing). `stall()` in `repro/lib.sh` waits for the backend to be in
`ClientWrite` with a
frozen `bytes_acked`, then **saturates** its local send buffer (section 2).
Then
`pg_promote(wait => false)`. HUNG means the standby was still in recovery
after 15 s.
| version | runs | HUNG | promotion | after `pg_terminate_backend()` of the
stalled backend |
|---|---|---|---|---|
| 19rc1 | 10 | **10** | n/a | promoted in 102-128 ms |
| 18.6 | 10 | 0 | 9-13 ms | n/a |
Controls on 19rc1, 3 runs each, all promoted in 10-24 ms: an idle connected
client, and an
`idle in transaction` session. So it takes a backend that is blocked in a
socket write.
`COPY ... TO STDOUT` not being read: HUNG 3/3 on 19, promoted 3/3 on 18.
**How long it lasts.** A promotion held behind a live, paused client was still
hung after
450 s (`results/D_long_hang_19.txt`): 90 "still waiting for backend with PID
..." lines,
backend in `ClientWrite`, `bytes_acked` frozen, the kernel's zero-window
persist timer
backing off from 4 to 11. The connection never died. We read Shihao's 949 s
as the case
where the probes stopped being answered (TCP retries run out). With a client
that is
still alive, for example a paused application thread or a `psql` sitting in a
pager,
nothing on the TCP side ends the wait. **949 s is not an upper bound.**
## 2. Mechanism, and why it is not 100% in the field
From a hung run (`results/evidence/19-select-run1.*`):
- `pg_stat_activity`: startup process `IPC / ProcSignalBarrier`, stalled backend
`Client / ClientWrite`.
- Standby log: `still waiting for backend with PID <stalled pid> to accept
ProcSignalBarrier`
every 5 s, right after `received promote request`.
- Startup backtrace: `WaitForProcSignalBarrier (generation=1) <-
UpdateLogicalDecodingStatusEndOfRecovery (logicalctl.c:757) <- StartupXLOG
(xlog.c:6279)`.
The barrier is emitted on every promotion, even with `wal_level = replica`
and no slots.
- Stalled backend backtrace: `secure_write (be-secure.c:347) <- internal_flush
<-
socket_putmessage <- printtup <- ExecutePlan`.
- gdb on the stalled backend: `ProcSignalBarrierPending = 1`, its slot's
`pss_barrierGeneration = 0` against a global 1. In `secure_write()` the
latch wakes the
wait and `ProcessClientWriteInterrupt(true)` runs, but that function only
acts on
`ProcDiePending`. The code goes back to `WaitEventSetWait`, and
`CHECK_FOR_INTERRUPTS()` is never reached.
**Whether a given stalled backend blocks promotion depends on its local send
buffer.**
Our first two passes, without the saturation step, hung 28/28 when run in one
CPU lane
but 0/11 in another lane or unpinned (`results/run2/`, and
`results/A_promote_select.csv` rows `select_unsaturated_laneB`: 0/5). In the
runs that
promoted, gdb shows the stalled backend **did** absorb the barrier (slot
generation 1,
nothing pending) and is still in `secure_write` / `ClientWrite` afterwards.
The send
queue shows how (`repro/diag/sendq.sh`, 3 runs, identical):
| server socket | before `pg_promote` | 2 s after |
|---|---|---|
| Send-Q (bytes queued, not acked) | 4 028 416 | 4 129 792 |
| sndbuf (`tb`) | 4 194 304 | 4 194 304 |
The peer window stays at zero, yet the backend queued ~100 KB more after the
promote
request. The kernel frees room in the local send buffer after the backend's
last
`EAGAIN` without reporting the socket writable, because epoll waits for a
threshold. The
barrier's own SIGUSR1 wakes the backend, the retried `write()` fits, the message
completes, `printtup` returns to `ExecutePlan`, `CHECK_FOR_INTERRUPTS()`
absorbs the
barrier, and the backend blocks again on the next row. Promotion goes through
by luck.
`stall()` therefore wakes the stalled backend with a harmless signal
(`pg_log_backend_memory_contexts()`) until its Send-Q stops growing, which is
the state
of a client that has been stuck for a while. With that step: 10/10 unpinned,
5/5 + 10/10
in a lane, 0/10 on 18.
For the thread: the failure is certain once the backend's send buffer is full,
which is
the steady state of a stuck client. A reproduction that sees "sometimes" is
seeing this
buffer effect, not a different bug. The same reasoning says that
`secure_write()`
should absorb barriers while it waits; relying on a write completing is what
makes it
racy.
Repro trap: shrinking the client's `SO_RCVBUF` makes the bug **not** reproduce.
The tiny
window keeps reopening, so the backend keeps completing flushes.
## 3. Blast radius
Stalled client as above, 15 s limit, 3 runs per cell unless noted
(`results/B_blast_barrier_users.csv`, `results/C_promotion_variants.csv`).
### 3a. New in 19, not in the report: standby **replay** stops, and can freeze
the primary
`EnableLogicalDecoding()` also waits for the barrier when the standby
**replays**
`XLOG_LOGICAL_DECODING_STATUS_CHANGE` (xlog.c:8793). The first logical slot
created on a
`wal_level = replica` primary therefore stops replay on every hot standby that
has a
stalled reader.
| case | 19rc1 | 18.6 |
|---|---|---|
| first logical slot on primary, stalled client on **standby**: replay |
**stopped 3/3** (startup in `ProcSignalBarrier`) | replayed in 11-12 ms [1] |
| same + `synchronous_commit = remote_apply`: a plain `INSERT` on the
**primary** | **commit blocked 3/3** in `SyncRep` until the standby backend is
killed | returned in 15-17 ms [1] |
| same, standby with `max_standby_streaming_delay = 1s` | **still stopped
3/3**: not a recovery conflict, nothing is cancelled | - |
| first logical slot on primary, stalled client on **primary**:
`pg_create_logical_replication_slot()` | **blocked 3/3** | returned in 15-16 ms
[1] |
[1] 18 cannot create a logical slot at `wal_level = replica`, so the 18 column
runs with
`wal_level = logical`, the configuration a user needed on 18 to do the same
thing.
In practice: someone creates a CDC or logical replication slot on the primary.
From then
on, one paused reader on a hot standby is enough to stop that standby's replay
with no
timeout. If the standby is a `remote_apply` synchronous standby, every commit
on the
primary waits too. Only the deactivation path (`DisableLogicalDecoding()`)
emits without
waiting.
### 3b. Other ProcSignalBarrier users: blocked too, but already in 18
| case | 19rc1 | 18.6 |
|---|---|---|
| `DROP DATABASE` on primary, stalled client on primary | blocked 3/3 | blocked
3/3 |
| `DROP DATABASE` replayed on standby, stalled client on standby | replay
stopped 3/3 | replay stopped 3/3 |
Same root cause (`PROCSIGNAL_BARRIER_SMGRRELEASE`, since 15). A fix that makes
`secure_write()` absorb barriers while blocked would cover these as well.
### 3c. Promotion variants
| case | 19rc1 | 18.6 |
|---|---|---|
| **failover after `kill -9` of the primary**, then promote | **HUNG 3/3** |
promoted, 12-13 ms |
| paused `pg_basebackup` reading from the standby (walsender in `ClientWrite`,
saturated) | **HUNG 4/4**, released 11-12 ms after terminating the walsender |
promoted 3/3, 12-30 ms |
| cascaded standby SIGSTOPped (its walsender on the standby) | promoted 3/3,
11-13 ms | promoted 3/3, 12-29 ms |
| `tcp_user_timeout = 20s` on the standby | promoted after **16.9-17.4 s** 3/3:
the backend dies with `could not send data to client: Connection timed out` |
promoted, 12-29 ms |
- A real failover hangs the same way. The trigger is the end of recovery, not
`pg_promote()`.
- A base-backup walsender is a stalled writer like any other. In the first
passes it
looked harmless (2 hangs out of 17) because of the send-buffer effect in
section 2. A
streaming walsender (cascade) does not block: it writes without blocking and
handles
interrupts in its own loop.
- Operator workaround that we measured to work: `tcp_user_timeout` bounds the
wait to
about its value (TCP keepalives do not, since they do not fire while data is
unacknowledged). Killing the backend named in the "still waiting for backend
with PID
..." log line also works.
## 4. What this adds to Shihao's item 8
1. Independent confirmation: 10/10 vs 0/10, mechanism confirmed with backtraces
and
barrier generations.
2. **New:** why the failure is not deterministic in the field: the barrier's
own signal
can squeeze one more message through a partly freed send buffer. This is
measured.
It also means the fix belongs in `secure_write()`'s wait.
3. **New:** replay of the logical-decoding status change on a standby has the
same wait.
A stalled reader on a hot standby stops replay with no timeout, and under
`remote_apply` it blocks commits on the primary.
`max_standby_streaming_delay` does
not help. Creating a logical slot on a replica-level primary also blocks
behind a
stalled reader on the primary.
4. The 949 s figure is not a ceiling: with a live paused client the hang did
not end in
450 s.
5. Crash failover and base-backup walsenders are affected. `tcp_user_timeout`
bounds it.
6. `DROP DATABASE` (primary and replay) has had the same failure since the
SMGRRELEASE
barrier. It is not a 19 regression, but it argues for fixing the absorb
side.
## 5. How the three passes compare
- Pass 1 (before a reboot wiped tmpfs), pass 2 and pass 3 agree on every case in
sections 3a and 3b.
- Pass 2 found the "sometimes" behaviour: it rarely hung outside one CPU lane,
the
base-backup walsender hung only sometimes, and one 450 s hold promoted at
once.
Section 2 explains all three, and pass 3 adds the saturation step.
- Harness failures we caught and excluded:
- Twice the standby did not start, which looked like a hang; `pair_up` now
reports
`SETUP_FAILED` and keeps the logs.
- Two cells ran after their shell lost write access when an act went to the
background.
- A `tcp_user_timeout` of 3 s expired before the promotion once saturation
added
seconds; it is now 20 s.
- `results/evidence/` holds the per-run activity, logs and backtraces of passes
2 and 3.
## Files
- `build/build.sh`: the two builds
- `repro/stall_client.py`: client that stops reading
- `repro/lib.sh`: ephemeral primary/standby/cascade harness; `stall()` with
settle and
saturation (`STALL_SATURATE=0` to see the luck)
- `repro/promote_hang.sh VER RUNS [HANG] [select|copyout|none|idletx]`: section
1
- `repro/blast.sh VER CASE [HANG]`: sections 3a-3c; `STANDBY_GUCS=` for extra
settings
- `repro/cells.sh`: runs cells with a 120 s cap each
- `repro/basebackup_stall.sh VER RUNS`: the paused base backup
- `repro/long_hang.sh VER SECS`: the long hold with TCP sampling
- `repro/diag/why_promoted.sh`, `repro/diag/sendq.sh`: section 2 diagnostics
- `results/`: CSVs, `D_long_hang_19.txt`, `evidence/`, `run1/`, `run2/`
- `shihao_thread.txt`: the source message
#!/usr/bin/env python3
"""A PostgreSQL client that sends one query and then stops reading.
Speaks just enough of the v3 protocol (startup, trust auth, simple Query) to
make a backend start streaming a large result, then never reads the socket
again. The kernel buffers fill and the backend blocks in secure_write()
(wait_event ClientWrite). The process stays alive and keeps ACKing TCP
zero-window probes, which is what a paused or wedged application looks like.
usage: stall_client.py PORT DBNAME SQL [--rcvbuf BYTES]
Prints "SENT <backend pid> <local port>" once the query is on the wire, then
sleeps until killed.
"""
import argparse
import os
import socket
import struct
import sys
import time
ap = argparse.ArgumentParser()
ap.add_argument("port", type=int)
ap.add_argument("dbname")
ap.add_argument("sql")
ap.add_argument("--host", default="127.0.0.1")
ap.add_argument("--user", default=os.environ.get("USER", "postgres"))
ap.add_argument("--rcvbuf", type=int, default=0, help="0 = kernel default")
a = ap.parse_args()
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
# Optional: shrink the receive buffer. Do NOT use this for the repro: with a
tiny
# buffer the kernel keeps reopening the window a few bytes at a time, the
backend
# completes a flush now and then, reaches CHECK_FOR_INTERRUPTS() and absorbs the
# barrier. The hang needs a window that stays at zero (default buffers do
that).
if a.rcvbuf:
s.setsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF, a.rcvbuf)
s.connect((a.host, a.port))
def recv_exact(n):
buf = b""
while len(buf) < n:
chunk = s.recv(n - len(buf))
if not chunk:
sys.exit("server closed the connection")
buf += chunk
return buf
def read_msg():
t = recv_exact(1)
(ln,) = struct.unpack("!I", recv_exact(4))
return t, recv_exact(ln - 4)
params = b"user\0" + a.user.encode() + b"\0database\0" + a.dbname.encode() +
b"\0\0"
s.sendall(struct.pack("!II", 8 + len(params), 196608) + params)
backend_pid = None
while True:
t, body = read_msg()
if t == b"R" and struct.unpack("!I", body[:4])[0] != 0:
sys.exit("only trust auth is supported")
if t == b"K":
backend_pid = struct.unpack("!I", body[:4])[0]
if t == b"E":
sys.exit("error during startup: %r" % body)
if t == b"Z":
break
q = a.sql.encode() + b"\0"
s.sendall(b"Q" + struct.pack("!I", 4 + len(q)) + q)
print("SENT", backend_pid, s.getsockname()[1], flush=True)
while True: # alive, connected, never reading
time.sleep(3600)
# lib.sh -- ephemeral primary/standby pairs for the PG19 promotion-hang repro.
# Source it; then `pair_up 19` or `pair_up 18`. Everything lives under
# $RUN (tmpfs), on high ports, and is torn down by pair_down. Never touches
# any other cluster on the machine.
#
# VER=19 -> REL_19_STABLE 0b8bff042a9 (19rc1) ports 56190/56191
# VER=18 -> REL_18_6 ports 56180/56181
set -u
HERE=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)
RUN=${RUN:-/tmp/shihao/run}
bin_of() { case $1 in 19) echo /tmp/shihao/pg19rc1/inst/bin;; 18) echo
/tmp/shihao/pg186/inst/bin;; esac; }
pport() { echo $((56100 + $1 * 10)); } # primary
sport() { echo $((56101 + $1 * 10)); } # standby
cport() { echo $((56102 + $1 * 10)); } # cascaded standby
pdir() { echo "$RUN/$1/primary"; }
sdir() { echo "$RUN/$1/standby"; }
cdir() { echo "$RUN/$1/cascade"; }
now_ms() { date +%s%3N; }
# q VER PORT SQL -- one-shot psql, tuples only, unaligned
q() { "$(bin_of "$1")/psql" -X -h 127.0.0.1 -p "$2" -d postgres -Atq -c "$3"; }
common_conf() { # $1 datadir $2 port
cat >> "$1/postgresql.conf" <<CONF
port = $2
listen_addresses = '127.0.0.1'
unix_socket_directories = '$1'
wal_level = replica
max_wal_senders = 10
hot_standby = on
fsync = off
log_line_prefix = '%m [%p] %b '
log_min_messages = log
logging_collector = off
shared_buffers = 64MB
CONF
}
pair_up() { # VER [cascade]
local v=$1 b; b=$(bin_of "$v")
pair_down "$v" >/dev/null 2>&1
mkdir -p "$RUN/$v"
"$b/initdb" -D "$(pdir "$v")" -A trust -U "$USER" --no-sync
>"$RUN/$v/initdb.log" 2>&1
common_conf "$(pdir "$v")" "$(pport "$v")"
echo "host replication all 127.0.0.1/32 trust" >> "$(pdir "$v")/pg_hba.conf"
"$b/pg_ctl" -D "$(pdir "$v")" -l "$RUN/$v/primary.log" -w start >/dev/null
# No replication slot on purpose: the report is about wal_level=replica, no
slots.
"$b/pg_basebackup" -h 127.0.0.1 -p "$(pport "$v")" -D "$(sdir "$v")" -R -X
stream --no-sync >/dev/null
sed -i "s/^port = .*/port = $(sport "$v")/; s#^unix_socket_directories =
.*#unix_socket_directories = '$(sdir "$v")'#" "$(sdir "$v")/postgresql.conf"
"$b/pg_ctl" -D "$(sdir "$v")" -l "$RUN/$v/standby.log" -w start >/dev/null
if [ "${2:-}" = cascade ]; then
"$b/pg_basebackup" -h 127.0.0.1 -p "$(sport "$v")" -D "$(cdir "$v")" -R -X
stream --no-sync >/dev/null
sed -i "s/^port = .*/port = $(cport "$v")/; s#^unix_socket_directories =
.*#unix_socket_directories = '$(cdir "$v")'#" "$(cdir "$v")/postgresql.conf"
"$b/pg_ctl" -D "$(cdir "$v")" -l "$RUN/$v/cascade.log" -w start >/dev/null
fi
# Fail loudly if a server did not come up: a dead standby looks exactly like a
# hung promotion to the callers ("still in recovery" never turns false).
if ! wait_until 30 "$v" "$(pport "$v")" "select count(*) >= 1 from
pg_stat_replication where state = 'streaming'" t \
|| [ "$(q "$v" "$(sport "$v")" "select pg_is_in_recovery()" 2>/dev/null)"
!= t ]; then
mkdir -p /tmp/shihao/evidence/setup-failed
cp "$RUN/$v"/*.log /tmp/shihao/evidence/setup-failed/ 2>/dev/null
echo "pair_up $v: setup failed" >&2
return 1
fi
}
pair_down() {
local v=$1 b d; b=$(bin_of "$v")
pkill -f "stall_client.py $(sport "$v") " 2>/dev/null
pkill -f "stall_client.py $(pport "$v") " 2>/dev/null
for d in "$(cdir "$v")" "$(sdir "$v")" "$(pdir "$v")"; do
[ -f "$d/postmaster.pid" ] && "$b/pg_ctl" -D "$d" -m immediate -w stop
>/dev/null 2>&1
done
rm -rf "${RUN:?}/$v"
}
# wait_until SECS VER PORT SQL EXPECTED -- poll every 10 ms; 0 if it matched
wait_until() {
local deadline=$(( $(now_ms) + $1 * 1000 ))
while [ "$(now_ms)" -lt "$deadline" ]; do
[ "$(q "$2" "$3" "$4" 2>/dev/null)" = "$5" ] && return 0
sleep 0.01
done
return 1
}
# stall VER PORT [SQL] -- start a non-reading client, echo its backend pid once
# that backend sits in wait_event ClientWrite
stall() {
local v=$1 port=$2 sql=${3:-"select repeat('x', 8000) from generate_series(1,
100000000)"} out pid
out=$(mktemp "$RUN/$v/stall.XXXX")
python3 "$HERE/stall_client.py" "$port" postgres "$sql" > "$out" 2>&1 &
for _ in $(seq 500); do grep -q '^SENT' "$out" && break; sleep 0.01; done
pid=$(awk '/^SENT/{print $2}' "$out")
[ -n "$pid" ] || { echo "stall client failed: $(cat "$out")" >&2; return 1; }
wait_until 20 "$v" "$port" "select wait_event from pg_stat_activity where pid
= $pid" ClientWrite \
|| { echo "backend $pid never reached ClientWrite" >&2; return 1; }
# ClientWrite is not enough. Right after the client's buffer fills, its
# kernel still reopens the window a few bytes at a time; a barrier that lands
# then gets absorbed because the backend completes a flush and reaches
# CHECK_FOR_INTERRUPTS(). Wait until the server socket stops moving data
# (bytes_acked unchanged for 2 s) so every run starts from a truly stuck
backend.
local lport last="" cur stable=0
lport=$(awk '/^SENT/{print $3}' "$out")
for _ in $(seq 60); do
cur=$(ss -tinH "( sport = :$port and dport = :$lport )" | grep -o
'bytes_acked:[0-9]*')
if [ -n "$cur" ] && [ "$cur" = "$last" ]; then stable=$((stable + 1)); else
stable=0; fi
[ $stable -ge 4 ] && break
last=$cur; sleep 0.5
done
[ $stable -ge 4 ] || echo "warning: socket of backend $pid never settled" >&2
# Settled bytes_acked is still not enough. The kernel can free room in the
LOCAL
# send buffer after the backend's last EAGAIN without reporting the socket as
# writable (epoll waits for a threshold). A barrier's SIGUSR1 then wakes the
# backend, the retried write() fits, the message completes, the next
# CHECK_FOR_INTERRUPTS() absorbs the barrier, and promotion goes through by
luck.
# Saturate first: wake the backend with a harmless signal until its Send-Q
stops
# growing. (STALL_SATURATE=0 skips this, to show the luck.)
if [ "${STALL_SATURATE:-1}" = 1 ]; then
local sq prev="" same=0
for _ in $(seq 40); do
q "$v" "$port" "select pg_log_backend_memory_contexts($pid)" >/dev/null
2>&1
sleep 0.2
sq=$(ss -tnH "( sport = :$port and dport = :$lport )" | awk '{print $3}')
if [ "$sq" = "$prev" ]; then same=$((same + 1)); else same=0; fi
[ $same -ge 3 ] && break
prev=$sq
done
[ $same -ge 3 ] || echo "warning: send queue of backend $pid kept growing"
>&2
fi
echo "$pid"
}
