Чтение distributed traces: critical path и fan-out

Прочитай distributed trace {{trace_url}} для {{endpoint}}. Найди где теряется время и сформулируй конкретный план оптимизации.

Базовая аксиома: trace — это не картинка из 100 spans которую надо «посмотреть». Это объект чтения с конкретным алгоритмом: критический путь, fan-out, budget per span, паттерны. Без алгоритма читать trace бесполезно.

1. Что такое span и trace

• Span — единица работы: HTTP-запрос, DB-запрос, вычисление, RPC-вызов. Имеет start/end, parent_id, attributes, events.
• Trace — DAG из spans с общим trace_id. Корневой span — entry point (HTTP request, message consume).
• Parent-child — вложенность по времени и каузальности. Child всегда внутри parent по времени.
• Sibling spans могут быть параллельны (fan-out) или последовательны (chain).

Trace viewer показывает Gantt chart: ось X — время, каждый row — span. Длина прямоугольника = duration.

2. Критический путь — главная техника

Critical path — последовательность spans от корня до листа, сумма duration которых = total latency корневого span.

Алгоритм:

1. Начни с корневого span (total = X ms).
2. Найди child с наибольшим end_time (а не duration!).
3. Спустись внутрь — повтори.
4. Дойдя до листа, у тебя цепочка spans, сумма которых ≈ X.

Почему end_time, не duration: если есть parallel children (A=100ms, B=200ms запущены вместе), critical path идёт через B. duration A не на critical path — оптимизация A ничего не даст.

Что искать на critical path:

• Один span занимает > 50% — оптимизируй его в первую очередь
• 5-10 spans по 10-20% — нет single bottleneck, оптимизируй пакетно
• Gap между spans (родитель долгий, child'ы мало) — синхронная работа в parent, не показанная в child spans

3. Fan-out — parallel calls

[--- root: 500ms ---]
  [-- A: 100ms --]
  [-- B: 150ms --]
  [-- C: 120ms --]
  [-- D: 200ms --]   ← на critical path

Здесь fan-out из 4 параллельных вызовов. Total = max(A,B,C,D) ≈ 200ms.

Что замечать:

• Fan-out с большим разбросом (10ms vs 500ms) — что-то одно тормозит, медианные мало значат, p99 правит балом
• Fan-out с одинаковым timing — внешняя зависимость (общая БД, общий downstream)
• Sequential fan-out (1 за другим, не параллельно) — упущенная возможность параллелизма, лёгкий win

ПЛОХО (sequential):
  [-- A: 100ms --][-- B: 100ms --][-- C: 100ms --]   total 300ms

ХОРОШО (parallel):
  [-- A: 100ms --]
  [-- B: 100ms --]    total 100ms
  [-- C: 100ms --]

4. Latency budget per span

Бюджет endpoint'а — твой SLO (например p99 ≤ 300ms). Разнеси по типам spans:

Что делать с этим:

• Сложи бюджеты — если сумма > SLO, нужен parallelism или кэш
• Найди spans которые превышают бюджет в 3-5 раз — основные кандидаты
• Если ВСЕ spans в бюджете, но total превышает SLO → проблема в gaps (синхронная работа вне spans) или в очерёдности (sequential вместо parallel)

5. Паттерны медлительности

N+1 в trace

[--- root: 800ms ---]
  [- DB: get_user: 5ms -]
  [- DB: get_orders_for_user: 10ms -]
  [- DB: get_items_for_order_1: 5ms -]
  [- DB: get_items_for_order_2: 5ms -]
  [- DB: get_items_for_order_3: 5ms -]
  ... × 100
  [- DB: get_items_for_order_100: 5ms -]

Признак: много одинаковых spans подряд, имена различаются только параметром. Фикс: один IN-запрос вместо 100. Или JOIN. Или dataloader / batch resolver. Импакт: 500ms → 30ms типично.

Серийные внешние calls

[--- root: 600ms ---]
  [-- API_A: 200ms --]
  [-- API_B: 200ms --]
  [-- API_C: 200ms --]

Признак: spans с external service последовательно, не parallel. Фикс: Promise.all / asyncio.gather / parallel goroutines. Если есть data dependencies — нельзя. Импакт: total = sum → total = max.

Holding the connection

[--- root: 500ms ---]
  [- DB query: 50ms -]
  ............... 400ms gap без spans ..............
  [- DB query: 50ms -]

Признак: большой gap без вложенных spans, parent живёт долго. Причина: синхронная работа CPU (сериализация, парсинг), I/O без instrumentation, sleep, lock waiting. Фикс: доинструментируй, найди что в gap. Часто это CPU-heavy транформации.

Cold path / cold cache

Trace #1: 50ms (cache hit)
Trace #2: 800ms (cache miss + всё пересчитано)

Признак: трейсы того же endpoint с радикально разной длительностью. Фикс: прогрев кэша, или вынос cold path в фон, или fallback на stale.

Cascade timeout

[--- root: 5000ms (timeout) ---]
  [-- A: 5000ms (timeout) --]
    [-- B: 5000ms (timeout) --]
      [-- DB: 5000ms (timeout) --]

Признак: вложенные spans с одинаковой длительностью равной таймауту. Причина: downstream тормозит / упал, каждый уровень ждёт свой полный timeout. Фикс: timeout budget propagation (deadline вместо timeout), circuit breaker.

Lock contention

[--- root: 800ms ---]
  [- prep: 10ms -]
  [- waiting for lock: 750ms -]   ← подозрительно ровный
  [- work: 40ms -]

Признак: ровная длительность span'а, не зависит от параметров. Фикс: профиль на блокировки, уменьши scope lock, перепиши на optimistic.

6. Чего НЕ видно в trace

• Что НЕ инструментировано — это gaps без spans. Tracing не покажет тебе CPU work без instrumentation.
• Async work после ответа (background tasks) — span закрывается с return, последующее не учитывается.
• Тонкие spans (< 1ms) часто сэмплированы или схлопнуты.
• Multi-tenant носители — span на отправку в очередь быстрый, но получатель работает долго в другом trace.

7. Sampling и tail-based sampling

Если sampling 1% — твой медленный trace мог не сохраниться. Включи tail-based sampling: семплируется всё, но сохраняются только slow / error traces.

Если trace кажется неполным — проверь:

• trace_state continuation между сервисами
• Header propagation (traceparent)
• Параметры sampler'а в каждом сервисе

8. Workflow чтения trace

1. Контекст: какой endpoint, SLO, на каком объёме воспроизводится
2. Total duration root span — соответствует жалобе?
3. Critical path — найди и распиши: A → B → C, длительности
4. Fan-out — есть ли parallel children, балансированы или нет
5. Паттерны — пройдись по checklist: N+1, серийные, gap, cold, cascade
6. Бюджет — сравни с типичными значениями, найди превышения
7. Gaps — есть ли куски парента не покрытые child spans
8. Hypothesis: один топ-3 кандидата на оптимизацию с ожидаемым импактом
9. Сравни с быстрым trace того же endpoint — что отличается

Anti-patterns

• ❌ Смотреть только на duration корневого span — не понимаешь где время потеряно
• ❌ Оптимизировать самый длинный child span, не убедившись что он на critical path — ноль эффекта
• ❌ Игнорировать gaps между spans — там может прятаться основной CPU work
• ❌ Параллелизация sequential fan-out, где есть data dependency — гонки, баги
• ❌ Считать что 100ms span быстрый, не сверившись с бюджетом span'а (auth должен быть 10ms)
• ❌ Делать выводы по одному trace — outlier, нужно 10-100 trace'ов одного endpoint
• ❌ Игнорировать sampling — медленные могут быть отброшены, выборка смещена
• ❌ Читать trace без знания what is expected — не отличишь патологию от нормы
• ❌ Инструментировать вообще всё — overhead 10%+, trace становится нечитаемым
• ❌ Удалять span после оптимизации — следующая регрессия будет невидима

На выходе

• Critical path с длительностями (A → B → C → ...)
• Топ-3 spans / pattern для оптимизации с ожидаемым импактом в ms
• Hypothesis о причине каждого (N+1, серийный fan-out, gap, cold cache, etc.)
• Конкретный fix для каждого (batch, parallel, кэш, deadline propagation)
• Что доинструментировать (gaps в trace)
• Critical path после фикса (моделированный)
• Регрессионный alert: p99 этого endpoint'а с конкретным threshold