Наблюдаемость распределённых систем: трассировка, корреляция, поиск причин

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

В распределённой системе нет ни стека, ни возможности остановить мир, ни одних часов. Запрос пользователя размазан по двенадцати процессам на восьми машинах в трёх зонах доступности; часть работы выполнилась асинхронно через очередь спустя сорок секунд после того, как пользователю уже вернули 200 OK; половина участников про существование этого запроса вообще не знает. Когда что-то ломается, у вас нет трассировки — у вас есть двенадцать несвязанных потоков логов с машин, часы которых разъезжаются на десятки миллисекунд, и график, на котором «выросла задержка».

Наблюдаемость — это инженерная дисциплина восстановления причинности постфактум. Не «поставить мониторинг», а «сделать так, чтобы из телеметрии можно было реконструировать граф причинно-следственных связей конкретной операции, не задавая системе новых вопросов и не выкатывая новый код». Определение, которое стало отраслевым (Чарити Мэйджорс): система наблюдаема, если вы можете отвечать на вопросы, которые не предвидели заранее.

Статья опирается на весь трек. Мы будем постоянно возвращаться к моделям отказов — потому что отказ узла неотличим от медленной сети, и в телеметрии это выглядит абсолютно одинаково; к времени и часам — потому что трейс описывает причинность, а рисуется на оси физического времени, и здесь начинается боль; к гарантиям доставки — потому что телеметрия сама доставляется at-least-once со всеми последствиями; к очередям — потому что это граница, на которой трейсы рвутся чаще всего. Операционная сторона (дежурства, SLO, ротации, постмортемы) разобрана в DevOps: наблюдаемость и дежурства; здесь — фундамент: почему наблюдать распределённую систему принципиально сложнее, чем локальную, и что именно с этим делать.

Почему «просто посмотреть, что происходит» невозможно

Начнём с ограничения, которое нельзя обойти покупкой инструмента. В распределённой системе нет мгновенного глобального состояния — Чанди и Лампорт показали это в 1985 году в работе про распределённые снимки. Наблюдатель не может посмотреть на все узлы одновременно: сообщение о состоянии узла A летит к вам конечное время, за которое A уже изменился. Любой «снимок системы» — склейка состояний разных узлов, взятых в разные моменты, и эта склейка может соответствовать состоянию, которого в реальности не существовало ни секунды.

Три следствия, из которых растёт всё остальное.

1. Всё, что вы видите, — прошлое. Дашборд со скрейпом раз в 15 секунд и окном агрегации в минуту показывает систему, какой она была от 15 до 75 секунд назад. На инциденте это ощущается физически: вы принимаете решения о состоянии, которого уже нет, и потом полчаса не понимаете, почему «откат не помог» (он помог — просто график ещё показывал старое).

2. Наблюдатель — часть системы. Экспорт телеметрии потребляет CPU, сеть, память и диск тех же узлов. Классическая петля: сервис деградировал → каждая ошибка пишет стек → объём логов вырос в двадцать раз → агент логов упёрся в диск → диск стал узким местом → сервис деградировал сильнее → логов ещё больше. Телеметрия превратилась в усилитель отказа; это ровно тот механизм самоподдержания, который описан в Metastable Failures in Distributed Systems (HotOS 2021). Отсюда правило: у пайплайна телеметрии должны быть жёсткие лимиты и приоритеты, и деградировать он обязан раньше, чем приложение.

3. Отсутствие сигнала не доказывает отсутствие события. Спан не сохранился, потому что не попал в выборку. Лог не долетел, потому что переполнилась очередь агента. Метрика не выросла, потому что окно агрегации проглотило всплеск длиной 200 мс. Фраза «в логах ничего нет, значит этого не происходило» — самая дорогая ошибка на разборе инцидента.

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

Три плоскости телеметрии и швы между ними

Метрики, логи и трейсы называют «тремя столпами». Метафора неудачная: столпы стоят отдельно и ничего друг о друге не знают. Правильнее — три плоскости проекции одного и того же потока событий, каждая сохраняет одно измерение и уничтожает остальные.

Главная мысль этого раздела: ценность даёт не плоскость, а шов между плоскостями. Метрика говорит «p99 вырос до трёх секунд» — и дальше тупик, потому что в ней нет ни одного конкретного запроса. Лог говорит «здесь ошибка» — и дальше тупик, потому что неизвестно, чей это был запрос и что происходило до. Швов ровно четыре, и все четыре надо построить руками:

• trace_id — главный шов. Обязан присутствовать в каждой строке лога, в атрибутах каждого спана и в exemplar метрики. Exemplar — это ссылка от бакета гистограммы на конкретный trace_id, попавший в этот бакет (exemplars в Prometheus, формат OpenMetrics). Именно exemplar превращает «p99 вырос» в «вот три конкретных трейса из хвоста, смотрите».
• span_id — уточняет лог до конкретного шага, а не «где-то в этом запросе».
• Resource attributes (service.name, service.version, k8s.pod.name, host.name, cloud.availability_zone) — отвечают на вопрос «кто это сказал». Они обязаны быть одинаковыми у всех сигналов одного процесса, иначе корреляция по сервису не работает: метрики придут с лейблом app, логи с полем service, трейсы с service.name, и объединить их будет нечем.
• Бизнес-ключи (order_id, idempotency_key, message_id, tenant.id) — шов между телеметрией и данными. Без них вопрос «этот платёж применился дважды?» из телеметрии не отвечается в принципе.

Отдельно про логи. В распределённой системе выигрывает не «много строк», а широкое каноническое событие: одна структурная запись на единицу работы, в которой три-четыре десятка полей — идентификаторы, тайминги по фазам, номер попытки, версия кода, зона, арендатор, размер ответа, признак попадания в кэш. Приём популяризовал Stripe под именем canonical log lines, а книга Observability Engineering (Majors, Fong-Jones, Miranda) построена вокруг того же тезиса: высокая кардинальность должна жить в широких событиях, а не в метриках. Практическая разница огромна: сто узких строк на запрос невозможно сгруппировать, одно широкое событие можно разрезать по любому полю без изменения кода — а это и есть определение наблюдаемости.

