Observability

5.1Логи, метрики, трейсы и алерты

Самая «взрослая» глава темы. Мониторинг говорит, работает сервис или нет. Observability отвечает на вопрос «почему», причём для проблемы, которую ты не предвидел заранее. Разница между кандидатами видна сразу: один перечисляет инструменты, другой рассказывает, как от графика дошёл до строки кода. Второй нанимается.

Сначала — пять слов, без которых глава не читается

Дальше в главе постоянно встречаются пять терминов. Произносят их все, а объясняет мало кто. Разберёмся сразу, чтобы потом не спотыкаться.

1. Метрика — это число, снимаемое регулярно

У метрики одно число, и раз в 15–30 секунд записывают его текущее значение. Получается ряд «время → значение», по которому рисуют график: «сколько запросов в секунду», «сколько горутин живёт». Метрика ничего не помнит про отдельные события, она их суммирует. Отсюда её главное свойство: она стоит одинаково при 10 и при 100 000 запросах в секунду, потому что записывается всё равно одно число.

2. Спан — это отрезок времени с именем, трейс — дерево таких отрезков

Спан (span, дословно «промежуток») выглядит так: «операция такая-то шла с 12:00:03.100 по 12:00:03.412». На одну операцию приходится один спан: обработка HTTP-запроса, поход в базу, вызов соседнего сервиса. У спана есть имя, время начала и конца, статус и ссылка на родителя, то есть на тот спан, изнутри которого его запустили.

Трейс собирает все спаны одного запроса по ссылкам на родителей. Получается дерево: наверху «весь запрос целиком», под ним лежат куски, из которых он состоял. Нарисованное дерево спанов выглядит как диаграмма Ганта: полоски разной длины, вложенные друг в друга. Смотришь на такую картинку — и сразу видишь, какая именно полоска съела 900 мс из секунды.

3. Перцентиль — это «сколько процентов оказалось не хуже»

Возьми все 10 000 замеров времени ответа за минуту и выстрой их по возрастанию, как детей по росту. Тогда p99 покажет значение того, кто стоит на 99-м месте из ста: 99 % замеров оказались не больше него, 1 % оказался больше. Всё, никакой другой математики за этим нет.

Физический смысл проще, чем формулировка: p99 = 400 мс означает «из каждой сотни запросов девяносто девять уложились в 400 мс, а один был медленнее». При 1000 запросов в секунду это 10 недовольных пользователей каждую секунду, то есть 36 тысяч за час. p50 (он же медиана) показывает «типичный» запрос, ровно середину строя. p99.9 говорит про один запрос из тысячи.

Почему тогда не пользоваться средним? Потому что среднее берёт все значения и размазывает их в одно число, а время ответа устроено крайне несимметрично: снизу его подпирает жёсткий пол (быстрее скорости сети не ответишь), а сверху хвост уходит в бесконечность из-за ретраев, промахов кэша, пауз GC, блокировок в базе. Один запрос на 5 секунд в компании тысячи быстрых почти не сдвинет среднее, но он реально был, и его кто-то ждал.

Совсем на пальцах: если в комнате девять человек с зарплатой 100 тысяч и один миллиардер, то средняя зарплата уйдёт в десятки миллионов, и это число не описывает никого из присутствующих. Медиана останется 100 тысяч, и вот она описывает девятерых. С временем ответа то же самое, только «миллиардеры» и есть те пользователи, которые пишут в поддержку.

4. Кардинальность — это сколько разных графиков породит одна метрика

К метрике можно прицепить лейблы (метки) и считать запросы в разрезе: «число запросов с методом GET по маршруту /users с кодом 200». Проблема в том, что каждая уникальная комбинация значений лейблов даёт отдельный график, который надо хранить. Кардинальность и есть количество таких комбинаций, то есть число разных временных рядов, порождённых одной метрикой.

Считается умножением: 8 маршрутов × 5 методов × 6 кодов ответа = 240 рядов, нормально. Добавили лейбл user_id с миллионом значений, и получилось 240 миллионов рядов, а мониторинг умер. «Взрыв кардинальности» случается, когда кто-то положил в лейбл величину, у которой много разных значений.

5. Сэмплирование — это «сохраняем не всё, а выборку»

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

Три столпа: что каждый даёт и чего не даёт

Логи, метрики и трейсы не заменяют друг друга: они отвечают на разные вопросы и стоят принципиально по-разному. Отвечая, называй и сильную сторону, и границу применимости каждого.

Иногда добавляют четвёртый и пятый столп: профили (continuous profiling, то есть pprof, который собирают постоянно; отвечает на вопрос «какая строчка кода жрёт CPU прямо сейчас в проде», про них отдельный раздел ниже) и события (деплои, миграции, изменения флагов, без которых график «стало плохо в 14:03» не с чем сопоставить).

Структурированные логи и slog

Строка log.Printf("user %s failed: %v", id, err) хороша ровно до момента, когда логов становится гигабайт в день. После этого по ним нужно искать и агрегировать, а грепать неструктурированный текст значит писать регулярки по чужому форматированию. Структурированный лог пишет событие с полями: {"level":"error","msg":"payment failed","user_id":"u-42","order_id":"o-99","err":"timeout","trace_id":"4bf9…"}. Такое можно фильтровать (user_id = "u-42"), считать («сколько таких за час»), строить по нему графики и связывать с трейсами.

С Go 1.21 это есть в стандартной библиотеке, пакет log/slog, и это правильный дефолт: единый интерфейс, за которым можно поменять реализацию (zap, zerolog) без правки вызовов.

// 1) Handler решает, как и куда писать. Формат выбирает он, а не место вызова.
h := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
    Level:     slog.LevelInfo,
    AddSource: true,                       // файл:строка дорого, но на ERROR окупается
    ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
        if a.Key == "password" || a.Key == "authorization" {
            return slog.String(a.Key, "[REDACTED]")   // санитайзер на уровне хендлера
        }
        return a
    },
})
logger := slog.New(h).With(                // 2) With даёт общие поля всем записям
    slog.String("service", "billing"),
    slog.String("version", version),
)
slog.SetDefault(logger)

// 3) Типизированные атрибуты вместо форматирования: slog.String, slog.Int, slog.Duration
logger.Info("payment processed",
    slog.String("order_id", o.ID),
    slog.Int64("amount_minor", o.Amount),
    slog.Duration("took", time.Since(start)),
)

// 4) Группы вкладывают объекты в JSON
logger.Info("request done",
    slog.Group("http",
        slog.String("method", r.Method),
        slog.String("route", route),       // шаблон пути, не конкретный URL
        slog.Int("status", ww.Status()),
    ),
    slog.Group("db", slog.Int("queries", n), slog.Duration("time", dbTime)),
)

// 5) Контекстный логгер: логгер с полями запроса кладём в context
func Middleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        reqID := r.Header.Get("X-Request-Id")
        if reqID == "" { reqID = uuid.NewString() }
        sc := trace.SpanContextFromContext(r.Context())

        l := slog.Default().With(
            slog.String("request_id", reqID),
            slog.String("trace_id", sc.TraceID().String()),  // мост «лог -> трейс»
        )
        ctx := context.WithValue(r.Context(), loggerKey{}, l)
        w.Header().Set("X-Request-Id", reqID)
        next.ServeHTTP(w, r.WithContext(ctx))
    })
}

// 6) LogAttrs идёт без аллокаций, для горячих мест
logger.LogAttrs(ctx, slog.LevelDebug, "cache lookup", slog.String("key", k))

With возвращает логгер с предвычисленными атрибутами: встроенные хендлеры форматируют их один раз, прямо при вызове, поэтому каждая запись от такого логгера дешёвая, и он годится именно для «контекста, общего для многих записей». Группы дают вложенность в JSON: поля одной темы лежат под общим префиксом, в Elasticsearch это поле http.method, и оно не столкнётся с одноимённым полем из другой группы. А LogAttrs обходится без промежуточных аллокаций, если логирование стоит на горячем пути.

Уровни: когда какой

Что логировать в проде и чего в логах быть не должно

Ориентир простой: по логу видно, что произошло с конкретным запросом, даже когда доступа к данным пользователя нет.

Обеспечивают это так: санитайзер на уровне Handler (как ReplaceAttr выше), потому что полагаться на дисциплину каждого места вызова нельзя; типы, которые не умеют печататься (свой тип Secret string с методами String()/LogValue(), возвращающими [REDACTED]), и тогда ни логгер, ни %v значение не покажут (но структуру с таким полем JSON-хендлер отдаст в encoding/json, и без своего MarshalJSON секрет уйдёт в лог); хеширование вместо значения, если нужно только сравнивать; и ретеншн: логи с любыми персональными данными живут строго ограниченное время.

Prometheus: pull-модель и типы метрик

Prometheus сам ходит за метриками: раз в 15–30 секунд делает HTTP GET на /metrics каждой цели, получает текстовый снимок текущих значений и кладёт в свою TSDB. Приложение ничего никуда не отправляет, оно просто держит счётчики в памяти и умеет их отрендерить.

Отсюда же правило про счётчики: Prometheus устойчив к перезапускам именно потому, что counter только растёт, а функция rate() умеет распознать сброс на нуль при рестарте пода. Модель на этом и держится: можно потерять пару скрейпов и не потерять данные.

Четыре типа метрик

Лейблы и взрыв кардинальности

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

# Хорошо: 8 маршрутов × 5 методов × 6 кодов = 240 рядов
http_requests_total{route="/users/{id}", method="GET", code="200"}

# Катастрофа: у user_id миллион значений
http_requests_total{path="/users/12345", user_id="u-12345", code="200"}
#   1 000 000 путей × 1 000 000 пользователей = ряды, которых физически не может быть.
#   Prometheus начнёт съедать память гигабайтами и умрёт по OOM,
#   а с ним ляжет весь мониторинг в момент, когда он нужнее всего.

Что делать, если уже взорвалось: найти виновника (topk(10, count by (__name__)({__name__=~".+"})) и страница /tsdb-status в Prometheus), убрать лейбл в коде, а на время переходного периода отрезать его через metric_relabel_configs на стороне скрейпа. И запомнить правило: высокая кардинальность живёт в логах и трейсах, а не в метриках. Искать по order_id надо в логах, а долю ошибок смотреть в метриках.

Гистограммы, бакеты и откуда берётся p99

