Один алерт на p99, пять медленных маршрутов, пять разных причин

На одной продуктовой платформе в Gambchamp сработал алерт на p99 латентности платёжного сервиса. Он говорил, что сервис медленный, и ничего — о том, где именно. Разбивка алерта по маршрутам ответила на этот вопрос — и показала, что у каждого медленного маршрута своя причина. Какие-то были реальными проблемами, какие-то — совсем не тем, чем казались.

Чем оказался каждый маршрут

• Инициация депозита: примерно половина запросов занимала 2,5–5 секунд. Это были синхронные вызовы внешних платёжных шлюзов, возвращавшие HTTP 200 с URL для редиректа, — никаких ошибок. Распределение было бимодальным: около 5 мс, когда вызов шлюза не нужен, и 2,5–5 с, когда нужен. p99 в восемь секунд — просто нормальная скорость шлюзов.
• Регистрация: 84 % запросов дольше секунды. Тайминги фаз в логах показали, что медианный запрос тратит 1,4 с на обработку, большую часть — на внешнюю проверку капчи (около 0,5 с).
• Запуск игры: 6 % медленных. Одна фаза — вызов коннектора игрового провайдера — имела медиану 1,2 с и p95 1,7 с. Всё остальное — миллисекунды.
• Промо-страница: 10 % запросов дольше секунды — но собственный тайминг обработчика ни разу не превысил 0,95 с. Время уходило за пределами обработчика. Эту до конца пока не поймали.
• Вывод средств: ещё один маршрут через шлюз, p99 около 2,5 с. Все остальные платёжные маршруты — около 50 мс.

Ловушки

• Бэкенды скрейпились дважды, двумя job’ами. Квантилям это безразлично, но счётчики и increase() удваиваются, если не зафиксировать job. Всегда фиксируйте его, когда считаете запросы.
• Тайминг обработчика в логах — это не длительность запроса. Он меряет только обработчик; гистограмма меряет то, что видит клиент. Для SLO доверяйте гистограмме; логи используйте, чтобы понять, куда уходит время внутри обработчика.
• Логи — это выборка. 763 строки лога против 2 419 наблюдений гистограммы за те же три часа. «В логах медленных запросов нет» не опровергает метрику.
• Сетка бакетов прыгала с 1,0 сразу на 2,5 секунды. Всё, что попадает в этот промежуток, интерполируется ближе к верху, поэтому p99 в 2,3 с может означать «где-то между 1 и 2,5». Смотрите на бакеты, прежде чем доверять числу.
• Квантиль прячет бимодальность. «p99 — пять секунд» звучало как «всё медленное». Бакеты показали два разных пути в коде.

Одну ошибку я сделал сам: сначала списал промо-страницу на артефакт бакетов. Бакеты разных job’ов совпали друг с другом — примерно 10 % запросов действительно были дольше секунды. Проверяйте, прежде чем объявлять артефакт.

Запросы, которые сделали работу

sum by (le) (increase(http_request_duration_seconds_bucket{app="X", route="Y"}[30m]))

Полное распределение показывает бимодальность и где сидят секунды. Доля запросов дольше секунды по маршрутам показывает, у каких маршрутов реальный хвост. А CPU throttling стоит исключить, прежде чем винить приложение.

Как изменился алертинг

• Алерт на латентность теперь агрегирует по (app, route), так что называет эндпоинт.
• Порог по трафику — больше 3 запросов за 10 минут, а не rate: маршрут депозита получает около четырёх запросов за 10 минут и действительно медленный, так что порог по rate его пропускал.
• Порог — 1,5 с, а не 1 с, выбран с оглядкой на сетку бакетов.
• Маршруты через шлюзы исключены и получили собственный алерт на 12 секунд за 30 минут. Две–восемь секунд там — норма; текст алерта прямо это говорит, чтобы дежурный не бросился искать баг в нашей инфраструктуре.

Выводы

• Алерт на латентность уровня сервиса должен называть маршрут.
• Смотрите на распределение, а не только на квантиль.
• Фиксируйте job скрейпа, когда что-то считаете.
• Внешние зависимости получают свои пороги и явную пометку в алерте.