PostgreSQL conflict with recovery: почему hot_standby_feedback со слотами опасен, а lag= в Patroni мерит не то

Короткий ответ: оба популярных лекарства от canceling statement due to conflict with recovery в связке Patroni + HAProxy вредны. hot_standby_feedback=on при включённых репликационных слотах сажает xmin в сам слот, и он переживает отключение реплики — проблема чтения превращается в риск для мастера. Рост max_standby_streaming_delay конвертируется в отставание, по которому балансировщик выкидывает реплику: вместо 25 отменённых запросов в сутки получаются веерные обрывы всего чтения. Настоящий виновник нашёлся замером: отставание в покое 0–43 КБ, всплеск от крона — 168 МБ за 3 секунды, а порог health-check стоял на 10 МБ.

Прод: один праймари и одна реплика под Patroni 3.0.2 с etcd, PostgreSQL 15, синхронный режим, слоты включены. Веб читает с реплики через HAProxy 2.4.30, CLI ходит на мастер. Четыре раза в час крон удаляет и создаёт около миллиона записей — чужая бизнес-логика, повлиять нельзя. За девять дней лог реплики дал 199 ERROR и 28 FATAL, и выглядят они так:

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

Ко мне пришли с вопросом «правильно ли разработчик написал перехватчик 40001», а вылилось это в рабочий день расследования, по итогам которого выяснилось: проблема не одна, а две, и связаны они на 5 %.

Коротко (TL;DR)

• Решение: убрать on-marked-down shutdown-sessions из read-бэкенда HAProxy. Реплика всё ещё может выпасть, но живые read-запросы дорабатывают, а новые соединения уходят на мастер через use_backend master if { nbsrv(slave) eq 0 }. Лечится ущерб, а не причина — осознанно.
• Не делать: hot_standby_feedback=on при use_slots: true и единственной реплике. xmin оседает в слоте и переживает смерть реплики; мастер копит мёртвые строки до заполнения диска.
• Не делать: поднимать max_standby_streaming_delay с 30 с до 300 с, если health-check балансировщика смотрит на replayed-позицию. Отложенный накат — это и есть то отставание, по которому реплику выкидывают.
• Грабли: lag= в Patroni задаётся только в байтах, временного порога в эндпоинте нет в принципе. Бизнес формулирует требование в секундах, health-check меряет в мегабайтах, и на пачечной записи эти величины расходятся в разы.
• Грабли: pg_replication_lag_seconds на реплике в тишине растёт сам по себе — она показывает возраст последней транзакции, а не отставание.
• Приём: длину всплеска можно восстановить из тайминга health-check (inter/fall/rise), не заводя новых метрик. 19 выпадений из 30 длились ровно минимально возможные 6 секунд.

Почему hot_standby_feedback при включённых слотах — плохой размен

Со слотами hot_standby_feedback перестаёт быть локальной настройкой реплики и становится долгом мастера, который тот не может списать. Это первое, что выдаёт любой поиск по тексту ошибки, и рекомендация правильная — документация PostgreSQL 15 в разделе про конфликты запросов говорит прямо: «The first option is to set the parameter hot_standby_feedback, which prevents VACUUM from removing recently-dead rows and so cleanup conflicts do not occur» (Hot Standby — Handling Query Conflicts).

Механика проста: реплика сообщает мастеру свой xmin, вакуум не трогает версии строк, которые ещё кому-то видны, конфликтов нет. Описание параметра там же честно предупреждает про цену — «can cause database bloat on the primary for some workloads» (runtime-config-replication).

Вся разница — в том, где живёт этот xmin. Без слотов он привязан к сессии walsender: реплика отвалилась — сессия закрылась — мастер свободен. Со слотами (postgresql.use_slots в Patroni по умолчанию true) xmin оседает в самом слоте, а слот — это персистентная сущность в каталоге. Описание колонки pg_replication_slots.xmin формулирует это без оговорок: «The oldest transaction that this slot needs the database to retain. VACUUM cannot remove tuples deleted by any later transaction» (pg_replication_slots).