Гистограмма работает не как «распределение» из учебника. В Prometheus это набор обычных счётчиков: для каждой границы le хранится, сколько наблюдений оказалось не больше неё. Счётчики кумулятивные, поэтому le="+Inf" равен общему числу наблюдений. Ни одного исходного значения не сохраняется — и в этом весь фокус: 10 000 запросов сжимаются в шесть чисел, которые можно складывать между инстансами.

# Канонический запрос: сначала rate по бакетам, потом сумма по le, потом квантиль
histogram_quantile(0.99,
  sum by (le, route) (
    rate(http_request_duration_seconds_bucket{service="api"}[5m])
  )
)

Порядок здесь не декоративный: rate() нужен, чтобы счётчики стали «в секунду» и пережили рестарты подов; sum by (le) складывает бакеты всех инстансов, и именно это делает гистограмму агрегируемой; и только потом считается квантиль. Чаще всего забывают le в by, и тогда запрос вернёт пустой результат, а Prometheus 3 добавит к нему только предупреждение о пропавшем бакетном лейбле.

Метрики HTTP-сервиса: RED и USE, перцентили против среднего

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

• RED = Rate (частота), Errors (ошибки), Duration (длительность). Придумал Том Уилки. Это метод про сервис: что видит пользователь, снаружи. Отвечает на «сколько к нам приходит, сколько мы ломаем, как долго отвечаем».
• USE = Utilization (утилизация, доля занятого времени), Saturation (насыщение, очередь тех, кто не поместился), Errors (ошибки). Придумал Брендан Грегг. Это метод про ресурс: про CPU, диск, пул соединений, то есть про то, что внутри.

Они дополняют друг друга и применяются в таком порядке: RED говорит, что плохо, а USE говорит почему. Пользователь жалуется на медленные ответы (это RED сказал: Duration выросла), и мы идём смотреть, какой ресурс насытился (это скажет USE: очередь к пулу БД длиной 40).

Про Saturation скажу отдельно, потому что именно её пропускают. Утилизация отвечает на вопрос «занят ли ресурс», а насыщение отвечает на «сколько народу стоит в очереди к нему». Разница принципиальная: диск, занятый на 100 %, ещё может справляться, если очередь к нему пустая; а вот очередь из десяти ожидающих уже больно бьёт, даже если утилизация 70 %. Бытовая аналогия: утилизация кассы в супермаркете показывает, сколько времени кассир пробивает товары, а насыщение показывает, сколько человек стоит в очереди. Покупатель чувствует второе.

Есть ещё «четыре золотых сигнала» Google SRE: latency, traffic, errors, saturation. Это тот же RED плюс насыщение, и именно насыщение чаще всего забывают, хотя именно оно предсказывает проблему до того, как она станет видна пользователю. Пул соединений к БД, занятый на 95 %, означает «через десять минут всё встанет», а никакая доля ошибок этого ещё не покажет.

Конкретный минимум для Go-HTTP-сервиса:

// RED: одна гистограмма закрывает rate, errors и duration сразу,
// у histogram есть _count (это rate) и лейбл code (это errors).
httpDuration = prometheus.NewHistogramVec(prometheus.HistogramOpts{
    Name:    "http_request_duration_seconds",
    Buckets: []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5},
}, []string{"route", "method", "code"})   // шаблон пути, не URL

// Saturation: предупреждает заранее
dbPoolInUse   = prometheus.NewGaugeFunc(..., func() float64 { return float64(db.Stats().InUse) })
inFlight      = prometheus.NewGauge(...)  // сколько запросов обрабатывается прямо сейчас
queueDepth    = prometheus.NewGauge(...)

// Плюс бесплатно из коробки: go_goroutines, go_memstats_*, go_gc_duration_seconds,
// process_cpu_seconds_total, process_open_fds, их даёт стандартный коллектор.

Почему среднее врёт

Напомню определение из начала главы: перцентиль показывает место в строю, выстроенном по возрастанию. p99 = 400 мс читается как «99 из каждых 100 запросов уложились в 400 мс, один не уложился». Среднее же описывает распределение одним числом и потому пригодно только для симметричных распределений. Latency симметричной не бывает никогда: у неё есть жёсткий пол (быстрее сети не ответишь) и длинный правый хвост (ретраи, промахи кэша, паузы GC, блокировки в БД).

Классический пример, который стоит уметь рассказать за десять секунд: 989 запросов по 10 мс и 11 запросов по 5 секунд. Считаем среднее: (989 × 10 мс + 11 × 5000 мс) / 1000 = 65 мс, то есть «всё отлично, укладываемся в SLO». А p99 покажет 5 секунд, потому что на 990-м месте в строю стоит уже пятисекундный запрос. Одна и та же минута трафика, два вывода противоположных. Правы те 11 человек, которые ждали пять секунд.

Второе, что делает среднее опасным: оно неустойчиво к выбросам и при этом их прячет. Если каждый пятидесятый запрос на полсекунды застревает в блокировке базы, среднее при обычных 50 мс сдвинется на 10 мс, и на графике это теряется в обычных колебаниях. p99 и p99.9 покажут это сразу, потому что они смотрят именно туда, в хвост.

• p50 (медиана) описывает типичный опыт: «как обычно работает сервис».
• p95/p99 показывают опыт худших пользователей. Именно они формируют мнение о продукте.
• p99.9 и max — редкие аномалии: паузы GC, попадание в блокировку, «холодный» под после деплоя.
• Правило хвоста: если страница делает 20 параллельных запросов к бэкенду, то вероятность, что ни один не попал в p99, равна 0.99²⁰ ≈ 82 %. То есть почти каждый пятый показ страницы увидит «одну сотую худших» запросов. Хвост здесь не редкий случай, а массовое явление.

SLI, SLO и error budget

Три аббревиатуры, которые звучат как юридический жаргон, а на деле описывают одну простую цепочку: что меряем → какую цифру считаем нормой → сколько нам разрешено сломать. Все три начинаются с SL, то есть Service Level, «уровень обслуживания». Дальше меняется только последняя буква.

• SLI, Service Level Indicator, «показатель уровня обслуживания». Это то, что меряем: конкретная измеримая величина, отражающая качество глазами пользователя. Например: доля успешных запросов, доля запросов быстрее 300 мс, свежесть данных в отчёте. Держись за «глазами пользователя»: загрузка CPU показателем уровня обслуживания быть не может, потому что клиенту на неё наплевать.
• SLO — Service Level Objective, «цель по уровню обслуживания». Это цифра, которую мы себе назначили для SLI на конкретном окне времени: «99.9 % успешных запросов за 30 дней». Внутренний инженерный документ, никаких юристов.
• SLA, Service Level Agreement, «соглашение об уровне обслуживания». То же самое, но записанное в договор с клиентом, с деньгами и штрафами за нарушение. Инженерное SLO делают строже SLA, чтобы, пробив свою внутреннюю цель, успеть починиться до того, как придётся платить.

Error budget («бюджет ошибок») следует из SLO арифметически, и это переворот в мышлении, ради которого всё и затевалось. Если цель 99.9 %, то 0.1 % запросов разрешено завершиться неуспешно. За 30 дней это 43 минуты полной недоступности или, при 1000 rps, около 2.6 млн неуспешных запросов. Это не «допустимый брак», а бюджет на риск: ресурс, который тратится на выкатки, эксперименты и миграции. Бюджет цел, значит можно рисковать и катить смелее; бюджет сожжён, значит рискованные выкатки замораживают, пока окно не сдвинется.

Практическая деталь, которая показывает опыт: алертить надо не на «SLO нарушено» (это уже поздно), а на скорость сжигания бюджета (burn rate) с несколькими окнами: быстрое сжигание (14.4× за час) будит дежурного немедленно, медленное (3× за сутки) ложится задачей на утро. Многооконный подход одновременно ловит и резкие обвалы, и медленную деградацию, и почти не даёт ложных срабатываний.

Алертинг: симптомы, а не причины

Главное правило: алерт должен срабатывать на то, что чувствует пользователь, а не на то, что происходит внутри. «Доля 5xx выше 1 % пять минут» и «p99 оформления заказа выше 2 с» говорят о симптомах. «CPU 90 %», «мало места в /var», «перезапустился под» называют причины, и они не обязаны означать проблему.

Одно исключение назвать стоит. Причины годятся для алертов, когда они предсказывают отказ с большим запасом времени и требуют действия заранее: «диск заполнится через 4 часа при текущем темпе», «сертификат истекает через 7 дней», «пул соединений занят на 95 %». Такие алерты идут не в звонок, а в тикет.

Алерт-фатиг и что с ним делать

Алерт-фатиг наступает, когда дежурный перестаёт реагировать, потому что 90 % срабатываний ничего не значат. Это опаснее отсутствия мониторинга: создаёт иллюзию контроля. Лечение:

• Каждый алерт обязан требовать действия. Тест простой: «что я сделаю, когда он придёт в 4 утра?» Нет ответа, значит это не алерт, а график на дашборде.
• Разделение срочности. Page (звонок, реагировать сейчас) / ticket (посмотреть в рабочее время) / dashboard-only. Большинство существующих алертов после честной ревизии переезжают вниз.
• Ревизия по итогам дежурства. Регулярный разбор: какие алерты сработали, какие из них были ложными, что удалить. Алерт, который за квартал ни разу не привёл к действию, удаляем.
• Группировка и подавление. Alertmanager: group_by, чтобы 50 подов дали одно уведомление; inhibit_rules, чтобы «нода недоступна» глушила все алерты про поды на ней; silence на время запланированных работ.
• Runbook в каждом алерте. Ссылка на инструкцию «что проверить, что сделать» лежит прямо в тексте уведомления.

Distributed tracing: trace, span, propagation

Когда запрос проходит через шесть сервисов, ни метрики, ни логи не отвечают на вопрос «где потерялись 900 миллисекунд». Трейсинг отвечает: он собирает все операции одного запроса в дерево с временными интервалами.

• Trace покрывает весь путь одного запроса через систему; опознают его по trace_id (16 байт), одинаковому у всех участников.
• Span закрывает одну операцию внутри трейса: HTTP-хендлер, запрос в БД, вызов соседа, кусок вычисления. У спана есть span_id, parent_span_id, имя, время начала и конца, статус, атрибуты (ключ-значение) и события.
• Context propagation передаёт trace_id и span_id родителя следующему сервису. По стандарту W3C это HTTP-заголовок traceparent (и tracestate для вендорских данных). В Kafka это заголовки сообщения, в gRPC метаданные.

