Пришло оповещение, что база упала. База не падала ни разу

Утром я открыл Slack и обнаружил четыре накопившихся оповещения CRITICAL.

504 AppHttpException: The request timed out.
  POST /customer/practice/attempts

PrismaClientKnownRequestError
  Transaction already closed

500 DriverAdapterError: canceling statement due to statement timeout
  GET /admin/dashboard/stats

DATABASE 서비스 다운
  "error": "Database health check (retry) timeout after 2000ms"

Последняя строка пугает сильнее всего. Она означает, что база мертва. А если смотреть на все четыре разом, складывается цельная история. Базе стало тяжело, из-за этого запросы к ней начали копиться, из-за этого HTTP-запросы стали отваливаться по таймауту, и в итоге не выдержал даже хелсчек. История правдоподобная.

Поэтому я начал с метрик базы. И на первом же экране эта история развалилась.

База скучала все 21 час

Я выгрузил метрики RDS за 21-часовое окно, включающее время аварии, с шагом в 5 минут. 252 точки данных.

Метрика	Минимум	Максимум
CPU	4,6%	19,7%
Соединения	53	73
Остаток CPU-кредитов	576	576
Задержка чтения	0s	0.01s
Задержка записи	0.01s	0.08s

CPU ни разу не перевалил за 20%, а у остатка кредитов минимум и максимум совпадают. То есть не потрачено ни одного. Задержка записи максимум 80 миллисекунд. Проверил и RDS Proxy. Задержка выдачи соединения максимум 26 миллисекунд, бэкенд-соединений максимум 36. Нигде нет числа, которое объяснило бы восьми- и десятисекундные запросы.

База не падала. Она даже не была занята.

Один запрос пересекает Атлантику двадцать пять раз

Откуда же взялись восьмисекундные запросы? Ответ виден в архитектуре.

Наш сервис работает в двух регионах, us-east и eu-west. Primary-база одна, она в us-east; чтения приложения в eu-west обслуживает локальная реплика, а вот записи целиком уходят через Атлантику в primary в us-east, проходя через RDS Proxy.

Проблема была в количестве записей. Я прошёл по коду запроса на сохранение попытки (POST /customer/practice/attempts) и посчитал. Upsert ассета 1 раз, чтение предагрегатов 3 раза, транзакция учебной попытки 4 раза, повторное чтение из раннера 1 раз, обновление прогресса 2-3 раза, транзакция серии около 6 раз, транзакция статистики 2 раза, обновление статуса повторения 2-3 раза. Примерно двадцать пять штук, разбросанных по трём независимым интерактивным транзакциям.

Это число прямо так и было записано в логах.

06:03:17  request_done  POST /customer/practice/attempts
          status=201  duration_ms=11695  query_count=25

25 запросов, 11,7 секунды. Причём этот запрос даже не упал. Он вытерпел свои 11,7 секунды и завершился с кодом 201.

Тут надо честно кое в чём признаться. Я не измерял, во сколько миллисекунд обходится одна такая поездка. В одном комментарии в коде RTT между регионами записан как 220 миллисекунд, в другом - как 80-100 миллисекунд на предложение. Не проверив, какое из двух значений верное, я записал в текст issue расчёт «25 x 220ms = 5,5 секунды». Сейчас я вижу, что это не измерение, а цитата. Точная формулировка звучит так: число поездок я посчитал (25), а стоимость одной поездки не измерял. Вывод от этого всё равно не шатается. Если двадцать пять раз слетать через Атлантику и обратно, издержки набегают в секундах.

На утреннем пике в Европе (06:00-06:10 UTC) скопилось 57 записей в primary, превысивших 3 секунды. LearningAttempt.create 8 989 мс, UserActiveDate.upsert 9 070 мс, LearningAttempt.findUnique 10 561 мс. Запросы наваливались друг на друга, и задержки поездок накапливались.

Два оповещения родились именно в этой щели.

Оповещения 1 и 2: пятисекундная транзакция не выдержала 9,3 секунды

Код обновления серии выглядел так.

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... шесть запросов, пересекающих регион ...
});

Объекта с опциями нет. Значит, применяется дефолтный таймаут интерактивной транзакции Prisma, то есть 5 000 миллисекунд. Обычно это не проблема. Если не лететь в другой регион.

Transaction API error: A query cannot be executed on an expired transaction.
The timeout for this transaction was 5000 ms,
however 9326 ms passed since the start of the transaction.

9 326 миллисекунд. Дальше это становится P2028, а запрос превращается в 504 на шлюзе.

