Сколько стоит pprof: измеряем накладные расходы профилирования в Go

«CPU-профиль стоит единицы процентов, снимайте прямо с прода». Эту фразу вы встретите почти в каждой статье про pprof. Я сам написал её в статье про pprof. Но ни в одном из этих текстов нет методики и цифр. Утверждение кочует из блога в блог как фольклор. Я решил проверить его сам: собрал реалистичный сервис, прогнал нагрузку с профилированием и без, посчитал разницу через benchstat. В статье все цифры и методика, по которой их можно воспроизвести.

Спойлер: фольклор в целом не врёт, местами он даже слишком осторожен. CPU-профиль оказался неотличим от бесплатного. Зато MemProfileRate = 1 отобрал у сервиса 61% пропускной способности, а безобидный на вид дамп горутин заморозил его на 400 миллисекунд. Обо всём по порядку.

Методика

Замерять накладные расходы на микробенчмарке бессмысленно. Профилирование добавляет цену не одной функции, а всему рантайму: сигналы, сэмплирование аллокаций, запись событий блокировок. Поэтому стенд имитирует типичный API-сервис.

Тестовый сервис. HTTP-обработчик делает то же, что средний продакшен-эндпоинт: декодирует JSON-запрос, ходит в БД-заглушку, собирает ответ из 20 элементов и кодирует его в JSON. Заглушка хранит данные в памяти под мьютексом и спит 300 микросекунд, имитируя сеть до базы. На каждый запрос приходятся аллокации, немного вычислений и ожидание на локе. Профили включаются флагами при старте.

func handler(w http.ResponseWriter, r *http.Request) {
	var req searchRequest
	if err := json.NewDecoder(r.Body).Decode(&req); err != nil {
		http.Error(w, err.Error(), http.StatusBadRequest)
		return
	}
	rows := db.query(req.UserID, req.Limit) // mutex + sleep 300µs
	resp := buildResponse(req, rows)        // 20 элементов, fnv-хэш, fmt.Sprintf
	w.Header().Set("Content-Type", "application/json")
	json.NewEncoder(w).Encode(resp)
}

Генератор нагрузки. Отдельная программа: 32 воркера в закрытом цикле шлют POST-запросы и записывают время каждого ответа. На выходе пропускная способность и перцентили p50/p90/p99/p99.9 в формате, который понимает benchstat.

Железо и софт. AMD Ryzen 5 PRO 4650U (6 ядер, 12 потоков), 30 ГБ RAM, Linux 6.12, Go 1.24.10. Сервису отдано GOMAXPROCS=8, генератору 3 потока. Это ноутбучный процессор с турбо-частотами, поэтому шум неизбежен.

Борьба с шумом. Та же схема, что в статье про бенчмарки: каждый замер повторяется 5-6 раз, конфигурации чередуются (не «шесть базовых прогонов, потом шесть с профилем», а попеременно), разницу считает benchstat. Он же показывает, значима ли она статистически. Если benchstat пишет ~ (p > 0.05), разница неотличима от шума. Один прогон длится 20 секунд, перед серией сервис прогревается.

Базовая производительность стенда без профилирования: 25-27 тысяч запросов в секунду, p50 около 1 мс, p99 около 3.2 мс. От серии к серии базовый уровень гулял на пару процентов, поэтому каждый эксперимент сравнивает конфигурации только внутри своей серии, со своей собственной базой.

Эксперимент 1: включённый CPU-профиль

Главный вопрос статьи. CPU-профиль работает через сигналы: на каждую секунду процессорного времени поток получает примерно 100 сигналов SIGPROF, и обработчик записывает текущий стек. Пока профиль снимается, эта машинерия крутится постоянно. Фольклор говорит, что стоит она единицы процентов.

Схема замера: сервис работает, я чередую 20-секундные прогоны без профиля и прогоны, во время которых снимается /debug/pprof/profile. Шесть пар прогонов, порядок внутри пары «база, потом профиль». Результат по числу запросов в секунду:

     │  baseline   │           profiled            │
     │    req/s    │    req/s     vs base          │
CPU    25.03k ± 4%   25.79k ± 1%  +3.04% (p=0.041 n=6)

Сервис с включённым профилем оказался на 3% быстрее. Это выглядит как ошибка методики: в паре «база, потом профиль» второй прогон мог выигрывать от прогретых кэшей или разогнавшегося турбобуста. Поэтому я прогнал ещё шесть пар в обратном порядке, сначала профиль, потом база. Эффект не исчез: снова +3.6% в пользу профиля, p=0.002. На объединённых 12 парах картина такая:

        │  baseline   │           profiled              │
