Миграция добавила одну колонку и заблокировала таблицу на 11 минут

MAATRIX

Миграция выглядела безобидно: одна колонка, дефолтное значение, ни одной строчки данных не тронуто. По всем правилам такой ALTER на современном Postgres должен отработать за миллисекунды. Вместо этого приложение легло на 11 минут, и первые полчаса разбора ушли на то, чтобы понять — а при чём тут вообще миграция, если она «должна быть мгновенной». Разбираем, как метаданные-онли изменение схемы устроило полноценный даунтайм и почему дело было вовсе не в самой миграции.

Что сломалось

В 14:02 по плану деплоя прошла миграция: ALTER TABLE users ADD COLUMN is_verified boolean NOT NULL DEFAULT false. Таблица users — не самая большая в базе, но одна из самых горячих: через неё идёт аутентификация, профиль, добрая половина JOIN-ов в API. CI прогнал миграцию на стейджинге за 40 мс, ревьюер посмотрел на diff, увидел константный DEFAULT и одобрил без вопросов — с Postgres 11 такие ALTER не переписывают таблицу и не должны представлять опасности.

В проде картина была другой. Через несколько секунд после начала миграции здоровье сервиса на дашборде провалилось в красное: p99 по эндпоинтам, которые трогают users, улетел за 30 секунд, дальше — таймауты. Через минуту начали копиться 502 от reverse proxy: воркеры приложения упирались в лимит подключений к базе, потому что каждое новое соединение зависало в ожидании. Алерт от healthcheck прилетел почти сразу, но пока дежурный открывал дашборды, простой уже шёл вовсю. Восстановилось всё резко, одним скачком — ровно через 11 минут после старта миграции, без какого-либо вмешательства со стороны дежурного.

Первая реакция — откатить миграцию. Но ADD COLUMN уже применился, а к моменту, когда дежурный дошёл до консоли, всё само разблокировалось. Стало ясно: разбираться нужно постфактум, по логам и метрикам, потому что живого инцидента уже не было.

Что показывали логи и метрики

Метрика подключений к Postgres (pg_stat_activity count) не выросла количественно — воркеры просто зависли на существующих соединениях, не открывая новых сверх лимита пула. Зато резко подскочила метрика pg_stat_activity в состоянии active с одинаковым wait_event_type = Lock. Это и была первая зацепка: не диск, не CPU, не сеть — база ждала блокировку.

Запрос, который дежурный прогнал постфактум по логам (Postgres логирует долгие ожидания блокировок, если включён log_lock_waits):

-- в postgresql.conf на момент инцидента:
-- log_lock_waits = on
-- deadlock_timeout = 1s

В логе базы за интервал инцидента нашлось вот что:

LOG:  process 24831 still waiting for AccessExclusiveLock on relation 16420
  of database 16391 after 1000.145 ms
DETAIL:  Process holding the lock: 19207. Wait queue: 24831, 24855, 24901, ...
STATEMENT:  ALTER TABLE users ADD COLUMN is_verified boolean NOT NULL DEFAULT false

Ключевая строка — Wait queue: 24831, 24855, 24901, .... Процесс 24831 — это сам ALTER, и за ним уже выстроилась очередь из десятков PID. Дальше в логе — вал похожих строк, но уже для обычных SELECT и UPDATE к users, которые ждут блокировку от процесса 24831. То есть ALTER не просто сам подвис — он утащил за собой в очередь весь трафик к таблице.

Метрика CPU на сервере базы в это время была спокойной, около 20-25%, диск — не в насыщении, репликация не отставала. Всё указывало на чисто блокировочную природу проблемы, а не на ресурсную.

Гипотеза первая: ALTER переписывает таблицу

Первая версия, которую проверяли, — что ALTER всё же вызвал полное переписывание таблицы, несмотря на константный DEFAULT. До Postgres 11 ADD COLUMN ... DEFAULT действительно требовал переписать каждую строку таблицы, и на таблице с десятками миллионов строк это могло занять и 11 минут, и больше.

Проверили версию сервера — 15-я ветка, значит fast default точно должен был сработать: метаданные о новом дефолтном значении сохраняются в системном каталоге, физическая перезапись строк не нужна, значение подставляется «на лету» при чтении для старых строк. Проверили размер таблицы — около 40 млн строк, немаленькая, но при fast default размер вообще не должен влиять на скорость ALTER. И самое главное — I/O на диске базы за время инцидента не показал всплеска записи, который неизбежен при переписывании 40 млн строк. Гипотезу отбросили: технической причины для физического рерайта не было, и метрики это подтверждали.

Гипотеза вторая и третья: что ещё проверяли

Следующая версия — deadlock. В postgres deadlock_timeout стоял в 1 секунду, и если бы возник настоящый deadlock (взаимная блокировка двух транзакций друг на друга), Postgres бы его сам обнаружил и откатил одну из транзакций с ошибкой deadlock detected — счётчик решился бы сам за секунды, а не за 11 минут. В логах ни одной строки про deadlock не нашлось, только про ожидание блокировки в очереди — это разные состояния: deadlock — это цикл ожиданий, тут же была прямая цепочка «ALTER ждёт X, все остальные ждут ALTER».

Вторая версия — реплика и её лаг. Проверили pg_stat_replication: лага не было, реплика получала WAL без задержек, потому что сам мастер не тормозил на диске — он тормозил на блокировке в памяти лок-менеджера, а это не генерирует WAL-трафик вообще. Отбросили.

