Симптом полевого разбора звучит так: «один запрос выглядит долгим, но каждая команда называет другой участок». Цена поспешной реакции — оптимизировать pricing, потому что его строка заметна, или увеличить timeout inventory, потому что он самый длинный. Оба действия могут ничего не изменить, если не доказано, как span связаны во времени и какая ветка удерживает ответ до конца.
Ниже нет production-инцидента и реальных latency. Это разбор controlled fixture из revision-модуля: пять span на одной логической шкале 0–240 ms. Именно ограничение делает вывод проверяемым. Мы можем увидеть trace-id, проверить parent/child и посчитать exclusive отрезки. Мы не можем из этой модели объявить, что любой inventory сервис медленный, что в системе есть service map или что collector уже получает такой export.
Фиксируем исходные данные до диагноза
Все ID, имена сервисов, интервалы, header и экспорт ниже синтетические. Они собраны в памяти модуля и не являются trace, URL, HTTP-заголовком, аккаунтом или измерением из системы пользователя.
Fixture строит root gateway.handle от 0 до 240 ms. Его child catalog.lookup занимает 20–220 ms. У catalog два child: pricing.read от 30 до 70 ms и inventory.fetch от 30 до 200 ms. У inventory есть inventory.adapter от 100 до 170 ms. Все пять span имеют один trace-id; каждый non-root span ссылается на существующий parent; каждый child полностью лежит внутри родительского interval. Это наш вход, а не уже найденная причина.
| Span | Parent | Интервал на общей шкале | Duration | Что можно заключить |
|---|---|---|---|---|
gateway.handle | root | 0–240 ms | 240 ms | конец-to-конец duration fixture; включает время catalog |
catalog.lookup | gateway.handle | 20–220 ms | 200 ms | вызван из gateway; не равен отдельным 200 ms после gateway |
pricing.read | catalog.lookup | 30–70 ms | 40 ms | короткая ветвь, которая завершается до inventory |
inventory.fetch | catalog.lookup | 30–200 ms | 170 ms | длинная sibling-ветвь pricing; включает adapter |
inventory.adapter | inventory.fetch | 100–170 ms | 70 ms | вложенная операция; её duration уже входит в inventory |
Сначала проверяем связность, потом смотрим длительность
Первый вопрос не «кто медленный?», а «это один trace?». Ответ в модели двойной: trace-id совпадает у всех записей, а parent-id образует одно дерево. Внешний header fixture создаётся из span gateway и затем разбирается обратно. Catalog получает этот span-id как parent. Такая проверка не доказывает транспорт, но отделяет проблему контекста от проблемы duration. Если trace-id расходится, дальнейшая арифметика бессмысленна: мы сравниваем несколько историй, а не одну.
Второй вопрос — «можно ли сравнить время?». Здесь да, потому что fixture использует одну logical clock и проверяет containment. В настоящем распределённом процессе timestamp могут брать разные хосты, а часы расходятся. Тогда визуальное перекрытие может быть свойством clock skew, а не параллельности. Не надо прятать эту границу под графиком. Перед тем как спорить о десяти миллисекундах между сервисами, нужно знать источник времени и отдельно проверить его в выбранной среде.
# Запускается только проверка учебной модели из этого revision-модуля.
node scripts/upgrade-2020-09.mjs --verify-fixture
# Важные части ожидаемого результата:
traceparentRoundTrip: true
childReceivedCurrentParent: true
criticalPathIsExpected: true
criticalPathExclusiveTimeMatchesRoot: trueКоманда выводит структуру, а boolean assertions делают договор явным. traceparentRoundTrip и childReceivedCurrentParent говорят о context. spanDurationIsEndMinusStart говорит о корректной форме интервалов. criticalPathIsExpected и criticalPathExclusiveTimeMatchesRoot относятся к именно этой модели. Если поменять parent inventory или сделает adapter длиннее своего parent, fixture остановится. Это лучше, чем исправить SVG вручную и потерять смысл примера.
Рисуем waterfall так, чтобы увидеть параллельность
Схема сразу останавливает ошибку «сложим все duration». Нельзя взять 240 + 200 + 40 + 170 + 70 и назвать результатом 720 ms: каждый child лежит внутри ancestor. Нельзя также вычеркнуть catalog, потому что в нём «нет собственной работы»: у него остаются отрезки 20–30 и 200–220 ms, а его child задают порядок пути. Правильный результат для fixture — 240 ms root. Остальные duration нужны, чтобы разложить эти 240, а не увеличить их.
| Факт в trace | Неверный диагноз | Почему он неверен | Следующая проверка |
|---|---|---|---|
inventory длится 170 ms | «adapter добавил ещё 70 ms сверху» | adapter уже вложен в interval inventory | сравнить exclusive inventory и duration adapter |
pricing длится 40 ms | «pricing и inventory надо сложить» | они перекрываются с 30 по 70 ms | проверить, какая ветвь заканчивается последней |
catalog заканчивается в 220 ms | «catalog — единственная причина 240 ms» | root имеет 40 ms вне catalog | посмотреть root exclusive segments |
| один trace-id у всех span | «все реальные границы покрыты» | fixture заранее перечисляет только пять span | сверить ожидаемый список границ в отдельном transport test |
Ищем critical path без двойного счёта
В controlled fixture critical path выбирается не по максимальному числу в таблице, а по последовательности, которая заканчивается последней: gateway.handle → catalog.lookup → inventory.fetch → inventory.adapter. У catalog pricing завершается в 70 ms, а inventory — в 200 ms, поэтому именно inventory удерживает его до финала. У inventory adapter завершает работу в 170 ms, поэтому он остаётся внутри выбранной последовательности. Это учебная модель одной causal tree, не общий алгоритм для любого backend-а.
Чтобы проверить сумму, fixture вычисляет exclusive время. Root имеет 40 ms вне catalog. Catalog имеет 30 ms вне объединения pricing/inventory. Inventory имеет 100 ms вне adapter. Adapter имеет собственные 70 ms. Получаем 40 + 30 + 100 + 70 = 240 ms. Pricing не входит в эту сумму как отдельная последовательная задержка: его 40 ms перекрыты inventory. Теперь можно сказать не «inventory виноват», а точнее: «в учебном дереве поздняя ветвь проходит через inventory; дальше надо проверить его прямой adapter и его own segment».
Header объясняет, почему это один trace
Waterfall не возникает из названий span. Ему нужна корректная цепочка контекста. W3C Recommendation 2020 задаёт traceparent с version 00, trace-id, parent-id и trace-flags. В fixture gateway serializes свой span-id как parent-id; catalog parses эту строку, создаёт child и сохраняет trace-id. Header ниже синтетический; он не отправляется по HTTP, не взят из access log и не содержит данные пользователя.
const rootContext = {
traceId: '4bf92f3577b34da6a3ce929d0e0e4736',
spanId: 'a111111111111111',
traceFlags: '01',
};
// Учебный перенос к следующей границе, не реальный исходящий HTTP-запрос.
const traceparent = createTrainingTraceparent(rootContext);
const received = parseTrainingTraceparent(traceparent);
// Получатель создаёт новый span с parentSpanId = received.parentSpanId.
const catalogSpan = {
spanId: 'b222222222222222',
parentSpanId: received.parentSpanId,
traceId: received.traceId,
};Это также объясняет предел разбора. Если catalog сам создаст новый root, то inventory может быть медленным, но мы не докажем связь с gateway из одного trace. Если header повреждён, parser должен отказаться от этой формы, а не сделать вид, что parent известен. Если всё-таки нужен новый root на границе доверия, связь можно проектировать отдельно; нельзя подменять этот выбор нечаянным форматом ID. Проверка context первична, потому что без неё duration остаются просто числами на разных листах.
Маршрут разбора одного подозрительного пути
- Сформулировать симптом и цену без причины: «лог одной операции есть, но путь до ответа не виден; неверная правка timeout увеличит стоимость следующего сбоя».
- Собрать только один trace и выписать его span с trace-id, span-id, parent-id, start и end. Сначала проверить одну logical history.
- Проверить format incoming context: version 00, ненулевые lowercase IDs и создание нового child span, а не повторный ID родителя.
- Построить waterfall на общей шкале. Отметить overlap, не складывать inclusive parent duration с child duration.
- Найти child, который завершает parent последним, и разложить выбранную цепочку на exclusive сегменты только там, где модель это допускает.
- Выбрать одну следующую проверку: transport propagation, прямой adapter или источник timestamp. Не объявлять виновника до этой проверки.
Исторические и технические ограничения
Trace Context Level 1 к сентябрю 2020 уже был Recommendation, но это стандарт переносимого контекста, а не соглашение о том, какие span автоматически создаст каждый framework. OpenTelemetry в этот период нельзя описывать как полностью стабильный tracing stack: историческая версия спецификации была до 1.0, а стабильность Trace API относится к началу 2021. Поэтому в пакете нет реальной collector-конфигурации и pretend-export в OTLP. Синтетический JSON fixture — удобный объект для проверки связей, а не формат, который обещает принять внешний backend.
Critical path здесь зависит от трёх предпосылок: одно дерево, вложенные интервалы и общая шкала времени. Нарушить любую из них легко: asynchronous job может жить после root, batch может иметь несколько причин, а часы двух машин могут расходиться. Тогда честный результат разбора — «не хватает модели», а не выделенная красная полоса. Это и есть полезное практический опыт М3: он учится связывать события через сервисные границы, но оставляет границы метода рядом с выводом.
Проверяемые источники
- W3C Trace Context Level 1 — Recommendation, 06 February 2020 — историческая Recommendation задаёт поля traceparent версии 00, правила проверки trace-id/parent-id и различает перенос контекста с участием в trace
- OpenTelemetry Specification v0.5.0 — historical changelog — tagged revision от 2 июня 2020 года; версия до 1.0 фиксирует развивающуюся спецификацию, а не готовую кросс-языковую платформу
- OpenTelemetry: Libraries — historical stability note — официальная документация относит стабильность Trace API к началу 2021 года; это редакционная граница, из-за которой статья сентября 2020 не обещает стабильный SDK