Логи, метрики и трассировка: как найти причину медленного запроса

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

Где искать причину? На пути одного запроса работают обратный прокси, API, кэш и база данных. У каждого компонента есть собственное представление о происходящем. Прокси знает, сколько ждал ответ. API знает, какую операцию выполнял. PostgreSQL знает, как исполнил SQL-запрос. По отдельности эти сведения дают неполную картину.

В этой главе мы построим путь от симптома до проверенной причины. Для этого понадобятся три вида данных:

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

Цель диагностики не состоит в том, чтобы найти компонент с самой высокой нагрузкой. Нужно установить причинную цепочку: какое действие замедлилось, почему оно замедлилось и объясняет ли это проблему пользователя.

Система, которую будем исследовать

Возьмём систему заказов из предыдущих глав учебного цикла:

Браузер
   ↓ HTTPS
Caddy
   ↓ HTTP во внутренней сети
FastAPI-приложение orders-api
   ├── Redis: кэширование
   ├── PostgreSQL: заказы
   └── RabbitMQ: задачи для фонового обработчика
                         ↓
                    orders-worker

Здесь важен только путь запроса. Устройство FastAPI, PostgreSQL, Redis и их запуск в контейнерах Docker уже разобраны отдельно.

Запрос GET /orders сначала проверяет кэш. Если подходящего результата нет, API получает заказы из PostgreSQL, формирует JSON и возвращает ответ через Caddy. Другой запрос, POST /orders, может сохранить заказ и передать задачу фоновому обработчику через RabbitMQ.

Это два разных пользовательских результата. Для GET /orders важно время HTTP-ответа. Для POST /orders одного быстрого ответа недостаточно: пользователь ожидает, что фоновое действие тоже завершится. Поэтому наблюдать нужно и синхронный запрос, и продолжение работы после него.

Вывод: сначала определите, что именно считает результатом пользователь. Иначе можно объявить систему исправной по быстрым HTTP-ответам, хотя нужное действие ещё не выполнено.

Почему одного вида данных недостаточно

Представим три сообщения:

Метрика: p95 времени GET /orders вырос с 0,25 до 1,8 секунды.
Трасса: в медленном запросе 1,7 секунды заняло обращение к PostgreSQL.
Лог: SQL-запрос прочитал большую часть таблицы orders.

Каждое сообщение отвечает на свой вопрос.

Лог вида database request took 1700 ms не показывает, затронуты ли десять запросов или половина пользователей. Метрика задержки PostgreSQL не показывает, какой именно SQL-запрос выполнялся. Трасса укажет на долгую операцию обращения к базе, но сама по себе не объяснит, ожидала ли база блокировку, читала ли всю таблицу или отправляла слишком много данных.

Такое разделение соответствует модели наблюдаемости OpenTelemetry. При этом три сигнала полезны только тогда, когда их можно сопоставить по времени, сервису, операции и, для конкретного запроса, по идентификатору трассы.

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

Метрики: как увидеть проблему до чтения отдельных запросов

Метрика представляет число, которое система регулярно измеряет. Для API заказов достаточно начать с четырёх групп:

1. Нагрузка: сколько запросов поступает за секунду.
2. Ошибки: сколько запросов завершается ошибкой.
3. Задержка: как распределено время ответа.
4. Зависимости: что происходит с базой, кэшем, очередью и рабочими процессами.

Допустим, за пять минут orders-api обработал 6000 запросов, из них 36 завершились статусом 5xx. Доля серверных ошибок равна:

Доля ошибок = число ответов 5xx / число всех ответов
            = 36 / 6000
            = 0,006 = 0,6 %

Числитель и знаменатель должны описывать один и тот же набор запросов за одно и то же время. Если считать ошибки только для GET /orders, а все запросы брать по сервису целиком, получится неверный показатель. Статусы 4xx также не следует автоматически смешивать с 5xx: часть из них означает ожидаемый отказ по правилам API.

Почему среднее время ответа обманывает

Пусть 95 запросов выполнились за 100 мс, а пять запросов за 4 секунды. Среднее время составит 295 мс. Оно выглядит приемлемым, хотя каждый двадцатый пользователь ждёт четыре секунды.