Третья версия — что дело в ORM, который якобы сам держит долгую транзакцию на каждый запрос. Проверили код приложения: обычные короткие транзакции, автокоммит на большинство запросов, ничего похожего на долгоживущие сессии со стороны основного веб-приложения. Гипотезу тоже сняли — открытая долгая транзакция явно была, но не из веб-слоя.

Реальная причина: очередь блокировок за одной долгой транзакцией

Разгадка нашлась через join pg_locks и pg_stat_activity — именно такой запрос стоило прогнать в первую минуту инцидента, а не постфактум по логам:

SELECT
  blocked.pid AS blocked_pid,
  blocked.query AS blocked_query,
  blocking.pid AS blocking_pid,
  blocking.query AS blocking_query,
  now() - blocking.query_start AS blocking_duration
FROM pg_locks bl
JOIN pg_stat_activity blocked ON blocked.pid = bl.pid
JOIN pg_locks bl2 ON bl2.locktype = bl.locktype
  AND bl2.database IS NOT DISTINCT FROM bl.database
  AND bl2.relation IS NOT DISTINCT FROM bl.relation
  AND bl2.pid != bl.pid
  AND bl2.granted
JOIN pg_stat_activity blocking ON blocking.pid = bl2.pid
WHERE NOT bl.granted;

Восстановленная картина: за 6 минут до деплоя миграции аналитический сервис запустил отчёт — тяжёлый SELECT с несколькими JOIN по users и таблице заказов, без LIMIT, готовящий выгрузку для внутреннего дашборда. Запрос читал таблицу почти 17 минут и удерживал на users обычный ACCESS SHARE lock — самый слабый уровень блокировки, который никому обычно не мешает: он совместим с другими SELECT, INSERT, UPDATE, DELETE.

Но он не совместим с ACCESS EXCLUSIVE — а именно такой лок берёт любой ALTER TABLE, даже метаданный, без переписывания строк. Когда ALTER пришёл и попытался взять ACCESS EXCLUSIVE, ему пришлось встать в очередь и ждать, пока завершится читающий аналитический запрос. Сам по себе этот SELECT никому не мешал — но как только за ним в очередь встал ALTER, сработало правило FIFO лок-менеджера Postgres: все последующие запросы к users, даже самые лёгкие SELECT id FROM users WHERE id = $1, тоже встали в очередь — не за аналитическим запросом (с которым они прекрасно совместимы), а за ALTER-ом, который в очереди оказался раньше них.

Это и есть суть инцидента: не ALTER был медленным, и не аналитический запрос был опасным сам по себе. Опасной оказалась комбинация — быстрый ALTER, вставший в очередь позади долгой транзакции, из-за FIFO-порядка блокировок утащил в ту же очередь весь остальной трафик к таблице. 11 минут — это оставшееся время работы аналитического запроса плюс несколько секунд на выполнение самого ALTER и разбор очереди после снятия блокировки. Разбор такого механизма блокировок и того, кто кого фактически ждёт в цепочке, подробнее описан в материале про блокировки в базе: кто кого ждёт — похожий сценарий, только без миграции в роли триггера, разобран в статье про блокировку на ровном месте.

Что изменили после инцидента

Первое и самое очевидное — на все DDL-миграции в проде добавили обязательный lock_timeout:

SET lock_timeout = '3s';
ALTER TABLE users ADD COLUMN is_verified boolean NOT NULL DEFAULT false;

Если ALTER не может взять ACCESS EXCLUSIVE за 3 секунды — он падает с ошибкой, а не встаёт в очередь на неопределённое время. Ошибка неприятна, но предсказуема и safe: приложение продолжает работать штатно, а не блокируется на 11 минут. Миграционный инструмент (в проекте использовали связку из тех же принципов, что в Flyway и Liquibase — подробнее про такие инструменты в статье про миграции баз данных с Flyway и Liquibase) настроили так, чтобы lock_timeout и повторные попытки с бэкоффом были частью пайплайна по умолчанию, а не решением на усмотрение автора миграции.

Второе — аналитические и отчётные запросы вынесли на реплику для чтения, чтобы длинные SELECT в принципе не могли конкурировать за блокировки с DDL на мастере. Там, где выгрузка обязана идти строго с мастера (например, для консистентности read-after-write), для такого запроса стали обязательными statement_timeout и явный LIMIT — эта же таблица правил описана в материале о том, как проверить, что миграция прошла успешно: проверка перед стартом деплоя должна включать не только состояние самой схемы, но и снимок активных долгих транзакций.

Третье — в чек-лист перед любым DDL добавили обязательный предварительный запрос к pg_stat_activity, который ищет транзакции старше 30 секунд на затрагиваемых таблицах, и блокирует запуск миграции, если такие найдены:

SELECT pid, now() - xact_start AS duration, query
FROM pg_stat_activity
WHERE state != 'idle'
  AND now() - xact_start > interval '30 seconds'
ORDER BY duration DESC;

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

Наконец — пересмотрели процесс отката. На случай, если DDL всё же зависнет в проде, у дежурного должна быть готовая команда для того, чтобы найти и, при необходимости, аккуратно прервать блокирующую транзакцию (pg_cancel_backend для мягкой отмены, pg_terminate_backend — для жёсткой, если первое не сработало), не дожидаясь, пока она закончится сама. План действий на такой случай хранится вместе с общим планом отката миграции, который теперь пересматривается на каждом ревью перед крупным деплоем схемы.

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