Этот код был единственным беззащитным во всей нашей кодовой базе. Остальные транзакционные пути проходят через утилиту withTxRetry, которая поднимает таймаут до 8 секунд и делает P2028 поводом для повтора. И только обновление серии осталось вне этого зонтика и использовало дефолтные 5 секунд.

Оповещение 4: хелсчек прошёлся по тому самому узкому месту, за которым следил

Самое страшное оповещение, «сервис DATABASE недоступен», оказалось на деле самым нелепым.

Код хелсчека был написан хорошо. Он бросает SELECT 1 с таймаутом в 2 секунды, при неудаче ждёт 500 миллисекунд и пробует ещё раз, а если и это не удаётся, шлёт оповещение CRITICAL. Чтобы не мешаться с пулом Prisma у приложения, ему даже выделили отдельный пул соединений (максимум 2). Замысел был в том, чтобы хелсчек оставался жив, даже когда пул приложения исчерпан.

Но путь, которым эта проба добирается до базы, изолирован не был.

// health.service.ts:139
// Если задан DIRECT_DATABASE_URL, берем его, иначе откатываемся к DATABASE_URL

DIRECT_DATABASE_URL задан не был. Сработал фолбэк, а DATABASE_URL указывает ровно на тот RDS Proxy, куда набивается запись приложения. То есть SELECT 1, брошенный health-пробой из eu-west, должен был перелететь Атлантику, пройти через тот самый забитый прямо сейчас прокси, добраться до primary в us-east и вернуться. За 2 секунды.

Код об этом знал. При срабатывании фолбэка он оставляет такое предупреждение.

DIRECT_DATABASE_URL is not set; DB health checks will use DATABASE_URL
and may still share proxy bottlenecks.

Эта строка так и лежала в логах. Просто её никто не читал.

Решающим доказательством стало то, что оба региона отказали одновременно. 12:02:17 - таймаут хелсчека у таска в us-east. 12:02:18 - таймаут и у таска в eu-west. Будь проблема локальной, лечь должна была только одна сторона. Раз они легли вместе, причина в том, что у них общее, то есть в пути через прокси.

Дальше всё пошло по накатанной. Хелсчек провалился оба раза, значит, /public/health отдаёт 503, оркестратор считает таск проблемным и заменяет его. Через 4 минуты поднялся новый таск. Новый таск сразу после загрузки словил ровно тот же таймаут хелсчека. Замена таска не делает Атлантику уже.

«Сервис DATABASE недоступен» не был симптомом аварии. Это наблюдатель прошёлся по забитой дороге того, за чем наблюдает, и доложил, что ему тяжело.

500 в админке оказалась отдельной историей

Здесь возникает соблазн связать все четыре оповещения в одно. Я тоже поначалу хотел свести их вместе. Но у 500 в админке был другой корень.

Когда GET /admin/dashboard/stats вытаскивает популярные слова, он ставит фильтр по последним 7 дням. Вот только у таблицы, на которую этот фильтр ложится (category_attempt), нет собственной колонки с датой. Дата есть только на стороне присоединяемой learning_attempt. Поэтому Postgres не может заранее отсечь часть category_attempt по дате и вынужден прочёсывать всю историю. Как ни раскладывай индексы, селективным этот фильтр не сделать.

slow_query path=/admin/dashboard/stats
           label=CategoryAttempt.groupBy dur=8009ms

statement_timeout равен 8 000 миллисекунд. 8 009 миллисекунд. Умерло с разницей в 9 миллисекунд. Это был полный скан, никак не связанный с регионами и обязанный рано или поздно рвануть по мере роста таблицы.

Три оповещения из четырёх росли из одного корня, а одно нет. То, что четыре оповещения появились на одном экране, ещё не значит, что причина у них одна.

Одна отвергнутая гипотеза

Один правдоподобный подозреваемый у нас был. Гипотеза, что конкуренцию за блокировки вызвал крон device-cleanup, который отрабатывает прямо перед всплеском в 06:00. Время совпадало, так что звучало довольно убедительно.

Я прочесал логи обоих регионов на отрезке 05:30-06:15. Ни единой записи, связанной с кроном. Проверил, откуда шёл тормозивший Device.updateMany, и это оказалось не массовое обновление из крона, а /v2/public/auth/refresh, то есть обычный пользовательский запрос на обновление токена. Гипотеза была отвергнута фактическим замером. Совпадение по времени - это корреляция, а отсутствие записей в логах - это факт.

Мы схлопнули перелёты

Лечение бывает двух видов. Есть путь терпеть симптом: поднять таймаут до 8 секунд, увеличить пул, навесить повторы. И есть путь убрать сами издержки: сократить число перелётов.

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

