4 часа недоступности: постмортем падения Dodo IS

Вечером пятницы 23 сентября, в самое «горячее» время для Додо Пиццы, развалилась платформа Dodo IS. Приём заказов превратился в тыкву, клиенты и пиццерии 4 часа испытывали проблемы. Это было наше самое крупное падение с 2018-го года как в техническом плане, так и по недополученной выручке.

Особенная боль — то, что мы упали в прайм-тайм. Наш бизнес устроен циклично и зависит от сезона: осенью заказов больше, чем летом, а по вечерам пятницы больше в несколько раз, чем утром вторника, обычно пик заказов приходится на вечер пятницы (с 16 до 20 по Москве). Это время — самое напряжённое для системы и самое ценное для бизнеса.

У Dodo IS произошёл каскадный сбой и мы долго не могли реанимировать систему. Описываем наш путь во время этого инцидента:

• Накинем ресурсов и все полетит?

• Рассылка от маркетинга пушей в самый пик — может, дело в этом?

• Наверняка это DDoS.

• Или плохой релиз, вышедший недавно?

• Короче, это что-то с базой.

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

Хронология событий и гипотезы

Первые алерты: ничего критичного, просто растёт нагрузка

Это была обычная пятница. Заказы принимались, алертов, которые говорили бы о сбоях системы, не было. В 16-52 прилетел алерт от MySQL о том, что много активных тредов.

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

В 16-59 — алерт с бэкенда мобильного приложения, летят ошибки.

Но система продолжала работать, заказы шли. Инцидент открыли только в 17:07.

Когда команда подключилась к разбору, заказы из всех источников поступали, хоть и валились ошибки при работе бэкенда мобильного приложения (mapi — от mobile api) с базой для хранения корзин и сессий (база на CosmosDB). Нагрузка на систему продолжала нарастать, близился вечерний пик заказов.

Каких-то явных отклонений мы не увидели и решили, что это естественный рост по нагрузке — мы упёрлись в лимиты базы (MySQL и CosmosDB).

Так выглядит архитектура заказа. Есть 3 источника заказа: касса ресторана, мобильное приложение и сайт. Все они проходят через Legacy Facade (LF), а потом попадают базу монолита. Касса частично берёт данные прямо из базы монолита.

Mapi и site (dodopizza.ru и сайты других стран) имеют своё хранилище, в основном это CosmosDB (или MongоDB, в зависимости от конфигурации) для хранения драфта корзин или предрасчётов, нужных на клиенте.

LF (Legacy Facade) — специально сделанный сервис, который выдаёт данные по http из базы. В нём есть части логики, которая когда-то была на слое репозиториев и сервисов доступов к данным в монолите. LF мы создали 5 лет назад, когда делали новый сайт и мобильное приложение, чтобы вести независимую разработку на клиентах. Логику приёма заказа, расчёта заказа, формирования меню, выдачи данных по клиенту, проверки промокодов зашили в LF.

Первая и основная гипотеза: не хватает ресурсов, надо добавить

Если трафик вырос, то не так важно, из-за чего именно: надо накинуть чуть больше ресурсов в разные части цепочки принятия заказа и всё полетит.

В 17:15 начинаем скейлить:

• поднимаем поды (считай количество инстансов приложения в Kubernetes) для Кассы с 3 до 5,

• поднимаем реквест-лимиты в CosmosDB,

• поднимаем поды у mapi с 4 до 8.

Но это не имеет эффекта, заказы с mapi падают в 0. Понимаем, что из всей цепочки не заскейлили БД монолита. Она у нас в нормальном режиме работает на 32 ядрах — скейлим до 64.

В 17:30 заказы по всей системе падают в 0.

Некоторое время после рестарта базы это нормально. Но когда база поднялась, то отказывает уже LF, в котором находится приём заказа от всех источников. LF кидает ошибки bulkhead rejected request: выдаёт слишком много ошибок на запросы, закрыл bulkhead и не принимает от источников заказа запросы на исполнение. Разбираемся, что делать с этим.

График заказов в минуту из всех источников показывает, что с 17:30 система не работала. Просто накинуть ресурсов было недостаточно.

Параллельно отмечаем, что была массовая рассылка пушей. Может, она тоже влияет?

Днём отдел маркетинга запустил СМС и пуш-рассылку почти на 3.5 млн клиентов.

