Трассы: где операция потратила время

§1Операция состоит из этапов

Метрики из главы 1.4 показали, что два запроса из двадцати длились около трёх секунд. Логи из главы 1.5 показывают, что с этими запросами произошло: код 200, исключения нет. Но ни метрика, ни запись о событии не отвечают на вопрос, куда ушли три секунды.

Обработчик /products выполняет три шага: validate проверяет параметры, dependency.wait ждёт ответа зависимости, serialize готовит JSON. Если для каждого шага сохранить момент начала и длительность, станет видно, какой шаг занял время. Такую запись о шагах одной операции называют трассой.

Трасса (trace) — запись о выполнении одной операции в виде связанных этапов на общей шкале времени. Трасса показывает, из каких шагов состояла операция, в каком порядке они шли и сколько длился каждый.

Этап трассы (span) — один интервал работы внутри операции: вызов функции, запрос к базе данных, обращение к другому сервису. У этапа есть имя, время начала, длительность и ссылка на родительский этап.

Английское span означает промежуток, пролёт. В русскоязычной документации слово обычно оставляют без перевода. В тексте справочника используется слово «этап», а в коде и интерфейсах инструментов встретится span.

Трасса полезна уже в одном процессе, как на стенде. Распределённой её называют, когда этапы одной операции выполняются в разных сервисах: API вызывает сервис цен, тот обращается к кэшу, а общая трасса связывает все три.

Первоисточник: OpenTelemetry · Traces ↗

Трасса состоит из этапов. Следующий раздел показывает, что записано в одном этапе.

§2Что хранит этап трассы

В сервисе стенда этап — словарь из трёх полей. Ниже запись медленного запроса из файла events.json.

"spans": [
  {"name": "validate",                    "offset_ms": 0.004,    "duration_ms": 11.168},
  {"name": "dependency.wait (simulated)", "offset_ms": 11.177,   "duration_ms": 3000.058},
  {"name": "serialize",                   "offset_ms": 3011.24,  "duration_ms": 10.419}
]

Поле name — имя этапа: что делал код на этом участке. Поле offset_ms — смещение: сколько миллисекунд прошло от начала запроса до начала этапа. На схеме оно задаёт, где начинается полоса. Поле duration_ms — длительность этапа в миллисекундах. Оно задаёт длину полосы.

Числа в записи согласованы между собой. validate начался почти сразу и длился 11,168 мс, значит, закончился около 11,17 мс, и следующий этап начался на 11,177 мс. Ожидание зависимости длилось 3000 мс и закончилось на 3011,2 мс, где начался serialize. Этапы идут друг за другом без промежутков.

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

Поля этапа — это числа. Чтобы увидеть по ним, где ушло время, этапы рисуют на шкале.

§3Как читать шкалу времени

Этапы трассы рисуют горизонтальными полосами друг под другом на общей оси времени. Из-за ступенчатого вида такую диаграмму называют водопадом (waterfall). Ниже этапы медленного запроса из прогона experiment.py.

Верхняя полоса GET /products — весь запрос. Это корневой этап, все остальные входят в него. Ниже три дочерних этапа. Нажимайте «Следующий этап» и сравнивайте положение полосы с числами под схемой.

Полоса dependency.wait занимает почти всю ширину шкалы: из трёх секунд запроса три приходятся на ожидание зависимости. Проверка параметров и подготовка ответа занимают по 11 мс и на такой шкале видны как тонкие черты.

1234

На стенде в имени этапа указано, что ожидание смоделировано. В настоящем приложении этап database длительностью 3 секунды оставил бы несколько вариантов: запрос ждал свободное соединение, ждал сеть или долго выполнялся сам SQL. Чтобы трасса отвечала точно, крупный этап делят на части: получение соединения, отправка запроса, выполнение, чтение результата.

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

§4Вложенные этапы не складывают

Этапы образуют дерево. Обработчик вызывает функцию загрузки товаров, та отправляет SQL-запрос, и каждый вызов становится этапом внутри этапа вызывающей функции.

Собственное время каждого этапа — время, не занятое дочерними этапами. Здесь оно показывает, что больше всего времени тратит сам запрос к базе.

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

