PostgreSQL conflict with recovery: why both standard fixes make it worse under Patroni
Short answer: Both top search results for canceling statement due to conflict with recovery are wrong on a Patroni cluster with replication slots and one replica. hot_standby_feedback=on parks the xmin horizon inside the slot, where it survives the replica’s death and bloats the primary; raising max_standby_streaming_delay converts held-back replay into the exact lag your load balancer ejects the replica for. What I shipped instead was removing on-marked-down shutdown-sessions from the read backend, after measuring that replica lag is 11.5 ms at the median against a health-check threshold of 10 MB.
The cluster: one primary and one replica under Patroni 3.0.2 with etcd, PostgreSQL 15, synchronous replication, use_slots: true. Web requests from PHP-FPM read through HAProxy 2.4.30 against the replica; CLI work (queues, scheduler) goes to the primary. Four times an hour a cron job deletes and recreates roughly a million rows, and it belongs to someone else’s business logic, so it is not negotiable. The application was catching SQLSTATE[40001], and a developer had already written an interceptor at the PostgresConnection level that retries the cancelled read on the primary. The question I was handed was whether he’d done it right. That took a day to answer and turned out to be about something else entirely.
TL;DR
- Fix: drop
on-marked-down shutdown-sessionsfrom the read backend — it was killing up to 44 live sessions per ejection, and the application does not see40001for those, it sees a dead socket. - Don’t:
hot_standby_feedback=onwith replication slots and a single replica — the xmin outlives the replica, so the failure mode moves from “a report dies” to “the primary fills its disk.” - Don’t: raise
max_standby_streaming_delaywhen the load balancer health-checks replayed position — you pay for it with fan-out read outages instead of ~20 cancelled queries a day. - Measure:
replay_lagsampled from the primary. Median 11.5 ms, p95 61.7 ms, max 2.30 s over 1250 samples, against a threshold that a 168 MB burst clears in three seconds. - Trap: Patroni’s
lag=parameter is bytes-only. A requirement stated in seconds cannot be expressed in it at all.
Why hot_standby_feedback is the wrong first move with replication slots
Replication slots change what hot_standby_feedback=on costs you, because the xmin stops being tied to a live connection. The PostgreSQL 15 documentation is upfront about the general risk: the parameter “can be used to eliminate query cancels caused by cleanup records, but can cause database bloat on the primary for some workloads” (runtime-config-replication). That sentence is what every answer on the internet is implicitly waving away when it recommends the setting.
The part that applies specifically here is one section over, in the description of slots: “Replication slots provide an automated way to ensure that the primary does not remove WAL segments until they have been received by all standbys, and that the primary does not remove rows which could cause a recovery conflict even when the standby is disconnected” (warm-standby).
Read that as an operator rather than as a feature description. Without slots, feedback xmin lives as long as the session does; kill the replica and the primary is free again. With slots, the xmin settles into pg_replication_slots.xmin and stays there while the replica is gone. There’s one replica in this cluster and no spare. Turning the setting on would mean any replica outage becomes unbounded bloat on the primary, and I’d have traded about twenty cancelled read queries a day for a way to take down the whole database. That one didn’t need a benchmark to reject.
Why raising max_standby_streaming_delay feeds the flap
Delaying WAL replay is only free if nothing downstream measures replay position, and on this cluster the load balancer does exactly that. max_standby_streaming_delay is the second-most-popular answer, and on paper it is the polite one: instead of killing the query, hold back the apply. The docs describe it as “the maximum total time allowed to apply WAL data once it has been received from the primary server,” defaulting to 30 seconds (runtime-config-replication). The cost stays on the replica, which is what makes it look safe.
It isn’t safe here. HAProxy’s health check calls Patroni’s /replica?lag=, and Patroni computes lag from the replayed position. Held-back replay is, by definition, replay lag. Push the parameter from 30 s to 300 s and every conflict-heavy moment turns into a five-minute-wide window where the balancer can decide the replica is stale and pull it from rotation. The outcome would have been strictly worse than the problem: instead of ~20 cancelled queries per day, fan-out outages across all reads.
The full set of candidates, and why each one died:
| Candidate | Where the cost lands | Why it was rejected |
|---|---|---|
hot_standby_feedback=on | Primary (bloat) | With slots, xmin survives replica downtime; single replica, no spare |
max_standby_streaming_delay 30s → 300s | Replica (replay lag) | Replay lag is what the health check ejects on; amplifies flapping |
| Health-check threshold 10 MB → 512 MB | Nothing measurable | The requirement was stated in seconds; any byte value is a guess at time |
HAProxy agent-check on wall-clock lag | New moving part | Correct, but a new component in the infrastructure; deferred until measured |
Drop on-marked-down shutdown-sessions | Nothing | Shipped |
The third row is the one I would have gotten wrong on my own. I proposed raising the byte threshold, and the customer rejected it with a better argument than mine: the requirement was written in time (“a second of staleness is fine, half a minute is not”), and a byte threshold answers a different question. On steady write load the two are nearly interchangeable. On batch write load they diverge by orders of magnitude, which is the whole story of this cluster.
Two problems that looked like one
Conflicts and replica ejections clustered in the same minutes because they share a cause, not because one causes the other; the overlap was 5%. There were two symptom streams. One in the PostgreSQL log:
ERROR: canceling statement due to conflict with recovery
DETAIL: User query might have needed to see row versions that must be removed.
FATAL: terminating connection due to conflict with recovery
And one in the HAProxy log:
Server slave/pg_replica is DOWN, reason: Layer7 wrong status, code: 503,
info: "Service Unavailable", check duration: 4ms. 0 active and 0 backup
servers left. 44 sessions active, 0 requeued, 0 remaining in queue.
Both landed at :00, :29–30 and :43–45. The connection seemed too obvious to check, which is precisely why it deserved checking.
Before I got there I burned time on two hypotheses that a timestamp comparison would have killed in a minute each:
- Checkpoints. With
checkpoint_timeout=15minthe primary logs checkpoints at :04, :19, :34 and :49. The ejections are at :00, :29–30, :43–45. No overlap at all. - The backup window. The backup script raises
max_standby_streaming_delayto 3600 s for the duration ofpg_dump, which looked like an excellent suspect. Every one of the 30 ejections lasted between 6 and 27 seconds. There is not a single hour-long window in the data.
Then I lined up the two event streams properly (the logs are in different timezones, so this needs converting to one scale first) and compared: 11 of 30 replica ejections and 12 of 227 conflict events fall in shared windows. Twelve out of 227 is 5%. Two independent symptoms driven by the same cron job, not a chain.
I should have run that correlation first. It cost one command, and it invalidated a morning’s worth of theories I’d been carefully stacking on top of each other.
What the lag actually was, in bytes and in seconds
The replica was never slow at applying WAL; it was slow at receiving it, and the difference decides which knob is even relevant. I sampled pg_stat_replication from the primary once per second, 330 samples:
| |
10:43:26 replay= 0.0MB flush= 0.0MB
10:43:27 replay=151.3MB flush=151.1MB ← cron batch starts
10:43:28 replay=168.0MB flush=168.0MB
10:43:29 replay= 92.8MB flush= 92.7MB
10:43:31 replay= 0.0MB flush= 0.0MB ← caught up
flush tracks replay to within a fraction of a percent. Nothing is queued waiting to be applied, so the lag is purely transport: the primary generated WAL faster than the link carried it. At rest the replica sits 0–43 KB behind. The health-check threshold is 10 MB. A burst of 168 MB clears that threshold by a factor of 17 and is gone within three seconds.
Then the measurement that actually settled the argument, using the *_lag interval columns over 20 minutes and 1250 samples:
| Metric | replay_lag |
|---|---|
| Median | 11.5 ms |
| p95 | 61.7 ms |
| Maximum | 2.30 s |
| Samples above 5 s | 0 |
| Samples above 30 s | 0 |
The stated requirement was “a second is acceptable, half a minute is not.” The replica never came within three orders of magnitude of unacceptable. And the nature of the lag is confirmed again by subtracting one column from the other at the peaks:
12:43:25 158.5 MB | flush 1.029 s | replay 1.029 s | delta +0.2 ms
12:28:24 98.6 MB | flush 0.685 s | replay 0.685 s | delta 0.0 ms
12:43:26 94.8 MB | flush 1.651 s | replay 1.652 s | delta +0.8 ms
Applying WAL adds fractions of a millisecond. The two peaks caught in that window are at :28 and :43, exactly 15 minutes apart, which is the cron job signing its work.
What lag= in the Patroni health check actually guards
The lag= parameter covers exactly one scenario, “replica alive but behind,” because role and state are checked independently of it. The source is more useful than the documentation here: the docs describe what the endpoint is for, the code describes what it does. From patroni/api.py in v3.0.2:
| |
Two things fall out of those few lines. First, parse_int(..., 'B'): the threshold is bytes, full stop. There’s no time-based variant of this endpoint, so the entire discussion about “what number should we put there” was unanswerable until somebody said the units out loud. Second, is_lagging sits in a chain with role and state, each able to produce a 503 on its own. A genuinely broken replica gets caught by state/role anyway: when streaming breaks, the row just vanishes from pg_stat_replication and there’s no byte figure left to compute.
Prometheus history sizes the one scenario the threshold does cover (pg_replication_lag_seconds, 15 s scrape, 60-day retention). Over 30 days, lag exceeded one minute exactly once: 15,927 seconds, or 4.4 hours, on 15 July, when the replica’s VM came back from a hypervisor reboot without network.
2.3 seconds in the worst normal case against 4.4 hours for a real failure. Four orders of magnitude between them, and the threshold was sitting right up against the lower bound. A threshold that far from the signal it’s supposed to catch isn’t “tuned strictly,” it’s tuned arbitrarily. The group_vars file even carries a comment from whoever raised it from 5 MB to 10 MB: “increased to avoid false DOWN during checkpoint/autovacuum.” Against a 168 MB burst, no value in that range was ever going to work.
Why pg_replication_lag_seconds lies when nobody is writing
On a replica, postgres_exporter computes this metric as now() - pg_last_xact_replay_timestamp(), so during write silence it grows on its own without the replica being behind by anything. Its p99 over the month is about 18 seconds, and reading that as “the replica served 18-second-stale data” is wrong: it means the last transaction it replayed was 18 seconds old, because no newer transaction existed. On the primary the same metric is flat zero. Only direct replay_lag sampling from the primary is trustworthy.
The second limitation is resolution. At a 15-second scrape interval, a four-second burst is invisible by construction. For short events the instrument is the HAProxy log, not the dashboard.
Reading burst length out of the HAProxy log
When monitoring resolution is too coarse, the health check itself is a measuring instrument with known timing. With inter 3s fall 3 rise 2:
DOWNis declared afterfall 3×inter 3s= 9 seconds above threshold.UPreturns afterrise 2×inter 3s= 6 seconds below it.- Therefore burst length ≈ DOWN duration + 3 s.
Applied to all 30 ejections over 8 days:
| DOWN lasted | Occurrences | Burst was | Survives fall 5? |
|---|---|---|---|
| 6 s | 19 | ~9 s | no — eliminated |
| 9 s | 2 | ~12 s | no — eliminated |
| 18 s | 2 | ~21 s | yes |
| 21 s | 6 | ~24 s | yes |
| 27 s | 1 | ~30 s | yes |
Nineteen of thirty lasted the minimum possible DOWN, meaning the burst barely crossed the threshold and was already over. Raising fall 3 → fall 5 requires 15 consecutive seconds above threshold and removes 21 of 30 ejections, 70%, with no staleness risk given the numbers above. The remaining nine ran 21–30 seconds and would still eject.
That arithmetic required no new tooling, no sampling, and no agreement from anyone. The data had been in the balancer log the whole time.
What I shipped, and how the rollout went sideways
One line removed from the read backend, leaving the failover-critical backends untouched:
| |
The HAProxy 2.4 manual describes the option plainly: with shutdown-sessions, “all connections to the server are immediately terminated when the server goes down” (configuration manual, §5.2). On a read backend fronting a replica that comes back within seconds, that is damage with no upside. In the logs it killed up to 44 sessions at once. The application does not see 40001 for those connections, it sees a severed socket, which the developer’s interceptor never catches. The replica can still be ejected during a burst; live reads now finish, and new connections fall through to use_backend master if { nbsrv(slave) eq 0 }. The option stays in the master and long_queries backends, where killing sessions during failover is the point.
Three things about the rollout worth stealing:
--check --diffon the whole playbook, not just my part. Someone had addedweight 80/weight 20by hand on the server and never put them in the template. A normal run would have silently erased them. I pulled the repository up to the server’s actual state first, then applied my change on top.- A
group_varsfile turned out to be a hardlink shared by three inventories. One edit, three environments changed. - I rolled it out with a restart instead of a reload. In master-worker mode
kill -USR2to the master reloads without dropping anything: the master holds the sockets, the port never closes, and the old worker drains its sessions. A restart dropped every connection at once — which is precisely the damage this change exists to prevent. Shipping a fix for connection drops by dropping every connection is the kind of thing you only do once.
What the application layer got wrong
The interceptor I was asked to review was correct; the defects were around it. Findings handed back to the developers:
ERRORandFATALare different events.ERROR: canceling statement due to conflict with recoverycancels the statement and leaves the connection usable.FATAL: terminating connection due to conflict with recoverydoes not. Over 9 days: 199ERROR, 28FATAL. One retry strategy cannot serve both.- The retry loop was unreachable past its first iteration, so it retried once regardless of configuration.
- The application under-reports by half. The database logged ~319 conflict events over two weeks; the application reported ~150 through a single
Log::warning. That gap is why nobody knew the size of the problem. application_nameis empty in every event, so a conflict cannot be attributed to a service from the database logs — only to a database user.- A pre-existing lazy-connection bug in the Laravel wrapper.
bindValues()opens with$this->getPdo()->getAttribute(...), andgetPdo()resolves the lazy closure and opens a connection to the primary. Every query with bindings calls it, read-only ones included, so the read/write split silently leaks connections to the primary on any parameterised read.
Half of my initial review comments on the interceptor did not survive my own re-checking. Separating “I would have written this differently” from “this is a defect” is most of what code review is, and I am not always good at it.
Step by step
- Count the events before theorising: split
ERRORfromFATALin the PostgreSQL log and get the rate per day. - Correlate every symptom stream by timestamp on one timezone scale, first, before building any causal story.
- Sample
pg_stat_replicationfrom the primary once per second; comparereplay_lsnagainstflush_lsnto separate transport lag from apply lag. - Sample the
*_laginterval columns to get lag in seconds, which is the unit your requirement is almost certainly written in. - Read your health-check endpoint’s source for the units it actually accepts before negotiating a threshold value.
- Derive burst duration from the balancer’s own
inter/fall/risetiming when scrape intervals are too coarse. - Check whether
hot_standby_feedbackis safe for your topology: with slots and one replica, it is not. - Run
--check --diffacross the whole playbook before applying, and reload rather than restart.
Bottom line
Neither of the two canonical answers to conflict with recovery was usable on this cluster, and both failures were topology-specific rather than wrong in general. hot_standby_feedback assumes you have no slots or a spare replica; raising the streaming delay assumes nothing downstream measures replay position. Check those assumptions against your own cluster before pasting either one into postgresql.conf.
The larger lesson is about units. The health check measured “how much WAL has not arrived” in bytes while the business requirement said “how stale is the data I am serving” in seconds. Every discussion about the right threshold was unanswerable until somebody wrote both sentences down next to each other. The measured answer was 11.5 ms median against a 4.4-hour real failure — and the deferred work, an agent-check agent reporting up/down from now() - pg_last_xact_replay_timestamp(), is now a decision that can be made with numbers instead of a guess.
<< Previous Post
|
Next Post >>