Профилирование в Go: что показывает pprof и чего он не показывает по умолчанию

Что здесь на самом деле спрашивают

Лестница почти всегда такая:

1. «Как найти, что тормозит?» — разминка; ответ «pprof» правильный, но начинать надо с того, какой профиль.
2. «Как снять профиль?» — три способа, и у каждого своё место.
3. «Чем flat отличается от cum?» — здесь проверяют, читал ли кандидат профиль сам.
4. «Как найти утечку памяти?» — про два вида значений в профиле кучи.
5. «Почему профиль блокировок пустой?» — вопрос, на котором спотыкаются и те, кто профили читал.
6. «Можно ли профилировать в продакшене?» — про цену и про то, кому открыт /debug/pprof.

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

База: профиль — это выборка, а не учёт

Профилировщик не записывает каждый вызов: это стоило бы слишком дорого. Почти каждый профиль — выборка (исключение — профиль горутин, о нём ниже): с какой-то частотой берётся сэмпл — снимок стека в момент события — и складывает одинаковые стеки. Что считается событием, зависит от профиля:

Снимают профиль тремя способами, и у каждого своё место:

• из теста или бенчмарка — go test -bench . -cpuprofile cpu.out, рядом -memprofile, -blockprofile, -mutexprofile. Это место для воспроизводимой нагрузки;
• из работающего сервиса — import _ "net/http/pprof", и по адресам /debug/pprof/ отдаются все профили. Это место для настоящей нагрузки;
• из кода — runtime/pprof: StartCPUProfile, Lookup("heap").WriteTo. Так устроены оба способа выше; руками это пишут, когда нужен профиль конкретного участка.

Читают профиль одинаково: go tool pprof — с режимами -top, -list, -web.

И сразу — какой инструмент на какой вопрос отвечает:

Ответ уровня Junior на «как найти, что тормозит»: снять профиль CPU — из бенчмарка через go test -cpuprofile или из сервиса через net/http/pprof — и открыть его в go tool pprof; наверху будут функции, в которых программа проводит больше всего времени.

Механизм 1: профиль CPU — выборка, в go1.24.7 — 100 раз в секунду

В runtime/pprof частоту не выбирают: StartCPUProfile её не принимает, она зашита. В исходнике рядом с ней объяснение:

Значит, при номинальных 100 Гц один сэмпл соответствует примерно 10 мс процессорного времени — в сумме, по статистике, а не по секундомеру у каждой функции. Две секунды работы одной горутины:

  длительность работы            2.11 с
  сэмплов в профиле               203
  сэмплов в секунду                96

Из этого числа следуют две вещи, которые стоит уметь сказать.

Короткие функции профиль может не увидеть. Функция, проработавшая 5 мс за весь запуск, получит в среднем полсэмпла — то есть ноль или один. Профиль отвечает на вопрос «где программа проводит много времени», а не «вызывалась ли функция».

«Total samples» в выводе — время, а не число. В другом прогоне — раздел 1 internals.go, другая нагрузка той же длины — go tool pprof -top печатает:

  Duration: 2.12s, Total samples = 2070ms (97.61%)

2070 мс — это 207 сэмплов, пересчитанных по номинальным 10 мс. Процент — доля процессорного времени от стенного: 97,61 %, потому что одна горутина занимает не больше одного ядра. Если занятых горутин несколько, процент может превысить 100 — прогон bench/goprof/cores.go:

  одна занятая горутина:  Duration: 2.11s, Total samples = 1.97s (93.39%)
  две занятые горутины:   Duration: 2.15s, Total samples = 3.89s (181.35%)

На двух ядрах две горутины набрали почти вдвое больше процессорного времени, чем прошло по часам.

Механизм 2: flat и cum

Вот таблица, ради которой профиль и открывают. Функция handle сама ничего не делает — только зовёт hashAll (тяжёлая работа) и parse (лёгкая). Строки выбраны из полного списка -top, поэтому колонку sum% — накопленный flat% в исходном порядке — здесь не читайте:

2) FLAT ПРОТИВ CUM НА ОДНОЙ И ТОЙ ЖЕ ЦЕПОЧКЕ
────────────────────────────────────────────
        flat  flat%   sum%        cum   cum%
           0     0% 94.20%     1750ms 84.54%  main.hashAll
        50ms  2.42% 77.29%       50ms  2.42%  main.parse
           0     0% 94.20%     1800ms 86.96%  main.handle

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