Слот не знает, что реплика умерла. Он знает, что кто-то ещё вернётся за этими строками.

Реплика в кластере одна, запасной нет. Включи я hot_standby_feedback, и сценарий «реплика ушла в ребут на полчаса» превращается в «мастер полчаса не вакуумит таблицу, по которой крон четыре раза в час прогоняет миллион строк». Меняем «падает отчёт на реплике» на «может лечь мастер». Совет из интернета не плохой — он молча предполагает отсутствие слотов и наличие второй реплики. У нас нет ни того, ни другого.

Почему поднять max_standby_streaming_delay в схеме с балансировщиком хуже, чем ничего не делать

Отложенный накат WAL на реплике буквально равен отставанию, по которому health-check выносит её из пула. Второй по популярности совет выглядит безобиднее первого: не убивать конфликтующий запрос, а подождать. Цена платится только на реплике, мастера не касается вообще. Я собирался поднять max_standby_streaming_delay с дефолтных 30 секунд до 300 и уже писал правку.

Остановила конфигурация балансировщика. Health-check у нас такой:

backend slave
    option httpchk GET /replica?lag=10485760
    http-check expect status 200
    default-server inter 3s fall 3 rise 2 on-marked-down shutdown-sessions

Patroni считает отставание по replayed-позиции — то есть по тому, сколько WAL реплика применила. А документация PostgreSQL описывает суть параметра прямо: «it is the maximum total time allowed to apply WAL data once it has been received from the primary server» (max_standby_streaming_delay). Задержка наката — это ровно рост дельты между позицией мастера и replayed-позицией реплики. Тот самый показатель, на который смотрит балансировщик.

Получается контур с положительной обратной связью. Конфликтный запрос тормозит накат → replayed отстаёт → health-check видит превышение порога → реплика уходит в DOWN → on-marked-down shutdown-sessions обрывает все живые соединения к ней. Вместо 25 отменённых запросов в сутки — веерный обрыв всего чтения на каждый всплеск. Хуже исходного состояния, причём заметно.

Третий подход — поднять сам байтовый порог с 10 МБ до 512 МБ — отверг заказчик, и по делу. Требование сформулировано во времени: «секундное отставание приемлемо, полминуты — нет». Порог задан в байтах. Любое число в байтах здесь — попытка угадать время через объём.

Что на самом деле выбивает реплику: посекундный замер отставания

Реплика отставала не потому, что тормозила накат, а потому, что WAL физически не успевал доехать. Развязку дал прямой замер на праймари — раз в секунду, 330 сэмплов:

1
2
3
4

SELECT now()::time(0),
       pg_wal_lsn_diff(pg_current_wal_lsn(), replay_lsn) AS replay_bytes,
       pg_wal_lsn_diff(pg_current_wal_lsn(), flush_lsn)  AS flush_bytes
FROM pg_stat_replication;

10:43:26     replay=  0.0MB   flush=  0.0MB
10:43:27     replay=151.3MB   flush=151.1MB   ← старт пачки крона
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   ← догнала

Ключевое здесь — flush практически равен replay. Разница между ними и есть время наката: то, что реплика получила, но ещё не применила. Она околонулевая. Значит накат не заторможен вообще, реплика применяет всё, что успела принять, и отставание чисто транспортное — мастер генерирует WAL быстрее, чем тот уезжает по сети.

В покое отставание держится в диапазоне 0–43 КБ. Всплеск от крона — 168 МБ за три секунды. Порог health-check при этом 10 МБ: до фона от него 240 раз вниз, до всплеска — 17 раз вверх. Всплеск перешагивает порог мгновенно и так же мгновенно кончается, и никакое значение между фоном и пиком не спасает — потому что промежуточных значений тут просто нет.

Отдельно смешное: порог уже поднимали до нас. В group_vars лежит комментарий «Увеличено чтобы избежать ложных DOWN во время checkpoint/autovacuum», 5 МБ → 10 МБ. Не помогло, и теперь понятно почему: против всплеска в 168 МБ удвоение десятка мегабайт не значит ничего.