req/s     25.23k ± 1%   25.95k ± 2%  +2.87% (p=0.000 n=12)
p50       999.0µ ± 1%   958.3µ ± 2%  -4.07% (p=0.000 n=12)
p99       3.461m ± 4%   3.442m ± 5%       ~ (p=0.128 n=12)

Медиана с профилем стабильно ниже, хвосты (p90, p99, p99.9) не отличаются. Профилирование воспроизводимо «ускоряет» сервис.

Разумеется, pprof не делает код быстрее. Причину я нашёл позже, после пятнадцати дополнительных экспериментов, и она оказалась неожиданной: StartCPUProfile при запуске аллоцирует профильный буфер размером около мегабайта, и на маленькой живой куче стенда этот лишний мегабайт работает как GC-балласт. Цель следующей сборки мусора отодвигается, сборки происходят реже, и сервис экономит на stop-the-world паузах и GC-ассистах. Тот же прирост воспроизводится вообще без профилирования, если просто держать в куче лишний буфер того же размера.

Это тот же приём, который Twitch когда-то использовал сознательно: их статья про memory ballast описывает, как балласт в 10 ГБ снизил нагрузку на CPU их API на 30% именно за счёт более редких сборок. У меня балласт получился случайно, в нагрузку к профилировщику. Подробное расследование с бисекцией рантайма тянет на отдельную статью.

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

Контрольный эксперимент это подтверждает. Я повторил замер на том же сервисе, но с живой кучей 2 ГБ (флаг стенда -bigheap): лишний мегабайт буфера на таком фоне ничего не меняет. «Ускорение» исчезло, и впервые проявилась настоящая цена CPU-профиля: −0.5% пропускной способности (p=0.041) и +0.6% медианной задержки, хвосты в шуме. Вот сколько на самом деле стоит профиль на 100 Гц для IO-bound сервиса, когда GC-эффекты не искажают картину: около половины процента. Это финальное подтверждение расхожих «единиц процентов», теперь уже с чистым замером.

Для практики важно другое. Реальная цена CPU-профиля оказалась настолько мала, что её не видно за эффектами управления питанием и шумом в 1-4%. Сервис обрабатывал 26 тысяч запросов в секунду, профиль снимался непрерывно, и ни пропускная способность, ни p99 не просели ни в одном из 12 прогонов. Обещанные «единицы процентов» подтверждаются с запасом: это верхняя граница, а не типичная цена. Снимать CPU-профиль с прода можно спокойно.

Сам профиль за 24 секунды занял около 90 КБ. Единственная заметная цена здесь не CPU, а внимательность: эндпоинт держит HTTP-соединение открытым все запрошенные секунды.

Эксперимент 2: heap-сэмплирование и MemProfileRate

Профиль кучи в Go включён всегда. Рантайм сэмплирует в среднем одну аллокацию на runtime.MemProfileRate байт, по умолчанию это 512 КБ. Чтобы поймать в профиль мелкие редкие аллокации, порог иногда снижают. Крайний случай MemProfileRate = 1 записывает каждую аллокацию. Вопрос: сколько стоит дефолт и сколько стоит крайность?

Сравнил четыре конфигурации: профиль выключен (MemProfileRate = 0), дефолтные 512 КБ, сниженный порог 64 КБ и запись всего подряд. По 5 прогонов на каждую, сервис перезапускался перед каждым прогоном, потому что менять rate нужно до первых аллокаций, на старте программы.

Первые три строки benchstat не различает: p-value от 0.15 до 0.55, разница в пределах шума. Дефолтное сэмплирование бесплатно, и даже порог 64 КБ на этом сервисе ничего не стоит. Это объясняет, почему Go может позволить себе держать профиль кучи включённым всегда.

А вот MemProfileRate = 1 обвалил сервис. Пропускная способность упала на 61% (p=0.008), медианная задержка выросла с 0.9 до 2.3 мс, p99 с 3.2 до 10 мс. На каждую записанную аллокацию рантайм собирает стек вызовов, а обработчик аллоцирует десятки объектов на запрос. В сумме это удвоение и утроение времени ответа.

Вывод простой. Снижать порог до 64 КБ можно смело. Ставить 1 в проде нельзя, это инструмент для локальной отладки, когда нужно найти конкретную мелкую аллокацию.

Эксперимент 3: block и mutex

Профили block и mutex по умолчанию выключены, и в статье про pprof я советовал включать их «осознанно», потому что агрессивный rate «может заметно замедлить горячие пути». Проверяем, насколько заметно.

