Реплика отстала на 6 часов из-за одной длинной транзакции на мастере

MAATRIX

В четверг утром отчёты в BI-системе показали вчерашние цифры вместо сегодняшних. Дашборд брал данные с read-реплики PostgreSQL, а реплика молчала — pg_last_xact_replay_timestamp() отставал от текущего времени на шесть часов. Никто ничего не деплоил, алерты на CPU и место на диске не срабатывали, а разработчики уже грешили на сеть между дата-центрами. Разгадка оказалась куда прозаичнее: ночью прошла одна транзакция, которая удалила 40 с лишним миллионов строк за один присест, и реплика физически не успевала переигрывать WAL с такой скоростью, с какой он приходил.

Что мы увидели: реплика молчит, а алерт не сработал

Первый сигнал пришёл не от мониторинга, а от аналитика, который заметил в отчёте вчерашние заказы. Стандартный алерт на репликацию у нас был завязан на разрыв соединения (state != 'streaming' в pg_stat_replication) и на рост pg_wal_lsn_diff между pg_current_wal_lsn() и sent_lsn — то есть на то, сколько WAL ещё не *отправлено* на реплику. Соединение не рвалось ни разу, а байтовое отставание по отправке колебалось в пределах нормы. Поэтому алерт молчал, хотя реальная проблема была в другом месте конвейера.

Смотрим на реплике:

SELECT now() - pg_last_xact_replay_timestamp() AS replication_delay;

 replication_delay
--------------------
 06:02:14.331508

На мастере — полная картина по pg_stat_replication:

SELECT client_addr, state,
       pg_wal_lsn_diff(pg_current_wal_lsn(), sent_lsn)  AS pending_send,
       pg_wal_lsn_diff(sent_lsn, write_lsn)              AS pending_write,
       pg_wal_lsn_diff(write_lsn, flush_lsn)             AS pending_flush,
       pg_wal_lsn_diff(flush_lsn, replay_lsn)            AS pending_replay,
       write_lag, flush_lag, replay_lag
FROM pg_stat_replication;

Результат был красноречивым: pending_send и pending_write — считаные килобайты, pending_replay — несколько гигабайт, а replay_lag — те самые шесть часов. То есть WAL приходил на реплику вовремя, ложился на диск вовремя, а вот *применялся* к данным с огромной задержкой. Это сразу сузило круг подозреваемых: дело не в сети и не в пропускной способности канала, а в том, как реплика переигрывает уже полученные записи.

Если такое разделение на write_lag/flush_lag/replay_lag вам ни о чём не говорит — коротко:

Подробнее о механике самого WAL и о том, зачем Postgres вообще пишет дважды, я разбирал в статье про WAL и запись «дважды» — она хорошо ложится в контекст этого разбора.

Гипотезы, которые отбросили за первый час

Дальше начался классический перебор подозреваемых, и почти все они оказались ложным следом.

Сеть между дата-центрами. Мастер и реплика стояли в разных локациях, поэтому сеть — первый кандидат. Прогнали iperf3 между хостами в оба конца — пропускная способность и джиттер были в норме, никаких признаков деградации канала. Плюс, как уже сказано, sent_lsn/write_lsn не отставали — если бы дело было в сети, отставание было бы видно уже на этапе доставки, а не только на этапе применения.

Неактивный или «зависший» слот репликации. Проверили pg_replication_slots:

SELECT slot_name, active, restart_lsn,
       pg_wal_lsn_diff(pg_current_wal_lsn(), restart_lsn) AS retained_bytes
FROM pg_replication_slots;

Слот был active = true, restart_lsn двигался — просто медленно, вслед за replay_lsn. Ложная тревога: слот вёл себя ровно так, как и должен, когда реплика отстаёт по применению, а не бездействует.

Нехватка места на диске реплики. df -h показал приличный запас — тоже мимо. Отдельно проверили, не растёт ли аномально каталог pg_wal на мастере из-за того, что реплика «придерживает» WAL слотом — здесь как раз пригодилась статья о том, почему растёт объём WAL: растущий pg_wal на мастере при работающем слоте — частый побочный эффект именно такого сценария, и в нашем случае каталог действительно раздулся на пару десятков гигабайт за ночь, но сам по себе это не было причиной, а следствием.