У handle flat 0 и cum 86,96 %: сама функция не тратит ничего, но почти всё время программа проводит под ней. Сортировка по flat её бы не показала, сортировка по cum поставила бы наверх.

Обратите внимание и на hashAll: у неё flat тоже 0. Тяжёлая работа сидит глубже — в функциях crypto/sha256, и наверху -top стоят именно они:

      1310ms 63.29% 63.29%     1310ms 63.29%  crypto/internal/fips140/sha256.blockAVX2

Отсюда порядок чтения, который стоит назвать на собеседовании:

• flat — где процессор выполнялся непосредственно;
• cum — какие пути вызовов ответственны за это время.

Нужны оба. По flat видно горячий код — здесь blockAVX2; по cum — чьё решение его вызывать: handle через hashAll. Часто выигрыш не в том, чтобы ускорить верх flat, а в том, чтобы реже вызывать путь, который виден по cum.

Механизм 3: профиль кучи — два разных вида значений

В каждой записи профиля кучи четыре вида значений — выделено и удерживается, в объектах и в байтах, — и -sample_index выбирает, какой из них показать. Два главных отвечают на разные вопросы. Документация определяет, на какой момент снят профиль:

Две функции: churn выделяет много и ничего не держит, retain выделяет немного и держит всё:

3) ПРОФИЛЬ КУЧИ: alloc_space ПРОТИВ inuse_space
───────────────────────────────────────────────
  alloc_space — сколько выделено за всё время:
    596.83MB 76.83% 76.83%   596.83MB 76.83%  main.churn
     16.19MB  2.08% 99.58%    16.19MB  2.08%  main.retain
  inuse_space — сколько удерживается сейчас:
  в выводе нет строки main.churn
     16.19MB 97.00% 97.00%    16.19MB 97.00%  main.retain

Функция, выделившая почти 600 МБ, в inuse_space отсутствует вовсе. Это не ошибка профиля, а смысл двух видов значений:

• inuse_space (по умолчанию у heap) — сколько байт кучи Go удерживается сейчас. Здесь видна утечка памяти кучи: что растёт от снятия к снятию и не уходит.
• alloc_space (по умолчанию у allocs) — всё, что выделялось. По ней ищут давление на сборщик: кто создаёт работу для сборки мусора, даже ничего не удерживая.

Но inuse_space — не универсальный детектор утечек:

• inuse_objects — тот же срез в штуках, а не в байтах: утечка множества мелких объектов в байтах может теряться;
• утечка горутин — это профиль горутин (Механизм 5): в профиле кучи она видна разве что косвенно, по тому, что эти горутины удерживают;
• память вне кучи Go — выделенная через cgo, ядром, отображённая в память — heap-профиль Go не показывает вовсе. Если процесс растёт, а inuse_space нет, искать надо там.

Профиль кучи — тоже выборка: в среднем одно выделение на runtime.MemProfileRate = 524288 байт. И о единицах: «MB» в выводе pprof — это 2²⁰ байт, то есть МиБ. Мелкое выделение, сделанное один раз, в профиль может не попасть, а частое попадёт пропорционально объёму.

Механизм 4: профили, которые выключены по умолчанию

Четыре горутины дерутся за один мьютекс — конкуренция настоящая. Профили блокировок и мьютексов:

4) ПРОФИЛИ БЛОКИРОВОК И МЬЮТЕКСОВ ПО УМОЛЧАНИЮ
──────────────────────────────────────────────
  без настройки:  block 0 записей, mutex 0 записей
  после SetBlockProfileRate(1) и SetMutexProfileFraction(1):
                  block 3 записей, mutex 2 записей

Без настройки оба пусты. Это самая частая ловушка: сервис с net/http/pprof, открыли /debug/pprof/block — пусто, сделали вывод «блокировок нет».

Отвечают они на разные вопросы:

• block — где и сколько горутины стояли на примитивах синхронизации: каналах, мьютексах, WaitGroup. Стек — того, кто ждал;
• mutex — где шла борьба за мьютекс, и стек того, кто его держал, в точке Unlock: где укорачивать критический участок.

Включаются они так:

Значение 1 — «записывать всё» — удобно для отладки, но не бесплатно. На крайних нагрузках, где почти вся работа — блокировки или захваты:

1) ПРОФИЛЬ БЛОКИРОВОК: SetBlockProfileRate(1)
─────────────────────────────────────────────
  серия                                  выключен       «всё»   кратн.
  1      пинг-понг, 200 000 обменов       88.7 мс    145.1 мс   x1.64
  2      пинг-понг, 200 000 обменов       82.5 мс    146.6 мс   x1.78
  3      пинг-понг, 200 000 обменов       75.1 мс    142.8 мс   x1.90

2) ПРОФИЛЬ МЬЮТЕКСОВ: SetMutexProfileFraction(1)
────────────────────────────────────────────────
  серия                                  выключен       «всё»   кратн.
  1      4 горутины × 200 000 захватов     16.5 мс     25.1 мс   x1.52
  2      4 горутины × 200 000 захватов     33.7 мс     54.1 мс   x1.61
  3      4 горутины × 200 000 захватов     29.2 мс     39.3 мс   x1.35

Прогон bench/goprof/interfere.go: ×1,64–1,90 для блокировок и ×1,35–1,61 для мьютексов. На сервисе, где блокировки — малая часть работы, доля будет меньше, но режим «каждое событие» в продакшене — осознанное решение, а не значение по умолчанию. Обычно ставят большее значение и получают выборку.

И различие, которое стоит знать. В go test флаг -blockprofile включает запись сам: если -blockprofilerate не указан, записываются все события блокировки. В сервисе такого нет — вызов runtime.SetBlockProfileRate должен быть в вашем коде.

Механизм 5: профиль горутин — и почему одного снимка мало

Сотня горутин ждёт канала, в который никто никогда не напишет:

5) ПРОФИЛЬ ГОРУТИН НАХОДИТ УТЕЧКУ
─────────────────────────────────
  горутин до: 1, после: 101
  в профиле: 100 горутин с одним и тем же стеком:
    main.main.func2              internals.go:246

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

снимок A → подождать → снимок B
тот же стек вырос и не вернулся обратно

Строка internals.go:246 — место, где они ждут; причину ищут там.

Почему горутины утекают и почему -race такую утечку не ловит, разобрано в уроке о каналах. Здесь — инструмент: /debug/pprof/goroutine?debug=1 в работающем сервисе, и сравнение двух снятий через несколько минут.

Глубже: сколько стоит профилирование и кому открыт /debug/pprof

Одна и та же работа — 400 вызовов handle — с профилем CPU и без, три серии:

6) ЦЕНА ПРОФИЛЯ CPU ДЛЯ САМОЙ ПРОГРАММЫ
───────────────────────────────────────
  серия   400 вызовов без профиля     с профилем CPU   надбавка
  1                     228.6 мс           219.4 мс      -4.0%
  2                     223.3 мс           223.5 мс       0.1%
  3                     222.1 мс           221.0 мс      -0.5%

Надбавка меняет знак от серии к серии: она меньше шума замера. Причина — та же частота: сто снимков стека в секунду — малая доля работы на фоне 800 000 вызовов sha256, которые 400 вызовов handle делают за ≈222 мс.

Отсюда практическое различие, о котором спрашивают: профиль CPU обычно достаточно лёгок для ограниченного снятия в продакшене — по запросу, через /debug/pprof/profile (по умолчанию 30 секунд, длительность задаёт ?seconds=N). А -race, который на замеренной нагрузке стоил ×4,8–5,0 по памяти и ×7,6–12 по времени, на всём парке не держат (это разобрано в уроке о гонках данных).

И граница у этих чисел: замер снят при GOMAXPROCS=2 на одной нагрузке go1.24.7. Надбавки выше шума на ней не обнаружено — это результат замера, а не универсальное число: цена зависит от нагрузки.

Инструмент не нейтрален. Профили влияют и на программу, и друг на друга. Профиль памяти, записывающий каждое выделение, сам становится строкой профиля CPU:

3) ПРОФИЛЬ ПАМЯТИ: MemProfileRate = 1
─────────────────────────────────────
  серия                                  выключен       «всё»   кратн.
  1      2 000 000 выделений по 64 Б      67.0 мс   3488.9 мс   x52.03
  2      2 000 000 выделений по 64 Б      59.8 мс   3734.4 мс   x62.43
  3      2 000 000 выделений по 64 Б      71.4 мс   3599.8 мс   x50.43

  доля runtime.mProf_Malloc в профиле CPU той же нагрузки (cum%):
    MemProfileRate по умолчанию: нет в профиле
    MemProfileRate = 1:          76.64%