Эти рассылки имеют ограничение на отправку — не более 200 тысяч в час, а рассылка в миллионы пушей растягивается на несколько часов и до суток, потому что клиенты находятся в различных часовых поясах. Пуши рассылают регулярно, обычно это происходит во время дневного (обеденного) пика и во время вечернего, чтобы была хорошая конверсия в клик.

Такая же по объёму рассылка последний раз была в одну из пятниц июля 2022 года, и Dodo IS выдержала. Нюанс был в том, что летом заказов меньше, чем в сентябре. И в этот раз рассылка наложилась на гораздо больший пик заказов.

В 17:42 останавливаем рассылку, но и после этого поднять систему не получается. После остановки дополнительная нагрузка от открытия пушей должна была уйти, а система подняться. Этого не произошло.

Продолжаем пытаться восстановить систему.

17:46 Из-за того что мобильное приложение перестало работать, клиенты пошли на сайт заказывать пиццу. Это не удивительно, ведь приложение само предлагает перейти на сайт. Скалируем site с 5 до 7 реплик, планируем довести до 10 реплик.

В 17:49 трафик на сайт увеличился в 3 раза, с 15 до 45 тысяч запросов. В обычный будний вечер (не пик) на сайте около 20 заказов в минуту, на мобилке — около 200. Не все пользователи мобилки уходят на сайт, а где-то четверть. Это даёт такой вклад в запросы.

Сильно возросший трафик на сайте вынуждает нас продолжать увеличивать количество реплик по цепочке, в том числе для LF.

Третья гипотеза: нас жёстко DDoS-ят

Но трафик на систему всё равно достаточно большой, даже для вечернего времени. Предполагаем, что идёт DDOS-атака, которую мы не можем отразить и которую не можем заметить. Если бы это была DDOS-атака, то фродовый трафик можно было бы порезать. И ещё снизить в этот момент нагрузку. Может быть, система бы поднялась. А пока мы достоверно не задетектили атаку, трафик может быть нашим собственным.

Количество запросов после 17:25 возрастает c 11 до 40-50 тысяч.

В 18:41 эта гипотеза как будто подтверждается: отражена атака на сайт в размере 2.7 млн запросов при норме 11000 запросов.

Но ни до, ни после этой подтверждённой атаки нам не удалось найти следов каких-либо других атак. К тому же атака была на сайт, а повышенный трафик в основном шёл на mapi. Уже после инцидента мы детально разбирали трафик, смотрели самостоятельно запросы. На mapi нелегитимного трафика не было, а на сайте он был и был отражён.

Во время всего инцидента мы не исключаем версию атаки. Периодически к ней возвращаемся. Это оттягивает силы и внимание от действий по другим направлениям.

Параллельно со всем этим мы пытались восстановить систему разными действиями и получить больше данных

На втором часу сбоя имеем:

1. Ресурсов накидали, не помогло.

2. Пуши стопнули, не помогло.

3. Предположили DDOS, но никаких подтверждений нет.

4. Dodo IS лежит.

Видимо, надо копать глубже и точечно настраивать части системы, чтобы её поднять.

В 18:19 снимаем трейс с LF, изучаем. Пробуем понять, что не позволяет системе подняться.

В 18:24 выставляем настройки Bulkhead в LF до 1000/100 (BulkheadConcurrency/BulkheadQueue).

Было:

<!-- BulkHead lf-->
    <add key="BulkheadConcurrency" value="150" />
    <add key="BulkheadQueue" value="20" />

Стало:

<!-- BulkHead lf-->
    <add key="BulkheadConcurrency" value="1000" />
    <add key="BulkheadQueue" value="100" />

В 18:24 рестартуем LF.

Идея была в том, чтобы разжать LF, позволив ему подняться, принять в себя все запросы.

Конечно, зажата пропускная способность была не просто так. Это нормальное ограничение, чтобы не пропускать в базу много трафика и не положить её. Положить базу — значит, положить все источники приёма заказа и часть других сервисов.

Также разжатием мы хотели увидеть новую информацию, новые данные.

База данных, к которой обращался LF, к тому времени была на 64 ядрах при нормальной работе в пики на 32-х. Загрузка по CPU у неё была около 17%. Это значит, что даже увеличив количество параллельных коннектов в базу, мы бы её не положили (при разжатии балкхэдов был расчёт, что увеличенная база выдержит).

В 18:32 ушли warnings от LF bulkhead rejected request.

В 18:34 появились заказы на кассе.

