Distributed tracing: как разобраться, что происходит с запросом внутри микросервисной системы

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

Для этого существует distributed tracing — распределённая трассировка.

В этой статье разберём, зачем она нужна, из чего состоит Trace, что такое Span, как между сервисами передаётся tracing context, какую роль в этом играет OpenTelemetry и где потом смотреть собранные данные.

Предупреждение: Этот материал предназначен для первичного знакомства с технологией распределенной трассировки (Distributed Tracing). В статье верхнеуровнево разбирается архитектура, основные понятия и стандарты. Для глубокой настройки конкретных инструментов в реальных проектах рекомендую обращаться к официальной документации OpenTelemetry и выбранных вами систем хранения данных.

Почему логов и метрик иногда недостаточно

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

Например, метрики показывают, что среднее время ответа выросло с 200 миллисекунд до 5 секунд. Логи в свою очередь могут показать, что в этот момент сервис начал дольше ждать ответа от другого сервиса.

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

Представим интернет-магазин или любое другое условное приложение. Пользователь открывает заказ и нажимает кнопку оплаты. Запрос приходит в api-gateway, оттуда отправляется в order-service. Тот проверяет пользователя через auth-service, сохраняет информацию о заказе и обращается к payment-service, который уже делает запрос во внешний платёжный API.

На схеме всё выглядит достаточно просто:

User
  │
  ▼
API Gateway
  │
  ▼
Order Service
  │
  ├──────► Auth Service
  │
  └──────► Payment Service
                │
                ▼
          Payment API

Теперь представим, что пользователь ждал ответа четыре секунды. Метрика order-service честно покажет нам эти четыре секунды. Но она не объяснит, что происходило внутри этого времени. Возможно, сам order-service выполнялся 50 миллисекунд, auth-service ответил за 20 миллисекунд, а оставшиеся почти четыре секунды ушли на payment-service

Можно пойти смотреть логи payment-service:

10:15:32 Request received
10:15:32 Creating payment
10:15:36 Payment API response received
10:15:36 Payment completed

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

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

Логи хорошо отвечают на вопрос:

Что произошло внутри конкретного компонента?

Если сервис получил ошибку от базы данных, упал с исключением или вернул определённый HTTP-ответ, именно в логах обычно находится подробная информация об этом событии.

Метрики отвечают на другой вопрос:

Что сейчас происходит с системой в целом?

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

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

HTTP GET /orders/123                    4.02 sec
│
├── auth-service                         20 ms
│
├── order-service                       100 ms
│
└── payment-service                     3.85 sec
    │
    └── POST payment-api                3.80 sec

Теперь видно не только то, что запрос был медленным, но и на каком участке возникла задержка. Чтобы понять, как tracing собирает такую структуру, нужно разобраться с двумя основными понятиями — Trace и Span.

Из чего состоит Trace: Trace ID и Span

Trace — это набор связанных операций, которые относятся к одной цепочке выполнения. Span — отдельная операция внутри этой цепочки. Если представить запрос, как поездку из точки А в точку Б, то Trace — это вся поездка, а Span — отдельные участки маршрута.

Пример Trace из Grafana:

У Span есть как минимум:

• время начала

• время окончания

• название операции

• тип операции

• информация о сервисе

• идентификаторы Trace и Span

• родительская связь

• дополнительные атрибуты

• статус выполнения

За счёт времени начала и окончания можно определить продолжительность конкретной операции. Например, обращение к PostgreSQL может быть представлено отдельным Span:

Но самое интересное начинается, когда Span'ы нужно связать друг с другом. Для этого используются идентификаторы. У каждого Trace есть Trace ID. У каждого Span есть собственный Span ID. У дочернего Span также есть Parent Span ID, который указывает на операцию, в рамках которой он был создан. Получается простая модель:

Trace ID
│
├── Span A
│
│   └── Span B
│
└── Span C

Один Trace ID объединяет операции в одну трассировку, а Span ID и parentSpanId позволяют восстановить отношения между отдельными операциями.

Условно можно запомнить так:

Trace ID отвечает на вопрос «к какому Trace относится операция?», а Span ID — «какая именно это операция?»

Реальный Trace из Grafana

Теперь вместо абстрактного примера посмотрим на реальный trace. В качестве примера возьмём данные, полученные из Grafana с OpenTelemetry.

У всех Span в этом примере один и тот же traceId:

1793fc1fb1c24c8f895a5ca50d85870a

При этом внутри Trace находится несколько операций:

35b712eb8dab9475  sql.pollingNotifier.poller
└── d963e559aa1987f2  sql.backend.listLatestRVs
    └── afbe7521e8907dd3  sql.db.transaction
        ├── 9688189f997b053e  sql.db.begin_tx
        ├── bcf00e9ab96c337a  sql.db.tx.query_context
        └── 7e093397ae71266e  sql.db.tx.commit