Три конфигурации: выключено, разумные пороги и максимум. Разумные пороги это SetBlockProfileRate(100000), то есть одно событие на 100 микросекунд блокировки, и SetMutexProfileFraction(100), каждый сотый конфликт. Максимум это SetBlockProfileRate(1) плюс SetMutexProfileFraction(1), писать всё. По 5 прогонов.

Сюрприз: benchstat не нашёл значимой разницы даже для максимальных настроек. Все p-value выше 0.2. На этом сервисе даже запись каждого события блокировки ничего не стоит.

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

Эксперимент 4: дампы на большой куче

Последние два кандидата: полный текстовый дамп горутин /debug/pprof/goroutine?debug=2 и снимок кучи с принудительной сборкой мусора /debug/pprof/heap?gc=1. Оба выглядят безобидно, оба в статье про pprof я советовал как инструменты диагностики. Проверяем на сервисе, у которого есть что дампить: живая куча 2 ГБ из 16 миллионов объектов и 50 тысяч запаркованных горутин.

Схема: генератор молотит 40 секунд и пишет посекундную статистику, на 12-й секунде снимается дамп горутин, на 25-й снимок кучи. Три прогона плюс контрольный без дампов. Контроль: 27.2k req/s, максимальная задержка ответа за 40 секунд 14.7 мс.

goroutine?debug=2 останавливает мир. Этот эндпоинт собирает стеки всех горутин через runtime.Stack, а он останавливает все горутины на время сборки. Результат виден невооружённым глазом:

сек   запросов   p99        max
11    27275      3.10ms     5.9ms
12    12265      3.65ms     387.0ms   <- дамп горутин
13    27242      3.05ms     6.7ms

В секунду дампа сервис обработал вдвое меньше запросов, а самые невезучие из них ждали ответа 387-404 мс во всех трёх прогонах. Это и есть длительность паузы: 50 тысяч стеков форматируются в 18 МБ текста при остановленном мире. Обычный ?debug=1 и бинарный профиль горутин таких пауз не дают: начиная с Go 1.19 паузы stop-the-world при сборе профиля горутин значительно сокращены.

heap?gc=1 бьёт только того, кто спросил. Принудительная сборка мусора на куче 2 ГБ заняла 1.4-1.5 секунды: столько ждал ответа сам запрос к эндпоинту. А вот остальной трафик этого не заметил: в секунды вокруг снимка ни пропускная способность, ни максимальная задержка не отличаются от контроля. GC в Go конкурентный, и даже принудительный полный цикл не останавливает обработку запросов на заметное время. Для сравнения, тот же gc=1 на куче 700 МБ занимал 0.5 секунды: цена растёт с размером кучи, но платит её вызывающий, а не пользователи.

Эксперимент 5: цена pprof в самом бинарнике

Все эксперименты выше меряют работающий профиль. Остался вопрос уровнем ниже: сколько стоит само присутствие pprof в программе? Сравним три варианта одной и той же CLI-программы: собранной вообще без pprof, с подключённым, но выключенным pprof и с активно пишущимся CPU-профилем.

Нагрузка здесь другая. Вместо HTTP-сервиса, который большую часть времени ждёт, одна горутина без пауз молотит процессор: JSON marshal и unmarshal плюс fnv-хэш в цикле. Это модель батч-джобы или кодека, худший случай для CPU-профиля.

Сначала размер бинарника:

Сам профилировщик почти ничего не весит. Бинарник раздувает не pprof, а net/http со всем деревом зависимостей, которое тянет за собой debug-сервер. Для сервиса это не новость, он и так импортирует net/http. А вот CLI-утилите ради профилирования достаточно runtime/pprof за полмегабайта.

Теперь скорость, 6 чередующихся прогонов:

Подключённый, но не активный pprof по скорости бесплатен: платишь размером бинарника и открытым портом, но не тактами. Это подтверждает выводы первых экспериментов с другой стороны.

А вот активный CPU-профиль на этой нагрузке уже виден: +15%. Контраст с экспериментом 1, где тот же профиль был неотличим от шума, объясняется просто. HTTP-сервис большую часть времени ждёт сеть и локи, SIGPROF-сэмплы редко застают его потоки на процессоре. Здесь же горутина занимает ядро без пауз, каждый из примерно 100 сэмплов в секунду прерывает горячий цикл и разматывает стек.

Но 15% это опять ноутбук. Повтор на облачной VM (той же, что в следующем разделе) поставил цифру на место: тот же CPU-bound цикл на серверном железе замедлился под профилем всего на 1.5% (p=0.002), а вариант только с runtime/pprof на 0.4%. Разница измерима, воспроизводима и при этом укладывается в те самые «единицы процентов» с большим запасом. Ноутбучные 15% читаются как верхняя граница для худшего окружения: турбо-частоты, энергосбережение и сигналы каждые 10 мс плохо сочетаются. На сервере даже худший для профиля случай, непрерывный CPU-bound код, стоит полтора процента.