Нам показалось, что вот сейчас всё полетит, раз уж касса ресторана принимает заказы.

Но на самом деле касса ресторана принимает заказы только при выключенном сайте и мобильном приложении. Значит, проблема не решена. Когда включаем сайт и mapi (это видно по графику дальше), то всё опять ложится.

C 19:05 в логах LF много ошибок:

• System.OperationCanceledException: Query execution was interrupted

• System.OperationCanceledException: The operation was canceled.

• Основные URL

  • /MasterDataManagement/v2/GetMenu

• Статистика:

По крайней мере, мы подсветили запросы, из-за которых не проходит флоу приёма заказа.

Основной из них — запрос на получение меню GetMenu.

При этом система не выдерживает, когда включаются все источники приёма заказа.

В 19:05 — количество SlowLog запросов выросло:

let _start_utc = datetime('2022-09-23T13:00:00Z');
let _end_utc = datetime('2022-09-23T20:00:00Z');
let _msk_start = datetime_add('hour', 3, _start_utc);
let _msk_end = datetime_add('hour', 3, _end_utc);
SreMysqlSlowLogs(MONOLITH_RU_DB, _start_utc, _end_utc)
| extend TimestampMsk=datetime_add('hour', 3, Timestamp)
| summarize count() by bin(TimestampMsk, 5m)
| render timechart

Понятно, что с разжатыми балкхэдами база не выдерживает, идут ошибки. Когда балкхэды разжимали, была слабая надежда, но она не оправдалась.

В 19:19 по совету @georgepolevoy применяем Bulkhead Policy в LF , чтобы уменьшить количество принимаемых запросов к API, тем самым снизить нагрузку на БД. Для ускорения процесса решили поправить прямо в Kubernetes в Secrets configs-legacyfacade. Но поломали конфиги (там нужно было конвертировать в base64).

В 19:27 замечаем, что сегодня нагрузка на БД чуть больше обычного.

Примерно в 19:38 видим, что на базе много тредов.

19:48 — зависшие запросы к БД.

Это запрос на метапродукты (т.е. например, есть продукт Кофе американо, а у него есть объём 0,2, 0,3 и 0,4 л) и топпинги (дополнительные ингредиенты) в меню. Да, это связано с вызовом метода GetMenu, который мы видели выше, когда разжали балкхэды.

В обычной жизни запросы к топпингам выполняются за 0.05 секунды, а на инциденте — более 10 секунд. Позже мы исследовали этот запрос и никакой неоптимальности на уровне SQL в нём не было. Этого запроса просто было слишком много и он не успевал обрабатываться. В качестве митигации думаем про изменение настройки thread_handling БД c one-thread-per-connection на pool-of-threads.

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

• В20:24выставили настройку thread_handling pool-of-threads и перезапустили БД.

• В 20:27 БД перезапустилась.

• В 20:28 БД по CPU высокое и не спадает. До этого CPU было небольшое, а теперь опять выросло. Грузим все 64 ядра мощной базы.

В итоге изменение свойств базы с обработкой коннектов нам не помогло.

На 21:00 вся система была в разваленном состоянии. Сайт, мобильное приложение и касса ресторана не принимают заказы уже 2,5 часа.

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

Четвёртая гипотеза: может, это плохой релиз?

Вернёмся чуть назад во времени. В 19:22 у собравшихся появляется идея посмотреть, что же выходило в этот день на продакшен из обновлений. Может, мы найдём в них какую-то зацепку, которая поможет починить всё. Смотрим на последний релиз монолита. Монолит делает запросы к базе монолита, в монолите находится LF, а значит, что-то могло повлиять на них.

Релиз был раскатан в 11:01 23 сентября и весь день проработал нормально. Обычно перформансные проблемы в релизе проявляются достаточно быстро.

Но этот релиз был раскатан в пятницу утром (в пятницу после 15 мы ничего не катим), и пока у него не было ни одного проработанного вечера. Этот вечер был первым.

Пошли изучать код релиза. В релизе было 15 задач, поэтому детальное изучение занимает время.

В 19:25 запускаем откат монолита России на 928 релиз.

В 19:27 релиз монолита падает по причине того, что под Migrator не сумел выполнить запрос к базе из-за того, что она нагружена.

Мигратор — это встроенный в релиз механизм обновления данных или схемы базы. Он используется для небольших изменений в базе, когда надо создать новую таблицу или обновить данные до 100К записей. Для больших изменений мы используем обновление базы вне релиза.