У корневого sql.pollingNotifier.poller поле parentSpanId пустое, поэтому именно он находится в корне этой цепочки

sql.backend.listLatestRVs ссылается на него через parentSpanId, а sql.db.transaction является дочерней операцией уже для sql.backend.listLatestRVs

Если представить эти связи как дерево:

Trace
1793fc1fb1c24c8f895a5ca50d85870a
│
└── sql.pollingNotifier.poller
    spanId: 35b712eb8dab9475
    │
    └── sql.backend.listLatestRVs
        spanId: d963e559aa1987f2
        │
        └── sql.db.transaction
            spanId: afbe7521e8907dd3
            │
            ├── sql.db.begin_tx
            │   spanId: 9688189f997b053e
            │
            ├── sql.db.tx.query_context
            │   spanId: bcf00e9ab96c337a
            │
            └── sql.db.tx.commit
                spanId: 7e093397ae71266e

Теперь становится хорошо видно, зачем вообще нужны parentSpanId. Самого Trace ID недостаточно.

Он говорит:

эти операции относятся к одному Trace

А родительские связи говорят:

эта операция была выполнена внутри этой операции

Именно так из набора независимых Span получается дерево выполнения.

В нашем примере это можно читать буквально:

1. sql.pollingNotifier.poller запускает операцию.

2. Внутри неё вызывается sql.backend.listLatestRVs

3. Та в свою очередь запускает sql.db.transaction

4. В рамках транзакции выполняются begin_tx, query_context и commit

Дополнительная информация тоже находится непосредственно в Span. Например, sql.db.transaction содержит атрибуты PostgreSQL: драйвер postgres, версию PostgreSQL, уровень изоляции Read Committed, признак read_only и операцию завершения транзакции commit

Как Span показывает время выполнения

Одно из главных преимуществ Span — возможность увидеть продолжительность операции. Корневой sql.pollingNotifier.poller выполнялся примерно 1,17 мс. Внутри него sql.backend.listLatestRVs занял примерно 1,17 мс, а sql.db.transaction — около 1,15 мс.

Внутри транзакции:

sql.db.begin_tx       ~0,37 ms
sql.db.tx.query_context ~0,38 ms
sql.db.tx.commit      ~0,26 ms

Получается примерно такая картина:

sql.pollingNotifier.poller             ~1.17 ms
│
└── sql.backend.listLatestRVs          ~1.17 ms
    │
    └── sql.db.transaction             ~1.15 ms
        │
        ├── begin_tx                   ~0.37 ms
        ├── query_context              ~0.38 ms
        └── commit                     ~0.26 ms

Как трейсы связываются между микросервисами

Теперь возникает вопрос: откуда второй сервис вообще знает, к какому Trace относится входящий запрос?

Ответ — tracing context. Это набор данных, который позволяет следующему компоненту продолжить уже существующую трассировку, а не создать новую.

Когда первый сервис получает запрос, OpenTelemetry либо создаёт новый Trace и корневой Span, либо извлекает контекст уже существующего Trace из входящего запроса. При вызове следующего сервиса текущий контекст передаётся вместе с запросом.

Упрощённо это выглядит так:

Client
  │
  │ HTTP request
  ▼
API Gateway
  │
  │ Trace context
  ▼
Order Service
  │
  │ Trace context
  ▼
Payment Service

HTTP

Для HTTP основным стандартом передачи tracing context является W3C Trace Context. В частности, используется HTTP-заголовок traceparent:

traceparent: 00-abc123...-def456...-01

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

В результате в системе получается примерно такая структура:

Trace ID: 1793fc1fb1c24c8f895a5ca50d85870a

API Gateway
└── Span A

    Order Service
    └── Span B

        Payment Service
        └── Span C

Все три Span относятся к одному Trace, но каждый сервис создаёт собственный Span, описывающий его часть работы.

gRPC

С gRPC принцип тот же, но технически tracing context передаётся через gRPC metadata. gRPC построен поверх HTTP/2, поэтому tracing-инструменты могут использовать metadata для передачи контекста между клиентом и сервером. OpenTelemetry автоматически внедряет tracing context в metadata исходящего RPC-вызова, а на стороне принимающего сервиса извлекает его и создаёт дочерний Span.

Упрощённо поток выглядит так:

Order Service
      │
      │ gRPC call
      │
      │ Metadata:
      │ traceparent: 00-abc123...-def456...-01
      ▼
Payment Service

То есть на уровне приложения разработчик обычно видит обычный gRPC-вызов:

OrderService → PaymentService  (а tracing context путешествует рядом в metadata)

На стороне Payment Service OpenTelemetry извлекает контекст из входящего RPC, связывает новый Span с родительским и получает:

Trace ID: 1793fc1fb1c24c8f895a5ca50d85870a