Трейс — это граф причинности, а не таймлайн

Самое вредное упрощение темы — считать трейс «водопадом». Водопад — способ отрисовки. Сущность трейса — направленный ациклический граф отношений «случилось-до», наложенный на ось физического времени. Это прямое прикладное воплощение частичного порядка Лампорта: ребро parent → child означает не «раньше по времени», а «причинно предшествует».

Из этой модели следуют три вещи, которые постоянно путают.

kind важнее, чем кажется. Пара CLIENT (у вызывающего) и SERVER (у вызываемого) описывает одно сетевое взаимодействие с двух сторон. Разность их длительностей — это сетевое время плюс время в очереди приёма плюс TLS плюс ожидание свободного воркера. Если у вас есть только одна сторона, вы принципиально не отличите «сервис медленный» от «сеть медленная» — а это ровно тот вопрос, на котором ломается половина расследований.

LINK — не то же самое, что parent. Родитель один и означает «эта работа выполняется в рамках вон той». Ссылок может быть много, и они означают «эта работа причинно связана вон с теми, но не вложена в них». Канонический случай — батч: консьюмер забрал 500 сообщений из Kafka от 500 разных трейсов. Сделать 500 родителей нельзя, выбрать одного — соврать. Правильный ответ: спан обработки батча со ссылками на все 500 контекстов. Второй случай — ретрай: попытка №3 логически связана с попытками №1 и №2, но не вложена в них.

Имя спана — низкой кардинальности. GET /users/{id}, а не GET /users/8134. Идентификатор уходит в атрибут. Нарушение этого правила делает бессмысленной агрегацию по именам спанов и взрывает индексы бэкенда — это ровно та же ошибка, что user_id в лейбле метрики, только дороже.

Идея прошла путь от X-Trace (NSDI 2007, сквозные метаданные через все слои стека) через Dapper (Google, 2010, семплирование и честные измерения накладных расходов) и Canopy (SOSP 2017, трассировка как аналитика, а не отладчик) до слияния OpenTracing и OpenCensus в OpenTelemetry в 2019-м и рекомендации W3C Trace Context в 2021-м. Первоисточники стоит прочитать целиком: в них разобраны ровно те компромиссы, которые вы будете выбирать заново в своей системе.

Контекст: 55 символов, на которых всё держится

Трейс собирается не в бэкенде, а на проводе. Каждый вызов обязан пронести идентификаторы дальше — иначе получатель заведёт новый корень, и одна операция превратится в два несвязанных трейса, между которыми нет ничего общего.

Формат зафиксирован в W3C Trace Context и поддержан всеми: OpenTelemetry, Jaeger, Datadog, AWS X-Ray (через мост), Azure Monitor. Два заголовка-спутника: tracestate — вендорские данные, включая порог вероятностного семплирования, и baggage — прикладной контекст (арендатор, эксперимент, класс приоритета), который едет по всей цепочке. Про baggage важно помнить две вещи: он едет ко всем, поэтому персональным данным и секретам там не место, и он растёт в размере — на длинной цепочке килобайт baggage превращается в килобайт на каждом RPC.

Автоинструментация закрывает HTTP и gRPC. Ломается контекст всегда на скучных границах: очередь, воркер, cron, аутбокс, вебхук. Разберём Kafka как самый частый случай.

# Продюсер: контекст кладём в ЗАГОЛОВКИ записи, не в тело.
# Тело — данные домена, оно версионируется и валидируется схемой; телеметрии там не место.
from opentelemetry import trace, propagate
from opentelemetry.trace import SpanKind

tracer = trace.get_tracer(__name__)

def publish_order_created(producer, order):
    # PRODUCER-спан завершается ПОСЛЕ подтверждения брокера, а не после вызова send():
    # иначе спан покажет 0.3 мс записи в сокет вместо реальных 40 мс до ack.
    with tracer.start_as_current_span(
        "orders.created publish",
        kind=SpanKind.PRODUCER,
        attributes={
            "messaging.system": "kafka",
            "messaging.destination.name": "orders",
            "messaging.message.id": order.message_id,   # бизнес-шов
        },
    ) as span:
        carrier: dict[str, str] = {}
        propagate.inject(carrier)                 # traceparent, tracestate, baggage
        headers = [(k, v.encode()) for k, v in carrier.items()]
        fut = producer.send("orders", key=order.id.encode(),
                            value=serialize(order), headers=headers)
        meta = fut.get(timeout=10)                # ждём ack — иначе спан врёт про длительность
        span.set_attribute("messaging.kafka.partition", meta.partition)
        span.set_attribute("messaging.kafka.offset", meta.offset)

# Консьюмер: батч из 500 сообщений от 500 РАЗНЫХ трейсов.
# Один родитель тут невозможен — используем ссылки.
from opentelemetry.trace import Link, get_current_span

def handle_batch(records):
    ctxs = [propagate.extract({k: v.decode() for k, v in (r.headers or [])}) for r in records]
    links = [Link(sc) for c in ctxs
             if (sc := get_current_span(c).get_span_context()).is_valid]

    # Спан батча: собственный трейс, связанный ссылками с 500 исходными
    with tracer.start_as_current_span(
        "orders process batch", kind=SpanKind.CONSUMER, links=links,
        attributes={"messaging.batch.message_count": len(records)},
    ):
        for r, ctx in zip(records, ctxs):
            # Спан обработки ОДНОГО сообщения — продолжение ЕГО исходного трейса.
            # queue_time_ms фиксируем явно: иначе ожидание в топике не видно нигде.
            with tracer.start_as_current_span(
                "orders process", context=ctx, kind=SpanKind.CONSUMER,
                attributes={"messaging.kafka.offset": r.offset,
                            "messaging.queue_time_ms": now_ms() - r.timestamp},
            ):
                process(r)