Тут происходит фатальная ошибка: вместо того, чтобы попробовать накатить релиз без мигратора, мы оставляем идею просто обновить систему и идём отрабатывать другие версии, а также изучать код всех 15 задач в поставке.

Возможно, откати мы тогда, все могло бы быть иначе.

После первой и единственной попытки откатить релиз отрабатываем версии с балкхэдами, точечными запросами в меню на базе и прочие.

В 21:18 всё таки решаем откатить на 928 релиз. Это тот релиз, который пристально изучали и в котором ничего не нашли и тот, на который мы ещё час назад попробовали откатить, но из-за мигратора не получилось. Фактически это уже был жест отчаяния: что бы мы ни делали, восстановить работу системы не выходило.

Релиз откатился примерно в 21:20.

• 21:26 По заказам пока лучше не стало. Нагрузка на БД по CPU спала, хотя по заказам лучше не стало.

• 21:30 Пошли заказы по mapi с растущим трендом.

Всё поднялось. Невероятно. Но что это было? Почему? Может, дело в релизе?

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

Анализ инцидента

Частью описания постмортема является анализ инцидента. Мы его делаем, отвечая на несколько вопросов:

Подробная хронология и анализ действий позволяет найти первопричину и исправить её.

Самая глубокая причина, до которой удалось докопаться

В базе данных с заказами России был неверно сконфигурирован кеш по работе с таблицами.

Массовая рассылка пуш-уведомлений для мобильных приложений вызвала нагрузку на mapi, которое в свою очередь нагрузило LF, который увеличил количество запросов к БД.

При этом в БД перестали попадать в кеш файловых дескрипторов таблиц, это увеличило количество тредов в Idle состоянии. Mapi при этом перестало работать, из-за недостаточного количества реплик на них была 100% нагрузка на CPU.

В попытке вернуть mapi в работоспособное состояние мы удвоили количество реплик приложения, тем самым вызвали срабатывание Bulkhead-механизма в LF (он сразу отклонял часть поступающих запросов), а также ещё сильнее нагружали БД, что привело к каскадным сбоям по всей системе.

Решения

Быстрые временные решения

1. Стоп на время фича-разработки в части Приём заказа. Субботник по стабильности.

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

Долгосрочные системные решения:

• Поменять настройки кеша файловых дескрипторов в базе. Улучшить работу базы.

  • Увеличить значение настройки table_open_cache с 2000 до 40000.

  • Узнать про innodb_log_file_size (сейчас 512 МБ, а нужно 3 Гб).

  • Innotop должен работать локально из-под VPN с SSL подключением до MySQL.

  • Сделать innodb-buffer-pool-load-at-startup.

  • Настроить процесс мониторинга метрик MySql БД монолита России и стран.

  • Исследовать SlowLog на предмет Full Scan запросов при рестарте LF.

  • Актуализировать ранбук «Большое количество тредов на БД».

• Переработать систему нагрузочного тестирования. Мы должны были отлавливать узкие места и проблемы заранее, а не на продакшен-среде.

  • Переработать сценарии. Надо добиться точности соответствия нагрузке на базу монолита.

  • Актуализировать профиль нагрузки с продовыми показателями. Сценарий нагрузки с рассылкой и открытием пуш-уведомлений был некорректным. Более года назад у нас были сценарии проверки открытия пуша на нагрузке. Но тогда рассылки были небольшие и сценарий был не критичным. Сейчас же количество рассылки выросло в несколько раз и вклад этого сценария стал больше. Это не учитывали в профиле нагрузки.

  • Актуализировать инфраструктуру ld и prod окружений.

  • Сделать возможность запуска нагрузки на разных стендах (сейчас все только на одном). Этим мы уберём узкое место в тестировании. Из-за этого узкого места мы не можем проверять достаточно сценариев.

  • Усилить состав инженеров по нагрузке.Наймем больше перфоманс инженеров, подключим разработчиков.

