14.10.2026

Continuous profiling в проде: Pyroscope и Parca

Непрерывное профилирование в проде: чем оно лучше разового pprof, как читать flame graphs, CPU/heap/alloc с низким оверхедом, pull vs push, связка профилей с трейсами. Практика на Go pprof и JVM async-profiler с Pyroscope и Parca.

Трейсы, логи и метрики отвечают, что медленно и где болит. Они не отвечают на последний вопрос: почему этот код жжёт CPU или память. Раньше за ответом лезли в прод с разовым pprof — когда инцидент уже случился и часто уже прошёл. Continuous profiling переворачивает подход: профиль снимается всегда, и в любой момент можно посмотреть, на что реально уходили ресурсы — задним числом.

Это шестая статья серии «Наблюдаемость на практике». Она добавляет четвёртый сигнал — профили — и замыкает картину: от «что случилось с запросом» к «почему это столько стоит».

Главное, что стоит знать заранее: связка «из трейса в профиль» работает не так, как обещает интуиция. Метки span_id среди меток серий нет — кардинальность, как и во всех предыдущих статьях серии. Но перейти из конкретного запроса в его профиль всё же можно: идентификатор спана лежит на уровне сэмплов. Работает это, но у короткого запроса профиль чаще всего пуст — сэмплов на него не хватает. Как это устроено и где граница — ниже, с проверкой.

В статье

Непрерывно против разово
Что приезжает: два языка, разные типы профилей
Как читать флеймграф
Связка со спаном: не то, что ожидаешь
Профиль не заменяет трейс
Опыт: покой против нагрузки
Сколько это стоит
Pull против push
Две ловушки в самой проверке
Итог
Документация и первоисточники

Непрерывно против разово

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

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

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

Версионная деталь Pyroscope 2.x, на которую стоит потратить пять минут

Release notes 2.0.0 обещают отказ на старте: «Error at startup when -architecture.storage includes v2 and no object-storage backend is configured», а значение по умолчанию — v1-v2-dual. Читается это однозначно: стенд без MinIO не поднимется, надо поднимать объектное хранилище.

Фактически Pyroscope 2.2.0 с дефолтами стартует нормально, и в логах видно, что работают оба пути записи:

msg="initializing v2 admin (metastore-based)"
starting module=segment-writer
starting module=ingester

Причина, почему отказа нет: второе изменение того же релиза гасит первое — дефолтный storage backend переключили с пустого на filesystem, а файловая система считается настроенным хранилищем, и условие отказа не выполняется. Остаётся только предупреждение о том, что при filesystem все реплики должны видеть одну и ту же файловую систему.

Вывод для стенда: MinIO не нужен, дефолты годятся. Вывод общий: две записи в одном changelog могут отменять друг друга, и проверять надо запуском, а не чтением.

Попутно: перейти в чистый v1 одним флагом нельзя. -architecture.storage=v1 роняет процесс с внятным сообщением «write-path=ingester is required for v1 storage layer» — флаги идут парой.

Готовность наступает не сразу, и фаз три

Здесь я тоже сначала недосчитал. Записал «две паузы по пятнадцать секунд», а фактически /ready проходит три последовательные фазы, и каждая сообщает о себе в теле ответа:

Metastore not ready: 14.99s before reporting readiness
Ingester not ready: waiting for 15s after being ready
Segment Writer not ready: waiting for 30s after being ready

15 + 15 + 30 — это минимум минута чистого ожидания, плюс время запуска модулей. На моей машине от старта контейнера до ready проходило около четырёх минут.

Последствие было не теоретическим: подъём стенда падал по таймауту. Ожидание стояло 120 секунд, Pyroscope становился готов позже, и скрипт объявлял отказ на исправном компоненте. Два вывода из этого.

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

Компонент, нужный одной статье, не должен задерживать остальные. Pyroscope вынесен в профиль compose и поднимается только когда профилирование включено:

./scripts/up.sh all otel none off     # без Pyroscope: 109 с
./scripts/up.sh all otel none both    # с Pyroscope и ожиданием его готовности

Метрики и SLO из статей 4 и 5 к Pyroscope отношения не имеют — и теперь не ждут его вовсе.

Попутная деталь того же ряда: docker compose down не трогает сервисы из профилей, если профиль не указан. Контейнер Pyroscope переживал «погашенный» стенд и попадал в следующий прогон со старыми профилями — что портило как раз проверку свежести данных. Лечится docker compose --profile "*" down.