Атрибут queue_time_ms заслуживает отдельного абзаца. Без него типовая картина выглядит так: продюсер-спан 5 мс, консьюмер-спан 12 мс, всё зелёное — а пользователь ждал заказ сорок минут. Эти сорок минут прошли между спанами, и, если не измерить их явно, в телеметрии их просто нет. Общее правило асинхронных систем: время ожидания между спанами не принадлежит ни одному спану, его нужно вычислять и записывать руками.

Вторая типовая граница — аутбокс (см. распределённые транзакции): запись в таблицу происходит в одном запросе, а отправка — в фоновом релее спустя секунды. Контекст надо сохранить в строке рядом с payload.

// carrier — map[string]string с методами Get/Set/Keys (propagation.TextMapCarrier).
// Запись: Inject кладёт traceparent и baggage в колонку trace_ctx той же транзакцией,
// что и бизнес-строку. Отправка: релей извлекает контекст СПУСТЯ секунды или минуты,
// и его спан становится продолжением исходного трейса, а не сиротой.
func RelayOne(row OutboxRow, producer Producer) error {
    var hdr carrier
    _ = json.Unmarshal(row.TraceCtx, &hdr)
    ctx := otel.GetTextMapPropagator().Extract(context.Background(), hdr)
    ctx, span := tracer.Start(ctx, "outbox relay", trace.WithSpanKind(trace.SpanKindProducer))
    defer span.End()
    // Лаг аутбокса — обязательный отдельный сигнал: ни в одном спане он не виден
    span.SetAttributes(attribute.Int64("outbox.lag_ms", time.Since(row.CreatedAt).Milliseconds()))
    return producer.Send(ctx, row.Topic, row.Payload)
}

Метрика качества инструментации, которую стоит завести первой: доля корневых спанов с kind = SERVER, у которых нет родителя, хотя вызов пришёл изнутри периметра. Каждая такая сирота — дыра в распространении контекста, и в отличие от всего остального она измеряется автоматически.

Часы врут — и трейс показывает это первым

Спан хранит start_unix_nano и end_unix_nano по стенным часам того узла, где он создан. Длительность внутри процесса обычно берут из монотонных часов (это корректно), но взаимное расположение спанов с разных машин рисуется по стенным. А стенные часы разъезжаются: типичный дрейф под NTP в датацентре — единицы миллисекунд, при проблемах с NTP — десятки и сотни, при виртуализации со «стоп-мирами» — секунды. Подробности механики — в статье про время.

Сценарий отказа, который видел каждый, кто смотрел трейсы дольше недели:

span api        [SERVER]  start=12:00:00.100  end=12:00:00.940   840ms
  span billing  [CLIENT]  start=12:00:00.120  end=12:00:00.900   780ms
    span ledger [SERVER]  start=12:00:00.048  end=12:00:00.870   822ms   ← начался РАНЬШЕ родителя

Дочерний спан начинается за 52 мс до родительского вызова. Причинно это невозможно; физически — часы узла ledger отстают примерно на 70 мс. Что происходит дальше, зависит от бэкенда:

• Jaeger применяет коррекцию рассинхронизации: сдвигает поддерево так, чтобы оно уместилось в родителя, и показывает предупреждение о поправке. Удобно — и опасно: после сдвига «сетевое время» между billing и ledger становится выдуманным числом, а вы будете по нему принимать решения.
• Tempo, Grafana и ряд других не корректируют: вы видите отрицательные интервалы и спаны, торчащие за границы родителя.
• Хуже всего вариант, когда часы разъехались на сотни миллисекунд, но недостаточно, чтобы порядок стал явно невозможным. Картинка выглядит правдоподобно, и вы уверенно обвиняете не тот сервис. Проверить это нечем — кроме метрик самих часов.

Правила выживания:

1. Длительность — только по монотонным часам. time.monotonic() в Python, time.Now() в Go (хранит монотонную компоненту), Stopwatch в .NET, System.nanoTime() в Java. Вычитание стенных меток может дать отрицательное число сразу после коррекции NTP — и это регулярно ломает гистограммы латентности.
2. Измеряйте рассинхронизацию и алертите на неё. node_timex_offset_seconds, node_timex_maxerror_seconds, chrony_tracking_last_offset. Порог: смещение выше 100 мс — предупреждение, выше 1 с — инцидент. Это не гигиена, а условие корректности всех ваших трейсов и всех сравнений таймстампов в логах.
3. Считайте число причинных нарушений — сколько спанов начались раньше своего родителя. Прямая метрика здоровья времени в кластере; обычно доступна в бэкенде трассировки или считается простым запросом.
4. Не выводите порядок событий из меток времени с разных машин. Порядок дают только причинные рёбра: parent/child, links, версии, логические часы. Если порядок принципиально важен — например, «кто первым захватил лизу» — доказывать его нужно фенсинг-токенами из координации, а не сравнением строк лога. Spanner решает эту задачу единственным честным способом: интервал неопределённости TrueTime и commit-wait длиной около $2\varepsilon$ (см. распределённые транзакции).

Семплирование и его смещение

Полная трассировка стоит дорого: спан — это 300–1500 байт; при 50 тысячах RPS и десяти спанах на запрос выходит около 500 тысяч спанов в секунду и сотни мегабайт в секунду в хранилище. Отсюда семплирование — и отсюда главная ловушка: инцидент почти всегда живёт в хвосте, а равномерное семплирование хвост выбрасывает первым.

Пусть доля семплирования $s$, доля «интересных» (ошибочных или медленных) запросов $p$. Вероятность сохранить хотя бы один интересный трейс за окно из $n$ запросов равна $1-(1-p \cdot s)^{n}$. При $p = 10^{-4}$ и $s = 0.01$ нужно порядка миллиона запросов, чтобы с приличной вероятностью поймать один трейс с ошибкой. Для редкого, но дорогого бага это значит: вы не поймаете его никогда.