// Инструментирование в Go: контекст и есть носитель трейса
tp := sdktrace.NewTracerProvider(
    sdktrace.WithBatcher(otlpExporter),                       // батчинг: не по спану на запрос
    sdktrace.WithSampler(sdktrace.ParentBased(               // решение родителя главнее
        sdktrace.TraceIDRatioBased(0.05),                     // своих корневых 5 %
    )),
    sdktrace.WithResource(res),                               // service.name, version, env
)
otel.SetTracerProvider(tp)
otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator(
    propagation.TraceContext{}, propagation.Baggage{},         // W3C traceparent
))

// Входящий HTTP: middleware достаёт traceparent и создаёт серверный спан
handler := otelhttp.NewHandler(mux, "api")

// Исходящий HTTP: транспорт сам кладёт traceparent в заголовки
client := &http.Client{Transport: otelhttp.NewTransport(http.DefaultTransport)}

// Свой спан вокруг значимой операции
func (s *Service) Charge(ctx context.Context, id string) error {
    ctx, span := otel.Tracer("billing").Start(ctx, "Charge")
    defer span.End()
    span.SetAttributes(attribute.String("order.id", id))       // высокая кардинальность здесь уместна

    if err := s.gw.Do(ctx, id); err != nil {                   // ctx передаём дальше, иначе разрыв
        span.RecordError(err)
        span.SetStatus(codes.Error, err.Error())
        return err
    }
    return nil
}

Сэмплирование: зачем и какое

Хранить все трейсы невозможно: при 10 000 rps и десяти спанах на запрос это 100 000 спанов в секунду, то есть терабайты в сутки, и львиная доля из них описывает совершенно обычные успешные запросы, на которые никто никогда не посмотрит. Сэмплирование ищет компромисс между стоимостью и полнотой.

Практика: ParentBased обязателен в любом варианте. Решение принимают один раз на входе, и дальше его уважают все, иначе получатся «дырявые» трейсы, где часть спанов есть, а часть нет. Дальше берут либо простой TraceIDRatioBased(0.01…0.1), либо OpenTelemetry Collector с tail-based-политикой «сохраняем 100 % трейсов с ошибкой, 100 % медленнее 1 с и 1 % остальных». Отдельно стоит debug-флаг: заголовок от внутреннего клиента, который форсирует сэмплирование конкретного запроса, чтобы можно было воспроизвести проблему и гарантированно получить трейс.

Профили в проде: pprof и охота на утечки горутин

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

Профиль показывает, как некий ресурс распределён по строчкам кода прямо сейчас. Собирается он сэмплированием (термин из начала главы): рантайм не записывает каждое событие, а раз в N миллисекунд или каждые N килобайт останавливается и запоминает текущий стек вызовов. Накопив тысячи таких замеров, получаем статистику: «40 % замеров пришлись на json.Marshal». Поэтому профиль в проде почти бесплатен: единицы процентов накладных расходов, а не трассировка каждого вызова.

В Go профилировщик встроен в рантайм, включать нечего: достаточно импортировать net/http/pprof, и все профили появятся на служебном порту.

import (
    "net/http"
    _ "net/http/pprof"   // регистрирует /debug/pprof/* в http.DefaultServeMux
)

// Служебный порт отдельный от пользовательского и наружу не торчит:
// профиль отдаёт имена функций, аргументы командной строки и адреса, это разведданные.
go func() { _ = http.ListenAndServe("127.0.0.1:6060", nil) }()

* Два профиля со звёздочкой по умолчанию выключены и не собираются, пока их не включишь явно: runtime.SetBlockProfileRate(n) и runtime.SetMutexProfileFraction(n). Оба стоят накладных расходов, поэтому их обычно включают только на время расследования: у мьютексов ставят большой делитель, у блокировок — редкую выборку, там параметр задаёт наносекунды простоя на одно событие. Остальные доступны без настройки.

# CPU за 30 секунд под реальной нагрузкой
go tool pprof -http=: "http://127.0.0.1:6060/debug/pprof/profile?seconds=30"

# Утечка памяти: два снимка с интервалом, дифф между ними покажет, что выросло
curl -s http://127.0.0.1:6060/debug/pprof/heap > h1.out
sleep 600
curl -s http://127.0.0.1:6060/debug/pprof/heap > h2.out
go tool pprof -http=: -base h1.out h2.out

# Горутины: debug=1 агрегирует по стекам, debug=2 даёт полный дамп со статусом каждой
curl -s 'http://127.0.0.1:6060/debug/pprof/goroutine?debug=1'

// Профиль виден в pprof.Profiles() наравне с heap и goroutine
p := pprof.Lookup("goroutineleak")
p.WriteTo(os.Stdout, 1)   // стеки: на чём стоят утёкшие горутины
fmt.Println(p.Count())    // считать после WriteTo: профиль наполняется при сборе

// вывод на программе с тремя утёкшими горутинами (go1.27):
// goroutineleak profile: total 3
// 3 @ 0x88148 0x220a0 0x21c24 0xdbd84 0x8df64
// #	0xdbd83	main.leak.func1+0x23	/tmp/x/main.go:12
//
// 3
// Адреса и пути свои у каждого запуска; значение имеет первая строка (сколько
// горутин утекло) и сгруппированный стек под ней. Count() до WriteTo вернул бы 0.

// И по HTTP, если импортирован net/http/pprof:
//   curl 'http://127.0.0.1:6060/debug/pprof/goroutineleak?debug=1'

Health checks: /health против /ready

Два эндпоинта отвечают на два разных вопроса, и путать их дороже всего в этой главе (см. каскадный CrashLoopBackOff в главе 3.1).

// liveness: плоский ответ. Проверяем только то, что чинится перезапуском.
mux.HandleFunc("/health", func(w http.ResponseWriter, r *http.Request) {
    if time.Since(worker.LastTick()) > 5*time.Minute {  // воркер завис, рестарт поможет
        http.Error(w, "worker stalled", http.StatusServiceUnavailable)
        return
    }
    w.WriteHeader(http.StatusOK)
})

// readiness: реальная готовность. Значения обновляет фоновая проверка,
// чтобы проба не ходила в БД на каждый вызов kubelet.
mux.HandleFunc("/ready", func(w http.ResponseWriter, r *http.Request) {
    switch {
    case !ready.Load():                       // идёт старт или получен SIGTERM
        http.Error(w, "not ready", http.StatusServiceUnavailable)
    case !dbHealthy.Load():                   // обязательная зависимость
        http.Error(w, "db unavailable", http.StatusServiceUnavailable)
    default:
        w.WriteHeader(http.StatusOK)          // необязательные (кэш, рекомендации) не валят ready
    }
})

Дашборд сервиса: что должно быть на первом экране

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

// Транспорт сам кладёт request_id во все исходящие вызовы
type ridTransport struct {
    base http.RoundTripper
}

func (t ridTransport) RoundTrip(r *http.Request) (*http.Response, error) {
    if id := RequestIDFrom(r.Context()); id != "" {
        r = r.Clone(r.Context())
        r.Header.Set("X-Request-Id", id)
    }
    return t.base.RoundTrip(r)
}

client := &http.Client{
    Transport: otelhttp.NewTransport(ridTransport{http.DefaultTransport}),
}

# Норма: 8 маршрутов × 5 методов × 6 кодов = 240 рядов
http_requests_total{route="/users/{id}", method="GET", code="200"}

# Добавили «на всякий случай» user_id и сырой path:
http_requests_total{path="/users/12345", method="GET", code="200", user_id="u-12345"}
#   1 000 000 путей × 1 000 000 user_id × 5 × 6 ≈ рядов больше, чем атомов в бюджете.
#   На практике: через час Prometheus занимает 40 ГиБ, свопится, потом OOMKilled.
#   Мониторинг мёртв. Инцидент разбирать нечем.

# Rate
sum(rate(http_requests_total{service="api"}[5m]))

# Errors: доля, а не абсолютное число. 100 ошибок при 1 rps и при 10 000 rps значат разное
sum(rate(http_requests_total{service="api",code=~"5.."}[5m]))
  / sum(rate(http_requests_total{service="api"}[5m]))

# Duration
histogram_quantile(0.99, sum by (le) (rate(http_request_duration_seconds_bucket[5m])))

# Неправильно: усреднять уже посчитанные перцентили
avg(histogram_quantile(0.99, rate(http_request_duration_seconds_bucket[5m])))

# Правильно: сначала складываем бакеты всех подов, потом считаем квантиль от суммы
histogram_quantile(0.99,
  sum by (le) (rate(http_request_duration_seconds_bucket[5m]))
)

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             ^^ версия
                ^^^^ trace-id: ОДИН на весь запрос
                                                 ^^^^ span-id отправителя
                                                 (у получателя станет parent_span_id)
                                                                  ^^ флаги: 01 = sampled

5.2PromQL и Prometheus в работе

Какие метрики снимать, разобрано в главе 5.1. Дальше их путь: PromQL превращает точки опроса в скорости и доли, правило становится алертом, алерт уведомлением, а сами точки Prometheus складывает на диск. Выводы сняты на стенде с Prometheus 3.14 и Alertmanager 0.34.

Стенд и модель данных