Поэтому задержку часто рассматривают через квантили. p95 = 1,8 с означает: в измеренной группе примерно 95 % запросов завершились не медленнее 1,8 секунды, а остальные были медленнее. Это не время «типичного» запроса и не предел, выше которого задержек не бывает.

Чтобы рассчитывать p95 по нескольким экземплярам API, можно собирать длительности в гистограмму. Гистограмма хранит количество наблюдений в диапазонах времени. Затем система мониторинга оценивает квантиль по накопленным диапазонам. В классическом формате Prometheus запрос может выглядеть так:

histogram_quantile(
  0.95,
  sum by (le, route) (
    rate(http_request_duration_seconds_bucket{service="orders-api"}[5m])
  )
)

Здесь:

• http_request_duration_seconds_bucket содержит счётчики попаданий в интервалы;
• rate(...[5m]) оценивает скорость роста счётчиков за пять минут;
• sum by (le, route) объединяет экземпляры сервиса, сохраняя границы интервалов le и маршрут;
• histogram_quantile(0.95, ...) оценивает p95 для каждого маршрута.

Это пример наших проектных имён метрик. Конкретная библиотека инструментирования может назвать их иначе. Границы интервалов надо выбрать с учётом реального времени ответа и целевого порога: слишком широкие интервалы дают грубую оценку p95. Усреднять готовые значения p95 от нескольких экземпляров нельзя, поскольку такое среднее не является p95 объединённого потока запросов. Ограничения и расчёт описаны в документации Prometheus по гистограммам.

Какие разрезы полезны

Для HTTP-метрики пригодятся service, шаблон маршрута, метод и класс ответа. Например:

service="orders-api"
route="/orders/{order_id}"
method="GET"
status_class="5xx"

В метку route нельзя помещать фактический путь /orders/1045, если число заказов не ограничено. Каждый новый идентификатор создаст новую временную серию. То же относится к email, user_id и trace_id. Prometheus прямо рекомендует не использовать неограниченные значения как метки.

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

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

Логи: как восстановить решение программы

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

Пример записи API:

{
  "timestamp": "2026-10-12T10:14:23.184Z",
  "level": "ERROR",
  "service": "orders-api",
  "environment": "production",
  "event": "orders.list.failed",
  "route": "GET /orders",
  "duration_ms": 1804,
  "error_type": "DatabaseTimeout",
  "trace_id": "a0892f3577b34da6a3ce929d0e0e4736",
  "span_id": "f03067aa0ba902b7"
}

Здесь event задаёт устойчивое имя события. По нему проще искать и считать ошибки, чем по произвольной фразе. service и environment указывают источник. route содержит шаблон, а не полный URL с параметрами. trace_id связывает запись с трассой, span_id помогает найти конкретную операцию внутри неё. Сопоставление логов с трассами по этим полям предусмотрено моделью логов OpenTelemetry.

Для нашего приложения полезно записывать:

• начало и итог важных фоновых задач;
• ошибки обращения к зависимостям с типом ошибки и выбранным действием, например retry или fail;
• смену значимого состояния заказа;
• необычные условия, которые помогают понять ветвление программы.

Записывать полный текст каждого SQL-запроса с подставленными значениями, тело каждого HTTP-запроса и все данные пользователя обычно плохая идея. Это создаёт объём, затрудняет поиск и может раскрыть персональные данные или секреты. Токены, пароли, заголовки авторизации и содержимое платёжных данных не должны попадать в диагностические записи.

Уровни логирования тоже имеют смысл. INFO подходит для значимого нормального события, WARNING для неожиданной, но обработанной ситуации, ERROR для операции, которая не дала обещанного результата. Если временный сбой уже повторяется штатным механизмом и не повлиял на пользователя, бездумное повышение каждого повтора до ERROR создаст ложную картину аварии. Но итог неудачных попыток должен быть виден.

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

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

Трассировка: как собрать путь одного запроса

Распределённая трасса представляет путь операции через сервисы. Она состоит из спанов. Спан измеряет одну операцию: обработку HTTP-запроса, обращение к Redis, выполнение SQL через драйвер, публикацию сообщения.

У спана обычно есть имя, время начала и конца, идентификатор трассы, собственный идентификатор, ссылка на родительский спан и атрибуты. Все спаны одного связанного запроса получают общий trace_id.

Для GET /orders трасса может выглядеть так:

GET /orders                         orders-api       1810 мс
├── cache.lookup                    orders-api          6 мс
│   └── Redis GET                   Redis-клиент         5 мс
├── db.acquire_connection           orders-api         24 мс
├── db.load_orders                   orders-api       1720 мс
│   └── PostgreSQL SELECT           PG-клиент        1710 мс
└── response.serialize              orders-api         12 мс

Важно, что PostgreSQL SELECT в такой трассе обычно создаёт инструментирование клиента базы в приложении. Этот спан показывает время, наблюдаемое клиентом. Он не раскрывает автоматически внутренний план PostgreSQL, ожидание блокировки или чтение страниц с диска. За этими сведениями придётся обратиться к данным базы.

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

Как спаны из разных сервисов узнают друг друга

Когда сервис вызывает другой сервис, он передаёт контекст трассы вместе с запросом. Для HTTP обычно используется заголовок traceparent. В нём находятся версия формата, trace_id, идентификатор родительского спана и флаги трассировки. Принимающий сервис извлекает контекст и создаёт собственный спан, связанный с вызвавшим его. Формат и механизм объяснены в документации OpenTelemetry.

Если контекст не передать, второй сервис создаст отдельную трассу. Обе части будут существовать, но связь между ними потеряется.

Идентификаторы полезны и в логах. Открыв медленную трассу, инженер берёт trace_id и ищет события только нужного запроса. Если трасса не сохранилась из-за выборочного сбора, отдельный request_id в ответе, логах и внутренних вызовах остаётся полезным способом поиска. Идентификатор не должен считаться средством авторизации.

Что меняется на границе очереди

Сообщение RabbitMQ обрабатывается позже и, возможно, другим процессом. Контекст нужно поместить в заголовки сообщения при публикации и извлечь в обработчике. Тогда публикацию и обработку можно сопоставить.

Однако очередь не всегда образует простую цепочку «родитель → ребёнок». Один обработчик может получить пакет сообщений, а одно сообщение может быть доставлено повторно. В таких случаях модель трассировки использует связи между спанами: они показывают причинное отношение без притворства, что операции являются одним непрерывным вызовом. Это различие описывают семантические соглашения OpenTelemetry для сообщений.

Время от публикации до начала обработки следует измерять отдельно. Если API ответил за 120 мс, а сообщение лежало в очереди девять минут, одна лишь длительность HTTP-трассы проблему не обнаружит.

Вывод: трасса показывает путь и место задержки. Чтобы она пересекала границы процессов, необходимо передавать контекст; чтобы объяснить найденную задержку, нужны сведения самого зависимого компонента.

Как добавить наблюдаемость в приложение заказов

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

Шаг 1. Дайте компонентам устойчивые имена

API должен сообщать, что он orders-api, а обработчик очереди, что он orders-worker. К каждому сигналу полезно добавлять окружение и версию выпуска. Тогда можно проверить, началась ли проблема сразу после конкретного развёртывания и касается ли она всех экземпляров.

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

Шаг 2. Соберите трассы на границах

Для Python существует автоматическое инструментирование OpenTelemetry. Оно может создавать спаны поддерживаемых HTTP-фреймворков и клиентских библиотек. Пример начальной настройки:

pip install opentelemetry-distro opentelemetry-exporter-otlp
opentelemetry-bootstrap -a install

OTEL_SERVICE_NAME=orders-api \
OTEL_TRACES_EXPORTER=otlp \
OTEL_METRICS_EXPORTER=none \
OTEL_LOGS_EXPORTER=none \
OTEL_EXPORTER_OTLP_PROTOCOL=grpc \
OTEL_EXPORTER_OTLP_ENDPOINT=http://otel-collector:4317 \
opentelemetry-instrument uvicorn app.main:app --host 0.0.0.0 --port 8000

OTEL_SERVICE_NAME задаёт имя источника трасс. Адрес otel-collector:4317 предполагает, что Collector доступен во внутренней сети и принимает OTLP по gRPC. Здесь метрики и логи намеренно собираются отдельными путями: HTTP-метрики может считывать Prometheus, а структурированные логи может забирать сборщик контейнерных логов. Это пример схемы, а не обязательный набор продуктов.

Сам Collector принимает телеметрию, может обработать её и отправить в хранилище трасс. Его обычная схема состоит из приёмника, обработчиков и экспортёра. Роль этих частей описана в документации OpenTelemetry Collector.