Head-based — решение принимается в начале трейса, до того как исход известен, и записывается битом sampled в traceparent. Плюс: дёшево, решение автоматически согласовано между всеми участниками. Минус: принято до того, как стало известно, что запрос упадёт.

Tail-based — все спаны собираются в коллекторе, буферизуются до завершения трейса, и лишь затем принимается решение. Плюс: можно сохранять 100% ошибок и 100% медленных. Минусы серьёзные: коллектор держит незавершённые трейсы в памяти (окно 10–30 секунд, умноженное на объём трафика), и все спаны одного трейса обязаны попасть в один экземпляр коллектора — нужна маршрутизация по trace_id (loadbalancing exporter). Если её не настроить, каждый коллектор увидит куски трейсов и будет принимать решения по неполной картине: половина медленного трейса сохранится, половина исчезнет, и вы будете смотреть на дыры.

# Рабочий компромисс: голова пропускает всё, хвост решает. Двухслойный коллектор.
# Слой 1 (agent) → loadbalancing exporter по trace_id → слой 2 (gateway) → tail_sampling
processors:
  tail_sampling:
    decision_wait: 15s              # ждём завершения трейса; больше — дороже память
    num_traces: 200000              # ёмкость буфера незавершённых трейсов
    expected_new_traces_per_sec: 5000
    policies:
      - name: errors-always         # все ошибки, без исключений
        type: status_code
        status_code: {status_codes: [ERROR]}
      - name: slow-always           # весь хвост латентности
        type: latency
        latency: {threshold_ms: 1000}
      - name: baseline              # фон для сравнения: без него хвост не с чем сравнивать
        type: probabilistic
        probabilistic: {sampling_percentage: 1}

Отдельная тонкость — согласованность решения. Если каждый сервис бросает свою монетку, трейсы становятся дырявыми: сохранены спаны A и C, спан B выброшен, и на месте виновника зияет пустота. Решение обязано либо ехать в traceparent (head-based), либо приниматься централизованно (tail-based). Корректный промежуточный вариант — детерминированное семплирование по хешу trace_id: все участники, применяя одно правило к одному trace_id, приходят к одному решению без всякой коммуникации. Так работает TraceIdRatioBased в OpenTelemetry, а порог кладётся в tracestate, чтобы бэкенд мог восстановить веса и не соврать в агрегатах.

Последнее и самое забываемое: семплированный трейс — это смещённая выборка. Считать по трейсам долю ошибок нельзя, если политика сохраняет все ошибки и один процент успехов: вы получите «40% ошибок» на здоровой системе. Доли считают метрики; трейсы отвечают на вопрос «почему», а не «сколько».

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

Метрика — это временной ряд, ключ которого есть набор лейблов. Число рядов растёт мультипликативно: 40 сервисов × 25 эндпойнтов × 8 кодов ответа × 30 инстансов = 240 000 рядов для одного счётчика. Добавьте лейбл user_id — получите миллионы рядов, OOM у Prometheus и счёт за облако, который заметит финансовый директор.

Отсюда фундаментальное ограничение: в метриках нельзя хранить то, что делает запрос уникальным — а именно уникальность и нужна для поиска причины. Это не недостаток реализации, это природа агрегата. Метрики отвечают на «что и насколько», и это их потолок.

# Что метрики умеют: показать, что плохо, и дать ссылку на конкретный трейс через exemplar
histogram_quantile(0.99,
  sum by (le, service) (rate(http_server_duration_seconds_bucket[5m]))
)

# Доля ретраев — ранний признак метастабильного отказа (см. 01 и 11).
# Выше 10 процентов — система лечит себя активнее, чем работает.
sum(rate(http_client_requests_total{retry="true"}[5m]))
  / sum(rate(http_client_requests_total[5m]))

# Расхождение взглядов: клиент видит ошибки, сервер их не видит.
# Это сигнатура серого отказа — балансировщик, сеть, TLS, исчерпание пула соединений.
sum(rate(client_errors_total{peer_service="ledger"}[5m]))
  - sum(rate(server_errors_total{service="ledger"}[5m]))

Три опоры, чтобы метрики оставались полезными:

• RED на каждом сервисе (Rate, Errors, Duration) и USE на каждом ресурсе (Utilization, Saturation, Errors) — метод USE Брендана Грегга.
• Насыщение важнее утилизации. «CPU 70%» не говорит ничего; длина очереди на входе говорит всё. По закону Литтла $L = \lambda W$ среднее число запросов в системе равно интенсивности, умноженной на время пребывания: очередь начинает расти раньше, чем упрётся любой ресурс, и это самый ранний доступный сигнал перегрузки.
• Алерты — на симптомы, а не на причины. «CPU выше 80%» будит человека ночью без вреда для пользователей; «доля успешных checkout ниже SLO» будит по делу. Формальная механика — alerting on SLOs в SRE Workbook: multi-window multi-burn-rate вместо порогов на ресурсы.

Поиск причины: критический путь, а не самый медленный спан

Типовая ошибка на разборе: открыть трейс, найти самый длинный спан и объявить его виновным. В системе с параллелизмом это неверно. Если родитель запустил три ветки параллельно и ждёт все, длительность родителя определяет самая поздно закончившаяся ветка, а не самая долгая. Ветка на 600 мс, стартовавшая сразу, не критична, если параллельная ветка на 200 мс стартовала на 500-й миллисекунде и закончилась последней.

Критический путь — набор интервалов, сокращение любого из которых сокращает общую длительность операции. Оптимизировать имеет смысл только их. Идея пришла из The Mystery Machine (Chow et al., OSDI 2014), где причинные связи между сегментами выводились автоматически из массива трейсов.

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