§5Параллельные этапы перекрываются

Обработчик может ждать несколько зависимостей одновременно. В асинхронном Python для этого используют asyncio.gather. Ниже сравниваются последовательный и параллельный вызовы двух зависимостей: кэша на 40 мс и внешнего API на 900 мс.

import asyncio
import time


async def call(name, seconds):
    await asyncio.sleep(seconds)
    return name


async def main():
    start = time.perf_counter()
    await call("redis", 0.04)
    await call("external_api", 0.9)
    print(f"последовательно: {(time.perf_counter() - start) * 1000:.0f} мс")

    start = time.perf_counter()
    await asyncio.gather(call("redis", 0.04), call("external_api", 0.9))
    print(f"параллельно: {(time.perf_counter() - start) * 1000:.0f} мс")


asyncio.run(main())

последовательно: 942 мс
параллельно: 902 мс

На водопаде параллельные этапы начинаются в одной точке и перекрываются. Их длительности тоже не складывают: 40 + 900 мс не равно 900 мс операции.

Цепочку этапов, от которой зависит длительность всей операции, называют критическим путём. Если ускорить кэш с 40 до 5 мс, параллельная операция всё равно будет длиться 900 мс: на критическом пути стоит внешний API. По трассе видно, ускорение какого этапа сократит операцию.

Третий случай обратный: сумма этапов оказывается меньше длительности операции.

§6Промежутки между этапами

Иногда между полосами на водопаде остаётся пустое место: родительский этап длится 800 мс, дочерние в сумме 300 мс, и 500 мс ничем не покрыты.

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

По одному промежутку причину не определить. Добавляют этапы в подозрительные участки кода или смотрят записи логов, которые попадают в этот интервал по времени и request_id. Точно можно утверждать только одно: текущая инструментация этот участок не покрывает.

До сих пор вся операция выполнялась внутри одного HTTP-запроса. Следующий раздел разбирает операцию, которая продолжается после ответа.

§7HTTP-ответ и фоновая задача

Не вся работа выполняется внутри HTTP-запроса. Отчёт строится несколько секунд, и держать всё это время соединение открытым не нужно. Поэтому маршрут POST /reports кладёт задание в очередь и сразу отвечает кодом 202 Accepted — «принято к обработке». Отчёт строит отдельный процесс-обработчик, когда до задания дойдёт очередь.

HTTP-запрос длился 40 мс. Задание ещё 1,2 секунды ждало свободный обработчик, а потом строилось 5 секунд. Пользователь получил отчёт через 6,2 секунды после нажатия кнопки, а метрика длительности API показывает 40 мс.

Из этого примера следуют два вывода. Первый: у фоновой операции три разных времени — ответ API, ожидание в очереди и выполнение задания. Каждое отвечает на свой вопрос, и одно не заменяет другое.

Второй вывод касается связи между частями. Фоновую задачу не рисуют внутри этапа HTTP-запроса, как будто запрос её ждал. Идентификатор трассы кладут в сообщение очереди, и обработчик создаёт свои этапы с тем же trace_id.

Когда одна задача обрабатывает сразу несколько сообщений, в OpenTelemetry используют связи между этапами (span links) вместо отношения «родитель — потомок».

Каждая трасса описывает одну операцию. Последний раздел показывает, как по отдельным трассам судить о сервисе в целом.

§8Одна трасса и весь сервис

Трасса описывает одну операцию. Длинный этап в ней показывает, где время потратил этот запрос, но не говорит, как ведут себя остальные.

Поэтому трассы используют вместе с метриками. Метрика сообщает, что p95 вырос и медленными стали 5% запросов. Затем берут несколько трасс медленных запросов и несколько трасс быстрых и сравнивают этапы. Если у всех медленных длинный один и тот же этап, а у быстрых он короткий, место проблемы найдено.

Сэмплирование трасс (sampling) — сохранение только части трасс. Сервис с десятками тысяч запросов в секунду не может хранить трассу каждого, поэтому сохраняет выборку.

Первоисточник: OpenTelemetry · Sampling ↗

§9Частые ошибки

§10Проверьте себя

§11Шпаргалка