Инструмент для этого был уже готов. В миграции от 27 июня лежала серверная функция create_practice_attempt_v1. Она сворачивает блокировку сессии, чтение, вставку, обновление метаданных сессии и чтение предагрегатов в одну SQL-функцию и укладывается в одну поездку. Она даже идемпотентна (при повторном вызове с тем же client attempt id второй вызов возвращает существующую строку и inserted=false).

Вот только фича-флаг PRACTICE_ATTEMPT_SINGLE_RT_ENABLED, включающий эту функцию, по умолчанию был false и в продакшене оставался выключенным.

Вместо того чтобы убирать регион или переезжать на active-active, мы всего лишь щёлкнули уже заготовленным выключателем.

Канарейка: по чему судить об успехе

Флаг включили только в eu-west. В us-east оставили выключенным как контрольную группу. Подняли task definition с 786 до 787 и раскатали rolling-деплоем.

Вот тут-то и начинается суть этой истории: что взять за метрику приговора. Задержка - это ловушка. Выкатите что-нибудь в час, когда трафика мало, и p95 улучшится, даже если вы ничего не чинили. Задержка, кстати, действительно улучшилась. p50 упал с 2 784 мс ниже 2 000 мс. Но доказательство это слабое.

Вместо неё я смотрел на число запросов к базе на один HTTP-запрос.

do      n=85   avg query_count = 22.0
posle   n=49   avg query_count = 15.3

Число запросов - это per-request метрика, не зависящая от нагрузки. Много трафика или мало, а сколько запросов к базе бросит один HTTP-запрос, определяет код. С 22 до 15,3, то есть примерно на 7 меньше. И эти 7 в точности совпадают с длиной списка запросов, который мы свернули в одну функцию (блокировка сессии + чтение + вставка + метаданные сессии + чтение предагрегатов). Доказательство того, что путь исполнения кода реально изменился, - именно это число. Не задержка.

Выборка после выката - это 49 запросов за 15 минут. В этом окне не было ни одной 5xx и ни одного P2028, но я не замерял рядом число ошибок за окно такой же длины «до выката» в тот же день. Этот флаг сворачивает только сохранение попытки. Транзакция серии по-прежнему летает между регионами. То, что в том окне P2028 случилось 0 раз, означает, что нам повезло, а не что это доказано.

Выкат прошёл успешно, но флаг чуть не исчез

У того, как мы включили канарейку, была своя цена. 787 - это task definition, зарегистрированный вручную из консоли. Как только пройдёт следующий штатный деплой, CD-пайплайн перезапишет его task definition без флага. Смертельным это не будет (перезапись возвращает нас к безопасному OFF). Просто улучшение тихо исчезнет.

Значит, надо было закрепить его в terraform, и тут вылезла вторая ловушка. Workflow terraform на push в develop применяет только staging, а production применяется только на push в main. Вот только в staging никакого региона eu-west нет в принципе. То есть если смёржить в develop PR с изменениями для продакшн-eu-west, не произойдёт ровным счётом ничего. Пришлось менять базовую ветку на main.

Была и третья ловушка. Если мёржить прямо в main, develop отстаёт, и, если не выполнить обратное слияние, следующий релиз откатит это изменение. Пришлось отдельно заводить back-merge PR.

«terraform apply прошёл успешно» и «изменение доехало до продакшена» - это два разных утверждения.

Что осталось

Когда приходит оповещение «база недоступна», начинать надо с метрик базы. Имя оповещению дал код, который его отправил, а не причина случившегося. Наш хелсчек обзавёлся даже отдельным пулом, изолированным от пула приложения, и всё равно застрял вместе с приложением, потому что дорога к базе была одна и та же. Изоляция - это не только разделить ресурсы, но и развести пути.

Если поднять таймаут с 5 секунд до 8, оповещения в тот день прекратятся. Но запрос всё так же будет пересекать Атлантику двадцать пять раз. Стоит трафику подрасти чуть сильнее, и 8 секунд тоже перестанет хватать. Лучше заранее решить, терпеть симптом или убирать издержки. Если природа издержек - это «число x расстояние», сокращать надо число.

Задержка пляшет вслед за нагрузкой, а per-request метрики не пляшут. Прежде чем успокаиваться, выкатив исправление производительности и увидев улучшение p95, стоит посмотреть, действительно ли уменьшилось количество работы, которую делает один запрос. Это число одинаково и в ночном выкате, и в обеденном.

Число поездок я посчитал, а задержку одной поездки взял из комментария в коде. Два этих комментария называли разные значения. Хорошо, что вывод от этого не поменялся, но в следующий раз он может и поменяться. Не измерил число - так и напиши, что не измерял.