• Увеличить способность системы выдерживать нагрузки. Все концы сходятся в нескольких точках отказа. Каждый домен вносит свой запутанный вклад в нагрузку LF и базы.

  • Оптимизировать выдачу меню. Источники заказа (сайт, mapi, касса) ходят за меню в LF, там оно кешируется, а при протухании кеша строится заново из базы монолита. Протухание кеша может быть из-за рестарта подов, потому что кеш в памяти.

  • Вынести расчёт заказа из монолита в отдельный сервис.

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

  • Улучшения в текущих сервисах

    • Актуализировать настройки Bulkhead для LF

    • Не отправлять пользователей из мобильного приложения на сайт, если он не доступен

    • Научиться поэтапно открывать трафик до сервисов mapi и сайта

    • Настроить HPA для mapi, сайта и LF

    • Добавить startup пробы для LF, для прогрева кешей

    • Механизм по отведению трафика сайта и mapi от LF

    • Проверить работу reaction. Назначил не того IC

    • Инструментировать все кеши метриками и трейсами system.diagnostics

• Улучшить мониторинг и инструкции при работе со сбоями.

  • Мониторинг не выдерживал такого количества участников инцидента (в пике на созвоне было более 20 человек). В середине инцидента мы потеряли метрики, их пришлось руками восстанавливать. Надо переходить с Prometheus на VictoriaMetrics.

Текущие изменения в получении меню

Меню — ключевой объект для приёма заказа. В нём сочетается много данных:

• список продаваемых товаров — для каждой пиццерии он несколько свой;

• описание продукта, карточка продукта. Есть особые карточки по особым дням, например, новогодняя пицца с бужениной и клюквенным соусом;

• сложные продукты (метапродукты) сочетают в одной карточке несколько товаров. Открывая Кофе, мы видим Кофе с объёмом 0,2, 0,3, 0,4 л;

• цены плюс персональные цены для некоторых пользователей;

• сама структура меню включает разные категории: пицца, комбо, закуски и т.д.;

• «стопы», т.е. какой-то продукт может закончится в пиццерии и будет поставлен в стоп продаж. В меню такой продукт отображается как не продающийся в данный момент.

Примеры меню:

Вся эта сборка происходит в момент запроса GetMenu. Конечно, кешируется на всех уровнях всё, что возможно. Но всё равно цепочка запросов последовательная, в случае каскадного сбоя (который и был у нас) загрузка достаточно тяжелая: клиентская часть приёма заказа(iOS, Android, касса) + кеши → mapi + его база + кеши → LF + кеши → база данных и её кеши.

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

Нам надо изменить архитектуру. Нужен сервис, который бы заранее стоил готовое меню, выкладывал бы его в JSON как статический контент, а дальше источники приёма заказа уже получали бы меню как файл. Тогда мы бы не зависели от кешей, тяжелые операции построения меню были бы отделены от критических операций получения меню.

Работа такого сервиса:

• RMQ — шина, по которой должны распространяться события об изменении продукта, структуры меню, цен, карточки продукта и т.д.

• DMS — библиотека, которая обрабатывает события в Consumers, учитывает данные? уже хранящиеся в сервисе, обогащает их текущими пришедшими через события. На выходе получается DataWindow – витрина данных.

• RegisterBuilder делает итоговый JSON, помещая его в Storage, это blob.

Или тот же путь подготовки данных, только верхнеуровнево:

• DataCatalog — сервис справочников. Он порождает события изменения меню, цен и все остальные.

• MenuService — наш сервис, который готовит меню. Он же ещё и порождает событие MenuChangedEvent, которое mapi/site/касса могут использовать для отслеживания каких-то изменений.

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

Таким образом, работа по созданию меню перекладывается из цикла запроса пользователя в асинхронный режим. Когда пользователь открывает мобильное приложение после прилёта маркетингового пуша, mapi надо только сходить в blob storage и скачать там JSON. Можно JSONи закешировать у себя, а инвалидировать кеш по событию menuChangedEvent. В любом случае, выдача меню не будет включать в себя построение его на лету.

Все это уже делалось и до сбоя 23 сентября, просто не успело полностью выйти. Мы форсировали работы по раскатке.

23 сентября 2022 года произошло самое крупное и долгое падение системы с 2018 года. Быстро разобраться и восстановить систему не получилось, поэтому нам пришлось приостановить разработку фич и сосредоточиться на поиске и исправлении глубинных причин.

В итоге мы оптимизировали меню, перерабатываем сценарии нагрузочного тестирования, улучшаем мониторинг и много еще чего.

Одной проблемы не было. Был комплекс проблем. Именно поэтому они все сыграли в некоторой синергии и дали такой эффект. В сложный системах нет одной первопричины(см How Complex System Failed).

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

Полезные ссылки:

Шаблон постмортема Dodo Engineering.