Нагрузка нарочно крайняя — одни мелкие выделения, — но вывод общий: снятый при MemProfileRate = 1 профиль CPU на 76,64 % показывает работу самого профилировщика памяти. Поэтому подробные режимы не включают все сразу и читают каждый профиль с поправкой на то, что было включено рядом.

Кому открыт /debug/pprof. Это обязательная вторая половина совета «снимайте в продакшене». Импорт net/http/pprof регистрирует обработчики на http.DefaultServeMux, и сервис, отдающий его на рабочий порт, отдаёт и профили — без какой-либо проверки доступа:

  сервис зарегистрировал только /hello и отдаёт DefaultServeMux

  GET /debug/pprof/cmdline           -> 200, аргументы: ["-db-password=demo-secret"]
  GET /debug/pprof/goroutine?debug=2 -> 200, строк «файл:строка»: 53
  GET /debug/pprof/heap              -> 200

Прогон bench/goprof/exposure.go, пароль в аргументах — выдуманный. Наружу уходят аргументы запуска, стеки с путями к исходникам и профили памяти. Поэтому /debug/pprof — служебная поверхность: отдельный слушатель (пример из документации пакета слушает localhost:6060), доступ только из внутренней сети или через аутентификацию, никакого выхода в публичный интернет.

Как отвечать на собеседовании

Короткий ответ: снять профиль CPU — из бенчмарка через go test -cpuprofile или из сервиса через net/http/pprof — и открыть в go tool pprof -top. Профилировщик сэмплирующий, поэтому наверху окажутся функции, где программа проводит больше всего времени, а короткие вызовы могут не попасть вовсе. Частоту — 100 раз в секунду в go1.24.7 — называют как деталь реализации, а не как свойство языка.

Этого достаточно, чтобы ответить верно. Дальше — то, что добавляют, если собеседник копает.

Если интервьюер копает глубже

На «чем flat отличается от cum» — пример с диспетчером. «flat — где процессор выполнялся непосредственно, cum — какие пути вызовов за это отвечают. У функции, которая только раздаёт работу, flat ноль, а cum почти весь профиль — у меня 86,96 %. Смотрят оба: часто дешевле реже вызывать путь, чем ускорять горячую функцию».

На «как искать утечку памяти» — два вида значений. «inuse_space — что удерживается на последнюю сборку; утечку ищут там, сравнивая два снятия. alloc_space — всё выделенное; по ней ищут давление на сборщик. Функция, выделившая шестьсот мегабайт и ничего не удержавшая, в inuse_space не видна вовсе. А утечку горутин ищут в профиле горутин, и память вне кучи Go heap-профиль не покажет».

На «почему профиль блокировок пустой» — он выключен. «Block и mutex по умолчанию не пишутся: у меня при настоящей конкуренции было 0 записей. Нужно вызвать runtime.SetBlockProfileRate и SetMutexProfileFraction. В go test -blockprofile это включается само, в сервисе — нет».

На утечку горутин — профиль горутин, два снятия. «Один снимок показывает скопление на одном стеке; утечка — когда этот стек растёт от снятия к снятию и не возвращается. Стек показывает, на чём они стоят».

На «можно ли в продакшене» — цена и доступ. «Профиль CPU — как правило, да, ограниченным снятием по запросу: на моей нагрузке надбавка не вышла за шум, но это не универсальное число. /debug/pprof — только на служебном слушателе, не наружу. Весь парк под -race — нет».

Дальше спросят

Частые заблуждения

Практика

Две задачи. Сначала ответьте, потом сверьтесь с настоящим выводом: в обеих правильный ответ взят из прогона скрипта, а не назначен.

fmt.Println(pprof.Lookup("block").Count())

before := pprof.Lookup("goroutine").Count()
never := make(chan int)
for i := 0; i < 100; i++ {
go func() { <-never }()
}
time.Sleep(50 * time.Millisecond)
fmt.Println(pprof.Lookup("goroutine").Count() - before)

churn(20000)
runtime.GC()
fmt.Println(strings.Contains(string(out), "main.churn"))

0
100
false

4
100
false

0
100
true

4
101
true

Проверка знаний