diff --git a/editorial/agent-rewrites/264.json b/editorial/agent-rewrites/264.json index 96d5dbb..038b5e3 100644 --- a/editorial/agent-rewrites/264.json +++ b/editorial/agent-rewrites/264.json @@ -1,7 +1,7 @@ { "index": 264, "slug": "editorial-2020-09-practice-tracing-basics", - "title": "Трассировка запроса: как найти задержку по одному trace", - "excerpt": "Разбираем разорванный trace: как передать trace context через границу сервисов, связать parent и child span, прочитать waterfall и остановиться, если данных недостаточно.", - "contentHtml": "
Сервис отвечает успешно, но один и тот же endpoint то укладывается в 40 миллисекунд, то ждёт почти секунду. В логах есть записи gateway, catalog и inventory. Связать их с одним запросом нельзя: у строк разные идентификаторы, а время запуска не совпадает. Цена ошибки — менять timeout, retry или запрос к базе вслепую. Можно убрать один видимый симптом и оставить настоящую задержку на следующем участке.
\nТезис. Трассировка помогает не потому, что добавляет ещё один лог. Она связывает операции в дерево: общий trace-id описывает одну историю, span-id описывает отдельную операцию, а parent-id показывает прямую связь. На транспортной границе сервис должен передать контекст, создать свой span и передать уже его как родителя следующей операции. Если граница не передала контекст, waterfall распадается и вывод о причине задержки становится гипотезой.
Представим учебный запрос к каталогу. Gateway принимает HTTP-запрос и создаёт span gateway.handle. Затем он вызывает catalog. Catalog получает trace context, создаёт catalog.lookup с родителем gateway и запускает два дочерних участка: pricing.read и inventory.fetch. Inventory, в свою очередь, вызывает адаптер.
В такой модели один trace содержит пять span. У всех один trace-id. Каждый span имеет собственный span-id. У дочернего span parent-span-id равен идентификатору операции, которая его вызвала. Эта связь важнее красивого имени сервиса: она показывает, кто породил ожидание.
| Симптом | Причина | Проверка | Действие |
|---|---|---|---|
| Строки лога нельзя собрать в запрос | Компоненты создают разные trace-id | Сравнить trace-id у входящего и исходящего span | Передавать контекст через границу |
| Child span существует, но parent неизвестен | Сервис создал span без текущего контекста | Проверить parent-span-id и порядок времени | Создавать child из извлечённого context |
| Waterfall показывает невозможное перекрытие | Сложили вложенные duration | Проверить интервалы start/end и вложенность | Считать critical path, а не сумму всех span |
| Trace пропал после proxy или очереди | Carrier не прошёл через транспорт | Сравнить header до отправки и после получения | Проверить конкретный adapter или carrier |
| Задержка есть, но причина не видна | Нужный участок не создаёт span или не попал в sampling | Проверить покрытие, sampling и экспорт | Не объявлять виновника без следующего сигнала |
Внутри одного процесса контекст можно передать аргументом функции или средствами SDK. После HTTP-вызова, сообщения очереди или фоновой задачи получатель сам его не угадает. Для HTTP используется carrier. Один распространённый вариант — W3C traceparent. В версии 00 он содержит version, trace-id, parent-id и trace-flags.
traceparent: 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01\n\n// gateway отправляет свой span как parent:\nconst outgoing = \\`00-\\${traceId}-\\${gatewaySpanId}-01\\`;\n\n// catalog создаёт новый span, но сохраняет traceId:\nconst catalogSpan = {\n traceId,\n spanId: '00f067aa0ba902b7',\n parentSpanId: gatewaySpanId,\n};\nКод выше — учебный пример. Он не открывает сеть, не заменяет SDK и не доказывает, что конкретный proxy сохранит заголовок. Его задача — показать два инварианта: trace-id остаётся тем же, а текущий span-id меняется на каждой участвующей границе.
\nПолучатель должен проверить формат до использования. Trace-id и parent-id имеют фиксированную длину и не могут быть нулевыми. Неверный header нельзя принимать как доверенный контекст. Если header отсутствует, сервис начинает новую историю или применяет явно заданную политику. Нельзя молча приписывать запрос к случайному trace.
\nПусть в учебном примере gateway.handle идёт от 0 до 240 миллисекунд, catalog.lookup — от 20 до 220, pricing.read — от 30 до 70, а inventory.fetch — от 30 до 200. Внутри inventory адаптер занимает интервал от 100 до 170 миллисекунд. Эти числа придуманы для объяснения и не являются измерениями production.
Pricing и inventory стартуют одновременно. Поэтому конец запроса определяется веткой inventory, а не суммой 40 и 170 миллисекунд. Время parent включает время дочерних span. Если сложить 240, 200, 40, 170 и 70, получится число, которое не описывает ни задержку запроса, ни critical path. Для анализа нужно найти цепочку зависимых операций и отдельно посмотреть участки parent, которые не закрыли child.
\nНаличие trace-id не означает, что история полная. Sampling может отбросить запрос. Экспорт может задержаться или завершиться ошибкой. Уровень логирования может скрыть событие. Прокси может удалить заголовок. Очередь может использовать другой carrier. Для каждой границы нужна отдельная проверка.
\nТрассировка также не показывает автоматически бизнес-причину. Длинный span базы может быть следствием блокировки, плохого плана, холодного соединения или внешнего лимита. Название inventory.fetch не различает эти случаи. Следующий шаг должен читать собственный сигнал участка: план запроса, размер очереди, код внешнего ответа или время подключения.
Не помещайте в trace context пароль, токен, email, полный URL с параметрами или тело запроса. Trace-id служит для связи операций. Доступ к trace и правила хранения должны учитывать, что span attributes часто попадают в журналы и хранилища наблюдаемости.
\nРазбор готов, если другой инженер может по одному запросу воспроизвести четыре факта: все нужные span имеют общий trace-id; каждая транспортная граница показывает отправленный и полученный context; parent-child связи согласуются с временем; критический путь объясняет задержку без сложения перекрывающихся интервалов. Для найденного участка существует следующий проверяемый сигнал.
\nЕсли хотя бы один факт неизвестен, результатом должна быть запись «причина не доказана» и конкретный следующий fetch, лог или измерение. Это не провал метода. Это правильная граница вывода: trace показывает путь запроса, но не разрешает придумывать отсутствующие данные.
\ntraceparent, правилами propagation и обработкой контекста.После условного выката дежурный инженер получает два одинаковых запроса: один завершился за 40 миллисекунд, другой ждал почти секунду. Gateway, catalog и inventory записали события, но их нельзя уверенно собрать в одну историю: идентификаторы различаются, а времена запуска не совпадают. Это учебный incident, поэтому числа ниже придуманы для проверки метода, а не выданы за замер production.
\nПервое действие — взять один запрос и сравнить контекст на каждой границе: какой traceparent отправил gateway, что извлёк catalog и какой span стал родителем следующего вызова. Цена ошибки здесь практическая: если сразу увеличить timeout или retry, можно скрыть потерю контекста и перенести задержку дальше. Задача статьи — показать, какие факты trace доказывает, а где нужен следующий сигнал.
Разберём контролируемую схему. Gateway принимает HTTP-запрос и создаёт корневой span gateway.handle. Он вызывает catalog. Catalog создаёт catalog.lookup как дочернюю операцию и параллельно запускает pricing.read и inventory.fetch. Inventory вызывает inventory.adapter. Так получается пять span в одной простой trace-истории.
trace-id идентифицирует всю историю, а span-id — одну операцию. У каждого span может быть не более одного parent в обычном дереве, но дочерних span может быть несколько. Поэтому имя сервиса ещё ничего не доказывает: нужно проверить идентификаторы, parent-child связь и интервалы start/end. Ниже приведены только значения учебной модели.
| Симптом | Возможная причина | Проверка | Действие |
|---|---|---|---|
| Строки нельзя собрать в один запрос | На границе создан новый root или потерян context | Сравнить trace-id во входящем и исходящем span | Проверить extract/inject и carrier |
| Child есть, но parent неизвестен | Span создан без активного Context | Сверить parent-span-id и момент создания | Создавать child из извлечённого Context |
| Сумма duration намного больше ответа | Вложенные или параллельные интервалы посчитали повторно | Сопоставить start/end и перекрытия | Искать критический путь, а не сумму строк |
| Trace обрывается после proxy или очереди | Carrier не прошёл через транспорт либо сработал sampling | Сравнить заголовок до отправки и после получения | Проверить конкретную boundary и полноту выборки |
| Самый длинный span не объясняет ответ | Он перекрывается с поздней веткой или слишком широк внутри себя | Найти последний end и следующий внутренний сигнал | Проверить адаптер, очередь или внешний ответ |
Внутри процесса Context можно передать средствами SDK. После HTTP-вызова или сообщения очереди получатель не угадывает его по имени сервиса. Propagator записывает context в carrier, например в HTTP-заголовки, а принимающая сторона извлекает его обратно. Это две разные операции: inject выполняет отправитель, extract — получатель.
\nВ W3C Trace Context заголовок traceparent версии 00 имеет четыре поля: version, trace-id, parent-id и trace-flags. Для trace-id используется 32 строчных шестнадцатеричных символа, для parent-id — 16; нулевые значения недействительны. При некорректном контексте реализация должна его проигнорировать, а решение о новой root-истории принимает политика инструмента.
Порядок для исходящего HTTP-вызова важен. Получив запрос, catalog сначала извлекает remote context и создаёт свой server span как child. Перед вызовом inventory он создаёт span исходящего обращения, обычно client span, делает его текущим и только потом inject-ит его context в новый carrier. Inventory извлекает carrier и создаёт свой server span. Тогда в исходящем заголовке меняется parent-id текущего вызова, а trace-id сохраняется.
\ntraceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01\n\n// Схема операций SDK, без сетевого вызова:\nconst incoming = propagator.extract(request.headers);\nconst serverSpan = tracer.startSpan('catalog.lookup', { parent: incoming });\nconst outgoing = tracer.startSpan('inventory.fetch', { parent: serverSpan });\npropagator.inject(outgoing.context(), requestToInventory.headers);\n\n// На стороне inventory:\nconst remote = propagator.extract(requestToInventory.headers);\nconst inventorySpan = tracer.startSpan('inventory.server', { parent: remote });\nЭтот фрагмент показывает последовательность, но не является готовым API для конкретного языка: названия методов у SDK различаются. Он также не обещает, что proxy сохранит заголовок. Для воспроизводимой проверки нужно записать carrier непосредственно перед отправкой и сразу после extract на стороне получателя.
\nВ учебной модели root gateway.handle идёт от 0 до 240 мс, catalog.lookup — от 20 до 220, pricing.read — от 30 до 70, а inventory.fetch — от 30 до 200. Внутри inventory адаптер занимает интервал от 100 до 170 мс. Pricing и inventory стартуют одновременно, поэтому их duration перекрываются.
Inclusive duration родителя включает работу children. Если сложить 240, 200, 40, 170 и 70, получится 720 мс, хотя root завершается за 240. Это не задержка запроса. Правильный вопрос другой: какая последовательность интервалов удерживает ответ до конца? В этой модели поздний child catalog — inventory, а pricing остаётся параллельной веткой, не входящей в критический путь после 70 мс.
\nДля этой простой шкалы критическая цепь раскладывается так: 0–20 мс до catalog, 20–30 мс до его children, 30–100 мс до adapter, 100–170 мс работы adapter, 170–200 мс после adapter, 200–220 мс после children и 220–240 мс до ответа. Сумма этих неперекрывающихся участков равна 240 мс. Это разложение относится к выбранной модели; для асинхронных links, retry и разных часов нужен другой анализ.
\nНиже — самодостаточный пример для Node.js без внешних пакетов. Он проверяет duration, наличие parent и то, какой child catalog завершился последним. Код не строит полноценный trace backend и не учитывает асинхронные links; его граница намеренно ограничена одной согласованной шкалой.
\nconst spans = [\n { name: 'gateway.handle', parent: null, start: 0, end: 240 },\n { name: 'catalog.lookup', parent: 'gateway.handle', start: 20, end: 220 },\n { name: 'pricing.read', parent: 'catalog.lookup', start: 30, end: 70 },\n { name: 'inventory.fetch', parent: 'catalog.lookup', start: 30, end: 200 },\n { name: 'inventory.adapter', parent: 'inventory.fetch', start: 100, end: 170 },\n];\n\nconst byName = new Map(spans.map((span) => [span.name, span]));\nconst duration = (span) => span.end - span.start;\nconst invalid = spans.filter((span) => {\n const parent = span.parent ? byName.get(span.parent) : null;\n return parent && (span.start < parent.start || span.end > parent.end);\n});\nconst catalogChildren = spans.filter((span) => span.parent === 'catalog.lookup');\nconst latestChild = catalogChildren.reduce((latest, span) =>\n span.end > latest.end ? span : latest,\n);\n\nconsole.log({\n rootDuration: duration(byName.get('gateway.handle')),\n latestCatalogChild: latestChild.name,\n latestCatalogChildEnd: latestChild.end,\n invalidParentRanges: invalid.length,\n});\n// { rootDuration: 240, latestCatalogChild: 'inventory.fetch',\n// latestCatalogChildEnd: 200, invalidParentRanges: 0 }\nРезультат подтверждает три локальных факта: root длится 240 мс, inventory завершается позже pricing, каждый child находится внутри parent. Одна шкала — условие входных данных, а не вывод программы. Код не подтверждает, что catalog действительно получил traceparent, что sampling сохранил все span или что задержка внутри adapter вызвана базой. Для последнего вывода нужен собственный сигнал adapter.
\nTrace показывает наблюдаемую структуру и интервалы, но не автоматически бизнес-причину. Длинный span базы может быть следствием блокировки, плохого плана, холодного соединения или внешнего лимита. Если span заканчивается после parent, сначала зафиксируйте противоречие: это может быть раннее закрытие, асинхронная работа или неверно выбранная модель связи.
\nОбычное дерево плохо описывает fan-out, очередь, retry и работу после ответа. Для операций с несколькими причинными источниками могут понадобиться links, а для разнесённых часов — проверка источника времени и допустимой погрешности. Отсутствие span не доказывает отсутствие работы: запись могла не попасть в sampling, экспорт мог задержаться или instrumentation могла не охватить участок.
\nНе передавайте в trace context пароль, токен, email, тело запроса или полный URL с параметрами. Trace-id нужен для корреляции, а не для хранения полезной нагрузки. Если следующий сигнал содержит персональные данные, применяйте правила доступа и маскирования вашей системы наблюдаемости.
\nРазбор готов, когда для одного проверочного запроса выполнены четыре условия: записи связаны с root и имеют объяснимые parent-child отношения; на каждой транспортной границе указан фактически отправленный и полученный context; критический путь рассчитан без двойного счёта вложенных и параллельных интервалов; после изменения повторён тот же симптом и отрицательный путь. Если один факт неизвестен, честный результат — «причина пока не доказана» и конкретный следующий fetch.
\ntraceparent, ограничения trace-id и parent-id и правила обработки входящего context.