На стенде это Pyroscope 2.2.0, а в приложениях — pyroscope-go для Go и javaagent для Java. Включается отдельно от телеметрии:

./scripts/up.sh all otel none go    # + профилирование Go
./scripts/up.sh all otel none both  # + профилирование Go и Java

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

Что приезжает: два языка, разные типы профилей

Первое, что стоит сделать после подключения, — спросить у Pyroscope, что он вообще получил. Не угадывать, а спросить: имена в его модели свои и с service.name из OTel напрямую не связаны.

block:contentions:count:contentions:count
block:delay:nanoseconds:contentions:count
goroutines:goroutine:count:goroutine:count
memory:alloc_objects:count:space:bytes
memory:alloc_space:bytes:space:bytes
memory:inuse_objects:count:space:bytes
memory:inuse_space:bytes:space:bytes
mutex:contentions:count:contentions:count
mutex:delay:nanoseconds:contentions:count
process_cpu:cpu:nanoseconds:cpu:nanoseconds
process_cpu:samples:count:cpu:nanoseconds

А вот распределение по сервисам:

go-frontend  -> block, goroutines, memory, mutex, process_cpu
java-backend -> ТОЛЬКО process_cpu
pyroscope    -> block, goroutines, memory, mutex, process_cpu

Три вывода отсюда.

У Java только CPU. Не потому, что агент не умеет, а потому, что PYROSCOPE_PROFILING_ALLOC и PROFILING_LOCK не заданы: в режиме ITIMER они не включаются сами.

Общий для двух языков тип ровно один — process_cpu:cpu:nanoseconds:cpu:nanoseconds. Сравнивать языки можно только на нём. Запрос Java по типу process_cpu:samples:count:cpu:nanoseconds (который есть у Go) возвращает HTTP 200, один фрейм и numTicks: 0 — выглядит как «профиля нет», хотя профиль есть. На этом легко потерять полчаса.

Pyroscope профилирует сам себя. Это удобно и заодно напоминание, что бэкенд профилей — тоже сервис со своей ценой.

Блокировочные профили Go требуют двух вызовов

Типы mutex и block у Go появляются не сами:

// Эти два вызова обязательны для блокировочных профилей, и по умолчанию они
	// выключены — то есть без них в Pyroscope просто не будет соответствующих
	// типов профиля, причём молча. Параметры у них разные по смыслу:
	// SetMutexProfileFraction(5) — в среднем каждое пятое событие конкуренции
	// за mutex; SetBlockProfileRate(5) — в среднем одно событие на каждые
	// 5 НАНОСЕКУНД блокировки, то есть практически все блокировки.
	runtime.SetMutexProfileFraction(5)
	runtime.SetBlockProfileRate(5)

Без них никакой ошибки не будет — просто в интерфейсе не окажется двух типов профиля, и вы решите, что Pyroscope их не поддерживает.

Два javaagent в одной JVM

JAVA_TOOL_OPTIONS: "${JAVA_BACKEND_JAVA_TOOL_OPTIONS:-}"

В эту переменную подставляются оба агента сразу — OTel и Pyroscope. Конфликта нет: первый занимается трейсами и метриками, второй профилями, точки инструментирования у них разные. В логе видно оба:

Picked up JAVA_TOOL_OPTIONS: -javaagent:/app/opentelemetry-javaagent.jar -javaagent:/app/pyroscope.jar
Config: Config{... profilerType=ASYNC, profilingEvent=ITIMER, format=JFR ...}
Profiling started

profilingEvent=ITIMER — важная деталь. Это сэмплирование по таймеру, а не через perf_events, и потому оно работает в контейнере без всяких capabilities. Проверено: perf_event_paranoid=2, CapEff=0000000000000000 — ни одной привилегии, а профили собираются.

Режим CPU через perf включается переменной PYROSCOPE_PROFILER_EVENT=cpu. Имя важно: PYROSCOPE_PROFILING_EVENT — по названию поля конфига — не читается и молча оставляет ITIMER. И отличить работающий perf от отката по логу нельзя: агент в обоих случаях пишет «Profiling started». Проверять надо по данным.

Как читать флеймграф

Два правила, которых достаточно на девяносто процентов случаев.

Ось X — это доля ресурса, а не время. Ширина фрейма означает «сколько процессорного времени пришлось на этот стек», а порядок фреймов слева направо не значит ничего: они отсортированы по имени, а не по хронологии. Флеймграф — не диаграмма Ганта, и читать его слева направо как последовательность выполнения нельзя.