Почему порог lag= в health-check Patroni нельзя задать в секундах

Временного порога в этом эндпоинте нет в принципе: lag= принимает исключительно байты. Документация Patroni формулирует это обтекаемо — «In addition to checks from replica, it also checks replication latency and returns status code 200 only when it is below specified value» (Patroni REST API). Слово «latency» сбивает с толку: единицы приводятся тут же и все они объёмные (kB, MB, GB), но пока не полезешь в исходник, остаётся ощущение, что секунды где-то рядом.

Исходник версии 3.0.2 не оставляет пространства для интерпретации (patroni/api.py, строки 101–109):

1
2
3
4
5
6
7
8
9

leader_optime = cluster and cluster.last_lsn or 0
replayed_location = response.get('xlog', {}).get('replayed_location', 0)
max_replica_lag = parse_int(self.path_query.get('lag', [sys.maxsize])[0], 'B')
if max_replica_lag is None:
    max_replica_lag = sys.maxsize
is_lagging = leader_optime and leader_optime > replayed_location + max_replica_lag

replica_status_code = 200 if not patroni.noloadbalance and not is_lagging and \
    response.get('role') == 'replica' and response.get('state') == 'running' else 503

Три вещи, которые видно только отсюда:

1. parse_int(..., 'B') — единица измерения зашита, байты и ничего кроме.
2. leader_optime берётся из DCS и обновляется раз в loop_wait, по умолчанию 10 секунд (Patroni settings). Сама величина, с которой сравнивают, уже несёт погрешность до десяти секунд.
3. Проверки роли и состояния идут независимо от проверки отставания, через and.

Третий пункт оказался самым важным. Умершая реплика отсекается не по lag, а по state/role: при обрыве стриминга строка в pg_stat_replication просто исчезает, и байтовую метрику неоткуда взять. То есть lag= покрывает ровно один сценарий — «реплика жива, но отстала». Всё остальное ловится другими условиями.

Сколько реплика отстаёт во времени — и почему метрика мониторинга врёт

Отставание во времени оказалось на три порядка меньше того, что заказчик считал неприемлемым. После выкатки я снял тот замер, которого не хватало для развязки: 20 минут, 1250 сэмплов с праймари, колонки write_lag/flush_lag/replay_lag. Документация описывает replay_lag как «Time elapsed between flushing recent WAL locally and receiving notification that this standby server has written, flushed and applied it» (pg_stat_replication) — то есть это полный путь байта от мастера до применения на реплике.

Требование звучало как «секунда приемлема, полминуты — нет». Медиана меньше неприемлемого порога в 2600 раз, худший из 1250 сэмплов — в 13 раз.

Транспортная природа отставания подтвердилась окончательно. Разница replay_lag минус flush_lag на самих пиках:

12:43:25   158.5 МБ | flush 1.029 с | replay 1.029 с | разница +0.2 мс
12:28:24    98.6 МБ | flush 0.685 с | replay 0.685 с | разница  0.0 мс
12:43:26    94.8 МБ | flush 1.651 с | replay 1.652 с | разница +0.8 мс

Накат добавляет доли миллисекунды к полутора секундам транспорта. В окно попали два запуска крона, в :28 и :43, ровно 15 минут врозь.

Дальше я полез в Prometheus за историей и чуть не сделал неверный вывод. Метрика pg_replication_lag_seconds за 30 дней давала p99 около 18 секунд — то есть по её версии реплика регулярно была несвежей почти на 20 секунд. Это неправда. На реплике postgres_exporter считает её как now() - pg_last_xact_replay_timestamp(), и в тишине между записями она растёт сама по себе: не потому что реплика отстала, а потому что новых транзакций не было. На праймари эта же метрика всегда ровно 0.

Проверить легко — в актуальном upstream в запрос добавлена ветка-предохранитель именно на этот случай (collector/pg_replication.go):

1
2
3
4
5