Долгий запрос на самой реплике. Логичное подозрение — читающий запрос на реплике конфликтует с применением WAL (recovery conflict), и Postgres откладывает replay до max_standby_streaming_delay. Проверили pg_stat_activity за ночь по логам — тяжёлых аналитических запросов в это окно не было, характерных canceling statement due to conflict with recovery в логах тоже нет. Тоже не оно — хотя в других инцидентах именно это часто и есть первопричина.

Где реплика реально застряла: iostat не врёт

Раз дело не в доставке WAL и не в конфликте с чтением, оставалось смотреть на саму работу процесса восстановления (startup process) на реплике. Запустили iostat прямо во время инцидента, на второй реплике, где похожая нагрузка ещё продолжалась:

iostat -x 1 5

Device   r/s   w/s   rkB/s   wkB/s   %util
sdb      412   890   8100    41200    99.8

%util возле 100% на томе с данными — процесс восстановления упирался в диск, а не в CPU (CPU реплики был загружен от силы на одно ядро — сам startup process в PostgreSQL до сих пор однопоточный для физической репликации, параллелизма при переигрывании WAL там нет). Реплика стояла на VPS с сетевым блочным хранилищем среднего класса — для обычной read-нагрузки IOPS хватало с запасом, но резкий всплеск случайной записи от переигрывания WAL с лихвой съедал лимит хранилища.

Дальше проверили, что именно вызвало такой всплеск записи. Посмотрели объём WAL, сгенерированный за ночь на мастере:

SELECT pg_size_pretty(pg_wal_lsn_diff(pg_current_wal_lsn(), '0/0'));

и сравнили с типичной ночью по данным Grafana (WAL-метрики мы туда уже тянули — как именно, описано в статье про мониторинг баз через Grafana). Объём WAL за эту ночь оказался в разы выше обычного — резкий пик ровно в то окно, когда должен был отработать ночной джоб очистки архивных заказов.

Виновник: DELETE на 40+ миллионов строк в одной транзакции

Смотрим pg_stat_activity на мастере (по счастью, транзакция ещё выполнялась, когда мы начали разбор):

SELECT pid, usename, state, now() - xact_start AS xact_age,
       left(query, 90) AS query
FROM pg_stat_activity
WHERE xact_start IS NOT NULL
ORDER BY xact_start
LIMIT 5;

  pid  | usename |  xact_age   |                query
-------+---------+-------------+-----------------------------------------------
 24831 | batch   | 05:47:02    | DELETE FROM orders_archive WHERE created_at < ...

Ночной джоб очистки архивных заказов, который раньше работал с таблицей поменьше, разросся вместе с бизнесом: раньше он удалял пару сотен тысяч строк за проход, а тут набралось больше 40 миллионов — партиционирование по дате для таблицы так и не сделали, а фильтр created_at < now() - interval '3 years' месяцами не запускался из-за упавшего cron, и накопился огромный хвост. Джоб выполнил DELETE без LIMIT и без разбивки на транзакции — одна операция, одна огромная транзакция, один непрерывный поток WAL-записей на десятки гигабайт.

Похожая тема — запрос без ограничения, который кладёт реплику — разобрана и в статье про запрос без LIMIT, положивший реплику и отчёты, но там источником был тяжёлый SELECT на стороне чтения; у нас — DELETE на стороне записи, механика поломки принципиально другая.

Почему один DELETE ломает конвейер репликации целиком

Здесь важно понимать физику процесса, а не искать «баг» в Postgres — система вела себя ровно так, как спроектирована.

Физическая репликация в PostgreSQL передаёт не SQL-запросы, а поток изменений на уровне страниц данных (WAL-записи). Когда транзакция удаляет 40 миллионов строк, для каждой затронутой страницы генерируется WAL-запись, а если это происходит вскоре после чекпоинта — ещё и full page write (полная копия страницы, а не только дельта) на первое изменение этой страницы после чекпоинта. Это резко увеличивает объём WAL: удаление затрагивает данные вперемешку по всей таблице и индексам, страницы модифицируются в случайном порядке, full page writes добавляют объём, и всё это утекает по сети на реплику практически без задержки — сеть с этим справляется.