Ось Y — глубина стека. Высокая башня — это глубокая вложенность вызовов, и сама по себе она ничего не стоит. Дорого — широкое, а не высокое.

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

Что искать: плато наверху. Широкая плоская вершина — это функция, которая тратит время сама, а не ждёт вложенные вызовы. Именно она кандидат на оптимизацию.

Diff-режим (сравнение двух периодов) отвечает на вопрос «что изменилось», и это чаще нужный вопрос, чем «что самое дорогое»: самое дорогое обычно известно и обычно оправдано.

Связка со спаном: не то, что ожидаешь

Обещание звучит так: нашли медленный трейс — перешли в профиль этого запроса. Проверим.

В Go подключена обёртка otelpyroscope. Она не экспортирует телеметрию и не меняет спаны — она навешивает на активную горутину pprof-метки:

if os.Getenv("PROFILING_ENABLED") == "true" {
		otel.SetTracerProvider(otelpyroscope.NewTracerProvider(tp))
	} else {
		otel.SetTracerProvider(tp)
	}

Обёртка ставится вокруг готового провайдера и до SetTracerProvider. Если зарегистрировать голый tp, меток не будет, а библиотека при этом останется «подключённой» — проверять надо по наличию меток в данных, а не по строчке импорта.

Теперь смотрим, какие метки реально появились:

__name__  __period_type__  __period_unit__  __profile_type__
__service_name__  __type__  __unit__
environment  pyroscope_spy  service_name  span_name

Метки span_id среди меток серий нет. Есть span_name, и у неё ровно одно значение — POST. Отсюда легко сделать вывод, что профиль конкретного запроса недоступен, — и он неверен. Метки серий — не единственное место, где лежит идентификатор. otel-profiling-go ставит span_id pprof-меткой на сэмплы и пишет в корневой спан атрибут pyroscope.profile.id с тем же значением. Pyroscope хранит span_id на уровне сэмплов, а не серий — поэтому кардинальность серий он не раздувает и в списке меток не виден, — и отдаёт профиль по нему отдельным запросом (SelectMergeSpanProfile, в Grafana это «Profiles for this span»).

Проверено отдельной пробой: 3000 запросов, из Tempo — pyroscope.profile.id их корневых спанов, из Pyroscope — профиль по этим идентификаторам:

$ ./scripts/span-profile-probe.sh
Проба Span Profiles, метка spanprof-1791666713: запросов 3000, успешных 3000
========================================================================
CPU go-frontend в окне прогона (±60 с): 2.15 с
корневых спанов с pyroscope.profile.id в окне: 3000
профиль по набору span_id: 1.07 с CPU, фреймов 348; функции стенда:
  main.(*Service).CreateOrder
  main.(*Service).CreateOrder.func1
  main.(*Service).handleOrder
  main.(*httpInventory).Lookup
  main.(*natsPublisher).Publish
  main.(*natsPublisher).Publish.WithSpanKind.func1
  main.fanoutHandler.Handle
  main.traceContextHandler.Handle
отдельных спанов с непустым профилем: 15 из 400
  пример: span_id 12da41d791ce1abf, 20 мс CPU, функции: ['main.(*Service).CreateOrder', 'main.(*Service).handleOrder', 'main.(*httpInventory).Lookup']
контроль, несуществующий span_id: 0

ИТОГ: профиль по span_id доступен: по набору запросов — с функциями обработки заказа; у отдельного короткого запроса — только если в него попал сэмпл (15 из 400); контроль пуст

Профиль конкретного запроса, таким образом, есть, но у него своя арифметика. Сэмплирующий профилировщик снимает стек сто раз в секунду, то есть один сэмпл — это 10 мс CPU. Короткий запрос, который на стороне Go тратит доли миллисекунды и основное время ждёт бэкенд, чаще всего не получает ни одного сэмпла: из 400 проверенных спанов непустой профиль у 15. Для долгого CPU-тяжёлого запроса профиль одного спана содержателен; для коротких осмысленнее профиль по набору спанов — например, по всем медленным запросам эндпоинта за час.

Две детали, на которых проба ошибалась, прежде чем заработать. Первая — окно: pyroscope-go отправляет профиль кусками по 10–15 с с одной меткой времени, и узкое окно прогона (3000 запросов укладываются в секунды) может не содержать ни одной такой метки — запрос возвращает пусто при исправном пути. Окно запроса к Pyroscope приходится расширять. Вторая — нагрузка: на 300 последовательных запросах сэмплов почти нет, и «пусто» неотличимо от «не работает». Поэтому в пробе есть контроль — несуществующий span_id обязан дать ноль.

