Один сервис инструментировать несложно. Настоящая боль начинается, когда запрос проходит через два сервиса, PostgreSQL и брокер, а трейс рвётся посередине — и вместо цельной картины остаются несвязанные огрызки. Распределённый трейсинг держится на одной вещи: контекст трейса должен пережить каждую границу — сетевую, процессную, асинхронную.
Это вторая статья серии «Наблюдаемость на практике». Если первая была про то, как порождать сигналы, эта — про то, как сшить их в сквозной трейс, что при этом ломается и сколько трейсов имеет смысл хранить. Все числа — с живого стенда: дословный traceparent с провода, два воспроизводимых разрыва, фактические доли сэмплирования.
В статье
- W3C trace context: что летит по проводу
- Проброс через HTTP
- Проброс через PostgreSQL
- Проброс через NATS: переносчик приходится писать руками
- Разрывы: каждая граница чинится отдельно
- Head sampling: решение на входе
- Tail sampling: решение после сбора трейса
- Чтение трейса и две ловушки TraceQL
- Итог
- Документация и первоисточники
W3C trace context: что летит по проводу
Проще всего понять, что такое trace context, посмотрев на него. В сеть стенда поставлен приёмник на netcat, а Go-сервис направлен на него — то, что печатает nc, и есть запрос как он есть:
GET /inventory/SKU-0001 HTTP/1.1
Host: hdr-catcher:8080
User-Agent: Go-http-client/1.1
Traceparent: 00-cbf7140397a7ca78a0ea9dde68a5a0ff-fc5e7dd1460a7338-01
Accept-Encoding: gzipВесь распределённый трейсинг — вот эта строка. Разбор по частям:
| Часть | Значение | Что означает |
|---|---|---|
00 |
версия формата | пока единственная |
cbf7140397a7ca78a0ea9dde68a5a0ff |
trace id, 32 hex | общий для всего трейса |
fc5e7dd1460a7338 |
span id, 16 hex | родительский спан для принимающей стороны |
01 |
флаги | младший бит — «трейс сэмплирован» |
Рядом с traceparent спецификация определяет tracestate — для вендор-специфичных данных; в этом стенде он не используется. Помимо W3C встречается формат B3 (наследие Zipkin), OpenTelemetry умеет оба, но по умолчанию ставит W3C.
Флаг сэмплирования — не мелочь. Именно через него решение «хранить трейс или нет», принятое на входе, доезжает до всех участников: принимающая сторона по умолчанию его наследует. Это и есть parentbased-поведение сэмплеров, о котором ниже.
Пропагаторы в стенде ставятся явно и до проверки, включён ли SDK:
// Пропагаторы ставятся ВСЕГДА, даже при выключенном SDK: они относятся к API
// и стоят копейки. Без них не будет проброса контекста между сервисами.
otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator(
propagation.TraceContext{},
propagation.Baggage{},
))Проброс через HTTP
На принимающей стороне контекст извлекается из заголовков, на отправляющей — записывается в них. В Go обе стороны — это обёртки.
Приём: otelhttp.NewHandler не только создаёт серверный спан, но и достаёт traceparent. Без него любой входящий запрос начинал бы новый трейс, даже если у вызывающего трейс уже был:
// otelhttp на входе даёт серверный спан и метрики HTTP автоматически, и он
// же ИЗВЛЕКАЕТ traceparent из заголовков — без этого запрос от внешнего
// клиента всегда начинал бы новый трейс.
handler := otelhttp.NewHandler(svc.Routes(), "http.server",
otelhttp.WithFilter(func(r *http.Request) bool {
// Проверки живости не нужны ни в трейсах, ни в метриках: они
// составляют большинство запросов и ничего не сообщают.
return r.URL.Path != "/health"
}),
)Отправка: обёртка транспорта. Разница с обычным клиентом — одна строка:
func newInstrumentedHTTPInventory(baseURL string, timeout time.Duration) *httpInventory {
return &httpInventory{
baseURL: baseURL,
client: &http.Client{
Timeout: timeout,
Transport: otelhttp.NewTransport(http.DefaultTransport),
},
}
}В Java всё это делает агент, без правок кода: серверный спан Tomcat и клиентские спаны стандартных HTTP-клиентов он создаёт и связывает сам.
Проброс через PostgreSQL
К базе контекст трейса не «пробрасывается» — SQL-протокол о нём не знает. Спан здесь описывает запрос со стороны приложения: сколько заняло, какая операция, какая таблица.
В стенде это делает Java-агент через инструментирование JDBC:
java-backend GET /inventory/{sku} SERVER 173.6 мс агент, tomcat-10.0
java-backend SELECT orders.inventory CLIENT 152.2 мс агент, jdbc152 мс из 173 — внутри SQL. И это честное число: медленный путь в стенде сделан задержкой в самом запросе, а не в приложении:
String sql = SLOW_SKU.equals(sku)
? "SELECT sku, name, quantity, pg_sleep(0.15) FROM inventory WHERE sku = ?"
: "SELECT sku, name, quantity FROM inventory WHERE sku = ?";Атрибуты спана БД агент заполняет по семантическим конвенциям: db.system, db.operation, db.sql.table, db.statement, db.user. Про db.statement принято предупреждать, что туда могут утечь персональные данные — и это предупреждение стоит уточнить. Вот фактические значения из Tempo:
SELECT sku, name, quantity, pg_sleep(?) FROM inventory WHERE sku = ?
SELECT sku, name, quantity FROM inventory WHERE sku = ?
INSERT INTO orders (order_id, sku, quantity, reserved) VALUES (?, ?, ?, ?) ON CONFLICT (order_id) DO NOTHING
SHOW TRANSACTION ISOLATION LEVELЛитералы обезличены: агент 2.30.0 подставляет вопросительные знаки сам. Санитайзер разбирает итоговый текст SQL и заменяет строковые и числовые литералы, как бы этот текст ни был собран, — значения, вклеенные конкатенацией, он обезличит так же. Риск утечки остаётся там, где санитайзер не срабатывает: он отключён, данные попали не в литерал (имена объектов, комментарии) или текст запроса кладёт в спан ручная инструментация либо библиотека, мимо которой агент не проходит.
Заодно виден SHOW TRANSACTION ISOLATION LEVEL, которого в коде приложения нет: это пул соединений Hikari. Трейс показывает и то, о чём автор кода не думает.
И ограничение, которое стоит держать в голове: трейс живёт в приложении. Внутрь планировщика PostgreSQL он не заглядывает — почему именно этот запрос медленный, отвечает EXPLAIN, а не waterfall.
Проброс через NATS: переносчик приходится писать руками
Асинхронная граница — то место, где трейс рвётся сам собой. У сообщения нет заголовков, похожих на HTTP, по умолчанию, и подписчик начинает новый трейс.
Для HTTP в OpenTelemetry есть готовый переносчик (propagation.HeaderCarrier). Для брокеров его нет: заголовки у каждого свои, и три метода приходится написать самому:
// natsHeaderCarrier переносит trace context в заголовки сообщения NATS. Для HTTP
// такой переносчик есть в готовом виде (propagation.HeaderCarrier), для брокеров
// его пишут руками: заголовки у каждого свои.
type natsHeaderCarrier nats.Header
func (c natsHeaderCarrier) Get(key string) string {
return nats.Header(c).Get(key)
}
func (c natsHeaderCarrier) Set(key, value string) {
nats.Header(c).Set(key, value)
}
func (c natsHeaderCarrier) Keys() []string {
keys := make([]string, 0, len(c))
for k := range c {
keys = append(keys, k)
}
return keys
}Публикация: спан вида PRODUCER плюс инъекция контекста в заголовки.
msg := nats.NewMsg(subject)
msg.Data = payload
if p.propagate {
otel.GetTextMapPropagator().Inject(ctx, natsHeaderCarrier(msg.Header))
}На стороне подписчика извлечением занимается Java-агент — он знает клиент NATS и создаёт спан CONSUMER, присоединяя его к тому же трейсу. Результат — один трейс на весь путь, включая асинхронную ветку:
go-frontend POST /order SERVER вход, otelhttp
go-frontend create_order INTERNAL ручной спан
go-frontend HTTP GET CLIENT otelhttp Transport
go-frontend orders.created publish PRODUCER ручной спан вокруг NATS
java-backend GET /inventory/{sku} SERVER агент, tomcat-10.0
java-backend SELECT orders.inventory CLIENT агент, jdbc
java-backend orders.created process CONSUMER агент, jnats
java-backend INSERT orders.orders CLIENT агент, jdbc
java-backend orders (x2) CLIENT транзакционные запросы пулаОтдельно про ссылки между спанами. Прямая связь parent/child уместна, когда обработка сообщения — продолжение того же запроса, как в стенде. Если же подписчик берёт пачку сообщений от разных производителей, единственного родителя у него нет, и правильная конструкция — ссылки (span links) на несколько спанов-источников. Иначе контекст «размазывается»: один трейс формально есть, но он объединяет несвязанные запросы.
Разрывы: каждая граница чинится отдельно
Теперь главное. Проверять целостность трейса «на глаз» бесполезно: при разрыве трейсы тоже есть, просто их два вместо одного, и в интерфейсе это выглядит почти одинаково. Поэтому в стенде проверка считает спаны и участки, а поломки задаются переменными — чтобы опыт повторялся одной командой.
./scripts/up.sh all otel http # HTTP-клиент без пропагатора
./scripts/trace-probe.sh http
./scripts/up.sh all otel nats # публикация без заголовков
./scripts/trace-probe.sh natsРезультаты различаются, и это самое поучительное:
| Поломка | Что исчезло из трейса запроса | Где нашлась оторванная часть | Что осталось |
|---|---|---|---|
| HTTP-клиент без пропагатора | исходящий HTTP-вызов, серверный спан Java, SELECT |
серверный спан Java и SELECT — отдельный трейс |
асинхронная ветка связана |
| публикация без заголовков | обработка события, INSERT |
обработка события и INSERT — отдельный трейс |
HTTP-ветка цела |
Границы чинятся по отдельности. Работающий проброс через HTTP ничего не говорит о том, что трейс переживёт брокер, — это два разных механизма, и в стенде каждый ломается независимо.
Проверка устроена так, что ни «трейс есть», ни «какого-то участка нет» успехом не считаются. Участок пропадает из трейса и при потере экспорта, и при задержке доставки, и при выключенной инструментации, поэтому разрыв засчитывается, только если обе части одного запроса найдены, лежат в разных трейсах и в каждой ровно ожидаемые участки. Найти оторванную часть по trace context нельзя — его-то и нет, — поэтому части связываются независимыми признаками. Java-часть ищется по метке прогона: Go передаёт её обычным бизнес-заголовком X-Load-Run (не trace context — разрыв он не маскирует), а Java-агент пишет заголовок в атрибут серверного спана. Часть подписчика — по order_id из ответа: Java пишет в лог «заказ сохранён» с этим order_id и своим trace_id, лог лежит в Loki. Дальше сверяется раскладка:
# (часть java в исходном трейсе?, подписчик в исходном трейсе?, участки исходного трейса)
plan = {
"whole": (True, True, ALL),
"http": (False, True, ALL - HTTP_SIDE - {"исходящий HTTP-вызов"}),
"nats": (True, False, ALL - NATS_SIDE),
}[expect]Оторванная часть при этом обязана содержать ровно свои участки: HTTP_SIDE (серверный спан и SELECT) или NATS_SIDE (обработка события и INSERT). Проба проверена и в обратную сторону: на стенде с поломкой HTTP режимы whole и nats отказывают с точным перечнем расхождений.
Отдельно стоит понять, почему при поломке HTTP из трейса исчезает и клиентский спан. Обычный http.Client не только не пишет заголовок — он и спана не создаёт: в Go нет байткод-инструментирования, вся автоматика живёт в обёртках. Убрали обёртку — исчезло и то и другое сразу. В Java та же поломка выглядела бы иначе: агент оставил бы спан на месте.
Head sampling: решение на входе
Head sampling решает судьбу трейса на входе, зная только его идентификатор. Дёшево и слепо: редкий ошибочный трейс имеет ровно те же шансы быть выброшенным, что и рядовой успешный.
Первое, что стоит проверить, — читает ли ваш SDK штатные переменные. Про Go SDK принято думать, что нет; для сэмплера это не подтвердилось:
контроль, без OTEL_TRACES_SAMPLER 200 трейсов из 200 запросов
OTEL_TRACES_SAMPLER=traceidratio, ARG=0.1 27 из 200 (13,5 %)
то же, другой seed нагрузки 28 из 200 (14,0 %)
то же, 1000 запросов 118 из 1000 (11,8 %)Контрольная точка здесь обязательна. Без строки «200 из 200» число 27 ничего не доказывает: трейсы могли просто потеряться, и вывод о сэмплировании был бы выдуман.
Про долю тоже нужна честность. На 200 запросах отклонение от заявленных 10 % заметное — 13,5 и 14 %; на 1000 запросов уже 11,8 %. Разброс биномиального распределения при сотне событий того же порядка, что и сама доля, поэтому проверять сэмплирование на сотне запросов бессмысленно. Заявленная доля — про поток, а не про вашу тестовую сотню.
И ещё одно следствие сэмплирования, которое обнаруживается позже и в другом месте: метрики, посчитанные из спанов, начинают занижать объём в те же разы. Измерено в статье 7 — при доле 10 % занижение оказалось 9,43-кратным.
Tail sampling: решение после сбора трейса
Tail sampling принимает решение, когда трейс уже собран, и потому может смотреть на признаки: была ли ошибка, сколько заняло. Платой служит буфер — Collector держит спаны в памяти, пока ждёт «хвост».
tail_sampling:
# Сколько ждать «хвост» трейса перед решением. Слишком мало — решение
# принимается по неполному трейсу и ошибка в конце запроса будет пропущена;
# слишком много — растёт память.
decision_wait: 5s
num_traces: 50000
expected_new_traces_per_sec: 200
policies:
# 1. Ошибки сохраняем ВСЕ. Это главный смысл tail sampling: редкие
# ошибочные трейсы нельзя отдавать на волю вероятности.
- name: errors
type: status_code
status_code:
status_codes: [ERROR]
# 2. Медленные сохраняем все: в стенде это путь с pg_sleep(0.15).
- name: slow
type: latency
latency:
threshold_ms: 100
# 3. Остальное — десятая часть. Быстрые успешные запросы одинаковы, и
# хранить их целиком незачем.
- name: rest
type: probabilistic
probabilistic:
sampling_percentage: 10Рекомендуемый порядок — tail_sampling до batch: сначала решение, потом упаковка того, что решено сохранить, — так в пачки не попадают спаны, которые всё равно будут отброшены. Сборку трейса batch не разрушает: tail_sampling сам группирует спаны по trace_id, в том числе пришедшие разными пачками. Чтобы обещание «сохраняем все ошибки» выполнялось, важнее два других условия. Первое — все нужные спаны должны доходить до процессора: если что-то отбрасывается раньше (head sampling в SDK, фильтр выше по конвейеру) или приходит позже decision_wait, решение принимается по неполному трейсу. Второе — все спаны одного трейса должны попадать в один и тот же экземпляр Collector: при нескольких экземплярах за обычным балансировщиком трейс расползается по ним, и каждый решает по своему куску; перед tail sampling для этого ставят балансировку по trace_id (loadbalancing-экспортёр). В стенде Collector один, поэтому второе условие выполнено само собой.
Проверять политики надо метриками самого процессора — это точнее любых догадок. Прогон: 400 запросов, состав плана посчитан заранее (34 медленных, 18 «нет товара», 17 отказов бэкенда, 331 быстрый успешный).
otelcol_processor_tail_sampling_count_traces_sampled{policy="errors",sampled="true"} 35
otelcol_processor_tail_sampling_count_traces_sampled{policy="slow",sampled="true"} 81
otelcol_processor_tail_sampling_count_traces_sampled{policy="rest",sampled="true"} 33
otelcol_processor_tail_sampling_global_count_traces_sampled{sampled="true"} 138
otelcol_processor_tail_sampling_new_trace_id_received 405Читается это так:
- политика ошибок отобрала 35 трейсов — ровно столько ошибочных запросов было в плане (18 + 17). Совпадение числа согласуется с тем, что сохранены все ошибки, но не доказывает этого: поимённо, по идентификаторам ошибочных запросов, трейсы не сверялись, и в отобранные могли попасть, например, ошибки проверок готовности вместо части плановых. Сохранение всех ошибок — то, ради чего tail sampling и берут, но проверять его надо по идентификаторам, а не по счётчику;
- вероятностная политика дала 33 из 405, то есть 8,1 % при заявленных 10 % — в пределах разброса;
- политика latency отобрала 81 трейс, хотя намеренно медленных было 34. Наблюдаемое — 81 трейс длиннее 100 мс; разница в 47 не означает, что ровно 47 обычных запросов замедлились: в наборе есть ошибочные запросы и проверки готовности, которые тоже могли превысить порог. Почему именно они оказались длиннее — конкуренция за ядра, GC, ожидание в пуле соединений — это гипотезы: счётчики процессора причин задержки не измеряют. Вывод, который из чисел следует: политика ловит фактическую длительность трейса, а не задуманную;
- сумма по политикам (35 + 81 + 33 = 149) больше глобальной (138), потому что политики пересекаются: медленный ошибочный трейс отбирается дважды;
- 405 новых идентификаторов при 400 запросах — лишние пять от проверок готовности, которые скрипт подъёма делает при старте.
Последний пункт — мелочь, но именно такие мелочи и отличают «числа сошлись» от «числа почти сошлись, и я не знаю почему».
Чтение трейса и две ловушки TraceQL
Tempo ищет трейсы на языке TraceQL, и здесь легко получить правдоподобное неверное число. Обе ловушки поймались в этом стенде.
Ловушка первая: duration — это про спан, а не про трейс. Поиск Tempo возвращает трейсы, а условие проверяет: duration — у отдельного спана, trace:duration — у трейса целиком. Один и тот же прогон, два запроса, в обоих случаях счёт в трейсах:
{span.load.run="tail-1" && duration>100ms} 34 ← трейсов, где есть спан длиннее 100 мс
{span.load.run="tail-1" && trace:duration>100ms} 80 ← трейсов длиннее 100 мсПолитика latency в Collector смотрит на длительность трейса, то есть сопоставлять её надо со второй строкой: 80 против 81 у процессора — сходится. По первой строке вывод получился бы противоположный: «политика отобрала только намеренно медленные», ошибка вдвое.
Ловушка вторая: поиск без окна времени смотрит не туда, а маленький лимит молча обрезает счёт. Без start и end Tempo ищет только по свежим данным, ещё не ушедшим из ingester’ов в хранилище; окно времени включает поиск и по хранилищу. В стенде запрос без окна не нашёл ничего при доехавших трейсах — и это выглядит как потеря данных, хотя данные на месте. Пустота здесь — свойство условий стенда, а не обязательный результат: на свежих трейсах тот же запрос их найдёт.
# Лимит заведомо больше любого прогона стенда. Со значением 200 подсчёт молча
# обрезался ровно на 200, и прогон из 1000 запросов выглядел как «все трейсы на
# месте»: число совпадало с ожиданием только потому, что упиралось в лимит.Это стоило мне ложного вывода: контрольная точка «200 трейсов из 200 запросов» выглядела доказательством исправности счёта, хотя счёт упирался в лимит и показал бы те же 200 при любом реальном числе.
Что касается чтения waterfall в Grafana: широкая полоса — узкое место, и в нашем трейсе она приходится на SELECT с pg_sleep, а не на приложение. Вложенность показывает, что выполнялось последовательно: спаны HTTP GET и SELECT почти совпадают по длительности с родителем, значит распараллеливать здесь нечего — надо ускорять сам запрос.
Итог
- Весь распределённый трейсинг — одна строка заголовка.
traceparentиз четырёх частей: версия, trace id, span id родителя, флаги. Флаг сэмплирования переносит решение «хранить или нет» на всех участников. - Границы чинятся по отдельности. Поломка HTTP уносит серверный спан Java и запрос к БД, поломка брокера — обработку события и запись. Работающий HTTP ничего не говорит про NATS.
- Для брокеров переносчик контекста приходится писать самому. Для HTTP он готовый; для NATS — три метода на десяток строк.
- «Трейс есть» — не критерий. При разрыве трейсов становится больше, а не меньше. Проверять надо число спанов и состав участков.
- Go SDK читает штатные переменные сэмплера — распространённое мнение об обратном для сэмплера неверно. Но фактическая доля на малой выборке пляшет: 13,5 % и 14 % на 200 запросах против 11,8 % на 1000 при заданных 10 %.
- Tail sampling ловит фактическую латентность, а не задуманную. Политика на 100 мс отобрала 81 трейс при 34 намеренно медленных: порог превысили и другие трейсы прогона, а почему — счётчики не говорят.
- Проверять политики надо метриками процессора.
otelcol_processor_tail_sampling_*отвечает точно, сколько какая политика отобрала, — в отличие от догадок по числу трейсов в бэкенде. - TraceQL различает
durationиtrace:duration. На одних данных 34 против 80. Плюс поиск без окна времени ищет только свежие данные, а маленькийlimitмолча обрезает счёт.
Дальше в серии: логи с trace_id и корреляция в Grafana — как от медленного спана дойти до конкретной записи лога и во что обходится нарушение правил Loki про лейблы.
Документация и первоисточники
- W3C Trace Context — формат
traceparentиtracestate. - OpenTelemetry: context propagation — пропагаторы, переносчики, инъекция и извлечение.
- OpenTelemetry Collector: tail sampling processor — типы политик и их параметры.
- OpenTelemetry: sampling — head против tail,
parentbased-сэмплеры. - Grafana Tempo: TraceQL — синтаксис, разница между областями спана и трейса.
- OpenTelemetry: messaging semantic conventions — спаны
PRODUCERиCONSUMER, ссылки вместо родителя. - Стенд, конфиги и сырые выводы —
digital-cookbook/observability/practice-stack.
Комментарии