CASE
    WHEN NOT pg_is_in_recovery() THEN 0
    WHEN pg_last_wal_receive_lsn () = pg_last_wal_replay_lsn () THEN 0
    ELSE GREATEST (0, EXTRACT(EPOCH FROM (now() - pg_last_xact_replay_timestamp())))
END AS lag

Вторая строка CASE — «получено равно применённому, значит лаг ноль» — гасит ровно тот эффект, который я наблюдал. В нашей версии её не было. Метрика не была сломана: она измеряла не то, что подразумевает её имя.

Одну вещь этот же Prometheus дал бесплатно. За 30 дней лаг превышал минуту ровно один раз: 15927 секунд, 4,4 часа — реплика осталась без сети после ребута гипервизора. Вот с чем стоит сравнивать порог: 2,3 секунды у худшего рабочего всплеска против 4,4 часов у настоящей поломки, разница почти в 6900 раз. Порог lag=10MB стоял вплотную к нижней границе этого диапазона.

И ограничение самого инструмента: при scrape-интервале 15 секунд всплески длиной 4 секунды Prometheus физически не разрешает. Для коротких событий источник — логи балансировщика, а не графики.

Как посчитать длину всплеска по таймингу самого health-check

Длина всплеска = длительность DOWN в логе плюс (fall − rise) × inter, и всё нужное для этого балансировщик уже записал сам. Приём пригодился, когда встал вопрос «а что даст fall 3 → 5», а разрешения мониторинга на такие короткие события не хватало.

Арифметика прямая. Пусть всплеск начался в T₀ и кончился в T₁:

• DOWN объявляется после fall 3 × inter 3s = 9 секунд превышения порога подряд, то есть в T₀ + 9.
• UP возвращается после rise 2 × inter 3s = 6 секунд ниже порога, то есть в T₁ + 6.
• Длительность DOWN = (T₁ + 6) − (T₀ + 9) = длина всплеска − 3 с.

Отсюда длина всплеска ≈ длительность DOWN + 3 с.

Разбор всех 30 выпадений за 8 дней по логу HAProxy:

19 из 30 длились ровно минимально возможный DOWN — всплеск едва перешагнул порог и тут же кончился. Отсюда конкретный ответ вместо мнения: fall 5 (нужно 15 секунд подряд) снял бы 21 выпадение из 30, то есть 70 %. Оставшиеся 9 всплесков длились 21–30 секунд и продолжали бы ронять реплику при любом fall.

Ради этого не пришлось ни заводить экспортёр, ни ждать неделю новых данных. Всё уже было в логах, надо было только вспомнить, что таймауты проверки — это тоже цена деления.

Почему «конфликты роняют реплику» оказалось совпадением, а не причиной

Совпали 11 выпадений из 30 и 12 конфликтов из 227 — пять процентов. Это разные события от одной причины, а не причина и следствие. И именно эту гипотезу я проверял последней, потратив до неё заметное время на две другие.

Гипотеза про чекпоинты: checkpoint_timeout=15min, в логе мастера чекпоинты идут в :04, :19, :34 и :49. Выпадения — в :00, :29–30, :43–45. Не совпадают ни разу.

Гипотеза про окно бэкапа: скрипт на время pg_dump выставляет max_standby_streaming_delay=3600s, и версия «он и выбивает реплику» выглядела складно. Все 30 выпадений длятся 6–27 секунд. Часовых окон нет ни одного.

Гипотеза «конфликты роняют реплику» держалась дольше всех, потому что и то и другое кучковалось по одним и тем же минутам. Логи лежали в разных таймзонах, я привёл их к одной шкале и сопоставил по таймстампам — вышло 5 %. Кучковались они по одним минутам просто потому, что у них общий источник: крон, который четыре раза в час перезаписывает миллион строк.

Корреляцию по таймстампам надо было делать первой. Одна команда сопоставления за минуту опровергла то, на что я потратил часы.

Что выкачено: убрать ущерб, если нельзя убрать причину