Что связка по span_name при этом тоже работает — проверено:

span_name="POST"          -> 370 фреймов, среди них:
                             main.(*Service).CreateOrder
                             main.(*Service).handleOrder
                             main.(*natsPublisher).Publish
                             main.(*httpInventory).Lookup
span_name="create_order"  ->   1 фрейм (только total, то есть пусто)

Вторая строчка — вторая находка. create_order это ручной спан бизнес-операции, он существует и прекрасно виден в Tempo, но метки с его именем нет. Причина в настройке по умолчанию: otel-profiling-go ставит span_name и span_id с областью «корневой спан» — все дочерние спаны наследуют имя и идентификатор корня. Область настраивается (WithSpanNameLabelScope, WithSpanIDLabelScope), и тогда метки получат и вложенные спаны — ценой большего числа значений span_name.

Почему метка называется «POST», а спан — «POST /order»

Сравним фактические имена спанов одного трейса с меткой профиля:

java-backend   GET /inventory/{sku}
java-backend   SELECT orders.inventory
java-backend   INSERT orders.orders
java-backend   orders.created process
go-frontend    orders.created publish
go-frontend    create_order
go-frontend    HTTP GET
go-frontend    POST /order          <- корневой спан

Корневой спан называется POST /order, а метка профиля — POST. Расхождение не случайно: otelhttp создаёт спан с именем по методу, а маршрут дописывает позже, когда роутер его разрешил. Метка же снимается на старте спана, до переименования.

Практическое следствие: у сервиса с десятком POST-эндпоинтов все они сольются в одну метку span_name="POST", и разрезать профиль по эндпоинту через otelhttp не выйдет. Нужен свой корневой спан с осмысленным именем, заданным сразу.

Профиль не заменяет трейс

На стенде есть намеренно медленный путь: pg_sleep внутри запроса к БД. В трейсе он виден как длинный спан. Что с ним в CPU-профиле:

фреймов в профиле Java: 645
pg_sleep среди них:       0

Ни одного. И это правильное поведение, а не потеря данных: во время ожидания ответа от БД процессор ничем не занят, и сэмплирующий профилировщик честно ничего не показывает.

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

Именно поэтому четыре сигнала не заменяют друг друга.

