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

MAATRIX

Каждый вторник около полудня в проде начинались ошибки deadlock detected, часть заказов зависала в статусе «обрабатывается», а саппорт получал шквал жалоб. В остальные дни недели база вела себя идеально — ни намёка на блокировки. Три недели подряд мы гонялись за призраком, пока не выписали в один список все запросы, которые трогают одни и те же таблицы по вторникам, и не увидели очевидную вещь: два сервиса брали одни и те же строки в противоположном порядке.

Первые сигналы: что мы увидели в мониторинге

Первый звоночек — алерт от Grafana по метрике pg_stat_database_deadlocks, которая резко подскакивала с нуля до 15-20 событий в течение 10-15 минут, и делала это стабильно по вторникам. В остальное время график был плоским. Одновременно росла метрика pg_stat_activity с состоянием active и wait_event_type = Lock — количество сессий, зависших в ожидании блокировки, доходило до 30-40 одновременно на пике.

На уровне приложения это выглядело как рост p99 у эндпоинта оформления заказа с обычных 80-120 мс до нескольких секунд, а часть запросов просто падала с ошибкой 500 и текстом вида deadlock detected в теле ответа — она долетала из драйвера до логов приложения без изменений. В Sentry инцидент группировался как один и тот же exception, но с разным SQL внутри — это и сбивало с толку на старте: казалось, что проблема не локализована в одном месте.

Мы завели дашборд с наложением трёх метрик друг на друга: deadlocks, количество активных соединений и загрузку CPU базы. Загрузка CPU почти не менялась — это сразу отсекло версию про нехватку ресурсов. Проблема была не в объёме нагрузки, а в её структуре.

Что показали логи PostgreSQL

Чтобы увидеть детали блокировок, а не только счётчик, мы включили расширенное логирование:

# postgresql.conf
log_lock_waits = on
deadlock_timeout = 1s
log_line_prefix = '%m [%p] user=%u db=%d app=%a '

После SELECT pg_reload_conf(); в логе стали появляться записи вида:

ERROR:  deadlock detected
DETAIL:  Process 18422 waits for ShareLock on transaction 998211234; blocked by process 18507.
        Process 18507 waits for ShareLock on transaction 998211201; blocked by process 18422.
        Process 18422: UPDATE inventory SET reserved = reserved + 1 WHERE product_id = 4471;
        Process 18507: UPDATE orders SET status = 'processing' WHERE id = 88213;
HINT:  See server log for query details.
CONTEXT:  while updating tuple (12,7) in relation "inventory"

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

Мы прогнали лог через pgbadger за сутки инцидента, чтобы собрать все deadlock-события в одну таблицу с текстами запросов. Выяснилось, что во всех случаях фигурировали ровно две пары запросов: обновление orders и обновление inventory для одного и того же товара и заказа, но в разных транзакциях. Дополнительно мы смотрели живую картину через:

SELECT blocked_locks.pid AS blocked_pid,
       blocking_locks.pid AS blocking_pid,
       blocked_activity.query AS blocked_query,
       blocking_activity.query AS blocking_query
FROM pg_catalog.pg_locks blocked_locks
JOIN pg_catalog.pg_locks blocking_locks
  ON blocking_locks.locktype = blocked_locks.locktype
 AND blocking_locks.database IS NOT DISTINCT FROM blocked_locks.database
 AND blocking_locks.relation IS NOT DISTINCT FROM blocked_locks.relation
 AND blocking_locks.pid != blocked_locks.pid
JOIN pg_catalog.pg_stat_activity blocked_activity ON blocked_activity.pid = blocked_locks.pid
JOIN pg_catalog.pg_stat_activity blocking_activity ON blocking_activity.pid = blocking_locks.pid
WHERE NOT blocked_locks.granted;

Этот запрос мы держали открытым в отдельной вкладке во время следующего вторничного окна и вживую наблюдали, как две сессии по очереди становятся то блокирующей, то заблокированной стороной — верный признак взаимной блокировки, а не банальной очереди за одним и тем же ресурсом.

Гипотезы, которые не подтвердились

Первая версия — рост нагрузки: по вторникам маркетинг обычно запускал рассылку с промокодами, и мы решили, что дело в наплыве заказов. Проверили количество запросов в эндпоинт оформления заказа за последние 8 вторников — корреляции с датами инцидента не было, в один из «тихих» вторников трафик был выше, чем в проблемный.

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

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

Четвёртая версия — репликация или её отставание провоцируют повторные попытки записи на мастере. Отставание реплики смотрели по pg_stat_replication — оно было в пределах нормы, без всплесков.

Пятая версия — pgBouncer в режиме transaction pooling путает транзакции между клиентами. Проверили конфиг — пул работал в session mode для этого сервиса, так что тут проблема исключалась сразу, хотя в целом это отдельная и вполне реальная категория граблей.

Только когда мы отказались от идеи искать «плохой» запрос и вместо этого стали смотреть на порядок обращения к таблицам с точки зрения всей системы — а не одного сервиса — картина сложилась.

Настоящая причина: два потока блокировок в разном порядке