CRITICAL-PATH(span, until):
    until  ← min(until, span.end)
    cursor ← until
    для child из детей span, отсортированных по child.end по убыванию:
        если child.end ≤ span.start или child.start ≥ cursor: пропустить
        если child.end < cursor:
            добавить сегмент (span, child.end, cursor)   # родитель работал сам
            cursor ← child.end
        добавить CRITICAL-PATH(child, cursor)            # рекурсия внутрь
        cursor ← max(child.start, span.start)
        если cursor ≤ span.start: выйти из цикла
    если cursor > span.start:
        добавить сегмент (span, span.start, cursor)

from dataclasses import dataclass, field

@dataclass
class Span:
    name: str
    start: float                       # мс от начала трейса (после коррекции часов!)
    end: float
    children: list["Span"] = field(default_factory=list)

Segment = tuple[str, float, float]     # (имя спана, начало, конец)

def critical_path(span: Span, until: float | None = None) -> list[Segment]:
    """Сегменты критического пути внутри span, заканчивающиеся в момент `until`.

    Время:  O(n log n) — на каждом узле сортируем его детей, суммарно детей ровно n.
    Память: O(n) на результат плюс O(глубина) на стек рекурсии.
    """
    until = span.end if until is None else min(until, span.end)
    out: list[Segment] = []
    cursor = until
    for child in sorted(span.children, key=lambda c: c.end, reverse=True):
        if child.end <= span.start or child.start >= cursor:
            continue                                  # ветка вне интересующего окна
        if child.end < cursor:
            # интервал, в котором не работал ни один ребёнок: собственная работа родителя
            out.append((span.name, child.end, cursor))
            cursor = child.end
        out.extend(critical_path(child, until=cursor))
        cursor = max(child.start, span.start)
        if cursor <= span.start:
            break
    if cursor > span.start:
        out.append((span.name, span.start, cursor))
    return out

def blame(root: Span) -> list[tuple[str, float]]:
    """Сколько миллисекунд критического пути приходится на каждый спан."""
    totals: dict[str, float] = {}
    for name, s, e in critical_path(root):
        totals[name] = totals.get(name, 0.0) + (e - s)
    return sorted(totals.items(), key=lambda kv: -kv[1])

# Демонстрация ловушки: самый длинный спан НЕ на критическом пути
trace = Span("checkout", 0, 840, [
    Span("cart",   10, 610),            # 600 мс — самый длинный в трейсе!
    Span("auth",   10, 130),
    Span("ledger", 240, 840, [          # тоже 600 мс, но заканчивается последним
        Span("lock_wait", 250, 770),
        Span("write",     770, 838),
    ]),
])
print(blame(trace))
# [('lock_wait', 520.0), ('checkout', 240.0), ('ledger', 68.0), ('write', 12.0)]
# 'cart' в списке отсутствует: его оптимизация не ускорит запрос НИ НА МИЛЛИСЕКУНДУ

Разница между «самым долгим спаном» (cart, 600 мс) и «главным виновником на критическом пути» (lock_wait, 520 мс) — это разница между впустую потраченным спринтом оптимизации и исправлением реальной проблемы. Обратите внимание и на 240 мс, приписанные самому checkout: это время, когда не работал ни один ребёнок, — сериализация, ожидание пула соединений, GC-пауза, планировщик, DNS. Такие «слепые» интервалы находятся только критическим путём и часто оказываются самой полезной находкой в трейсе.

Второй приём того же класса — агрегирование критических путей по тысячам трейсов. Один трейс — анекдот; распределение по 50 тысячам трейсов из хвоста показывает, что в 70% медленных запросов критический путь проходит через ожидание блокировки в ledger. Это уже вывод, с которым можно идти к владельцу сервиса. Развитие идеи — Pivot Tracing (SOSP 2015): запросы к телеметрии вдоль причинных путей, «покажи мне размер очереди в HDFS в тех случаях, когда запрос пришёл от этого клиента».

Хвост при веерном вызове: почему «обычно быстро» ничего не значит

Ключевая арифметика распределённой производительности — из The Tail at Scale (Dean, Barroso, CACM 2013). Если запрос обращается к $n$ узлам параллельно и ждёт все ответы, а вероятность «медленного» ответа одного узла равна $p$, то вероятность медленного пользовательского запроса равна $1-(1-p)^{n}$.

Сто узлов, каждый из которых «медленный» лишь в одном проценте случаев, дают 63% медленных запросов. Следствия для наблюдаемости:

• Мерить надо p99 и p99.9 на клиентской стороне, а не среднее на серверной. Среднее в такой системе не описывает вообще ничего.
• Квантили не складываются и не усредняются. avg(p99) по подам — число без смысла. Складывать нужно бакеты гистограмм, а квантиль считать в самом конце.
• Хвост нужно связывать с причиной, и каждая причина требует своего сигнала: длительность GC-пауз, длительность компакции, вытеснение кэша, троттлинг cgroup (container_cpu_cfs_throttled_seconds_total — недооценённая метрика, объясняющая половину загадочных p99 в Kubernetes), шумный сосед по диску.
• Практическое противоядие из той же статьи — хеджированные запросы: послать дубль второй реплике, если первая не ответила за p95. Наблюдаемость обязана считать hedged_requests_total и долю побед дублей: иначе вы не заметите, что хеджирование удвоило нагрузку и само стало причиной перегрузки. Хеджирование — это осознанный обмен «немного лишней работы» на «отрезанный хвост», и обе части обмена должны быть измерены.

Серые отказы: когда изнутри всё зелено, а снаружи всё сломано

Самый неприятный класс отказов описан в Gray Failure: The Achilles’ Heel of Cloud-Scale Systems (Huang et al., HotOS 2017). Компонент не падает — он деградирует частично, и его собственная проверка здоровья этого не видит. Авторы вводят понятие дифференциальной наблюдаемости: отказ является серым ровно тогда, когда взгляд системы на себя расходится со взглядом клиента.