Из read-бэкенда HAProxy убран on-marked-down shutdown-sessions — реплика по-прежнему может выпасть, но живые read-запросы больше не обрываются:

1
2
3
4
5

 backend slave
     option httpchk GET /replica?lag=10485760
     http-check expect status 200
-    default-server inter 3s fall 3 rise 2 on-marked-down shutdown-sessions
+    default-server inter 3s fall 3 rise 2

В бэкендах master и long_queries опция оставлена — там она нужна для failover, чтобы при смене роли клиенты не остались висеть на бывшем мастере. На read-бэкенде она делала ровно противоположное задуманному. Документация HAProxy 2.4 описывает её так: «all connections to the server are immediately terminated when the server goes down. It might be used if the health check detects more complex cases than a simple connection status, and long timeouts would cause the service to remain unresponsive for too long a time» (HAProxy 2.4 configuration, on-marked-down). Формулировка описывает застрявшую базу. У нас база не застревала — она на три секунды отставала.

В логах это выглядело так:

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.

44 живые сессии, убитые одним решением балансировщика о том, что реплика отстала на 10 мегабайт. Причём приложение видит при этом не SQLSTATE[40001], а оборванный коннект — и перехватчик, с которого началась вся история, его не ловит вообще. Новые соединения уходят на мастер сами, это уже было настроено: use_backend master if { nbsrv(slave) eq 0 }.

Размен здесь честный: убран ущерб, не причина. Для корректного критерия нужен свой health-check — agent-check HAProxy с агентом на реплике, отдающим up/down по now() - pg_last_xact_replay_timestamp(). Это новая сущность в инфраструктуре, и решение о ней принимается с цифрами на руках. Теперь цифры есть.

Приложению в ревью ушло другое: разделить ERROR (запрос отменён, соединение живо) и FATAL (соединение разорвано) — это разные сценарии восстановления; убрать недостижимый цикл повторов; добавить метрику вместо одного Log::warning. Сам перехватчик оказался корректным. Половина моих первоначальных замечаний к нему не пережила перепроверки — полезное упражнение на отделение «я бы написал иначе» от «здесь дефект».

Грабли по дороге: Ansible, ротация логов и ленивое соединение

Три находки, не связанные с задачей напрямую, но каждая из них дороже самой правки.

--check --diff вскрыл дрейф конфигурации. На сервере руками были дописаны weight 80 / weight 20, в шаблоне их не было. Прогон плейбука молча стёр бы чужую работу. Пришлось сначала подтянуть код к фактическому состоянию сервера и только потом класть свою правку. Отдельно выяснилось, что один файл group_vars оказался хардлинком на три инвентаря — правка в одном месте меняет все три. Перед выкаткой на давно живущий прод надо читать весь diff, а не только «свой» кусок: это единственный шанс не стереть чужую работу.

pg_log не ротировался: 5 ГБ на реплике, 21 ГБ на мастере, файлы с 2023 года. Причина не в logrotate, а в том, что рабочий конфиг разошёлся с шаблоном Patroni. Настройки лежали в bootstrap.dcs, а документация Patroni про эту секцию высказывается недвусмысленно: «All later changes of bootstrap.dcs will not take any effect! If you want to change them please use either patronictl edit-config or Patroni REST API» (Patroni SETTINGS). Секция применяется ровно один раз, при первичном bootstrap кластера. Дальше живые параметры лежат в DCS, и правка шаблона не делает ничего.

Ленивое соединение с репликой терялось на любом запросе с биндингами. В проектной обвязке метод bindValues() начинался с $this->getPdo()->getAttribute(...). В Laravel getPdo() резолвит ленивое замыкание, и это буквально одна строка (Illuminate\Database\Connection):

1
2
3
4
5
6
7
8

public function getPdo()
{
    if ($this->pdo instanceof Closure) {
        return $this->pdo = call_user_func($this->pdo);
    }

    return $this->pdo;
}