По вторникам в 12:00 по расписанию cron запускалась джоба сверки остатков — она сверяла резервы в inventory с фактическими заказами в orders и приводила их в соответствие после ручных корректировок склада за выходные. Джоба написана отдельной командой полгода назад и с тех пор почти не менялась — про неё банально забыли, когда собирали список подозреваемых.

Логика джобы внутри одной транзакции выглядела так:

BEGIN;
UPDATE inventory SET reserved = reserved - 1 WHERE product_id = 4471;
UPDATE orders SET status = 'reconciled' WHERE id = 88213;
COMMIT;

А сервис оформления заказа в своей транзакции делал ровно обратное:

BEGIN;
UPDATE orders SET status = 'processing' WHERE id = 88213;
UPDATE inventory SET reserved = reserved + 1 WHERE product_id = 4471;
COMMIT;

Обе транзакции обновляют одни и те же две строки, но захватывают блокировки в противоположном порядке: одна сначала берёт inventory, потом просит orders, вторая — наоборот. Пока обе джобы работали в разное время, конфликта не было — сервис оформления заказов работал непрерывно, а сверочная джоба раз в неделю. Но во время самой сверки, которая шла 15-20 минут и обрабатывала сотни товаров, вероятность того, что в этот же момент придёт живой заказ на тот же самый товар, резко выросла — и как только это происходило, обе транзакции упирались друг в друга.

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

Как мы это исправили

Первым и главным фиксом стало приведение порядка блокировок к единому стандарту для всех мест кода, которые трогают orders и inventory в одной транзакции: сначала всегда inventory, потом всегда orders, независимо от того, какой сервис пишет запрос. Мы завели это правило явно в внутренней документации по работе с этими двумя таблицами и добавили комментарий прямо над обеими транзакциями с ссылкой на инцидент — простое, но рабочее решение против забывчивости.

-- реконсиляция: было
UPDATE inventory ...;
UPDATE orders ...;

-- сервис заказов: стало (раньше было наоборот)
BEGIN;
UPDATE inventory SET reserved = reserved + 1 WHERE product_id = 4471;
UPDATE orders SET status = 'processing' WHERE id = 88213;
COMMIT;

Вторым слоем защиты добавили retry с экспоненциальной задержкой на уровне приложения конкретно для кода ошибки 40P01 (deadlock_detected в PostgreSQL) — сама по себе смена порядка блокировок снимает проблему, но не гарантирует, что похожая ситуация не возникнет в другом месте кода, которое мы пока не нашли:

import time
import random
import psycopg2

def run_with_retry(fn, max_attempts=3):
    for attempt in range(max_attempts):
        try:
            return fn()
        except psycopg2.errors.DeadlockDetected:
            if attempt == max_attempts - 1:
                raise
            time.sleep((2 ** attempt) + random.uniform(0, 0.5))

Третьим шагом сократили длительность транзакции сверочной джобы: раньше она обрабатывала весь список товаров одной транзакцией на 15-20 минут, что расширяло окно возможного конфликта. Разбили на батчи по 50 товаров с отдельным COMMIT на каждый батч — окно конкуренции для конкретной строки сократилось с 15-20 минут почти до долей секунды, и это резко снизило саму вероятность пересечения с живым трафиком, даже без изменения порядка блокировок.

Четвёртым — перенесли время запуска сверочной джобы с полудня на раннее утро (05:00 по местному времени сервера), когда живых заказов на порядок меньше. Это не устраняет причину, но снижает частоту совпадений до почти нулевой — простая мера, которая стоила одной строчки в конфиге cron, а не переписывания логики.

Как предотвратить повторение: мониторинг и защита

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

Мы оставили включённым log_lock_waits на постоянной основе — накладные расходы на логирование ожиданий блокировок минимальны, а информация бесценна при разборе следующего похожего случая. Алерт на pg_stat_database_deadlocks теперь настроен не на абсолютное значение, а на любое отклонение от нуля за скользящее окно 15 минут — раньше порог был выставлен слишком высоко и первые случаи просто терялись в шуме.

Если у вас несколько сервисов или джоб пишут в одни и те же таблицы, стоит явно выписать матрицу «кто и в каком порядке трогает какие таблицы внутри одной транзакции» — часто выясняется, что таких пересечений больше, чем казалось на старте, особенно если часть кода писали разные команды в разное время. Отдельно мы настраивали общий обзор состояния базы через мониторинг баз данных через Grafana — без графиков по блокировкам и ожиданиям такие инциденты приходится разбирать вручную по обрывочным логам, что занимает не часы, а дни.

Стоит также иметь в виду похожий класс проблем на уровне межсервисного взаимодействия, а не только базы — например, когда падение одного сервиса каскадом утягивает остальные из-за общих ресурсов или очередей; мы разбирали такой случай в статье про то, как отвалился один микросервис и утянул ещё пять. Логика там та же: скрытая зависимость между независимо задеплоенными частями системы, которая не видна ни одной из команд по отдельности.

Если вы разворачиваете PostgreSQL с нуля и ещё не настраивали логирование и базовые параметры блокировок, есть смысл сразу заложить эти практики в конфиг — по шагам это описано в статье как установить и настроить PostgreSQL на VPS, там же разбираются параметры, влияющие на поведение при конкурентной записи.

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