Три канонических сценария и их сигнатуры в логах.

1. Диск деградировал, health-check не заметил. Проверка пишет 4 КБ в файл и получает подтверждение из page cache за 0.2 мс. Реальные записи с fsync занимают 900 мс. В логах etcd последовательно появляется:

{"level":"warn","msg":"apply request took too long","took":"1.203s","expected-duration":"100ms",
 "prefix":"read-only range ","request":"key:\"/registry/pods/\" range_end:\"/registry/pods0\""}
{"level":"warn","msg":"failed to send out heartbeat on time","heartbeat-interval":"100ms",
 "expected-duration":"200ms","exceeded-duration":"312.4ms"}
{"level":"info","msg":"raft.node: 8e9e05c52164694d elected leader 91bc3c398fb3c146 at term 47"}

Причинная цепочка одна и та же: медленный диск → долгий fsync WAL → пропущенные heartbeat → выборы лидера → таймауты у всех клиентов кластера, включая kube-apiserver. Со стороны это выглядит как «упал Kubernetes», а причина — один диск на одном узле. Ровно этот сценарий делает etcd_disk_wal_fsync_duration_seconds главным предиктором здоровья управляющего слоя.

2. Односторонний разрыв связности. Узел A слышит B, B не слышит A. B считает A мёртвым и инициирует выборы; A считает себя живым лидером. В логах A — lost the TCP streaming connection with peer, у B — постоянные выборы и растущий etcd_server_leader_changes_seen_total. Это тот самый неполный отказ из моделей отказов, и он невидим для любого мониторинга, который проверяет узлы, а не пары узлов. Лечится матрицей связности: каждый узел меряет RTT и успешность до каждого и экспортирует это как метрику с лейблами from/to. В etcd такая метрика есть из коробки — etcd_network_peer_round_trip_time_seconds.

3. Перегрузка одного арендатора. Средняя латентность в норме, но один tenant видит таймауты. В агрегате не видно ничего; видно только при разрезе по tenant.id — то есть по высококардинальному полю, которого в метриках нет и быть не может. Отвечают на этот вопрос только трейсы и широкие структурные события.

Общее правило: всегда меряйте с обеих сторон границы. Клиентская и серверная латентность одного вызова — две разные метрики, и их разность содержит сеть, очередь приёма, TLS-хендшейки и исчерпание пула соединений. Расхождение между ними — самый сильный из доступных сигналов серого отказа. Второй уровень — внешние пробы, идущие тем же путём, что настоящий клиент, включая DNS, балансировщик и TLS, и желательно из другой сети.

Порядок в этой машине не случаен. «Что изменилось» проверяется раньше трейсов, потому что в подавляющем большинстве инцидентов причина — недавнее изменение, а не спонтанная деградация. И смягчение всегда идёт раньше поиска причины: откатить релиз, выключить флаг, сбросить нагрузку — а разбираться после того, как пользователям стало хорошо.

Наблюдаемость доставки: дубли, лаг и почему exactly-once не виден в телеметрии

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

Иллюзия первая: телеметрия точна. Телеметрия — сама распределённая система со всеми теми же свойствами. OTLP-экспортёр ретраит при 503 — и на бэкенд приезжают дубликаты спанов. Батч-процессор при переполнении очереди молча выбрасывает данные, оставляя в логе коллектора запись вида Exporting failed. Dropping data. {"dropped_items": 8192}. Логи по UDP теряются вообще без следа. То есть телеметрия — это at-most-once с элементами at-least-once, и рассуждать по ней надо соответственно. Минимальный набор мета-метрик обязателен: otelcol_processor_dropped_spans, otelcol_exporter_send_failed_spans, глубина очереди экспортёра, число отвергнутых по лимитам рядов. Без них вы не отличите «событий не было» от «телеметрия молча умерла» — а это два прямо противоположных вывода на инциденте.

Иллюзия вторая: exactly-once можно увидеть в трейсах. Нельзя — и не потому, что инструменты плохие, а потому что видеть нечего. Как разбиралось в идемпотентности, сквозной exactly-once невозможен: отправитель не может отличить «сообщение потерялось» от «ответ потерялся», и любой корректный клиент повторяет запрос. Трейс честно покажет три попытки доставки, потому что три попытки и были. Сколько раз применился эффект, знает только состояние системы, а не телеметрия. Наблюдаемость effectively-once строится из трёх вещей, и все три надо построить явно:

1. Счётчик подавленных дублей duplicates_suppressed_total с разрезом по обработчику. Он должен быть больше нуля: ноль означает не «дублей нет», а «дедупликация сломана и вы этого не видите». Сценарий отказа: после релиза ключ идемпотентности начали генерировать внутри функции ретрая — каждая попытка получает новый ключ, счётчик падает в ноль, дубли применяются молча. Алерт на падение счётчика ловит это за минуты; без него баг живёт до сверки с бухгалтерией.
2. Ключ идемпотентности как атрибут спана плюс span links между попытками. Тогда все повторы одной логической операции собираются в один запрос к бэкенду, и вопрос «сколько раз это применилось» превращается в один клик, а не в трёхдневный разбор.
3. Сверка инвариантов в данных — периодический recon-джоб, проверяющий утверждения о состоянии: сумма проводок равна сумме заказов, число строк в ledger равно числу уникальных message_id. Это единственный сигнал, который действительно доказывает effectively-once. Всё остальное — косвенные улики. Метрика расхождения сверки должна висеть на дашборде рядом с SLO.

Иллюзия третья: лаг консьюмера — это одна метрика. Их две, и путать их дорого. Лаг в сообщениях (records-lag-max) отвечает на «сколько не обработано»; лаг во времени (насколько стар обрабатываемый сейчас элемент) отвечает на «насколько устарели данные» и соответствует бизнес-смыслу. При падении трафика лаг в сообщениях уменьшается сам собой, создавая иллюзию выздоровления, тогда как временной лаг остаётся прежним. Оба выводятся из закона Литтла: при интенсивности $\lambda$ и пропускной способности $\mu$ очередь растёт со скоростью $\lambda-\mu$, а время разбора накопленного равно $L/(\mu-\lambda)$. Эту оценку полезно выводить прямо на дашборд словами «разберём за 42 минуты» — она отвечает на вопрос дежурного лучше любого графика.