Проблема — на стороне применения. WAL на реплике переигрывает один процесс (startup process), последовательно, страница за страницей. Он не может распараллелить работу между ядрами и вынужден делать реальные операции ввода-вывода — читать страницу, если её нет в кэше, применять изменение, писать обратно. Когда WAL прибывает пачками по гигабайту в минуту, а хранилище реплики рассчитано на равномерную read-нагрузку отчётов, а не на всплеск случайной записи — образуется очередь. Сеть и доставка (write_lag, flush_lag) не страдают, а вот replay_lag растёт линейно, пока объём WAL не иссякнет. Именно поэтому мониторинг только по «догнала ли реплика по объёму переданных байт» ничего не покажет — нужен отдельный взгляд именно на replay_lag.

Ситуация усугубляется тем, что вся операция была одной транзакцией: Postgres не может частично применить DELETE, пока не увидит COMMIT, а WAL всё равно генерируется и передаётся по ходу выполнения (стриминг WAL не ждёт коммита), поэтому разница «одна транзакция или сто мелких» не в том, когда данные уходят по сети, а в том, что при мелких транзакциях реплика получает возможность равномерно применять изменения и не накапливать при первом же сбое или скачке нагрузки такой длинный хвост непрерывной работы без промежуточных точек.

Что мы изменили после разбора

Первое и главное — переписали джоб очистки: вместо одного DELETE — процедура с батчами и промежуточными коммитами. В отличие от анонимного DO-блока, COMMIT внутри тела разрешён именно в процедуре, вызванной через CALL на верхнем уровне (начиная с PostgreSQL 11):

CREATE OR REPLACE PROCEDURE purge_orders_archive(batch_size int)
LANGUAGE plpgsql
AS $$
DECLARE
  deleted int;
BEGIN
  LOOP
    DELETE FROM orders_archive
    WHERE ctid IN (
      SELECT ctid FROM orders_archive
      WHERE created_at < now() - interval '3 years'
      LIMIT batch_size
    );
    GET DIAGNOSTICS deleted = ROW_COUNT;
    EXIT WHEN deleted = 0;
    COMMIT;
    PERFORM pg_sleep(0.2);
  END LOOP;
END;
$$;

CALL purge_orders_archive(5000);

Пауза pg_sleep(0.2) между батчами — сознательный компромисс: джоб выполняется дольше, зато не создаёт единого всплеска WAL, а реплика успевает применять изменения параллельно с их поступлением, без затяжной очереди.

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

Третье — на реплике включили recovery_prefetch = on (доступно начиная с PostgreSQL 13): при переигрывании WAL Postgres заранее запрашивает с диска страницы, которые понадобятся для следующих записей, вместо того чтобы упираться в синхронное чтение по одной странице за раз. Это не убирает узкое место полностью, но заметно сглаживает всплески на медленном или сетевом хранилище.

Четвёртое, и по деньгам самое ощутимое — реплику, на которую завязана отчётность, перенесли на выделенный сервер с локальным NVMe вместо сетевого блочного хранилища общего назначения. Для равномерной read-нагрузки сетевой диск работал нормально, но именно всплески случайной записи при переигрывании WAL — его слабое место, и для такой роли выделенный сервер с предсказуемым IOPS обходится дешевле повторных инцидентов с отчётностью. Если разворачиваете что-то подобное с нуля, схема первичной настройки описана в статье про настройку репликации PostgreSQL на VPS, а общую механику отставания реплики — в материале как работает репликация и отставание реплики.

Пятое — завели простое правило для команды: любая массовая операция (DELETE/UPDATE) больше определённого числа строк проходит через батч-процедуру и запускается в окно с наименьшей нагрузкой на отчётность, а не как попало через забытый cron.

Частые вопросы