Автоматическое инструментирование показывает вызовы библиотек, но не знает, почему приложение вызвало их. Для важной операции создайте спан вручную:

from opentelemetry import trace

tracer = trace.get_tracer("orders-api")


def load_orders(customer_id: int):
    with tracer.start_as_current_span("orders.load") as span:
        span.set_attribute("app.orders.source", "postgresql")
        return repository.load_recent_orders(customer_id)

Имя orders.load описывает действие. Атрибут app.orders.source помогает отличить обращение к базе от ответа из кэша. Сам customer_id здесь нужен функции, но не обязан попадать в атрибут спана. Пример ручных спанов соответствует Python API OpenTelemetry.

Перед публикацией сообщения контекст можно записать в его заголовки, а при получении извлечь:

from opentelemetry import trace
from opentelemetry.propagate import inject, extract

tracer = trace.get_tracer("orders-worker")

# Отправитель
headers = {}
inject(headers)
publish_order_task(payload, headers=headers)

# Получатель
context = extract(message.headers or {})
with tracer.start_as_current_span("orders.confirm", context=context):
    confirm_order(message.body)

publish_order_task и confirm_order здесь обозначают функции нашего приложения. Конкретный клиент RabbitMQ должен сохранить переданные заголовки сообщения без переименования. Для пакетной обработки и повторных доставок связи спанов могут потребовать иной модели; главное, не терять исходный контекст и идентификатор самой задачи.

Шаг 3. Определите небольшое число полезных метрик

Для orders-api начальный набор может быть таким:

Счётчик растёт при каждом событии; после перезапуска процесса он начинается заново, поэтому скорость изменения считают функцией вроде rate(). Измеритель текущего значения может расти и уменьшаться. Гистограмма сохраняет распределение длительностей для расчёта квантилей и доли операций ниже заданного порога.

Названия в таблице предложены для нашего приложения. Перед добавлением каждой метрики спросите: какое решение мы примем по её изменению? Например, рост db_pool_wait_seconds ведёт к проверке размера пула и длительности занятых соединений. Рост числа промахов кэша при одновременном росте задержки базы заставляет исследовать TTL, вытеснение и нагрузку на PostgreSQL.

Шаг 4. Проверьте связь сигналов до аварии

В тестовом окружении выполните один запрос и проверьте цепочку:

HTTP-запрос → спан orders-api → дочерний спан зависимости
            → лог с тем же trace_id → метрика соответствующего маршрута

Затем выполните действие с фоновой задачей и убедитесь, что обработчик получает контекст сообщения. Отдельно проверьте, что при ошибке сохраняются тип ошибки, место сбоя и результат повторной попытки, а секреты не записываются.

Вывод: работоспособность телеметрии проверяется поиском конкретного тестового запроса от начала до конца. Сам факт, что Collector или панель мониторинга запущены, ничего не доказывает.

Разбор происшествия: GET /orders стал медленным

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

1. Подтверждаем симптом

График показывает, что за десять минут p95 для GET /orders вырос с 0,25 до 1,8 секунды. Нагрузка осталась примерно прежней: около 20 запросов в секунду. Доля 5xx поднялась с 0,1 до 0,6 %.

Это говорит о деградации конкретного маршрута. Но пока неизвестно, что замедлилось. Рост времени CPU на сервере может быть причиной, следствием или совпадением. Начинать с него как с готового объяснения рано.

2. Находим один медленный запрос

В журнале Caddy находим запрос с длительностью 1,84 секунды. Его трасса в orders-api длится 1,81 секунды. Разница мала: основная задержка находится после передачи запроса приложению, а не в установлении соединения с прокси. Это вывод для этого запроса; его ещё нужно подтвердить на других медленных трассах.

В трассе:

Трасса сузила область поиска до обращения к базе. Но фраза «виноват PostgreSQL» пока неточна: долгим может быть запрос, ожидание блокировки, передача большого результата или работа клиента.

3. Проверяем гипотезу данными базы

В логах приложения находим шаблон SQL-операции без пользовательских значений:

SELECT id, status, total, created_at
FROM orders
WHERE customer_id = $1
ORDER BY created_at DESC
LIMIT 20;

Статистика исполнения показывает, что именно эта группа запросов стала дорогой. Если в PostgreSQL включено расширение pg_stat_statements, можно посмотреть число вызовов и суммарное время:

SELECT calls, mean_exec_time, total_exec_time, query
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 10;

calls означает число исполнений. mean_exec_time показывает среднее время одного исполнения в миллисекундах. total_exec_time показывает суммарное время группы. Большое суммарное время может получиться как из редких очень долгих, так и из частых умеренно долгих запросов, поэтому смотрим оба значения. Возможности расширения описаны в документации PostgreSQL.

Затем исследуем план запроса на подходящих данных:

EXPLAIN (ANALYZE, BUFFERS)
SELECT id, status, total, created_at
FROM orders
WHERE customer_id = 42
ORDER BY created_at DESC
LIMIT 20;

Предположим, план показывает последовательный просмотр миллионов строк и сортировку большого промежуточного результата ради последних двадцати заказов одного клиента. Это объясняет высокое время: базе приходится найти подходящие строки в большом объёме данных и только затем выбрать первые двадцать.

Для такого шаблона возможное решение:

CREATE INDEX CONCURRENTLY orders_customer_created_idx
ON orders (customer_id, created_at DESC);

Индекс позволяет быстрее найти заказы клиента уже в нужном порядке. Но добавлять его только по одному медленному примеру нельзя. Нужно проверить реальные планы и частоту запросов, объём таблицы, стоимость дополнительной записи в индекс, способ безопасного создания и результат после изменения. Основы индексов и EXPLAIN подробно разобраны в материале о PostgreSQL.

EXPLAIN (ANALYZE) исполняет запрос, а не только строит план. Даже для SELECT он может создать заметную нагрузку. Для изменяющих данные операций последствия ещё серьёзнее. BUFFERS помогает увидеть обращения к страницам данных, но не заменяет измерение полного клиентского времени. Эти ограничения прямо указаны в документации команды EXPLAIN.

4. Проверяем, что это действительно причина

После изменения сравниваем на том же маршруте и сопоставимой нагрузке:

• план и время SQL-операции;
• p95 и p99 HTTP-ответа;
• число промахов кэша;
• долю ошибок;
• использование ресурсов PostgreSQL;
• медленные трассы.

Допустим, время SQL снизилось с 1,7 секунды до 35 мс, а p95 GET /orders вернулся к 0,26 секунды. Совпадение изменения на уровне базы и пользовательского показателя подтверждает гипотезу гораздо сильнее, чем один улучшившийся запрос.

Вывод: трасса указала место потери времени; статистика и план базы объяснили механизм; повторное измерение подтвердило, что изменение устранило пользовательский симптом.

Контрпример: долгий спан базы не всегда означает плохой SQL

Теперь представим ту же трассу с долгим обращением к PostgreSQL, но план запроса быстрый. Что проверить?

Сначала разделите ожидание соединения и выполнение SQL. Если 1,5 секунды уходит на получение соединения из пула, оптимизация индекса почти ничего не изменит. Нужно выяснить, почему соединения заняты: много одновременных запросов, слишком длинные транзакции, утечка соединений или слишком малый пул.

Если соединение получено быстро, проверьте состояние самой базы. pg_stat_activity показывает выполняющиеся операции и события ожидания:

SELECT pid, state, wait_event_type, wait_event
FROM pg_stat_activity
WHERE state <> 'idle';

wait_event_type = 'Lock' у нужной операции направляет проверку к блокировкам и транзакциям. Отсутствие ожидания блокировки не доказывает отсутствие проблемы: возможны медленный ввод-вывод, большой результат, сетевые задержки и другие причины. Смысл полей pg_stat_activity описан в документации PostgreSQL.

Похожая ловушка есть с Redis. Допустим, клиентский спан Redis GET длится 250 мс, а SLOWLOG пуст. Это не противоречие: Redis SLOWLOG измеряет время выполнения команды внутри сервера, не включая весь путь общения с клиентом. Тогда следует проверить сеть, пул соединений, перегрузку клиента и размер передаваемого значения.

Вывод: название медленного спана указывает на границу операции, которую нужно исследовать. Оно не доказывает, какой механизм внутри этой границы сломался.

Второй сценарий: HTTP быстрый, а результат не приходит

Пользователь отправил POST /orders. API вернул успешный ответ за 140 мс, но подтверждение заказа не появилось. Графики HTTP в норме. Если смотреть только на них, проблема останется невидимой.