Что смотреть в реальных системах

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

etcd (консенсус, координация). Метрики: etcd_disk_wal_fsync_duration_seconds (p99 обязан быть ниже 10 мс — главный предиктор всех бед), etcd_disk_backend_commit_duration_seconds, etcd_server_leader_changes_seen_total (любой рост — тревога), etcd_server_proposals_failed_total, etcd_network_peer_round_trip_time_seconds, размер БД против квоты. Сигнатуры в логах: apply request took too long, failed to send out heartbeat on time, lost the TCP streaming connection with peer, request timed out, possibly due to previous leader failure, mvcc: database space exceeded. Официальный список — в документации по мониторингу etcd.

Kafka (очереди, репликация). Метрики: UnderReplicatedPartitions (норма — строго ноль), IsrShrinksPerSec, OfflinePartitionsCount, RequestHandlerAvgIdlePercent, лаг по группам, частота ребалансов. Сигнатуры: Shrinking ISR from 1,2,3 to 1, Preparing to rebalance group ... reason: removing member ... on heartbeat expiration, Attempt to heartbeat failed since group is rebalancing, Offset commit failed. Типичная петля метастабильности: обработка стала дольше max.poll.interval.ms → консьюмер исключён из группы → ребаланс → партиции переехали на других → те тоже не успевают → ребаланс. В трейсах это видно как всплеск обработок одного и того же оффсета разными подами — то есть как всплеск дублей, а не как ошибка. Ни один спан при этом не красный.

Cassandra (кворумы, партиционирование). Смотреть: латентность координатора против латентности реплики — встроенная дифференциальная наблюдаемость: если координатор существенно хуже реплик, проблема в кворуме или сети, а не в дисках. Дальше: DroppedMessages по типам, глубина hinted handoff, частота read repair и Digest mismatch, паузы GC, число SSTable в компакции. Сигнатуры: MUTATION messages were dropped in last 5000 ms, DigestMismatchException, Finished hinted handoff, GCInspector ... G1 Young Generation GC in 1520ms. Рост digest mismatch не всегда беда, но всегда сообщение о том, что реплики расходятся сильнее обычного — то есть окно eventual-согласованности расширилось.

Spanner (распределённые транзакции, время). Смотреть: латентность транзакций с разложением на фазы, время ожидания блокировок (SPANNER_SYS.LOCK_STATS_TOP_MINUTE показывает горячие строки и колонки прямо по именам), долю прерванных транзакций, неопределённость TrueTime. Здесь наблюдаемость упирается в теорию: commit-wait около $2\varepsilon$ — не баг, а цена внешней согласованности, и объяснить рост латентности при расширении интервала неопределённости часов можно только зная механику (Spanner, OSDI 2012). Сценарий отказа: горячая строка → рост ожидания блокировок → рост прерываний → ретраи → строка ещё горячее. Снова метастабильность, и лечится она изменением схемы (шардирование ключа), а не добавлением ресурсов.

Общая рекомендация: для каждой инфраструктурной системы должен существовать список «пять метрик и пять строк лога», записанный в runbook. Этот список — сжатая модель отказов конкретной системы, и он ценнее любого дашборда на сорок графиков.

Что инструментировать: минимальный честный набор

Порядок внедрения, если начинать с нуля и нужен эффект как можно раньше.

1. Контекст на всех границах. Сначала распространение, потом всё остальное. Аудит: для каждой границы — HTTP, gRPC, Kafka, cron, аутбокс, вебхуки, батч-джобы — проверить наличие traceparent. Метрика качества — доля спанов-сирот (см. выше).
2. trace_id и span_id в каждой строке лога. Структурный формат, JSON или logfmt. Это дешевле трассировки и почти так же полезно.
3. RED-метрики на каждом сервисе с exemplars. Без exemplars переход «метрика → трейс» остаётся ручным, а на инциденте ручное не делается.
4. Семантические соглашения OpenTelemetry semantic conventions: http.request.method, server.address, messaging.system, db.system.name, error.type. Скучно и критично: единые имена — единственное, что позволяет строить общие дашборды и правила сразу по десяткам сервисов.
5. Атрибуты, специфичные для распределённой системы, которых нет ни в одной автоинструментации и которые придётся добавить руками: messaging.queue_time_ms, номер попытки ретрая, idempotency_key, partition/shard, leader_epoch или фенсинг-токен, consistency_level запроса к хранилищу, флаг «ответ из кэша», флаг «сработало хеджирование», tenant.id.
6. Мета-телеметрия пайплайна: отброшенные спаны, глубина очередей экспортёра, ошибки экспорта, отвергнутые ряды.
7. Внешние пробы — тем же путём, что настоящий клиент, из другой сети.

Про бюджет: разумный ориентир — накладные расходы трассировки не выше 2–5% CPU при head-семплировании и корректном батчинге; Dapper публиковал именно такие цифры. Если у вас получается 20%, ищите синхронный экспорт, слишком мелкие спаны или логирование внутри горячего цикла.

Типичные ошибки