$this->pdo — это write-соединение. Метод bindValues() вызывается для любого запроса с биндингами, включая чисто читающий. То есть каждый параметризованный SELECT открывал соединение с мастером просто чтобы прочитать атрибут PDO. Ленивое подключение к праймари, ради которого read/write split и городится, не работало вообще.

И ещё два наблюдения из логов. Приложение отрапортовало около 150 событий за две недели против примерно 319 в логе БД — оно видит меньше половины того, что с ним происходит. А application_name пуст во всех событиях, поэтому атрибутировать запрос к конкретному сервису по логам БД невозможно: виден только пользователь БД, а под ним ходят все. Второе чинится одной строкой в DSN, первое — метрикой вместо записи в лог. Обе дырки обнаруживаются только когда садишься считать вручную.

Пошагово

1. Прежде чем трогать hot_standby_feedback, проверить SELECT slot_name, xmin, catalog_xmin FROM pg_replication_slots; и число реплик. Слоты + одна реплика — параметр не включать.
2. Снять посекундный замер pg_wal_lsn_diff по replay_lsn и flush_lsn с праймари. Если flush ≈ replay, отставание транспортное, и тормозить накат бессмысленно.
3. Снять замер во времени — write_lag/flush_lag/replay_lag из pg_stat_replication, минимум несколько сотен сэмплов, с попаданием в пиковое окно.
4. Сопоставить таймстампы конфликтов и выпадений реплики, приведя логи к одной таймзоне. Делать это первым, а не последним.
5. Посчитать длину всплесков из лога балансировщика: длительность DOWN + (fall − rise) × inter. Отсюда — обоснованное значение fall.
6. Проверить, что метрика мониторинга измеряет заявленное. Для pg_replication_lag_seconds — сравнить значение на реплике в простое со значением на праймари.
7. Прогнать ansible-playbook --check --diff целиком и вычитать весь diff, а не свой кусок.
8. Выкатывать конфиг HAProxy через reload (kill -USR2 мастеру в master-worker режиме), а не рестартом. Сокеты держит мастер-процесс, порт не закрывается, старый воркер доживает текущие сессии.

Восьмой пункт — из тех, что пишешь по итогам собственной ошибки. Я выкатил рестартом и разом оборвал все соединения — ровно то, от чего избавляет сама правка.

Итог

Байтовый порог отставания отвечает на вопрос «сколько WAL не доехало». Бизнесу нужен ответ на другой — «насколько несвежие данные я сейчас отдаю». На ровной нагрузке эти вопросы почти эквивалентны, на пачечной расходятся в разы: у нас фон 43 КБ, порог 10 МБ, всплеск 168 МБ. Вся дискуссия про «какой порог поставить» была бессмысленной, пока это не проговорили вслух.

Порог, который срабатывает на рабочем всплеске в 2,3 секунды, притом что настоящая поломка выглядит как 4,4 часа, — это не «настроено строго». Это настроено случайно: между этими двумя величинами почти четыре порядка, и порог сел вплотную к нижней. Правильный путь дальше — agent-check с временным критерием через pg_last_xact_replay_timestamp(); промежуточный и уже обоснованный — fall 3 → 5, который снимает 70 % выпадений без риска отдать несвежие данные. Оставшиеся 30 % — всплески по 21–30 секунд; их закрывает либо более высокий байтовый порог, либо смена единицы измерения на секунды.

Отдельный вывод для расследований: когда не хватает разрешения у мониторинга, считай из тайминга того, что уже логируется. Health-check с известными inter/fall/rise — готовый прибор с секундной точностью, и он ведёт запись всё время, пока ты решаешь, какую метрику завести.

Первоисточники, к которым я обращался по дороге:

• PostgreSQL 15 — Hot Standby, Handling Query Conflicts
• PostgreSQL 15 — hot_standby_feedback и max_standby_streaming_delay
• PostgreSQL 15 — pg_replication_slots и pg_stat_replication
• Patroni 3.0.2 — patroni/api.py, обработка lag=
• Patroni — REST API и SETTINGS
• HAProxy 2.4 — configuration manual, on-marked-down
• postgres_exporter — collector/pg_replication.go