Метрики очереди показывают, что число готовых к выдаче сообщений растёт, а скорость завершения задач падает. Здесь полезно различать:

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

RabbitMQ предоставляет такие показатели через интерфейс мониторинга и экспортёр метрик; их значение и ограничения описаны в руководстве RabbitMQ.

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

Трасса и лог конкретной задачи показывают следующую картину:

POST /orders                 140 мс
publish order.confirm         12 мс
... сообщение ждёт в очереди 8 минут ...
orders-worker: confirm_order  20 с
└── вызов внешнего сервиса    timeout

Очередное сообщение может прийти повторно после сбоя обработчика. Для диагностики нужны устойчивый task_id, число попыток, время создания задачи и итог каждой попытки. При этом task_id подходит для поиска в логах, но не для метки Prometheus из-за неограниченного числа значений.

Пользовательский показатель здесь должен описывать не только HTTP-ответ, но и время от принятия заказа до подтверждения. Его можно измерять по времени создания и завершения задачи:

Время завершения заказа = время появления подтверждения − время принятия заказа

Если заказ принят в 10:00, а подтверждён в 10:09, показатель равен девяти минутам, даже если HTTP-запрос длился 140 мс. Это измерение помогает увидеть сбой, который не проявляется в статусах API.

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

Что может исказить диагностику

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

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

Инструментированы не все операции. Большой пустой промежуток внутри HTTP-спана может скрывать ожидание пула соединений, блокирующий код или собственную функцию приложения. Добавляйте ручной спан там, где он позволяет различить проверяемые гипотезы.

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

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

Сама телеметрия тоже может теряться. Если приложение не может отправить спаны в Collector, пропавшая трасса не говорит о нормальной работе приложения. Контролируйте ошибки экспорта и состояние самого Collector: он предоставляет внутренние метрики приёма и отправки данных.

Шум затрудняет поиск. Трасса из сотен малозначимых спанов и поток одинаковых логов способны скрыть важный переход. Полезность сигнала проверяется вопросом: какое предположение он позволит подтвердить или отвергнуть?

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

Практический порядок разбора

Когда жалоба уже поступила, двигайтесь от пользовательского симптома к проверяемой причине:

1. Назовите нарушенный результат. Медленный GET /orders, ошибка сохранения заказа или задержанное подтверждение заказа требуют разных измерений.
2. Определите масштаб по метрикам. Выясните время начала, затронутые маршруты, версии, экземпляры, нагрузку и долю ошибок.
3. Выберите несколько характерных трасс. Сравните медленные и обычные запросы, найдите место, где их пути или длительности расходятся.
4. Откройте связанные логи. Ищите по trace_id, а для фоновой работы также по task_id. Уточните ошибку и действие программы.
5. Проверьте зависимый компонент его собственными средствами. Для PostgreSQL это статистика, ожидания и план; для Redis это клиентское время и серверная диагностика; для RabbitMQ это состояния сообщений и скорость обработчиков.
6. Сформулируйте гипотезу до изменения системы. Например: «после роста таблицы запрос стал читать большую часть orders, поэтому p95 списка заказов вырос».
7. Измените один существенный фактор и проверьте результат. Сравните пользовательский показатель и показатель предполагаемой причины при сопоставимой нагрузке.

Если трасса показывает долгий вызов базы, а метрики базы спокойны, это повод углубить измерение, а не выбрать любимое объяснение. Если база ускорилась, но p95 HTTP не изменился, найденная проблема могла быть побочной.

Итог

Логи, метрики и трассировка становятся полезны вместе, когда между ними есть общие имена сервисов, время, маршрут и идентификаторы операций.

Метрики отвечают, что ухудшилось и для какой доли запросов. Трассировка показывает, где прошло время конкретной операции. Логи и средства зависимого сервиса помогают установить, почему это место стало медленным или ошибочным. После исправления нужно вернуться к пользовательскому показателю: именно он показывает, решена ли исходная проблема.

Для системы заказов это означает наблюдать не только время ответа orders-api, но и выполнение SQL, поведение кэша, состояние очереди и завершение фоновой задачи. Тогда между сообщением пользователя «заказ не появился» и технической причиной возникает проверяемый путь, а не цепочка догадок.