flowchart TB metric["МЕТРИКА
что плохо
p95 вырос, доля ошибок выше SLO"] trace["ТРЕЙС
где в цепочке
какой участок съел время"] log["ЛОГ
что именно произошло
подробности этого запроса"] profile["ПРОФИЛЬ
почему это столько стоит
какая функция жжёт процессор"] metric -->|"алерт разбудил"| trace trace -->|"по trace_id"| log trace -->|"по имени операции"| profile wait["Ожидание в БД или в сети:
видно в ТРЕЙСЕ,
в CPU-профиле НЕТ"] burn["Горит процессор:
видно в ПРОФИЛЕ,
трейс покажет только длительность"] trace -.-> wait profile -.-> burn


flowchart TB
    metric["МЕТРИКА
что плохо
p95 вырос, доля ошибок выше SLO"]
    trace["ТРЕЙС
где в цепочке
какой участок съел время"]
    log["ЛОГ
что именно произошло
подробности этого запроса"]
    profile["ПРОФИЛЬ
почему это столько стоит
какая функция жжёт процессор"]

    metric -->|"алерт разбудил"| trace
    trace -->|"по trace_id"| log
    trace -->|"по имени операции"| profile

    wait["Ожидание в БД или в сети:
видно в ТРЕЙСЕ,
в CPU-профиле НЕТ"]
    burn["Горит процессор:
видно в ПРОФИЛЕ,
трейс покажет только длительность"]

    trace -.-> wait
    profile -.-> burn

Пунктирные ветви — это и есть граница между двумя последними сигналами, и её стоит запомнить до инцидента, а не во время.

Опыт: покой против нагрузки

Утверждение «этот фрейм появился из-за нагрузки» требует доказательства. Снимаем профиль дважды.

go-frontend: 1 фрейм, CreateOrder отсутствует

go-frontend:  639 фреймов, CreateOrder присутствует
java-backend: 645 фреймов, InventoryController присутствует

В покое в профиле остаётся только служебное — сборка мусора и периодический reader OTel SDK. Без первой половины опыта вывод «широкий фрейм появился из-за нагрузки» был бы предположением.

Эта же пара замеров закрывает вопрос «а точно ли профилирование вообще работает»: в самопроверке стенда критерий сформулирован как наличие конкретных функций, а не «профиль непустой» и тем более не «сервис ответил 200».

./scripts/verify-profiles.sh 4000

ГОДЕН   профиль go-frontend присутствует           1 (ожидалось 1)
ГОДЕН   профиль java-backend присутствует          1 (ожидалось 1)
ГОДЕН   CreateOrder в профиле Go                   1 (ожидалось 1)
ГОДЕН   InventoryController в профиле Java         1 (ожидалось 1)
ГОДЕН   фреймов в профиле Go                    1561 (нужно не меньше 60)
ГОДЕН   фреймов в профиле Java                  3629 (нужно не меньше 300)
ГОДЕН   метка span_name присутствует               1 (ожидалось 1)
ГОДЕН   CreateOrder в профиле по корневому спану   1 (ожидалось 1)
ГОДЕН   ожидание pg_sleep НЕ в CPU-профиле         0 (ожидалось 0)
ПРОПУСК CreateOrder отсутствует в профиле покоя  в окне покоя 650 фреймов — стенд был горячим

Последняя строка — не поблажка, а следствие честной интерпретации. Окно «покоя» длится двадцать секунд и снимается перед нагрузкой; если стенд работал до запуска проверки, в этом окне уже лежит осевшая активность прошлых прогонов, и утверждать по ней что-либо нельзя. Критерий выносится только на чистом стенде, а на горячем — прямо помечается как пропущенный.

Два режима проверки, и путать их нельзя

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

Критерии искали функции в окне последнего часа. На тёплом стенде это означает, что CreateOrder находится за секунды — но из прошлых прогонов, а не из текущего. Проверка при этом рапортовала успех и выглядела как доказательство того, что профиль собран сейчас. Симптом был виден прямо в её же выводе: «профиль покоя» содержал 650 фреймов и ту самую функцию, а итог оставался ГОДЕН.

Теперь режимов два, и каждый отвечает на свой вопрос:

./scripts/verify-profiles.sh          # PIPELINE: конвейер подключён и отдаёт функции
./scripts/verify-profiles.sh fresh    # FRESH: профиль ЭТОГО прогона доехал

PIPELINE — окно час, быстро, отвечает «всё ли подключено». Честно сообщает в отчёте, что свежести не доказывает.

FRESH — пересоздаёт контейнер Pyroscope перед прогоном. Хранилище у него внутри контейнера, тома нет, поэтому старые профили исчезают физически, и найденное принадлежит только текущей нагрузке.

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

замер покоя
нагрузка
цикл нагрузки 120 с
ПЕРЕСОЗДАНИЕ Pyroscope   <- стирает ровно то, что собрали

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

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

Первый прогон fresh-режима сразу дал полезный отказ: InventoryController нашёлся (4200 фреймов у Java), а CreateOrder — нет вовсе, ни за 600 секунд ожидания. В профиле go-frontend оставалось 179 фреймов чисто служебного — сборка мусора и периодический reader OTel SDK.

Причина оказалась не в задержке и не в объёме запросов, а в том, что именно сэмплирует профилировщик. Он сэмплирует время — сто раз в секунду снимает стек. Шесть тысяч запросов проходят за пятнадцать секунд, дают около полутора тысяч сэмплов на весь процесс, и у сервиса, который почти всё это время ждёт ответа соседа, прикладные функции в такую выборку просто не попадают.

Проверяется это прямо: если ту же нагрузку держать не залпом, а циклом в течение двух минут, картина меняется полностью:

фреймов: 1158, своих (main.*): 13, CreateOrder: True
  main.main
  main.(*Service).handleOrder
  main.(*Service).fail
  main.fanoutHandler.Handle
  main.traceContextHandler.Handle

Поэтому fresh-режим меряется секундами нагрузки, а не числом запросов:

log "FRESH: держу нагрузку ${FRESH_LOAD_SECONDS}с — профилировщику нужно ВРЕМЯ, а не запросы"
  load_began="$(date +%s)"
  rounds=1
  while [ $(( $(date +%s) - load_began )) -lt "$FRESH_LOAD_SECONDS" ]; do

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

Сколько это стоит

Документация обещает накладные расходы «в единицы процентов». Это то самое утверждение, которое надо либо подтвердить своими числами, либо честно сказать, что подтвердить не удалось.

Замер: 20 000 запросов, восемь параллельных отправителей, два прохода на режим, во всех режимах телеметрия OTel включена — меряется именно надбавка за профили. Перед каждым прогоном стенд поднимается заново с чистыми томами, прогрев 600 запросами, пауза, ресурсы снимаются циклом docker stats --no-stream.

Три режима: noprof — только OTel; goprof — плюс профилирование Go; bothprof — плюс агент Pyroscope для Java.

Латентность: вывода нет

тег              p50     p90     p99     max     длительность
noprof-1         5.5     14.2    29.3    100.4   55.208s
goprof-1         4.8     12.0    24.5    66.7    52.707s
bothprof-1       6.3     16.6    34.2    93.8    57.977s
noprof-2         5.1     13.5    25.8    63.2    54.088s
goprof-2         5.5     14.1    27.6    61.8    55.168s
bothprof-2       5.2     14.0    28.1    71.7    54.706s

Разброс между двумя проходами одного и того же режима шире разницы между режимами. По всем трём перцентилям:

p50:
  noprof    проходы 5.5, 5.1, разброс 0.4 мс
  goprof    проходы 4.8, 5.5, разброс 0.7 мс
  bothprof  проходы 6.3, 5.2, разброс 1.1 мс
  goprof против noprof:   -0.1 мс — ВЫВОДА НЕТ: разброс (1.1 мс) шире эффекта (0.1 мс)
  bothprof против noprof: +0.5 мс — ВЫВОДА НЕТ: разброс (1.1 мс) шире эффекта (0.5 мс)

Обратите внимание на goprof-1: 5,5 против 4,8 — с профилированием получилось «быстрее». Это не открытие про ускоряющее профилирование, это ровно тот шум, из-за которого одиночный прогон нельзя принимать за результат.

Значит ли это, что профилирование бесплатно? Нет. Значит, что на этом профиле нагрузки его цена по латентности меньше разрешающей способности замера. Утверждать «единицы процентов» я не могу — не потому, что документация врёт, а потому, что мои числа этого не показывают.

Память Go: единственный измеримый эффект

А вот здесь эффект отчётливый и разброс его не перекрывает:

noprof    26.1, 30.2  (разброс 4.1)
goprof    44.0, 45.9  (разброс 1.9)
bothprof  42.5, 45.3  (разброс 2.8)

goprof против noprof:   +16.8 МиБ — эффект превышает разброс 4.1
bothprof против noprof: +15.7 МиБ — эффект превышает разброс 4.1

Плюс примерно 17 МиБ на процесс — это около 60 % от исходных 28 МиБ. Число выглядит внушительно в процентах и скромно в мегабайтах, и второе тут важнее: это фиксированная надбавка на буферы профилировщика, а не растущая с нагрузкой.

Для сравнения, в статье 1 телеметрия обошлась в 8–12 МиБ на тот же процесс. То есть профили стоят памяти примерно вдвое дороже, чем трейсы, метрики и логи вместе взятые.

CPU и Java: вывода снова нет

CPU go-frontend:  noprof 49.6, 50.3; goprof 50.3, 52.8; bothprof 51.9, 50.5
  goprof против noprof: +1.6 % — ВЫВОДА НЕТ: разброс (2.5) шире эффекта (1.6)

ОЗУ java-backend: noprof 727.3, 514.0 (разброс 213.3!)
  ВЫВОДА НЕТ ни по одному режиму

Разброс памяти JVM между двумя проходами одного режима — 213 МиБ. Это не свойство профилирования, а свойство сборщика мусора: момент снятия снимка попадает то до, то после сборки. На такой метрике нельзя измерить надбавку в десятки мегабайт, и никакое увеличение числа прогонов этого не исправит — надо мерить не потребление, а что-нибудь устойчивое (например, jvm_memory_used_bytes после принудительной сборки).

Ровно то же случилось в волне 1 с памятью JVM, и вывод тот же: метрика, разброс которой шире искомого эффекта, для этого эффекта непригодна. Честнее написать, почему вывода нет, чем привести одно из двух чисел.

Что с этим делать на практике

Из замера следует не «профилирование бесплатно», а три вещи поскромнее:

По латентности цена не улавливается на нагрузке в 20 000 запросов при восьми параллельных отправителях. Если ваш SLO по латентности имеет запас в единицы миллисекунд — проверяйте на своём профиле.
Память Go растёт предсказуемо, примерно на 17 МиБ на процесс. При сотне подов это 1,7 ГиБ, и это уже разговор.
Частота сэмплирования — рычаг, и у двух вызовов он разный. SetMutexProfileFraction(5) — в среднем каждое пятое событие конкуренции за mutex. SetBlockProfileRate принимает не долю, а наносекунды: в среднем одно событие на каждые rate наносекунд блокировки. Значение 5 из стенда — это практически полное сэмплирование блокировок, а не «каждое пятое», и оно дорогое. Для длительной работы ставят порядок микросекунд и больше (например, 10000 — одно событие на 10 мкс блокировки).

Pull против push

Две модели сбора, и выбор между ними — не вопрос вкуса.

Pull: бэкенд сам ходит по целям и забирает профили с эндпоинтов вроде /debug/pprof. Так работает Parca. Плюс — приложение ничего не знает о профилировании и никуда не отправляет; минус — бэкенду нужен список целей и сетевой доступ к каждой.

Push: агент или SDK внутри приложения отправляет профили сам. Так работает Pyroscope, и так сделано на стенде. Плюс — работает для эфемерных задач, которые не проживут до следующего скрейпа: cron-задача, serverless-функция, короткий под. Минус — приложение должно знать адрес бэкенда и нести SDK.

Ровно та же развилка была в статье про метрики: Prometheus скрейпит, OTLP шлёт. И ответ тот же: эфемерность решает. Если процесс живёт минуту, pull его не застанет.

Отдельная ветвь — профилирование через eBPF (Parca Agent, Grafana Beyla): агент снимает профили всей машины извне процессов, инструментирование не нужно вовсе. Цена — символы. Без отладочной информации стеки останутся адресами, и для Java с JIT-компиляцией это отдельная работа. На стенде этот путь не проверялся, поэтому утверждать о нём ничего не буду.

Две ловушки в самой проверке

Обе стоили времени и обе поучительны — они про то, как инструмент проверки врёт убедительнее самого инструмента.

Ошибка запроса, которая выглядела как отсутствие данных

Селектор Pyroscope сам содержит двойные кавычки: {service_name="go-frontend"}. При подстановке такого значения внутрь JSON-строки склейкой в шелле кавычки не экранируются, и уходит сломанное тело:

{"label_selector":"{service_name="go-frontend"}"}

Pyroscope отвечает на это внятной ошибкой:

{"code":"invalid_argument","message":"unmarshal message: unmarshal into *querierv1.SelectMergeStacktracesRequest: proto: syntax error (line 1:98): invalid value go-frontend"}

А разбор ответа, который просто берёт d['flamegraph']['names'], получает пустой список и печатает «фреймов 0». Ошибка запроса превратилась в вывод «профиля нет» — и следующие полтора часа ушли на поиск несуществующей задержки доставки профилей.

Лечится двумя вещами, и обе обязательны: тело запроса собирает json.dumps (экранирование получается по построению), а разбор отличает ошибку сервера от честной пустоты:

if 'code' in d or 'message' in d:
    # Ошибка сервера, а не пустой профиль. Разница принципиальна: первое значит
    # «запрос неверен», второе — «данных за окно нет».
    sys.stderr.write('  ОШИБКА Pyroscope: %s\n' % d.get('message', d.get('code')))
    print('-1:-1'); raise SystemExit

И ещё одна ошибка, уже в рассуждении, а не в коде. Устранив дефект запроса, я записал, что «задержка доступности профилей» была его артефактом: на исправленном запросе профиль появился через 28 секунд. Это неверный вывод из удачного совпадения — окно тогда захватывало данные предыдущих прогонов, которые уже осели.

Отдельный замер на чистом окне показал обратное, и об этом стоит знать заранее.

Профиль доступен не сразу — и это минуты, а не секунды

Прогон 4000 запросов, затем опрос окна «от начала нагрузки до сейчас» каждые пятнадцать секунд:

+21 с    фреймов   1
 +75 с    фреймов   8
+129 с    фреймов  41
+238 с    фреймов  76
+292 с    фреймов 110
+438 с    фреймов 142    функция CreateOrder так и не появилась

При этом Pyroscope профили принял — это видно по его собственным метрикам, и отказов нет:

pyroscope_distributor_received_compressed_bytes_sum{type="process_cpu"} 994311
pyroscope_distributor_received_compressed_bytes_sum{type="jfr"}        2151822

Сравнение по ширине окна в один и тот же момент ставит точку:

окно  60 с -> фреймов  10, CreateOrder нет
окно 120 с -> фреймов  53, CreateOrder нет
окно 300 с -> фреймов 112, CreateOrder нет
окно 600 с -> фреймов 651, CreateOrder ЕСТЬ

Свежие данные видны частично и с отставанием; полная картина доступна только для окна, отстоящего на минуты. Причина в архитектуре записи: профили оседают в сегментах и становятся доступны после сброса и компакции.

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

Критерии, проходившие на пустых данных

Пока профили были пусты, два критерия проверки бодро рапортовали ГОДЕН:

ГОДЕН   ожидание pg_sleep НЕ в CPU-профиле       0 (ожидалось 0)
ГОДЕН   CreateOrder отсутствует в профиле покоя  0 (ожидалось 0)

Оба — суждения об отсутствии, а на пустом профиле не найдётся ничего. Критерий проходил, ничего не проверив.

Правило, которое из этого следует и которое стоит дороже конкретного скрипта: любое утверждение «X в данных нет» требует отдельной проверки, что данные вообще есть. В стенде это сделано явно — вывод про pg_sleep объявляется недействительным, если в профиле Java меньше 300 фреймов:

SLEEP_VERDICT_VALID=1
if [ "$SLEEP_FRAMES" -lt 300 ] 2>/dev/null; then
  SLEEP_VERDICT_VALID=0
  echo "  ВНИМАНИЕ: профиль Java слишком мал ($SLEEP_FRAMES фреймов) — вывод про pg_sleep недействителен"
fi

Итог

Что стоит забрать:

Непрерывное профилирование отвечает на вопросы о прошлом. Разовый pprof требует, чтобы вы успели и чтобы проблема повторилась.
Спросите Pyroscope, что он получил. Типы профилей у Go и Java разные; общий ровно один. Запрос по чужому типу отвечает 200 с пустым флеймграфом — это выглядит как «данных нет».
Блокировочные профили Go не появятся без SetMutexProfileFraction и SetBlockProfileRate. Молча, без предупреждений.
ITIMER работает в контейнере без capabilities. Проверено при perf_event_paranoid=2 и нулевом наборе привилегий. И по логу нельзя отличить работающий perf от отката — агент в обоих случаях пишет «Profiling started».
span_id — не метка серии, а метка сэмплов. Профиль конкретного запроса доступен по span_id из атрибута pyroscope.profile.id; у короткого запроса он обычно пуст (сэмпл — это 10 мс CPU), поэтому для коротких запросов полезнее профиль по набору спанов. Метка span_name по умолчанию берётся у корневого спана.
Метка ставится только корневому спану, и имя берётся на старте. Спан называется POST /order, метка — POST: otelhttp дописывает маршрут позже. Все POST-эндпоинты сольются в одну метку.
Ширина фрейма — стоимость, высота — вложенность. Оптимизируют плато наверху, а не высокий узкий шпиль.
CPU-профиль ничего не скажет об ожидании. pg_sleep в профиле отсутствует при 645 фреймах — и это правильно. Медленное из-за ожидания ищут в трейсе.
Ошибка запроса легко маскируется под отсутствие данных. Разбор ответа обязан отличать ошибку сервера от честной пустоты.
Суждение «X в данных нет» требует проверки, что данные есть. Иначе критерий проходит на пустоте.
Профилировщик сэмплирует время, а не запросы. Тонкий по CPU сервис выглядит в профиле пустым, потому что ждёт, а не потому что бездействует. Залповая нагрузка на 15 секунд не даёт его функциям попасть в выборку вовсе.
Проверка на широком окне подтверждает старые данные. «Функция найдена» на тёплом стенде не значит «профиль собран этим прогоном» — для этого нужен отдельный режим с очищенным хранилищем.
Компонент с долгой готовностью не должен блокировать остальное. У Pyroscope готовность — три фазы и около четырёх минут; в профиле compose он не мешает статьям, которым не нужен. И docker compose down без --profile "*" его не гасит.

На этом вторая волна серии закончена: метрики (статья 4) дали числа, SLO (статья 5) превратили их в решения, профили закрыли вопрос о цене. Дальше — трейсы как данные и стоимость телеметрии целиком.

Документация и первоисточники

Grafana Pyroscope: документация — архитектура, типы профилей, запросы.
pyroscope-go — SDK для Go, список типов профилей и настройки.
otel-profiling-go — обёртка над TracerProvider, навешивающая pprof-метки.
Pyroscope Java agent — переменные окружения, режимы сэмплирования.
async-profiler — что внутри агента и чем ITIMER отличается от perf.
Go: runtime/pprof — типы профилей и их включение.
Brendan Gregg: Flame Graphs — исходная идея и как их читать.
Parca — альтернатива с pull-моделью и eBPF.
Стенд, конфиги, скрипты проверок и сырые выводы замеров — digital-cookbook/observability/practice-stack.

Обсуждение в Telegram

Присоединиться →