1. Считать, что купленный APM равен наблюдаемости. Инструмент показывает только то, что вы в него положили. Не пронесли контекст через очередь — никакой вендор связь не восстановит.
2. Ставить идентификаторы в имя спана, а user_id — в лейбл метрики. Первое убивает агрегацию и раздувает индексы, второе даёт взрыв кардинальности и OOM. Уникальное живёт в трейсах и широких событиях.
3. Усреднять квантили. avg(p99) по подам — число без смысла. Складывать бакеты, квантиль считать после.
4. Выводить порядок событий из меток времени с разных машин. Порядок дают только причинные рёбра и логические часы.
5. Считать доли по семплированным трейсам. Выборка смещена политикой; доли считают метрики.
6. Логировать в горячем цикле по строке на элемент. Телеметрия становится доминирующей нагрузкой и превращается в усилитель отказа.
7. Алертить на причины, а не на симптомы. «CPU выше 80%» будит без пользы; «доля успешных checkout ниже SLO» будит по делу.
8. Не измерять время ожидания в очереди. Спаны зелёные, пользователь ждёт сорок минут, в телеметрии этих минут нет вообще.
9. Не мерить рассинхронизацию часов. Все трейсы искажены, никто об этом не знает, и команды спорят, чей сервис виноват.
10. Игнорировать различие CLIENT и SERVER. Без обеих сторон невозможно отделить сеть от сервиса — то есть невозможно ответить на главный вопрос распределённой отладки.
11. Считать нулевой счётчик дублей доказательством отсутствия дублей. Чаще он означает сломанную дедупликацию.
12. Хранить трейсы 30 дней, а логи 3 дня. Инцидент разбирают по пересечению сигналов; куцый срок хранения любого из них обесценивает остальные.
13. Инструментировать только успешный путь. Ретраи, таймауты, срабатывания circuit breaker, попадания в DLQ обязаны создавать события — иначе самый интересный участок системы остаётся тёмным.

Мини-итог

• Наблюдаемость распределённой системы — это реконструкция причинности постфактум, потому что стек вызовов, отладчик и глобальное состояние недоступны принципиально (Чанди и Лампорт, 1985).
• Метрики, логи, трейсы и профили — проекции одного потока событий. Ценность даёт не плоскость, а швы: trace_id, span_id, resource attributes, бизнес-ключи и exemplars.
• Трейс — это DAG отношений «случилось-до», а не таймлайн. kind разделяет сеть и сервис, links описывают батчи, слияния и ретраи, имена спанов обязаны быть низкой кардинальности.
• Контекст обязан пересекать каждую границу процесса, потока и носителя. Рвётся он на очередях, воркерах, cron и аутбоксе — то есть там, где нет автоинструментации.
• Часы разъезжаются, и трейсы показывают это первыми: дети раньше родителей, отрицательные интервалы, выдуманное «сетевое время» после автокоррекции. Меряйте смещение часов и считайте нарушения причинности.
• Семплирование неизбежно и смещает выборку. Голова — дёшево и согласованно; хвост — дорого, но ловит ошибки. Практика — комбинация плюс детерминированное решение по trace_id.
• Причину ищут на критическом пути, а не в самом длинном спане; алгоритм O(n log n) находит заодно «слепые» интервалы собственной работы родителя.
• При веере в 100 узлов «медленно в 1% случаев» превращается в 63% медленных запросов. Меряйте p99 клиента, а не среднее сервера.
• Серые отказы диагностируются дифференциальной наблюдаемостью: расхождением взгляда системы на себя и взгляда клиента. Меряйте обе стороны каждой границы и связность попарно.
• Телеметрия сама теряет и дублирует данные. Отсутствие сигнала не доказывает отсутствие события; мета-метрики пайплайна обязательны.
• Exactly-once в трейсах не виден и не может быть виден: at-least-once — это норма, а число применённых эффектов знает только состояние. Наблюдаемость effectively-once = счётчик подавленных дублей + ключ идемпотентности в спанах + сверка инвариантов в данных.

Источники

• Sigelman et al., Dapper, a Large-Scale Distributed Systems Tracing Infrastructure (Google, 2010) — родоначальник современной трассировки с честными цифрами накладных расходов.
• Fonseca et al., X-Trace: A Pervasive Network Tracing Framework (NSDI 2007) — исходная идея сквозных метаданных.
• Kaldor et al., Canopy (SOSP 2017), Chow et al., The Mystery Machine (OSDI 2014) и Mace et al., Pivot Tracing (SOSP 2015) — трассировка как аналитика: критический путь, автоматический вывод причинности, запросы вдоль причинных путей.
• Dean, Barroso, The Tail at Scale (CACM 2013) — арифметика хвостов и хеджированные запросы.
• Huang et al., Gray Failure: The Achilles’ Heel of Cloud-Scale Systems (HotOS 2017) — дифференциальная наблюдаемость.
• Bronson et al., Metastable Failures in Distributed Systems (HotOS 2021) — отказы, поддерживающие сами себя.
• Chandy, Lamport, Distributed Snapshots: Determining Global States of Distributed Systems (1985) и Lamport, Time, Clocks, and the Ordering of Events in a Distributed System (1978).
• Corbett et al., Spanner: Google’s Globally-Distributed Database (OSDI 2012) — TrueTime, commit-wait и что из этого следует для метрик.
• W3C Trace Context и W3C Baggage — стандарты формата контекста на проводе; OpenTelemetry Specification, Semantic Conventions и Collector: tail sampling — модель данных и рабочие ручки.
• Majors, Fong-Jones, Miranda, Observability Engineering и Brandur Leach, Canonical Log Lines — широкие структурные события вместо предагрегации.
• Beyer et al., Google SRE Book: Monitoring Distributed Systems, SRE Workbook: Alerting on SLOs и Brendan Gregg, The USE Method.
• etcd: Monitoring и Jaeger: Architecture — практические справочники.

Что дальше

Наблюдаемость отвечает на вопрос «что сломалось» уже после того, как сломалось. Логичный следующий шаг — ломать самим, в контролируемых условиях, и проверять, что система ведёт себя так, как обещает документация: Тестирование распределённых систем: chaos engineering, Jepsen, симуляция. Там же выяснится приятное: вся инструментация, построенная в этой статье, — обязательное условие осмысленного chaos-эксперимента, потому что без корреляции невозможно отличить «система выдержала» от «система сломалась незаметно».