Разбор инцидента: API иногда отвечает медленно
В главе расследование проходит путь от жалобы до подтверждённой причины. На каждом шаге отмечено, что уже установлено, что пока неизвестно и какие данные нужны дальше.
Гипотеза становится выводом только после проверки на данных, которые могли её опровергнуть.
- Раздел
- Основы наблюдаемости
- Уровень
- Начальный · Python знаком
- Связанные главы
- 1.4 — метрики, 1.5 — логи, 1.6 — трассы
- Зачем это знать
- Искать причину сбоя по данным и проверять первую догадку
§1Условия разбора
В предыдущих главах метрики, логи и трассы разбирались по отдельности. Здесь все три сигнала работают вместе на одном инциденте. Инцидентом называют любое событие, которое ухудшает работу сервиса для пользователей: сбой, замедление, потерю данных.
Пациент жалуется на слабость. Врач уточняет жалобу, назначает анализы, сужает круг возможных болезней, ставит диагноз, назначает лечение и проверяет, помогло ли оно.
Пользователь жалуется на медленный каталог. Инженер уточняет жалобу, смотрит метрики, сужает область поиска, находит причину, исправляет её и проверяет по данным, помогло ли исправление.
Сервис каталога отвечает на запрос GET /products списком товаров. Он запущен в трёх экземплярах: api-1, api-2 и api-3. Балансировщик распределяет запросы между ними примерно поровну. Каждый экземпляр читает товары из PostgreSQL через пул соединений.
Пул соединений — набор заранее открытых соединений с базой данных, которые обработчики запросов берут на время и возвращают обратно. Открывать новое соединение на каждый запрос долго, поэтому соединения используют повторно.
Размер пула ограничен. Если все соединения заняты, следующий обработчик ждёт, пока одно из них вернётся в пул. SQL-запрос при этом может выполняться быстро, но время ожидания соединения добавляется к длительности всего HTTP-запроса.
В 14:20 в поддержку пишет пользователь: «Список товаров иногда загружается несколько секунд». Разработчик открывает каталог — страница загружается за 180 мс. Панель ошибок в Grafana спокойная. Ниже весь ход расследования, а в следующих разделах каждый шаг разобран подробно.
Жалоба: иногда 4–5 секунд
Один повторный запрос прошёл за 180 мс.
Одна проверка быстрая. Частота замедлений неизвестна.
Есть ли распределение длительностей за интервал жалобы?
Кнопки листают материалы по порядку. На каждом шаге видно, какой факт появился, что из него следует и какой вопрос задаётся дальше.
Расследование начинается с самой жалобы: в исходном виде с ней работать нельзя.
§2Шаг 1. Уточнить жалобу
Быстрая ручная проверка после жалобы ничего не доказывает: она показывает только, что один запрос в 14:25 выполнился быстро. Если медленным оказывается каждый двадцатый запрос, разработчик попадал на быстрый с вероятностью 95%.
Закрывать жалобу рано, но и искать причину пока не в чем. Сначала жалобу превращают в описание, с которым можно работать.
| Что уточнить | Зачем | Что получили |
|---|---|---|
| Интервал времени | Выбрать окно, в котором искать данные | С 13:50 до 14:20 |
| Операция | Отделить API от загрузки картинок и скриптов страницы | Долго грузится сам список, то есть ответ /products |
| Частота | Понять масштаб: каждый запрос или редкие случаи | «Иногда», примерно каждое пятое открытие |
| Идентификатор запроса | Найти конкретный медленный запрос в логах и трассах | Пользователь прислал X-Request-ID из инструментов разработчика браузера |
Жалоба
«Список товаров иногда загружается несколько секунд».
Описание для работы
С 13:50 часть запросов /products выполняется несколько секунд; есть идентификатор одного из них.
Описание готово. Теперь нужно узнать, сколько запросов затронуто, и на этот вопрос отвечают метрики.
§3Шаг 2. Оценить масштаб по метрикам
Первыми смотрят метрики: они показывают картину по всем запросам сразу. Нужны три показателя за интервал с 13:30 до 14:20: поток запросов, доля ошибок и распределение длительностей.
| Показатель | 13:30–13:50 | 13:50–14:20 | Что из этого следует |
|---|---|---|---|
| Поток запросов /products | 180 в секунду | 185 в секунду | Нагрузка почти не изменилась |
| Доля ошибок | 0,1% | 0,1% | Ошибок больше не стало |
| Медиана длительности | 90 мс | 95 мс | Типичный запрос почти не изменился |
| p95 длительности | 160 мс | 4 200 мс | Медленная часть запросов выросла резко |
Две панели построены по одним и тем же запросам, но у каждой своя шкала: иначе линия медианы прижалась бы к нулю и её изменения были бы не видны. Медиана держится около 90 мс — типичный запрос не изменился. p95 после 13:48 поднимается с 160 мс до 4 200 мс: изменилась медленная часть запросов. Пунктир — выпуск версии 2.15.0. Совпадение по времени — повод для гипотезы, но ещё не вывод. Значения взяты из таблицы выше.
Медиана осталась прежней, значит, большинство запросов по-прежнему быстрые. p95 вырос в 26 раз, значит, не меньше каждого двадцатого запроса стал очень медленным. Это сходится со словом «иногда» в жалобе.
Две популярные догадки
- Всплеск трафика: поток почти не изменился.
- Массовые ошибки: доля ошибок прежняя, поэтому панель ошибок и была спокойной.
Чего метрики не говорят
- Сколько пользователей пострадало: p95 описывает запросы, а один пользователь делает много запросов.
- Почему часть запросов медленная.
Известно, что медленная часть запросов выросла. Следующий шаг выясняет, где находятся эти запросы.
§4Шаг 3. Сузить область
Когда масштаб понятен, область поиска сужают: метрику длительности делят по меткам — экземпляр, версия, маршрут.
| Экземпляр | Версия | p95 длительности | CPU | Память |
|---|---|---|---|---|
| api-1 | 2.14.0 | 150 мс | 35% | 410 МБ |
| api-2 | 2.15.0 | 9 800 мс | 31% | 400 МБ |
| api-3 | 2.14.0 | 165 мс | 37% | 420 МБ |
Медленные запросы сосредоточены на api-2, два других экземпляра работают как раньше. Общий p95 4 200 мс получился из смеси: примерно треть запросов попадает на api-2 и тянет общее распределение вверх.
Почему общий p95 меньше, чем p95 сбоящего экземпляра
На api-2 p95 равен 9 800 мс, а общий p95 сервиса — 4 200 мс. api-2 входит в общее распределение, и меньшее число выглядит странно. Расчёт это объясняет.
- Доля api-2
Балансировщик делит запросы поровну, на
api-2приходится примерно треть всех запросов. - Что отсекает общий p95
5% самых долгих запросов сервиса. Почти все долгие запросы — с
api-2. - Пересчёт на api-2
5% от всех запросов — это около 15% запросов самого
api-2. - Итог
Общий p95 примерно равен 85-му перцентилю
api-2, до его 95-го он не доходит. По измерениям это 4 200 мс.
Отсюда два следствия. Общий перцентиль не равен ни одному перцентилю экземпляра, и по нему нельзя судить о худшем из них. А если изменить долю api-2 в балансировке, общий p95 изменится, хотя сам api-2 будет работать так же.
В таблице есть ещё две подсказки. На api-2 установлена новая версия 2.15.0, выпущенная в 13:48. CPU и память у всех экземпляров одинаковые, значит, api-2 не перегружен вычислениями: запросы на нём чего-то долго ждут.
Совпадение с выпуском версии — подсказка. Доказательством оно не является. В 13:48 на api-2 могло измениться и другое: переезд на другой сервер, новая сетевая настройка. Нужно посмотреть внутрь медленного запроса.
Область сузилась до одного экземпляра и одной версии. Чтобы увидеть, чего ждут запросы, нужна трасса.
§5Шаг 4. Посмотреть трассу медленного запроса
Пользователь прислал идентификатор запроса. По нему находят трассу и лог этого запроса.
| Этап | Начало | Длительность |
|---|---|---|
| GET /products | 0 мс | 2 910 мс |
| acquire_connection — получение соединения из пула | 5 мс | 2 800 мс |
| SELECT products — SQL-запрос | 2 805 мс | 35 мс |
| serialize — подготовка JSON | 2 840 мс | 65 мс |
Верхняя полоса — весь запрос, три нижние — его этапы. Полоса acquire_connection занимает почти всю шкалу: запрос ждал свободное соединение из пула. Обращение к базе и подготовка ответа на этом фоне почти не видны — 35 и 65 мс. По общей длительности запроса такую картину не отличить от медленной базы данных.
Из 2 910 мс запрос 2 800 мс ждал соединение. Сам SQL-запрос занял 35 мс — нормальная скорость. Без трассы по общей длительности легко решить, что медленно работает база данных. Трасса эту гипотезу опровергает: база отвечает быстро, запрос долго не может получить соединение.
В логе того же запроса есть запись уровня WARNING: pool_wait_exceeded pool_size=2 waiting=14. Приложение предупреждает, что в пуле два соединения, а ждут четырнадцать запросов.
Одна трасса описывает один запрос, поэтому проверяют, типична ли картина: берут ещё несколько медленных трасс с api-2 и несколько быстрых с api-1. У медленных везде длинный этап acquire_connection, у быстрых он короче миллисекунды.
Место задержки найдено: ожидание соединения. Причина этого ожидания пока неизвестна, и следующий шаг её ищет.
§6Шаг 5. Выдвинуть гипотезы и проверить их
Участок, где уходит время, найден, а механизм ещё нет. Долгое ожидание соединения бывает по разным причинам, и у каждой своё исправление. Поэтому гипотезы записывают все сразу и для каждой определяют, чем её проверить.
| Гипотеза | Чем проверить | Что её опровергнет | Результат |
|---|---|---|---|
| Вырос поток запросов на api-2 | Поток по экземплярам | Поток на api-2 такой же, как на api-1 и api-3 | Опровергнута: около 62 запросов в секунду, как у соседей |
| Соединения не возвращаются в пул (утечка) | Время удержания соединения, число выданных и возвращённых | Каждое соединение возвращается через 40–100 мс | Опровергнута: возвращаются в среднем через 40 мс |
| Появились долгие транзакции | Длительность транзакций в PostgreSQL | Все транзакции короче 100 мс | Опровергнута: долгих транзакций нет |
| Уменьшился размер пула | Конфигурация версий 2.14.0 и 2.15.0 | Размер пула в обеих версиях одинаковый | Подтверждается: в 2.15.0 пул по ошибке уменьшен с 10 до 2 |
Осталась конфигурация. Расчёт показывает, хватает ли двух соединений.
- 62
- запросов в секунду на один экземпляр
- 0,04 с
- сколько каждый запрос держит соединение
- 2,5
- сколько соединений в среднем заняты одновременно
Два соединения меньше, чем 2,5: запросы приходят быстрее, чем освобождаются соединения, и очередь ожидания растёт, пока поток не спадёт. С десятью соединениями те же 2,5 заняли бы четверть пула.
Этот расчёт объясняет все наблюдения сразу: медленно только на api-2, CPU в норме, SQL быстрый, ожидание длинное.
Одна гипотеза выдержала проверку и расчёт. Последняя проверка — исправить и измерить снова.
§7Шаг 6. Проверить исправление
Гипотеза объясняет данные, но окончательно её подтверждает вмешательство. Размер пула 10 возвращают только на api-2, больше ничего не меняют и сравнивают показатели при том же потоке запросов.
| Показатель api-2 | До исправления | Через 15 минут после |
|---|---|---|
| p95 длительности | 9 800 мс | 155 мс |
| p95 ожидания соединения | 8 900 мс | меньше 1 мс |
| Поток запросов | 62 в секунду | 63 в секунду |
| Активные соединения в PostgreSQL от api-2 | 2 | 3–5 |
Длительность вернулась к уровню соседних экземпляров, ожидание соединения исчезло, а поток не изменился. Значит, улучшение вызвано размером пула: нагрузка при этом не снижалась.
Причина подтверждена. Остаётся записать ход расследования так, чтобы его можно было проверить.
§8Отчёт о расследовании
Расследование заканчивается письменным отчётом. Его читают те, кто не участвовал в разборе: руководитель, другие команды, вы сами через полгода. В хорошем отчёте измеренные факты отделены от выводов, и рассуждение можно проверить.
Симптом: с 13:50 часть запросов GET /products выполнялась несколько секунд.
Интервал: 13:50–14:40, экземпляр api-2, версия 2.15.0.
Масштаб: p95 на api-2 вырос с 150 мс до 9 800 мс; медиана и доля ошибок
не изменились; api-1 и api-3 не затронуты.
Наблюдения: в трассах медленных запросов acquire_connection занимает до 2 800 мс,
SELECT — 35 мс; в логах pool_wait_exceeded pool_size=2.
Причина: в версии 2.15.0 размер пула соединений изменён с 10 на 2.
Требуется около 2,5 одновременных соединений, запросы ждут в очереди.
Проверка: размер пула 10 на api-2 → p95 155 мс при том же потоке.
Не выяснено: как изменение попало в конфигурацию и почему его не поймали тесты.
Действия: проверка размера пула в CI; правило оповещения на ожидание соединения.«База данных тормозила»
Звучит правдоподобно, но неверно и непроверяемо: нет ни измерений, ни механизма.
«Запросы ждали соединение до 2,8 с при SQL 35 мс, потому что пул уменьшили до 2»
Названы механизм, измерения и способ проверки.
Строка «Не выяснено» показывает, где кончается расследование, и превращается в задачи. Строка «Действия» закрывает то, что выявил разбор: без правила на ожидание соединения похожий сбой снова первым заметит пользователь, раньше мониторинга.
Скачать бланк отчёта ↓ — те же разделы в пустом виде для практики 1.9.
Первоисточник: Google SRE Book · Effective Troubleshooting ↗
§9Частые ошибки
| Что делают | Что получается | Как правильно |
|---|---|---|
| Закрывают жалобу после одной быстрой проверки | Редкие медленные запросы остаются незамеченными | Смотреть распределение длительностей за интервал жалобы |
| Ищут причину только на панели ошибок | Проблемы длительности не видны, потому что ответы успешные | Проверять и ошибки, и длительности |
| Смотрят только общие показатели сервиса | Сбой одного экземпляра теряется среди исправных | Делить показатели по экземплярам и версиям |
| Считают длинный этап трассы причиной | Находят место ожидания, но не механизм | Выдвигать гипотезы и проверять каждую данными |
| Увеличивают ресурс, не проверив последствия | Проблема переходит в соседнюю систему, например в базу данных | Проверять побочные эффекты исправления |
| Пишут в отчёте «тормозила база» | Вывод нельзя проверить, исправление может быть неверным | Указывать измерения, механизм и способ проверки |
§10Проверьте себя
Упражнение ниже проверяет выбор сигнала. В каждой строке отметьте все подходящие варианты и нажмите «Проверить выбор».
В каждой строке может быть несколько верных вариантов. После проверки под строкой появляется пояснение.
Медиана длительности не изменилась, а p95 вырос в 20 раз. Что это говорит о запросах?
Большинство запросов остались быстрыми, а небольшая часть, не меньше 5%, стала очень медленной. Жалоба «иногда медленно» описывает такую картину.
В трассе SQL-запрос занял 35 мс, а вся операция — 2 900 мс. Доказано ли, что база данных в порядке?
Доказано, что этот SQL-запрос выполнился быстро. Ожидание могло быть до обращения к базе, например при получении соединения. Для вывода о базе в целом нужно проверить и другие медленные трассы.
Экземпляр получает 50 запросов в секунду, каждый держит соединение 60 мс. Хватит ли пула из трёх соединений?
В среднем нужно 50 × 0,06 = 3 одновременных соединения. Пул из трёх будет занят полностью, и любое колебание потока создаст очередь. Нужен запас.
У api-2 p95 равен 9 800 мс, а общий p95 сервиса — 4 200 мс. Как общее число может быть меньше?
Перцентиль считается по объединённой выборке. На api-2 приходится около трети запросов, поэтому 5% самых долгих запросов сервиса — это примерно 15% запросов api-2. Общий p95 оказывается ближе к 85-му перцентилю api-2, чем к его 95-му.
После увеличения пула задержки пропали. Какие ещё данные стоит проверить?
Что поток запросов не снизился одновременно с исправлением и что база данных выдерживает новое число соединений.
§11Шпаргалка
- Жалоба → интервал, операция, частота, идентификатор запроса.
- Метрики показывают масштаб: поток, ошибки, медиана и p95.
- Разбивка по экземплярам и версиям сужает область.
- Трасса показывает, на каком этапе ушло время.
- Длинный этап — место проблемы, механизм ищут гипотезами.
- Каждая гипотеза проверяется данными, которые могут её опровергнуть.
- Исправление подтверждают сравнением при той же нагрузке и проверкой побочных эффектов.
- Отчёт: симптом, масштаб, наблюдения, причина, проверка, что не выяснено, действия.