Стенд собран из контейнеров: Prometheus 3.14.0 и Alertmanager 0.34.0 из образов quay.io/prometheus/*, два экземпляра сервиса orders на Go 1.27.1 с prometheus/client_golang 1.24.1 и генератор нагрузки: 8 запросов в секунду к app-1, 4 к app-2. Сервис отдаёт счётчик http_requests_total{route, code}, гистограмму http_request_duration_seconds{route} и info-метрику orders_build_info{version} со значением 1. Prometheus опрашивает его раз в 15 секунд (scrape_interval: 15s) и с тем же интервалом вычисляет правила.

Серия (time series) задаётся именем и полным набором меток. Имя хранится как метка __name__, метки job и instance добавляет Prometheus при опросе, другое значение любой метки даёт другую серию со своей историей. Запрос по имени возвращает instant vector: по одной точке на серию, самую свежую не старше пяти минут. Суффикс [1m] делает range vector (тип matrix) со всеми точками окна. Ответы API, сокращённо:

GET /api/v1/query?query=http_requests_total
{"status":"success","data":{"resultType":"vector","result":[
 {"metric":{"__name__":"http_requests_total","code":"200","instance":"app-2:8080","job":"orders","route":"/api/orders"},
  "value":[1789604917.035,"1426"]},
 …ещё три серии]}}

GET /api/v1/query?query=http_requests_total{instance="app-1:8080",route="/api/orders",code="200"}[1m]
{"status":"success","data":{"resultType":"matrix","result":[{"metric":{…},
  "values":[[1789604863.373,"2685"],[1789604878.373,"2745"],[1789604893.375,"2805"],[1789604908.373,"2866"]]}]}}

В минутное окно попали четыре опроса, отметки гуляют на пару миллисекунд. С Prometheus 3.0 окно открыто слева: точка ровно на левой границе в него не попадает. Range vector не нарисуешь, не сложишь и не агрегируешь, его принимают функции вроде rate и *_over_time:

http_requests_total[1m] + 1     parse error: binary expression must contain only scalar and instant vector types
sum(http_requests_total[1m])    parse error: expected type instant vector in aggregation expression, got range vector

На каждый опрос Prometheus пишет и синтетические серии: up (1 при удачном опросе), scrape_duration_seconds, scrape_samples_scraped. У app-1 это 2 мс и 256 точек, большая часть от метрик рантайма Go.

rate, irate и increase: что происходит внутри окна

rate(v[5m]) считает среднюю скорость роста счётчика в секунду. На границы окна точки почти никогда не ложатся, и зазоры до границ Prometheus достраивает. Серия app-1 с 4 запросами в секунду в момент T = 00:28:17.121:

s = http_requests_total{instance="app-1:8080",route="/api/orders",code="200"}

s[1m]                   2625 (T−48.745 с)  2685  2745  2805 (T−3.746 с)
increase(s[1m])         240.0053334518545
rate(s[1m])             4.000088890864242
irate(s[1m])            3.9994667377682975
increase(s[5m])         1198.9305413257357
s - s offset 5m         1200
increase(s[5m] anchored)  1200

Четыре точки покрывают 44,999 с из 60, прирост между крайними 180. Зазор слева 11,255 с, справа 3,746 с, оба меньше 1,1 среднего интервала между точками (16,5 с), и Prometheus считает, что серия шла через всё окно: 180 × 60 / 44,999 = 240,0053. Это increase, а rate делит его на 60. Отсюда дробные числа на целочисленном счётчике: increase оценивает прирост по средней скорости между крайними точками, и за пять минут оценка 1198,93 разошлась с разностью значений 1200.

В extrapolatedRate (promql/functions.go) ещё два правила: при зазоре больше 1,1 среднего интервала серия, видимо, началась или кончилась внутри окна, и прирост тянут на половину интервала; слева не заходят дальше момента, где счётчик был бы нулём. По умолчанию float-серии в 3.14 считаются как в 2.53. irate берёт две последние точки без достройки, 60 / 15,002 с = 3,9995: он ловит всплеск за один опрос, хорош на графике и плох в алерте. Модификатор anchored (экспериментальный, с 3.7 за флагом --enable-feature=promql-extended-range-selectors) берёт последнюю точку до окна и последнюю в нём без экстраполяции и возвращает целое.

Сброс счётчика и длина окна

В 00:28:37 app-2 заменили контейнером с новой версией, счётчик нового процесса начался с нуля:

s2 = http_requests_total{instance="app-2:8080",route="/api/orders",code="200"}

s2[3m] в 00:29:52.672   1246 1276 1306 1336 1366 1396 1426 | 5 33 62 92 121
increase(s2[3m])        328.3616462930528
resets(s2[3m])          1

Любое уменьшение rate и increase принимают за сброс, так что на gauge они выдают мусор. Пять запросов нового процесса до первого опроса учтены, а 12,7 секунды трафика старого после опроса в 00:28:24 пропали.

Теперь длина окна. За десять минут в каждый из 601 момента в [15s] попадала одна точка, в [30s] две, в [1m] четыре. rate(s[15s]) не вернул ни одного значения: ему нужны две точки. [30s] работает, пока не пропал ни один опрос: один таймаут, и на графике дыра, а алерт гаснет. Отсюда правило четырёх интервалов: потеряешь опрос, и в окне ещё три точки. Grafana держит для этого $__rate_interval, по её документации это max($__interval + scrape_interval, 4 × scrape_interval).

Агрегация, подзапросы и сдвиг во времени

sum by (job) оставляет перечисленные метки, sum without (instance) убирает перечисленные. В правилах удобнее without: до алерта доедут метки, о которых автор не подумал. Порядок функций важен, через 75 секунд после замены app-2:

sum by (job) (rate(http_requests_total{job="orders"}[3m]))       11.684251307748013
rate(sum by (job) (http_requests_total{job="orders"})[5m])      parse error: ranges only allowed for vector selectors
rate(sum by (job) (http_requests_total{job="orders"})[3m:15s])  46.43030303030302
sum by (job) (http_requests_total{job="orders"})[3m:15s]        7501 7681 … 8401 8582 5861 6040 … 6580

rate по каждой серии сам разбирается со сбросом app-2, сумма скоростей около 12 в секунду. А сумма счётчиков разных процессов уже не счётчик: она упала с 8582 до 5861, rate принял это за сброс, прибавил 8582 и завысил ответ вчетверо. Документация rate и irate прямо требует: сначала скорость, потом агрегация.

[3m:15s] задаёт подзапрос: внутреннее выражение вычисляется с шагом 15 с и даёт range vector. offset сдвигает выборку назад, @ ставит её на Unix-момент, оба пишутся сразу после селектора или подзапроса:

max_over_time(sum(rate(http_requests_total[1m]))[1h:1m])     12.023648103284325
min_over_time(sum(rate(http_requests_total[1m]))[1h:1m])     7.977777777777777
count_over_time(sum(rate(http_requests_total[1m]))[1h:1m])   60
sum(rate(http_requests_total[5m])) / sum(rate(http_requests_total[5m] offset 10m))   1.000240920794823
sum(http_requests_total @ 1789604793)                        7141
sum(rate(http_requests_total[5m])) offset 10m
  parse error: offset modifier must be preceded by an instant vector selector or range vector selector or a subquery

Минимум 7,98 пришёлся на минуты, когда app-2 стоял. Точек в [1h:1m] 60, а не 61: левая граница подзапроса тоже открыта, и по миграционному гайду Prometheus 3 выровненный foo[1m:1m] теперь даёт одну точку. Без шага подзапрос берёт evaluation_interval.

Сопоставление векторов: доля ошибок и метки из info-метрики

Бинарная операция ищет пары серий с одинаковым набором меток без учёта имени. Новая версия на app-2 отдаёт 3 % ответов 5xx, и доля «в лоб» получается единицей:

rate(http_requests_total{code="500"}[2m]) / rate(http_requests_total[2m])
  {code="500", instance="app-2:8080", job="orders", route="/api/orders"}   1

В пару числителю нашёлся он сам. ignoring (code) исключает метку из сравнения (on (…), наоборот, оставляет только перечисленные), но тогда справа на группу две серии, 200 и 500, и Prometheus откажется выбирать. Поэтому обе стороны сначала агрегируют до одного набора меток, а версию приклеивают тут же:

(
    sum by (instance) (rate(http_requests_total{code=~"5.."}[2m]))
  or
    sum by (instance) (rate(http_requests_total[2m])) * 0
)
/ sum by (instance) (rate(http_requests_total[2m]))
* on (instance) group_left (version) orders_build_info

  {instance="app-2:8080", version="1.5.0"}   0.026190476190476195
  {instance="app-1:8080", version="1.4.2"}   0

Без or … * 0 app-1 из результата пропадает: ошибок у него не было, а CounterVec заводит серию при первом обращении к этим меткам (здесь это Inc), так что паре в делении взяться неоткуда, и на дашборде вместо нуля «нет данных». Info-метрику держат ради меток, как kube_pod_info с узлом пода или target_info из OpenTelemetry. Умножение на её единицу значение не меняет, а group_left (version) переносит метку справа. Слева на группу on (instance) может быть несколько серий, справа только одна:

rate(http_requests_total[2m]) * on (instance) orders_build_info
  multiple matches for labels: many-to-one matching must be explicit (group_left/group_right)
sum by (instance) (rate(http_requests_total[2m])) * on (job) group_left (version) orders_build_info
  found duplicate series for the match group {job="orders"} on the right hand-side of the operation: […];
  many-to-many matching not allowed: matching labels must be unique on one side

В проде вторую ошибку ловят, когда у info-метрики ненадолго две серии на объект и старая не помечена устаревшей: по документации экспериментальной info() такой запрос падает до пяти минут, а сама info() в этом конфликте выбирает новую серию.

Staleness: куда девается серия пропавшей цели

В 00:36:59 контейнер app-2 остановили, последняя точка счётчика записана в 00:36:54. Через 20 секунд:

up{instance="app-2:8080"}                        0
s2                                               пусто
last_over_time(s2[10m])                          960
absent(up{job="orders",instance="app-2:8080"})   пусто
absent(s2)                                       {code="200", instance="app-2:8080", route="/api/orders"}  1
absent_over_time(s2[5m])                         пусто, через 5 мин после последней точки: 1

Серия пропала из instant-запросов сразу, а не через пять минут. Когда опрос не удался или серия исчезла из ответа цели, Prometheus пишет в прежние серии staleness marker, особое значение NaN, и после него селектор считает серию закончившейся; так же при исчезновении цели из service discovery и с сериями, которые правило перестало возвращать. Пять минут --query.lookback-delta остаются пределом поиска точки для серий без маркера. Prometheus передаёт маркеры и по remote write, а promtool push metrics их не шлёт: записанная им серия отвечала через 290 секунд и пропала к 310-й. absent возвращает 1 для пустого вектора, absent_over_time для окна без точек; алерты на пропажу данных во втором вопросе.

Recording rules и правила алертов

Recording rule раз в evaluation_interval вычисляет выражение и сохраняет результат новой серией: тяжёлый запрос считается один раз, алерт и дашборд смотрят на одно число. Имена по соглашению документации Prometheus: level:metric:operations, то есть оставшиеся метки, имя метрики без _total, операции от последней к первой.

groups:
  - name: orders-recording
    rules:
      - record: instance_code:http_requests:rate1m
        expr: sum without (route) (rate(http_requests_total{job="orders"}[1m]))
      - record: instance:http_requests_5xx_per_requests:ratio_rate1m
        expr: |2
            sum without (code) (instance_code:http_requests:rate1m{code=~"5.."})
          /
            sum without (code) (instance_code:http_requests:rate1m)
      - record: job:http_requests_5xx_per_requests:ratio_rate1m
        expr: |2
            sum without (instance, code) (instance_code:http_requests:rate1m{code=~"5.."})
          /
            sum without (instance, code) (instance_code:http_requests:rate1m)
  - name: orders-alerts
    rules:
      - alert: OrdersInstanceErrors
        expr: instance:http_requests_5xx_per_requests:ratio_rate1m > 0.05
        for: 3m
        labels: {severity: ticket}
        annotations:
          summary: "{{ $labels.instance }}: {{ $value | humanizePercentage }} ответов 5xx"
      - alert: OrdersErrorBudgetBurn
        expr: job:http_requests_5xx_per_requests:ratio_rate1m > 0.2
        for: 1m
        keep_firing_for: 2m
        labels: {severity: page}
        annotations:
          summary: "{{ $labels.job }}: {{ $value | humanizePercentage }} ответов 5xx"

Для доли по job делят сумму на сумму, а не усредняют доли экземпляров, иначе 8 и 4 запроса в секунду весили бы одинаково. Пока выражение возвращает серию, а for не истёк, алерт pending, потом firing. Условие пропало, и алерт гаснет на первом же вычислении, а с keep_firing_for горит ещё заданное время. $labels и $value берутся из сработавшей серии, активные алерты пишутся в серию ALERTS.

$ promtool check rules bad.yml
Checking bad.yml
  FAILED:
bad.yml: 5:15: group "bad", rule 1, "instance:http_requests:rate5m": could not parse expression: 1:49: parse error: unclosed left parenthesis
bad.yml: group "bad", rule 2, "Broken": annotation "summary": template: __alert_Broken:1: unexpected "}" in operand

promtool test rules гоняет правила на синтетических сериях. В тесте стенда '0+150x40' даёт 10 запросов в секунду, а '_x7 0+30x33' добавляет 2 ошибки в секунду начиная с 1m45s. Ожидание «в 6m горит OrdersInstanceErrors» проходит, в 5m падает:

$ promtool test rules tests/orders_test.yml
  SUCCESS
$ promtool test rules tests/orders_5m_test.yml
  FAILED:
    alertname: OrdersInstanceErrors, time: 5m,
        exp:[
            0:
              Labels:{alertname="OrdersInstanceErrors", instance="app-1:8080", job="orders", severity="ticket"}
              …
        got:[]

В 2m у серии ошибок точки 0 и 30, экстраполяция влево упирается в ноль, rate даёт 0,5 вместо 2, и доля 4,76 % ниже порога. В 2m15s доля 9,1 % и алерт в pending, в 5m15s он firing. В CI такой тест ловит правку, после которой алерт перестал срабатывать.

Alertmanager: маршруты, группировка, inhibition и silence

После вычисления Prometheus шлёт в Alertmanager алерты в firing и погасшие, один и тот же не чаще --rules.alert.resend-delay (минута), а кому и в каком составе прийти уведомлению, решает Alertmanager. Получатель на стенде печатает строку на каждый webhook:

route:
  receiver: team
  group_by: [alertname, job]
  group_wait: 30s
  group_interval: 2m
  repeat_interval: 4h
  routes:
    - matchers: ['severity="page"']
      receiver: pager
      group_wait: 10s
receivers:
  - name: team
    webhook_configs: [{url: "http://hook:9000/hook"}]
  - name: pager
    webhook_configs: [{url: "http://hook:9000/hook"}]
inhibit_rules:
  - source_matchers: ['alertname="OrdersErrorBudgetBurn"']
    target_matchers: ['severity="ticket"']
    equal: [job]

Алерт спускается в первый подходящий дочерний маршрут (дальше только при continue: true), и алерты с одинаковыми метками из group_by составляют группу. group_wait держит её первое уведомление, чтобы дождаться соседей и подавляющих алертов. По тику group_interval уходят изменения, а repeat_interval повторяет то, что не менялось. Inhibition глушит цели, пока горит источник с теми же метками из equal, silence глушит по матчерам на время.

Сценарий: в 00:46:33 обе реплики отдают 40 % ответов 5xx, в 00:51:04 10 %, в 00:58:04 на app-2 ставят silence, в 00:58:09 ошибки кончаются. Лог получателя:

00:48:25 receiver=pager status=firing group={alertname=OrdersErrorBudgetBurn,job=orders} alerts=1
00:54:15 receiver=team status=firing group={alertname=OrdersInstanceErrors,job=orders} alerts=2
00:54:25 receiver=pager status=resolved group={alertname=OrdersErrorBudgetBurn,job=orders} alerts=1
01:00:15 receiver=team status=resolved group={alertname=OrdersInstanceErrors,job=orders} alerts=1
  resolved {alertname=OrdersInstanceErrors,instance=app-1:8080,severity=ticket}

Без inhibition команде пришло бы второе уведомление о том же сбое. Тикеты ушли в 00:54:15, а не в 00:53:45, когда погас page: группа появилась в 00:49:45, её тики пришлись на 00:50:15, 00:52:15 и 00:54:15, и на первых двух всё было подавлено. Оба экземпляра пришли одним уведомлением, потому что instance нет в group_by. Silence ставили так:

$ amtool --alertmanager.url=http://localhost:9093 silence add \
    alertname=OrdersInstanceErrors instance=app-2:8080 \
    --duration=1h --author=oncall --comment="canary rollback in progress"
c1d66a93-b559-41e2-b482-dcc7f8304d12

Нативные гистограммы

Классическая гистограмма из главы 5.1 состоит из серий _bucket{le} с заранее выбранными границами. Нативная укладывает распределение в одну серию: границы растут в геометрической прогрессии, а пустые бакеты не хранятся вовсе. В client_golang её включают поля опций:

Buckets: []float64{.01, .025, .05, .1, .25, .5, 1}, // классические остаются
NativeHistogramBucketFactor:     1.1,       // соседние границы отличаются не больше чем на 10%
NativeHistogramMaxBucketNumber:  160,       // потолок числа бакетов
NativeHistogramMinResetDuration: time.Hour, // не сбрасывать чаще раза в час

Библиотека берёт ближайший не больший множитель вида 2²⁻ⁿ, для 1.1 это 2^1/8 ≈ 1,0905, восемь бакетов на удвоение. Сверх потолка гистограмма сбрасывается, а если MinResetDuration не прошёл, снижает разрешение; без потолка документация поля называет её вектором для DoS. В client_golang 1.24 поля ещё экспериментальные, в Prometheus нативные гистограммы стабильны с 3.8 и включаются scrape_native_histograms. Нативную часть client_golang отдаёт только в protobuf, curl /metrics покажет классические бакеты, а always_scrape_classic_histograms сохраняет обе формы.

Для сравнения 3 % запросов замедлили до 260–320 мс. Генератор нагрузки считал точный p99 по своим замерам, поминутно от 281 до 298 мс:

histogram_quantile(0.99, sum by (le) (rate(http_request_duration_seconds_bucket[5m])))   0.39941170380740243
histogram_quantile(0.99, sum(rate(http_request_duration_seconds[5m])))                  0.29715458167274456
histogram_fraction(0, 0.3, sum(rate(http_request_duration_seconds[5m])))                0.9910951475092551
count by (__name__) ({__name__=~"http_request_duration_seconds.*"})
  http_request_duration_seconds 4   _bucket 32   _count 4   _sum 4

Медленные запросы попали в классический бакет (0.25, 0.5], и интерполяция дала 399 мс, на 40 % больше правды. У нативной вокруг 300 мс бакеты шириной 23–27 мс, и ошибка меньше ширины бакета. На вопрос «какая доля быстрее 300 мс» histogram_fraction ответит при любом пороге, а классическая знает ответ только для своих le. Серия одна на маршрут и экземпляр, в каждой около 40 занятых бакетов, и sum складывает гистограммы целиком, без by (le). Одна ловушка: remote_write с протоколом 1.0 по умолчанию их не отправляет (send_native_histograms: false), с сообщением 2.0 отправляет всегда.

Хранение и кардинальность

Свежие точки живут в head, в памяти, а перед этим дописываются в WAL (журнал упреждающей записи), по которому head восстанавливается после рестарта; заполненные чанки head сбрасывает в chunks_head и читает через mmap. Двухчасовыми порциями данные уходят в неизменяемые блоки с чанками, индексом и meta.json, позже блоки сливаются. Через 46 минут работы блоков ещё нет. Снапшот через админский API (флаг --web.enable-admin-api) сбрасывает head в блок; снапшотами же документация советует делать резервные копии:

$ docker exec dv-c2-prom du -sh /prometheus/wal /prometheus/chunks_head
1.7M	/prometheus/wal
128.0K	/prometheus/chunks_head
$ curl -s -XPOST localhost:19090/api/v1/admin/tsdb/snapshot
{"status":"success","data":{"name":"20260917T010210Z-322a559e0a48212c"}}

В каталоге блока лежат chunks/, index, meta.json и tombstones. В meta.json 1395 серий и 239 712 точек за 45,5 минуты, чанки заняли 711 КБ, около трёх байт на точку (документация для оценки диска называет в среднем 1–2). Retention по умолчанию 15 дней, удаляются только целиком устаревшие блоки. В 3.14 флаги --storage.tsdb.retention.time и .size в --help помечены [DEPRECATED]: настройки переехали в перечитываемый конфиг, и экземпляр с настройкой ниже отдаёт в /api/v1/status/runtimeinfo "30d or 50GiB".

storage:
  tsdb:
    retention:
      time: 30d
      size: 50GB

Лимит размера учитывает WAL, но удаляет только блоки, а компакция временно держит и старые блоки, и новый: отсюда совет документации ставить не выше 80–85 % диска. Долгое хранение и общий вид по многим серверам даёт remote_write: Prometheus читает свой WAL и шлёт точки во внешнее хранилище, а недоступность приёмника переживает без потерь около двух часов, пока WAL не обрезан. Режим --agent оставляет только опрос и remote_write.

Почему user_id в метке убивает Prometheus, разобрано в главе 5.1. Виновника дешевле всего искать на странице TSDB status (/tsdb-status) или в её API: числа берутся из индекса head.

$ curl -s 'localhost:19090/api/v1/status/tsdb?limit=3' \
    | jq -r '.data | .seriesCountByMetricName[], .labelValueCountByLabelName[] | "\(.value) \(.name)"'
80 prometheus_http_request_duration_seconds_bucket
72 prometheus_http_response_size_bytes_bucket
65 prometheus_http_requests_total
428 __name__
92 le
63 handler

Лидирует сам Prometheus: счётчик запросов он заводит сразу на все 63 своих HTTP-обработчика, а у вызванных гистограммы множатся на бакеты. Запрос topk(3, count by (__name__) ({__name__=~".+"})) вернул те же три метрики, но читает точку из каждой серии, а promtool tsdb analyze по блоку показывает ещё метки с наибольшим churn, рождением и смертью серий.

Метрики из Go: свой Registry, promhttp и метрики рантайма

reg := prometheus.NewRegistry()
requests := promauto.With(reg).NewCounterVec(prometheus.CounterOpts{
    Name: "http_requests_total",
    Help: "HTTP requests by route and status code.",
}, []string{"route", "code"})
reg.MustRegister(
    collectors.NewGoCollector(collectors.WithGoCollectorRuntimeMetrics(collectors.MetricsAll)),
    collectors.NewProcessCollector(collectors.ProcessCollectorOpts{}),
)
mux.Handle("GET /metrics", promhttp.HandlerFor(reg, promhttp.HandlerOpts{Registry: reg}))

promauto.NewCounter без With регистрирует метрику в глобальном DefaultRegisterer, а promhttp.Handler() отдаёт глобальный реестр, где уже есть коллекторы Go и процесса. Это удобно, пока конструктор вызывается один раз; второй вызов, например во втором тесте пакета, падает с panic: duplicate metrics collector registration attempted. Свой реестр, переданный в конструктор, это снимает: promauto.With(reg) сохраняет удобство, а коллекторы в пустой реестр добавляют явно. HandlerFor договаривается о формате, включая protobuf, а HandlerOpts.Registry заводит счётчик ошибок сбора promhttp_metric_handler_errors_total.

GoCollector по умолчанию         29 семейств go_*, 35 строк: go_memstats_*, go_goroutines, go_gc_duration_seconds…
+ WithGoCollectorRuntimeMetrics  133 семейства, 219 строк: всё из runtime/metrics Go 1.27

histogram_quantile(0.99, sum by (instance, le) (rate(go_sched_latencies_seconds_bucket[5m])))
  app-1 0.000574   app-2 0.000464   prometheus 0.000703

Самая полезная из новых go_sched_latencies_seconds: сколько горутины провели runnable до получения процессора, то есть насыщение CPU из USE. Рядом go_cpu_classes_gc_total_cpu_seconds_total для доли CPU на сборку мусора и go_sync_mutex_wait_total_seconds_total для конкуренции за мьютексы. go_memstats_* в client_golang тоже считаются через runtime/metrics; сопровождающие советуют их оставить, а остальное включать по надобности правилами MetricsScheduler, MetricsGC, ведь MetricsAll добавил восемь классических гистограмм по 8–12 бакетов.

up{job="orders"} == 0                              цель в discovery есть, но не отвечает
absent(up{job="orders"})                           пропали все цели job
(count(up{job="orders"} == 1) or vector(0)) < 2    живых реплик меньше двух
absent_over_time(batch_last_success_timestamp_seconds{job="batch"}[26h])

replica=a и replica=b
  /api/v2/alerts: [{"alertname":"Watchdog","replica":"a",…},{"alertname":"Watchdog","replica":"b",…}]
  01:22:08 receiver=team status=firing group={alertname=Watchdog} alerts=2

те же реплики с alert_relabel_configs: [{action: labeldrop, regex: replica}]
  /api/v2/alerts: [{"alertname":"Watchdog","severity":"none"}]
  01:23:08 receiver=team status=firing group={alertname=Watchdog} alerts=1

http_requests_total{instance="app-1:8080",code="500",route="/api/orders"}
родилась с первыми ошибками в 00:46:33; первые точки 00:46:43=15, 00:46:58=47, 00:47:13=67

в 01:03:07   значение счётчика           576
             increase(…[1h])             570.708957021963
             increase(…[1h] anchored)    561

5.3OpenTelemetry в Go-сервисе

Трассировка в Go ломается тихо: SDK не настроен, пропагатор пустой, процесс вышел раньше, чем ушла пачка спанов, а в логе ни одной ошибки. Ниже сервис собран по частям, от API до Collector с tail sampling, и на каждом шаге видно, что доехало до Jaeger.

Прогоны: Go 1.27.1, go.opentelemetry.io/otel v1.46.0, contrib v0.71.0, otelpgx v0.12.0, franz-go v1.21.7; в контейнерах Collector contrib 0.161.0, Jaeger 2.21.0, Postgres 18 и Kafka 4.3.1.

API и SDK: что подключает библиотека, а что main

API (go.opentelemetry.io/otel, otel/trace) даёт интерфейсы: tracer, спан, атрибут. SDK (otel/sdk/…) их реализует: сэмплер, процессоры, экспортеры, ресурс. Библиотеки вроде otelhttp импортируют только API и берут глобальный провайдер, а SDK настраивает main, и экспортер с версией SDK выбирает сервис. Пока SDK нет, провайдер раздаёт пустышки:

tr := otel.Tracer("example.com/orders") // SDK никто не настраивал
ctx, span := tr.Start(context.Background(), "charge")
sc := span.SpanContext()
fmt.Printf("span: %T recording=%v valid=%v trace_id=%s\n", span, span.IsRecording(), sc.IsValid(), sc.TraceID())
span.End()

h := http.Header{}
otel.GetTextMapPropagator().Inject(ctx, propagation.HeaderCarrier(h))
fmt.Printf("propagator fields=%v headers after Inject=%v\n", otel.GetTextMapPropagator().Fields(), h)

otel.SetTracerProvider(sdktrace.NewTracerProvider()) // SDK появился позже, tr тот же
_, span2 := tr.Start(context.Background(), "charge")
fmt.Printf("after SetTracerProvider: %T recording=%v valid=%v\n", span2, span2.IsRecording(), span2.SpanContext().IsValid())

$ go build -o noop ./cmd/noop && ./noop
span: global.nonRecordingSpan recording=false valid=false trace_id=00000000000000000000000000000000
propagator fields=[] headers after Inject=map[]
after SetTracerProvider: *trace.recordingSpan recording=true valid=true

Пустышка ничего не пишет и не падает. Tracer, взятый до настройки SDK, пересоздавать не нужно: глобальный провайдер передаст вызовы настоящему. А пропагатор по умолчанию пустой и заголовков не пишет даже при настоящем SDK.

Resource описывает источник (service.name, версию, окружение) и едет в каждой пачке OTLP. Без имени SDK подставит имя бинарника, и сервисы с бинарником app сольются в Jaeger в один:

$ go build -o orders ./cmd/resource && ./orders default | grep service.name
  service.name=unknown_service:orders

Ресурс по умолчанию читает OTEL_SERVICE_NAME и OTEL_RESOURCE_ATTRIBUTES. Если имя есть и в коде, решает порядок слияния: в resource.Merge(resource.Default(), свой) побеждает код, в resource.New с WithAttributes(…) и WithFromEnv() последний по списку детектор, то есть переменная.

Имена атрибутов задают семантические конвенции (semconv): в Go это пакеты по версиям (в otel v1.46.0 последний semconv/v1.43.0) со своим SchemaURL. Ресурсы с разными схемами не сливаются:

_, err := resource.Merge(resource.Default(), // внутри SDK схема 1.43.0
    resource.NewWithAttributes(oldsemconv.SchemaURL, // semconv/v1.26.0
        oldsemconv.ServiceName("orders")))
fmt.Println("err:", err)
// err: conflicting Schema URL: https://opentelemetry.io/schemas/1.43.0 and https://opentelemetry.io/schemas/1.26.0

Так бывает после обновления SDK со старым импортом semconv. Бери версию, которую импортирует sdk/resource, или resource.NewSchemaless.

TracerProvider: экспортер, процессор и Shutdown

func setupTracing(ctx context.Context, name string, ratio float64) (func(context.Context) error, error) {
    exp, err := otlptracegrpc.New(ctx) // адрес из OTEL_EXPORTER_OTLP_ENDPOINT, иначе localhost:4317
    if err != nil {
        return nil, fmt.Errorf("otlp exporter: %w", err)
    }
    res, err := resource.Merge(resource.Default(), resource.NewWithAttributes(semconv.SchemaURL,
        semconv.ServiceName(name), semconv.ServiceVersion(version)))
    if err != nil {
        return nil, fmt.Errorf("resource: %w", err)
    }
    tp := sdktrace.NewTracerProvider(
        sdktrace.WithBatcher(exp), // BatchSpanProcessor
        sdktrace.WithResource(res),
        sdktrace.WithSampler(sdktrace.ParentBased(sdktrace.TraceIDRatioBased(ratio))),
    )
    otel.SetTracerProvider(tp)
    otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator(
        propagation.TraceContext{}, propagation.Baggage{}))
    return tp.Shutdown, nil
}

Экспортеров OTLP два: otlptracegrpc и otlptracehttp (POST на /v1/traces, по умолчанию protobuf). Collector слушает gRPC на 4317, HTTP на 4318. Порт перепутан (export создаёт спаны и зовёт Shutdown с таймаутом 5 секунд):

$ OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4318 ./export -proto grpc -n 5
grpc/batch: 5 spans, span.End() avg 1µs
shutdown error: context deadline exceeded
Shutdown took 5.002s

gRPC-экспортер считает недоступность временной и повторяет попытки до конца контекста, наружу выходит только context deadline exceeded. Так же молча ломается WithEndpoint без WithInsecure(): экспортер идёт по TLS (в переменной это решает схема, http:// или https://). HTTP-экспортер на 4317 сразу пишет в лог malformed HTTP response.

SimpleSpanProcessor экспортирует спан прямо в End(), BatchSpanProcessor кладёт в очередь на 2048 спанов и раз в 5 секунд шлёт пачки до 512 штук:

$ export OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4317
$ ./export -processor batch -n 20
grpc/batch: 20 spans, span.End() avg 0s
…
$ ./export -processor simple -n 20
grpc/simple: 20 spans, span.End() avg 451µs
…
$ OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4999 ./export -processor simple -n 2 -shutdown=false
2026/09/17 04:50:07 traces export: exporter export timeout: rpc error: code = Unavailable desc = connection error: …
…
grpc/simple: 2 spans, span.End() avg 10.001884s

С недоступным Collector каждый End(), а с ним и ответ пользователю, ждёт таймаут экспорта в 10 секунд. У батчера спаны лежат в памяти до отправки, и процесс без Shutdown их теряет (jaeger-count.sh считает trace_id сервиса в Jaeger):

$ OTEL_SERVICE_NAME=exp-shutdown ./export -n 20
…
$ OTEL_SERVICE_NAME=exp-noshutdown ./export -n 20 -shutdown=false
…
$ for s in exp-shutdown exp-noshutdown; do printf '%s: ' $s; ./jaeger-count.sh $s; done
exp-shutdown: 20
exp-noshutdown: 0

В поде так пропадают до пяти секунд трейсов перед каждым рестартом. Спан, закрытый после Shutdown, тоже не уходит, поэтому по SIGTERM зовут srv.Shutdown(sctx), потом shutdownTracing(sctx) с общим таймаутом меньше terminationGracePeriodSeconds: иначе недоступный Collector съест срок и остановку оборвёт SIGKILL. Остановка HTTP-сервера разобрана в статье «Веб-сервисы» раздела Go, глава 10.2.

otelhttp, otelgrpc и pgx

Спаны на входящие и исходящие вызовы дают обёртки из contrib. Цепочка в опытах: gateway → orders → payments → Postgres. chain.sh поднимает её и шлёт запросы, jtraces.py печатает трейс из API Jaeger.

handler := otelhttp.NewHandler(mux, *name,
    otelhttp.WithFilter(func(r *http.Request) bool { return r.URL.Path != "/healthz" }))

var client = &http.Client{Transport: otelhttp.NewTransport(http.DefaultTransport), Timeout: 5 * time.Second}

cfg, err := pgxpool.ParseConfig(*dsn)
cfg.ConnConfig.Tracer = otelpgx.NewTracer()

srv := grpc.NewServer(grpc.StatsHandler(otelgrpc.NewServerHandler()))
conn, err := grpc.NewClient("127.0.0.1:50051",
    grpc.WithTransportCredentials(insecure.NewCredentials()),
    grpc.WithStatsHandler(otelgrpc.NewClientHandler()))

$ ./chain.sh "" "" /orders/42 /healthz && ./jtraces.py gateway d
GET /orders/42 -> 200
GET /healthz -> 200
traces with gateway: 1
trace 88ca0ce28ff70e3b14a174c9c5b97450
  gateway   GET /orders/{id}         span=dccbd86e947047de parent=-                SERVER   UNSET
  gateway   HTTP GET                 span=09eb75a5e6e47d6a parent=dccbd86e947047de CLIENT   UNSET
  orders    GET /orders/{id}         span=633372b4e28a40b4 parent=09eb75a5e6e47d6a SERVER   UNSET
  orders    load order               span=ce309bbca0a8431b parent=633372b4e28a40b4 INTERNAL UNSET
  orders    HTTP GET                 span=646d2b58198650eb parent=ce309bbca0a8431b CLIENT   UNSET
  payments  GET /payments/{id}       span=86c796c2286f0f6f parent=646d2b58198650eb SERVER   UNSET
  payments  pool.acquire             span=0700d5cad8aa1629 parent=86c796c2286f0f6f CLIENT   UNSET
  payments  connect                  span=9fca51937ce75e2f parent=0700d5cad8aa1629 CLIENT   UNSET
  payments  SELECT                   span=ccb3aa7661ac83cd parent=86c796c2286f0f6f CLIENT   UNSET
  payments  SELECT                   span=d9307bebbd99a666 parent=ccb3aa7661ac83cd CLIENT   UNSET

• Имя серверного спана GET /orders/{id} собрано из метода и r.Pattern (ServeMux заполняет его с Go 1.23); второй аргумент NewHandler с otelhttp v0.69.0 на имя не влияет. У роутера без r.Pattern имя будет GET, и нужен WithSpanNameFormatter.
• /healthz трейса не оставил, его отрезал WithFilter. Успешные спаны остались UNSET: OK инструментирование само не ставит.
• otelpgx пишет ожидание пула, подключение и запрос, вложенный SELECT готовит выражение на первом вызове. В db.query.text плейсхолдеры без значений. Спан запроса будет, только если в контексте уже есть записываемый спан.
• otelgrpc ставится как stats.Handler, traceparent едет в метаданных. Перехватчики вроде UnaryServerInterceptor устарели в v0.46.0, к v0.63.0 их удалили.

Свои спаны: атрибуты, события и ошибки

func loadOrder(ctx context.Context, id string) error {
    ctx, span := tracer.Start(ctx, "load order")
    defer span.End()
    span.SetAttributes(attribute.String("order.id", id))
    span.AddEvent("cache miss", trace.WithAttributes(attribute.String("cache", "redis")))
    time.Sleep(15 * time.Millisecond)

    code, err := call(ctx, client, *next+"/payments/"+id)
    if err == nil && code >= 400 {
        err = fmt.Errorf("payments returned %d", code)
    }
    if err != nil {
        span.RecordError(err)                                // событие exception
        span.SetStatus(codes.Error, "payment lookup failed") // статус спана
        return err
    }
    return nil
}

RecordError только добавляет событие exception, статус остаётся Unset; ошибкой спан делает SetStatus. Заказа 13 в базе нет:

$ ./chain.sh "" "" /orders/13 && ./jtraces.py gateway d | head -7
GET /orders/13 -> 502
traces with gateway: 1
trace 4278e79403dda87da52c7422154f6512
  gateway   GET /orders/{id}         span=ba405b7c43c459fa parent=-                SERVER   ERROR
  gateway   HTTP GET                 span=80b656f31a8d22b4 parent=ba405b7c43c459fa CLIENT   ERROR
  orders    GET /orders/{id}         span=8f2a11810b33c155 parent=80b656f31a8d22b4 SERVER   ERROR
  orders    load order               span=a3233ba7d84841a2 parent=8f2a11810b33c155 INTERNAL ERROR payment lookup failed
  orders    HTTP GET                 span=fc4a180dc471cb9d parent=a3233ba7d84841a2 CLIENT   ERROR
  payments  GET /payments/{id}       span=9bf3b45d6bd433f0 parent=fc4a180dc471cb9d SERVER   UNSET

Серверный спан payments с ответом 404 остался UNSET: по конвенциям HTTP 4xx для сервера не ошибка. Клиентский спан orders на тот же 404 получил ERROR и error.type=404, а 502 помечен ошибкой с обеих сторон. В Jaeger у load order значок ошибки, теги error=true, otel.status_code=ERROR и otel.status_description, в Events cache miss и exception.

Контекст на проводе: traceparent, tracestate, baggage

Заголовок traceparent (формат в главе 5.1) пишет и читает пропагатор. Без SetTextMapPropagator в setupTracing каждый сервис начинает свой трейс:

$ ./chain.sh "-no-propagator" "" /orders/42 >/dev/null
$ for s in gateway orders payments; do ./jtraces.py $s d | sed -n 3p; done
  gateway   GET /orders/{id}         span=4d643f7e33a4288a parent=-                SERVER   UNSET
  orders    GET /orders/{id}         span=c86fadf495cbbd5d parent=-                SERVER   UNSET
  payments  GET /payments/{id}       span=e4ed9adaca141a4c parent=-                SERVER   UNSET

Три корня вместо одного дерева. С пропагатором gateway кладёт в baggage tenant.id=acme и зовёт партнёра, сервер без OpenTelemetry, печатающий заголовки:

$ ./chain.sh "" "-external http://127.0.0.1:9099/partner -baggage" /orders/42
GET /orders/42 -> 200
GET /partner
…
  Baggage: tenant.id=acme
  Traceparent: 00-459034cfe4326ff669358d629fe2d406-f4fa710edf7cfc26-01
…

tracestate TraceContext передаёт как есть: на traceparent с флагом 00 и tracestate: congo=t61rcWkgMzE следующий сервис получил тот же trace_id, новый span_id, флаг 00 и тот же tracestate.

Kafka: заголовки сообщения и span link

Пропагатору нужен TextMapCarrier над заголовками сообщения (Get, Set, Keys), для franz-go он есть в kotel.

// продюсер: контекст спана отправки уходит в заголовки
sendCtx, send := tr.Start(reqCtx, "send "+topic, trace.WithSpanKind(trace.SpanKindProducer))
r := &kgo.Record{Topic: topic, Key: []byte(id), Value: []byte(`{"order_id":"` + id + `"}`)}
prop.Inject(sendCtx, kotel.NewRecordCarrier(r))
if err := cl.ProduceSync(sendCtx, r).FirstErr(); err != nil {
    log.Fatal(err)
}
send.End()

// консьюмер, внутри PollFetches: сообщение станет ссылкой
msgCtx := prop.Extract(ctx, kotel.NewRecordCarrier(r))
_, span := tr.Start(ctx, "process "+topic, // родитель: контекст цикла, а не сообщение
    trace.WithSpanKind(trace.SpanKindConsumer),
    trace.WithLinks(trace.LinkFromContext(msgCtx)),
    trace.WithAttributes(semconv.MessagingSystemKafka, semconv.MessagingOperationTypeProcess,
        semconv.MessagingOperationName("process"), semconv.MessagingDestinationName(topic),
        semconv.MessagingConsumerGroupName("billing")))
span.End()

$ ./kafkademo
header traceparent: 00-b047f7f8ccac4bde5a3e06010951bc10-d4d4bb96d400514f-01
send orders   producer trace=b047f7f8ccac4bde5a3e06010951bc10 span=d4d4bb96d400514f parent=e4396c3d03e02370
POST /orders  server   trace=b047f7f8ccac4bde5a3e06010951bc10 span=e4396c3d03e02370 parent=-
process orders consumer trace=7714de8ff06efe34602b2486ca51de66 span=dd866df4a8053c7b parent=- link=b047f7f8ccac4bde5a3e06010951bc10/d4d4bb96d400514f

Спан обработки начал свой трейс и хранит ссылку (link) на спан отправки, в Jaeger это раздел Links. Так по умолчанию советуют конвенции messaging (semconv 1.44, статус Development), причина в главе 5.1. Плагин kotel v1.7.1 по умолчанию делает спан ребёнком, а ссылку только с kotel.LinkSpans().

Сэмплирование в SDK: решает корень

Description() у ParentBased(TraceIDRatioBased(0.1)) перечисляет пять сэмплеров: корневой TraceIDRatioBased{0.1} и AlwaysOnSampler или AlwaysOffSampler для удалённого и локального родителя, сэмплированного или нет. Доля работает только в корне. sampling гоняет 1000 запросов через три сервиса со своими TracerProvider и считает записанные серверные спаны:

$ ./sampling | grep -A1 '^[A-D]:'
A: ParentBased(TraceIDRatioBased(0.1)) у gateway, ParentBased у остальных
  recorded: gateway=98 orders=98 payments=98; complete traces=98, broken=0
--
B: gateway как в A, orders=TraceIDRatioBased(0.5), payments=TraceIDRatioBased(0.05) без ParentBased
  recorded: gateway=99 orders=512 payments=46; complete traces=46, broken=466
--
C: как A, но клиент сам присылает traceparent с флагом 01
  recorded: gateway=1000 orders=1000 payments=1000; complete traces=1000, broken=0
--
D: как C, но gateway сам решает и для чужого traceparent
  recorded: gateway=119 orders=119 payments=119; complete traces=119, broken=0

В A у orders своя доля 0.5, но родитель есть всегда, и сервисы записали одни и те же трейсы. В B каждый решает сам, и целых трейсов столько, сколько записал payments: с порогом сравнивается часть того же trace_id, и 5 % входят в 10 % и в 50 %. В C флаг 01 от клиента включил запись на всей цепочке; на входе это переопределяют sdktrace.WithRemoteParentSampled(ratio) и sdktrace.WithRemoteParentNotSampled(ratio) (опыт D).

Collector: конвейер, агент и шлюз

OpenTelemetry Collector принимает телеметрию, обрабатывает и отправляет дальше по конвейерам из receivers, processors и exporters.

receivers:
  otlp:
    protocols:
      grpc:
        endpoint: 0.0.0.0:4317
      http:
        endpoint: 0.0.0.0:4318

processors:
  memory_limiter:
    check_interval: 1s
    limit_percentage: 80        # от memory.max контейнера
    spike_limit_percentage: 20

exporters:
  otlp_grpc/jaeger:
    endpoint: dv-o3-jaeger:4317
    tls:
      insecure: true
    sending_queue:
      batch: {}                 # пачки собирает экспортер
  debug:
    verbosity: basic

service:
  telemetry:
    metrics:
      readers:
        - pull:
            exporter:
              prometheus:
                host: 0.0.0.0
                port: 8888
  pipelines:
    traces:
      receivers: [otlp]
      processors: [memory_limiter]
      exporters: [otlp_grpc/jaeger, debug]

• memory_limiter первым: выше мягкого порога он отказывает приёмнику, и отказ доходит до отправителя раньше, чем данные осели в конвейере. Процент считается от лимита контейнера: с --memory 256m в логе limit_mib: 204, spike_limit_mib: 51.
• Пачки. Годами последним ставили процессор batch, теперь сборку пачек переносят в экспортер (sending_queue::batch, как в примерах документации). queuebatch на замену batch есть в ядре с 0.158, в contrib 0.161.0 его нет. batch ставят после сэмплирования, чтобы не упаковывать выброшенное.
• Имена. С 0.144 экспортеры называются otlp_grpc и otlp_http, с 0.153 loadbalancing стал load_balancing; старые имена остались псевдонимами.
• debug с verbosity: detailed печатает в лог каждый спан.

Свои метрики Collector по умолчанию отдаёт на localhost:8888 внутри контейнера, и снаружи порт молчит, пока в service.telemetry не задан хост:

$ curl -s 127.0.0.1:8888/metrics | grep -E '^otelcol_receiver_(accepted|refused)_spans'
otelcol_receiver_accepted_spans{receiver="otlp",transport="grpc"} 1231
otelcol_receiver_refused_spans{receiver="otlp",transport="grpc"} 0

Агент живёт рядом с сервисом (sidecar или DaemonSet): SDK шлёт на близкий адрес, агент буферизует, добавляет данные пода и пересылает. Шлюз, Deployment за Service, держит в одном месте сэмплирование, фильтры, адреса и секреты бэкендов. Часто работают оба слоя.

Tail sampling в Collector

tail_sampling копит спаны в памяти по trace_id, ждёт decision_wait с первого спана трейса и проверяет политики. Трейс сохраняется, если хоть одна политика сказала «да» и ни одна drop не сказала «выбросить»:

# фрагмент tail.yaml, остальное как выше
processors:
  tail_sampling:
    decision_wait: 10s          # по умолчанию 30s
    num_traces: 50000           # сколько трейсов держать в памяти до решения
    policies:
      - name: errors
        type: status_code
        status_code: {status_codes: [ERROR]}
      - name: slow
        type: latency
        latency: {threshold_ms: 500}
      - name: rest
        type: probabilistic
        probabilistic: {sampling_percentage: 10}
  batch: {}

service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [memory_limiter, tail_sampling, batch]
      exporters: [otlp_grpc/jaeger]

tailwatch.sh шлёт 240 трейсов (200 быстрых, 20 с ошибкой, 20 по 600 мс) и считает виды в Jaeger:

$ ./tailwatch.sh
sent 240 traces, shutdown: <nil>
t+2s: normal=0 error=0 slow=0
t+8s: normal=0 error=0 slow=0
t+18s: normal=15 error=20 slow=20
$ curl -s 127.0.0.1:8888/metrics | grep '^otelcol_processor_tail_sampling_global_count_traces_sampled'
otelcol_processor_tail_sampling_global_count_traces_sampled{decision="not_sampled",sampled="false"} 185
otelcol_processor_tail_sampling_global_count_traces_sampled{decision="sampled",sampled="true"} 55

Пока идёт decision_wait, в Jaeger пусто, потом приходят все ошибки, все медленные и 15 быстрых из 200 (rest, 10 % по хешу trace_id). latency меряет трейс от самого раннего начала до самого позднего конца среди пришедших спанов, и трейс длиннее decision_wait оценивается по неполным данным.

По документации процессора все спаны трейса должны прийти в один экземпляр. Обычный Service разложит соединения по репликам, поэтому реплику выбирает слой с load_balancing (конфиг в третьем вопросе).

Логи и метрики рядом с трейсом

В главе 5.1 trace_id клали в логгер один раз в middleware. Если брать контекст в момент записи, рядом ляжет и span_id текущего спана. Хендлер-обёртка для slog пишет обычный JSON в stdout:

type traceHandler struct{ slog.Handler }

func (h traceHandler) Handle(ctx context.Context, r slog.Record) error {
    if sc := trace.SpanContextFromContext(ctx); sc.IsValid() {
        r.AddAttrs(slog.String("trace_id", sc.TraceID().String()), slog.String("span_id", sc.SpanID().String()))
    }
    return h.Handler.Handle(ctx, r)
}

func (h traceHandler) WithAttrs(as []slog.Attr) slog.Handler {
    return traceHandler{h.Handler.WithAttrs(as)}
}

func (h traceHandler) WithGroup(name string) slog.Handler {
    return traceHandler{h.Handler.WithGroup(name)}
}

$ ./logs handler
{"time":"2026-09-17T04:52:15.460124+03:00","level":"INFO","msg":"payment processed","order_id":"42","trace_id":"c8f7e82600c2ca853f9c94caf8c40f0f","span_id":"ed4acf94dc453bb3"}
{"time":"2026-09-17T04:52:15.460597+03:00","level":"INFO","msg":"payment processed","order_id":"43"}

Вторая запись сделана через log.Info без контекста, и trace_id взять неоткуда. Другой путь даёт мост contrib/bridges/otelslog: slog.Handler, который отдаёт записи в Logs SDK (дальше по OTLP в Collector) и сам ставит trace_id и span_id:

$ ./logs bridge   # экспортер stdoutlog вместо OTLP, вывод сокращён
{"Timestamp":"2026-09-17T04:52:15.474825+03:00",…,"Body":{"Type":"STRING","Value":"payment processed"},…,"TraceID":"afaaa8735d55a3be3731393728bc95a6","SpanID":"19c924d56ee14427","TraceFlags":"01",…}

Если логи собирает агент со stdout подов, хватит своего хендлера; мост нужен для логов по OTLP. Сигнал логов в Go пока Beta (sdk/log v0.22.0, API менялся в v1.45), место вызова мост кладёт в code.* только с otelslog.WithSource(true). Писать в оба места позволяет slog.NewMultiHandler (Go 1.26).

Exemplars (глава 5.1) Metrics SDK прикрепляет сам к измерениям с контекстом сэмплированного спана (OTEL_METRICS_EXEMPLAR_FILTER=trace_based по умолчанию). Экспортер Prometheus отдаёт их в OpenMetrics и protobuf, но не в обычном текстовом формате:

$ curl -s -H 'Accept: application/openmetrics-text' 127.0.0.1:9464/otel | grep 'le="0.05"'
http_server_request_duration_seconds_bucket{http_route="/orders/{id}",otel_scope_name="example.com/orders",otel_scope_schema_url="",otel_scope_version="",le="0.05"} 1 # {trace_id="f0466d31eefcf0b97878c20f38ada88c",span_id="1f356d2bfbbaa463"} 0.042 1.7896099358424408e+09

Без заголовка Accept та же строка кончается на } 1, без exemplar.

Сколько стоит инструментирование

Бенчмарк зовёт обработчик напрямую, без сети; экспортер выбрасывает спаны. Медианы benchstat по шести прогонам на Apple M4 Pro:

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

Поэтому не трассируют пробы /healthz и /ready (их отрезает WithFilter), скрейп /metrics, горячие функции, итерации цикла (спан на весь цикл, число элементов в атрибут) и кэш в памяти. Спан ставят на границе: входящий запрос, исходящий вызов, запрос в базу, заметный шаг бизнес-логики.

$ OTEL_GO_X_OBSERVABILITY=true OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4999 ./queuefull
100000 spans in 121ms, heap in use 3 MiB
otel.sdk.exporter.span.inflight{error.type=""} 512
otel.sdk.processor.span.queue.capacity{error.type=""} 2048
otel.sdk.processor.span.queue.size{error.type=""} 2048
otel.sdk.processor.span.processed{error.type="queue_full"} 97440
otel.sdk.processor.span.processed{error.type=""} 512
…

exporters:
  load_balancing:
    routing_key: traceID          # все спаны трейса уходят в один экземпляр
    protocol:
      otlp:
        tls:
          insecure: true
    resolver:
      k8s:
        service: otelcol-sampler.observability   # Service перед репликами с tail_sampling
        ports: [4317]

$ curl -s 127.0.0.1:9464/otel | grep -E '^(http_server.*le="0.05"|orders_created|target_info)'
http_server_request_duration_seconds_bucket{http_route="/orders/{id}",otel_scope_name="example.com/orders",otel_scope_schema_url="",otel_scope_version="",le="0.05"} 1
orders_created_total{otel_scope_name="example.com/orders",otel_scope_schema_url="",otel_scope_version=""} 1
target_info{service_name="orders"} 1
$ curl -s 127.0.0.1:9464/prom | grep -E '^(http_server.*le="0.05"|orders_created)'
http_server_request_duration_seconds_bucket{http_route="/orders/{id}",le="0.05"} 1
orders_created_total 1