Order Service
└── Span B
      │
      └── gRPC
          │
          └── Payment Service
              └── Span C

Брокеры сообщений

С брокерами появляется ещё один важный нюанс. Представим, что order-service не вызывает payment-service напрямую, а отправляет событие в Kafka:

Order Service
     │
     │ Kafka message
     ▼
   Kafka
     │
     │ message
     ▼
Payment Service

Здесь HTTP-заголовка traceparent между двумя сервисами уже нет. Более того, обработка сообщения может начаться через несколько секунд после его публикации, когда исходный HTTP-запрос уже давно завершился. Поэтому tracing context необходимо положить непосредственно в сообщение. Например, сообщение может выглядеть так:

Kafka message

Headers:
  traceparent = 00-abc123...-def456...-01

Payload:
  {
    "orderId": "12345",
    "amount": 1000
  }

В Kafka, RabbitMQ, NATS и других брокерах для этого обычно используются message headers / properties. На стороне consumer происходит обратная операция:

Kafka
  │
  │ сообщение + traceparent
  ▼
Payment Service
  │
  ├── извлечение контекста
  │
  └── создание Span

Payment Service извлекает traceparent из заголовка сообщения, восстанавливает tracing context и создаёт новый Span уже как продолжение исходного Trace.

В результате даже асинхронная цепочка остаётся связанной:

При этом Span A не вызывает Span B напрямую, как это происходит при обычном синхронном взаимодействии родительского и дочернего элементов. Между ними находится сквозная передача сообщений (message propagation): один сервис публикует сообщение, а другой позже начинает его обработку.

OpenTelemetry: зачем он нужен

К этому моменту мы уже знаем, что такое Trace, Span и tracing context. Но возникает следующий вопрос: кто всё это создаёт и куда отправляет? Здесь появляется OpenTelemetry.

OpenTelemetry — это набор стандартов, API, SDK и инструментов для сбора data telemetry. В его область входят: traces, metrics, logs. Главная идея — предоставить приложению единый способ создавать и передавать телеметрию, не привязывая код к конкретной системе хранения или визуализации. Например, сегодня компания использует Jaeger, а завтра решает перейти на Grafana Tempo. Не хотелось бы переписывать код всех приложений только из-за смены backend.

Упрощённая архитектура выглядит так:

Приложение создаёт телеметрию через OpenTelemetry. Collector получает её, при необходимости обрабатывает, фильтрует или маршрутизирует, а затем отправляет в нужный backend.

Таким образом, можно разделить задачи:

Где смотреть трейсы: Jaeger и Grafana Tempo

Когда данные собраны, их нужно где-то хранить и анализировать. Для этого существуют tracing backend'ы. Один из наиболее известных вариантов — Jaeger. Другой популярный вариант — Grafana Tempo. Его часто используют вместе с Grafana, особенно если в инфраструктуре уже есть Prometheus для метрик и Loki для логов.

Получается примерно такая схема:

Это позволяет строить полноценный сценарий расследования инцидента:

Как искать ошибки с помощью Trace

Tracing полезен не только для поиска задержек. Допустим, пользователь получил 502:

POST /api/orders
│
└── order-service
    │
    ├── PostgreSQL             OK
    │
    └── payment-service       ERROR
        │
        └── payment-api       HTTP 502

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

После этого уже имеет смысл перейти в логи payment-service и посмотреть подробности:

• какой именно запрос выполнялся

• какой ответ пришёл от внешней системы

• сколько было попыток

• почему сервис вернул ошибку выше по цепочке

Когда трассировка действительно нужна

И под конец хотелось бы сделать небольшую ремарку — когда нужны трейсы, а когда без них вполне можно обойтись.

Трассировка имеет смысл не просто потому, что у нас есть микросервисы и хочется видеть красивые графики в Grafana. Её основная ценность появляется тогда, когда по логам и метрикам уже сложно быстро ответить на вопрос: «что произошло с конкретным запросом и где именно он потерял время?» Особенно это актуально для систем, где один пользовательский запрос проходит через несколько сервисов, базы данных, очереди и внешние API.

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

Кроме того, добавляется немало эксплуатационных задач:

• Контроль объёмов входящего трафика

• Мониторинг коллекторов и хранилищ

• Регулярное обновление компонентов

• Решение проблем, когда сама система наблюдаемости начинает пожирать ресурсы и генерировать проблемы

В небольшой монолитной системе с несколькими endpoint'ами и одной базой обычных логов и метрик зачастую достаточно. Полноценная трассировка начинает окупаться по мере роста количества сервисов, асинхронного взаимодействия, внешних зависимостей и сложности самого запроса. При этом не обязательно сразу собирать и хранить 100% трейсов — выборка позволяет оставить трассировку для наиболее полезной части запросов и контролировать стоимость инфраструктуры.

Хороший критерий здесь простой:

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

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