Проверка на облачной VM

Все замеры выше сделаны на ноутбуке. Это честное железо, но с оговорками: турбобуст, агрессивное энергосбережение, фоновые процессы. Чтобы проверить, что выводы не артефакт ноутбука, я повторил эксперименты 1-4 на свежей VM в Яндекс Облаке: 8 vCPU Intel Cascade Lake, 16 ГБ RAM, Ubuntu 24.04, Go 1.24.5. VM создавалась скриптом, жила полчаса и удалялась, так что окружение воспроизводимо с нуля.

Облачная VM оказалась быстрее ноутбука: 30-35 тысяч запросов в секунду против 25-27. Все выводы воспроизвелись, а некоторые цифры стали даже нагляднее.

Два наблюдения из этой таблицы.

Странное «ускорение» из эксперимента 1 на этой VM утонуло в шуме: 30.5k против 31.5k req/s, p=0.31. GC-эффект от профильного буфера никуда не делся, просто на 8 ядрах он меньше облачного шума. На большем числе ядер он, наоборот, вырастает: на 20-ядерной VM тот же стенд ускорялся под профилем на четверть, что и запустило расследование из предыдущего раздела.

MemProfileRate = 1 на VM стоил ещё дороже: минус 73% пропускной способности вместо 61%. Облачный сервис обрабатывал больше запросов в секунду, значит, аллоцировал чаще, и запись каждой аллокации отбирала большую долю времени. Цена этой настройки растёт вместе с нагрузкой, что лишний раз подтверждает: в проде ей делать нечего.

Дамп горутин на VM затормозил сервис так же, как на ноутбуке: в секунду дампа сервис просел с 38.8 до 15.6 тысяч запросов, максимальная задержка подскочила до 337 мс. Пауза stop-the-world никуда не делась и на серверном железе.

Практические выводы

Сведу всё в одну таблицу. Цифры с моего стенда, на вашем железе будут другие, но порядки сохранятся.

Три правила, которые из этого следуют.

Во-первых, снимайте CPU-профиль и снимки кучи с прода без колебаний. Страх «профилирование замедлит сервис» не подтверждается даже на ноутбуке с шумным окружением. Единственное настоящее требование безопасности здесь другое: debug-эндпоинты не должны торчать наружу.

Во-вторых, значение 1 для любого rate это инструмент локальной отладки. Разница между «писать всё» и «сэмплировать» может стоить вам половины пропускной способности, как у MemProfileRate = 1. При этом умеренные настройки (64 КБ, порог 100 мкс для block) не стоят ничего, а данных дают достаточно.

В-третьих, у дампов на большом сервисе есть цена, и она разная. goroutine?debug=2 останавливает мир пропорционально числу горутин: при 50 тысячах это уже сотни миллисекунд. Если нужен профиль горутин с нагруженного прода, начните с ?debug=1 или бинарного профиля. heap?gc=1 наоборот безопасен для трафика, просто будьте готовы подождать ответ.

Итог

Фольклор про дешёвый pprof подтвердился и даже оказался слишком осторожным. CPU-профиль под нагрузкой 26 тысяч запросов в секунду не показал измеримых накладных расходов: разница с базой утонула в шуме 1-4%, а из-за GC-эффекта от аллокации профильного буфера профилируемый сервис формально оказался даже быстрее. Дефолтное heap-сэмплирование бесплатно, как и разумные пороги block/mutex.

Оговорка одна: «бесплатность» CPU-профиля это свойство сервисов, которые много ждут. На чисто вычислительном коде цена профиля измерима: 1.5% на серверной VM и до 15% на ноутбуке, это показал эксперимент с CPU-bound CLI-программой.

Дорогими оказались крайности. MemProfileRate = 1 отобрал 61% пропускной способности. goroutine?debug=2 на 50 тысячах горутин заморозил сервис на 400 мс. heap?gc=1 на куче 2 ГБ заставил вызывающего ждать полторы секунды. Все три инструмента полезны, просто у них есть цена, и теперь она измерена.

Методика воспроизводима: стенд из HTTP-сервиса с БД-заглушкой, генератор нагрузки с перцентилями, 5-12 чередующихся прогонов на конфигурацию и benchstat для проверки значимости. Повтор на облачной VM дал те же выводы, так что дело не в моём ноутбуке. Подробнее про такую схему измерений я писал в статье про бенчмарки, а что делать с профилями, которые вы теперь можете спокойно снимать с прода, разобрано в статье про pprof.