3.3 Профилирование и бенчмарки · Память, GC и производительность

3.3Профилирование и бенчмарки

Выберем профиль по вопросу о CPU, памяти или расписании и научимся снимать данные в воспроизводимом окне.

Какие бывают профили

Профиль	Что собирает	Как	Когда нужен
`cpu`	стеки горутин, которые в этот момент жгут CPU	сэмплирование по `SIGPROF`, 100 Гц	высокий CPU, медленные ответы
`heap`	аллокации: `inuse` и `alloc`, байты и объекты	сэмплирование, 1 из ~512 КБ	утечки, нагрузка на GC
`allocs`	то же, но по умолчанию в режиме `alloc_space`	тот же сэмплер	кто мусорит
`goroutine`	стек каждой живой горутины	полный снимок, STW на момент снятия	утечка горутин, дедлоки
`goroutineleak` 1.27	стеки только тех горутин, которые заблокированы навсегда: ждут примитив, до которого уже никто не дотянется	при снятии запускает свой цикл GC, отсюда точность	утечка горутин - сразу список виновных, без чтения тысяч стеков вручную
`block`	где горутины ждут синхронизацию (каналы, мьютексы, `WaitGroup`)	выключен, включается `SetBlockProfileRate`	«тормозит, а CPU простаивает»
`mutex`	кто держит замок и заставляет ждать других	выключен, `SetMutexProfileFraction`	контеншен на общем мьютексе
`threadcreate`	стеки, из-за которых рантайм создал ОС-поток	всегда включён	рост числа `M`: cgo, блокирующие сисколлы
`trace`	полный лог событий планировщика, GC, сети	по запросу, за интервал	«где именно теряется время» на таймлайне

Профиль goroutineleak: новый штатный способ искать утечки горутин

До Go 1.27 утечку горутин искали косвенно: смотрели, как растёт /sched/goroutines, снимали goroutine?debug=2 и глазами искали в тысячах стеков те, что висят на chan receive подозрительно долго. Работало, но требовало опыта и терпения. Профиль goroutineleak делает это сам: он показывает только те горутины, которые заблокированы навсегда. Эвристики тут нет, определение точное: горутина ждёт на канале, мьютексе или WaitGroup, а сам этот примитив уже недостижим из живой части программы, значит, разбудить её физически некому. Пропустить утечку он может: если до примитива дотягивается глобальная переменная или стек работающей горутины, примитив считается живым.

Экспериментом профиль был в Go 1.26 (GOEXPERIMENT=goroutineleakprofile), с Go 1.27 общедоступен: он есть в pprof.Profiles() и в /debug/pprof/goroutineleak вместе с остальными. Ждать очередного цикла GC не нужно: при каждом снятии профиль сам запускает сборку с поиском утечек, а обычный runtime.GC() его не наполняет.

func leak() {
    ch := make(chan int)     // никто не прочитает
    go func() { ch <- 42 }() // навсегда
}

func main() {
    leak()
    runtime.GC()
    p := pprof.Lookup("goroutineleak")
    fmt.Println(p.Count())   // 0 (разбор ниже)
    p.WriteTo(os.Stdout, 1)  // стек виновной горутины
}

// Настоящий вывод go1.27:
// 0
// goroutineleak profile: total 1
// 1 @ 0x104177f18 0x104112224 0x104111e38 0x1041cb918 0x10417e024
// #    0x1041cb917    main.leak.func1+0x27    /app/main.go:12
//
// Count() до первого WriteTo возвращает 0 и после второго runtime.GC() тоже:
// профиль наполняется в момент снятия, а не по циклу GC. После WriteTo
// тот же Count() вернёт 1. На собесе на этой детали и валится ответ
// «проверю утечку счётчиком»: смотреть надо сам профиль.

$ curl -s 'http://localhost:6060/debug/pprof/goroutineleak?debug=1'
goroutineleak profile: total 1
1 @ 0x102320728 0x1022b18a4 0x1022b14b8 0x1024cd698 0x1023277a4
#	0x1024cd697	main.leak.func1+0x27	/app/main.go:12

# в pprof, как обычный профиль
$ go tool pprof -http=:8080 'http://localhost:6060/debug/pprof/goroutineleak'

Как это звучит на собесе: «утечку горутин раньше ловили по счётчику runtime.NumGoroutine и библиотекой goleak в тестах; с Go 1.27 есть штатный профиль goroutineleak, который прямо в проде отдаёт стеки горутин, навсегда вставших на недостижимом примитиве». Такой ответ сразу выделяется: про этот профиль большинство ещё не слышало.

// block и mutex по умолчанию выключены: они не бесплатны, включай по делу
runtime.SetBlockProfileRate(10_000)     // ожидания от 10 мкс пишутся все, короче выборочно (в наносекундах)
runtime.SetMutexProfileFraction(100)    // учитывать 1 событие контеншена из 100
runtime.MemProfileRate = 512 * 1024     // дефолт; 1 = профилировать каждую аллокацию (медленно)

Снять профиль с прода

CPU- и heap-профили собираются выборкой, поэтому снимать их можно прямо на проде: оверхед единицы процентов. Цена в точности: цифры приблизительные и тем точнее, чем дольше снимаешь, а очень быстрая и редкая функция может вообще не попасть в выборку.

import (
    "net/http"
    _ "net/http/pprof"   // регистрирует хендлеры в http.DefaultServeMux
)

func main() {
    // отдельный слушатель на localhost, не публичный порт приложения
    go func() { http.ListenAndServe("127.0.0.1:6060", nil) }()
    // ... основной сервер на своём mux ...
}

# CPU за 30 секунд под нагрузкой
$ go tool pprof -http=:8080 'http://localhost:6060/debug/pprof/profile?seconds=30'
# куча прямо сейчас, после форс-цикла GC
$ go tool pprof -http=:8080 'http://localhost:6060/debug/pprof/heap?gc=1'
# горутины: debug=1 агрегирует, debug=2 даёт полные стеки с временем ожидания
$ curl -s 'http://localhost:6060/debug/pprof/goroutine?debug=2' | less
# трейс на 5 секунд
$ curl -so trace.out 'http://localhost:6060/debug/pprof/trace?seconds=5' && go tool trace trace.out

Про безопасность pprof-эндпоинта на собесе спрашивают отдельно

Импорт net/http/pprof регистрирует хендлеры в глобальном http.DefaultServeMux. Если основной сервер поднят на nil-хендлере, профили торчат наружу вместе с API. Это классическая находка пентеста.
Что утекает: goroutine?debug=2 отдаёт полные стеки, а в них имена функций, структура кода и иногда аргументы; /debug/pprof/cmdline отдаёт командную строку со всеми флагами (нередко с секретами); символы бинаря выдают версии зависимостей.
Что ломается: profile?seconds=300 держит CPU-профилирование пять минут, heap?gc=1 форсирует полный цикл GC, goroutine делает STW на снятие снимка. Любым из них можно устроить DoS.
Как правильно: отдельный слушатель на 127.0.0.1 или на внутреннем интерфейсе, доступ через kubectl port-forward; либо свой ServeMux с явной регистрацией pprof.Index и аутентификацией; либо сборка с build tag, включающим pprof только в отладочных образах.

Метки горутин: чей это запрос

Профиль отвечает на вопрос «какая функция жжёт CPU». На сервисе почти сразу нужен другой разрез: «какой обработчик», «какой тенант», «фон или онлайн». Для этого в runtime/pprof есть метки (labels): пары ключ-значение, которые вешаются на горутину. Метки наследуются: горутина, запущенная внутри помеченной, получает те же метки, поэтому достаточно поставить их один раз на границе запроса.

import "runtime/pprof"

func handler(w http.ResponseWriter, r *http.Request) {
    labels := pprof.Labels("handler", "createOrder", "tenant", tenantOf(r))
    pprof.Do(r.Context(), labels, func(ctx context.Context) {
        createOrder(ctx, r)      // всё, что здесь запустится, унаследует метки
    })
}

# какие метки вообще есть в профиле
$ go tool pprof -tags cpu.pprof
# только выборки одного обработчика
$ go tool pprof -tagfocus='handler=createOrder' -http=:8080 cpu.pprof
# метки видны и в goroutine-профиле:
$ curl -s 'http://localhost:6060/debug/pprof/goroutine?debug=1' | grep labels
# labels: {"handler":"createOrder", "tenant":"acme"}

Стоят метки немного: набор хранится у горутины и копируется при pprof.Do, поэтому ставить их на границе запроса нормально, а внутри горячего цикла нет. Второе ограничение касается кардинальности: каждое уникальное сочетание значений режет профиль на отдельную группу, так что «handler» и «tenant» в метках уместны, а идентификатор запроса раздувает профиль (у него значение уникально для каждого вызова).

Go 1.27: метки видно прямо в трейсбеке при панике

Раньше метки жили только внутри профилей. С Go 1.27 (если в go.mod стоит go 1.27 или новее) рантайм печатает их в заголовке горутины в трейсбеке, и по падению сразу видно, что именно горутина обрабатывала:

panic: boom

goroutine 1 [running] {handler: createOrder, request_id: "abc-123"}:
main.main()
	/app/main.go:16 +0xfc

До 1.27 в этой строке были только номер горутины и её состояние. По ним нельзя было понять, на каком запросе всё сломалось, и приходилось искать соседние строки лога по времени. Особенно выручает связка с GOTRACEBACK=all, когда печатаются все горутины: видно виновную и заодно то, чем были заняты остальные. Отключается GODEBUG=tracebacklabels=0. Одна ловушка: pprof.Do возвращает прежние метки в defer, а при панике defer-ы отрабатывают до печати трейсбека. Паника прямо в функции, переданной в Do, выйдет без меток, и в логе net/http о панике в обработчике их тоже не будет. Видны они у горутин, запущенных внутри Do, при фатальных ошибках рантайма вроде concurrent map writes и у остальных горутин в выводе с GOTRACEBACK=all. А request_id в метках здесь как раз к месту, в отличие от профилирования.

Как читать профиль

$ go tool pprof cpu.pprof
(pprof) top10            # топ по flat
(pprof) top10 -cum       # топ по cum: где «висит» всё поддерево
(pprof) list encodeRow   # исходник функции с цифрами напротив строк
(pprof) peek mallocgc    # кто вызывает и кого вызывает
(pprof) traces           # сырые стеки с весами
(pprof) web              # SVG-граф вызовов (нужен graphviz)
(pprof) png > cpu.png

Две колонки надо различать: flat считает время (или байты) в самой функции, без вызванных ею, а cum добавляет всё поддерево. Диагностика идёт сверху вниз по cum («в каком поддереве проблема»), а конкретную строку находишь по flat и list.

Отдельно про веб-интерфейс: go tool pprof -http=:8080 … поднимает локальный сервер и открывает те же данные в браузере. С Go 1.26 стартовой страницей стал flame graph, а не граф вызовов, как раньше (граф никуда не делся, он в меню View). И это правильный дефолт: по флеймграфу ответ «где горячо» читается за секунды, а граф вызовов на большом сервисе превращается в стену из сотен узлов. Читая флеймграф, помни: по горизонтали отложено не время. Соседей pprof ставит по убыванию ширины, так что «слева направо» не значит «раньше-позже».

Flame graph. Читается снизу вверх: корень внизу, листья сверху; pprof рисует то же вверх ногами, с корнем root наверху. Искать надо не пики, а плато: широкий фрейм в верхней части означает, что процессор проводит время именно там. За узким высоким «шпилем» стоит глубокий, но дешёвый стек.

Алгоритм: «сервис ест много CPU»

Убедиться, что это сервис. top/kubectl top pod: точно ли наш процесс, точно ли user-time, а не iowait и не сосед по ноде.
Снять CPU-профиль под нагрузкой, 30 секунд: go tool pprof -http=:8080 '...profile?seconds=30'. Профиль без нагрузки бесполезен.
Посмотреть top -cum и флеймграф. Три типовых картины:
- широко runtime.gcBgMarkWorker, mallocgc, memmove: значит, проблема в аллокациях, а не в CPU, переходи к heap-профилю;
- широко runtime.mapaccess, runtime.growslice, reflect.*, encoding/json: виноваты структуры данных и сериализация;
- широко runtime.futex, lock2, selectgo: упёрлись в синхронизацию, снимай mutex/block и trace.
list по подозреваемой функции, чтобы найти конкретные строки.
Написать бенчмарк, воспроизводящий горячий путь, зафиксировать базу.
Починить, сравнить benchstat-ом, выкатить, снять профиль снова.
Если код уже оптимален, проверить уровнем выше, не делаем ли мы вообще лишнюю работу (кэш, батчинг, отказ от сериализации, другой формат).

Алгоритм: «сервис ест много памяти»

Разделить три диагноза. Растёт /gc/heap/live (реально больше живых данных) или только RSS (память не отдана ОС)? Во втором случае утечки нет.
Проверить горутины первым делом: /debug/pprof/goroutine?debug=1. Если их десятки тысяч и число растёт, утекают горутины, а не память, и искать надо незакрытые каналы и запросы без таймаута.
Два heap-снапшота с интервалом и -base: go tool pprof -base h1 h2, режим inuse_space.
Разделить утечку и кэш: у кэша рост выходит на плато, а утечка растёт линейно, пропорционально числу запросов.
list и traces по подозреваемой функции: кто держит ссылку.
Проверить типовой список: глобальные мапы, подслайсы большого массива, забытые Ticker, незакрытые resp.Body, хвост слайса после удаления.
Если утечки нет, а памяти всё равно много, значит, такой профиль нагрузки: снижай аллокации, ставь GOMEMLIMIT, крути GOGC.

go tool trace: то, чего pprof не покажет

pprof отвечает на вопрос «где тратится CPU», а trace на вопрос «почему ничего не происходит». Он пишет каждое событие рантайма с наносекундной точностью и раскладывает их на таймлайн.

Goroutine analysis, главный экран: по каждой горутине видно, сколько она выполнялась и сколько ждала планировщик, сеть, синхронизацию, GC.
Scheduler latency: сколько горутина стояла в очереди готовых, не получая свободного P. Рядом Synchronization blocking: сколько ждала мьютексы и каналы.
GC-фазы прямо на таймлайне: видно STW, mark assist конкретных горутин, работу воркеров.
Network blocking / Syscall profile: сколько ждали сеть и сисколлы.
Пользовательские регионы: trace.WithRegion, trace.NewTask, trace.Log. Ими размечаешь свой код, и он появляется на той же оси.

import "runtime/trace"

f, _ := os.Create("trace.out")
trace.Start(f)
defer trace.Stop()

// размечаем свой код
ctx, task := trace.NewTask(ctx, "processOrder")
defer task.End()
trace.WithRegion(ctx, "validate", func() { validate(o) })

Когда брать trace вместо pprof

Если «латентность плавает, а CPU низкий», почти всегда нужен trace. Типовые находки: горутина ждала P (мало GOMAXPROCS или один тяжёлый воркер занял всех), латентность запросов совпадает с фазой маркировки (mark assist), длинный сисколл заблокировал M, вся работа села на один P из-за неудачного разделения на горутины. С Go 1.21+ трассировка стала заметно дешевле (1–2% оверхеда), поэтому её реально включать на проде на несколько секунд. С Go 1.22 появился flight recorder (golang.org/x/exp/trace, в 1.25 переехал в runtime/trace): кольцевой буфер последних секунд трейса, который сбрасывается по событию. Такой буфер выручает при редких всплесках латентности.

Устройство бенчмарка

func BenchmarkEncode(b *testing.B) {
    payload := makePayload()   // готовим данные до цикла
    b.ReportAllocs()           // всегда: аллокации важнее наносекунд
    b.ResetTimer()             // если подготовка была дорогой

    for i := 0; i < b.N; i++ {
        sink, _ = Encode(payload)   // sink на уровне пакета, чтобы вызов не выкинули
    }
}

var sink []byte   // «слив»: мешает компилятору удалить вызов как мёртвый код

// Go 1.24: вот так правильно
func BenchmarkEncode(b *testing.B) {
    payload := makePayload()   // не попадёт в замер: первый b.Loop() сбросит таймер
    b.ReportAllocs()

    for b.Loop() {
        Encode(payload)        // sink не нужен: аргументы и результат компилятор не выкинет
    }
}

b.N задаёт число итераций текущего прогона, а не «сколько раз запустить тест». testing запускает функцию несколько раз, каждый раз увеличивая b.N, пока прогон не займёт -benchtime (по умолчанию 1 секунда). Отчёт печатается по последнему прогону: ns/op = elapsed / b.N.

Подбор b.N. Правильный ответ: «b.N показывает, сколько раз пройдёт цикл, и testing подбирает его так, чтобы прогон занял benchtime». Добивка: в цикле по b.N функция вызывается несколько раз целиком, поэтому глобальное состояние между прогонами надо сбрасывать; с for b.Loop() она вызывается один раз.

Dead code elimination и почему b.Loop() это решает

// Врёт: компилятор видит, что результат не используется, и выкидывает вызов.
// Бенчмарк покажет 0.25 ns/op, столько стоит пустой цикл.
func BenchmarkBad(b *testing.B) {
    for i := 0; i < b.N; i++ {
        Hash("hello")
    }
}

// Старый рабочий приём: «слив» в пакетную переменную
var sinkU uint64
func BenchmarkOld(b *testing.B) {
    var acc uint64
    for i := 0; i < b.N; i++ {
        acc = Hash("hello")
    }
    sinkU = acc     // компилятор обязан сохранить: переменная видна снаружи
}

// Go 1.24: результаты вызовов в теле b.Loop() компилятор не выкидывает.
// Литерал не спасёт: с Go 1.26 Hash("hello") инлайнится и считается
// при компиляции, поэтому вход берём из переменной пакета
var input = "hello"

func BenchmarkNew(b *testing.B) {
    for b.Loop() {
        Hash(input)
    }
}

Go 1.26: b.Loop больше не мешает инлайну

У первой реализации b.Loop() была расплата. Чтобы тело цикла нельзя было выкинуть, компилятор удерживал живыми значения внутри него и заодно переставал инлайнить вызовы в теле цикла. Получалась подмена: бенчмарк честно мерил функцию, но её неинлайненный вариант, а в проде она инлайнилась и вела себя иначе, потому что после подстановки включаются остальные оптимизации и escape analysis нередко оставляет объект на стеке. Расходились обе цифры, и ns/op, и allocs/op.

В Go 1.26 это починили: тело for b.Loop() компилируется как обычный код, инлайн работает. Проверяется одной командой. В выводе должно быть inlining call to … на строке из тела цикла:

$ go test -run='^$' -bench=Add -gcflags='-m' .
./lib.go:3:6: can inline Add
./lib_test.go:7:12: inlining call to testing.(*B).Loop
./lib_test.go:8:6: inlining call to Add        # тело цикла инлайнится, как в обычном коде

Метод	Что делает
`b.ReportAllocs()`	добавляет `B/op` и `allocs/op` в вывод (то же, что флаг `-benchmem`)
`b.ResetTimer()`	обнуляет таймер и счётчики: подготовка не попадёт в измерение
`b.StopTimer()` / `b.StartTimer()`	пауза вокруг дорогой подготовки внутри цикла (сама пауза не бесплатна)
`b.Loop()` 1.24	цикл с автоматическим ResetTimer и защитой от DCE - новый рекомендуемый способ
`b.RunParallel`	гоняет тело в `GOMAXPROCS` горутин: измеряет контеншен
`b.ReportMetric(v, "unit")`	своя метрика в отчёте, например `rows/s`
`b.SetBytes(n)`	добавляет `MB/s` - удобно для кодеков и IO

# прогнать 10 раз, чтобы было что статистически сравнивать
$ go test -run='^$' -bench=Encode -benchmem -count=10 > old.txt
# ... правки ...
$ go test -run='^$' -bench=Encode -benchmem -count=10 > new.txt
$ go install golang.org/x/perf/cmd/benchstat@latest
$ benchstat old.txt new.txt
goos: darwin
goarch: arm64
pkg: enc
cpu: Apple M4 Pro
          │   old.txt   │               new.txt               │
          │   sec/op    │   sec/op     vs base                │
Encode-14   1.130µ ± 2%   1.012µ ± 4%  -10.49% (p=0.000 n=10)

          │   old.txt    │                new.txt                │
          │     B/op     │     B/op      vs base                 │
Encode-14   1.000Ki ± 0%   0.000Ki ± 0%  -100.00% (p=0.000 n=10)

          │  old.txt   │               new.txt               │
          │ allocs/op  │ allocs/op   vs base                 │
Encode-14   1.000 ± 0%   0.000 ± 0%  -100.00% (p=0.000 n=10)

Почему benchstat, а не «глазами»

Один прогон бенчмарка даёт одно измерение шумной величины. benchstat берёт -count=N прогонов, считает медиану, разброс и p-value по критерию Манна-Уитни. Если p > 0.05, он честно печатает ~, то есть «разницы нет». Фраза «ускорил на 3%» без benchstat на собесе звучит как «я померил шум».

Семь способов, которыми микробенчмарк врёт

Dead code elimination: результат не используется, и вызов удалён.
Constant folding. Аргумент константный, и компилятор посчитал всё на этапе компиляции.
Инлайнинг: в бенчмарке функция инлайнится, а в реальном коде (вызов через интерфейс) нет.
Идеальный кэш. Одни и те же данные миллион раз лежат в L1, а в проде за ними приходится ходить в память. Реальная разница легко доходит до 10 раз.
Идеальный предсказатель ветвлений: одинаковый вход делает все ветки предсказуемыми.
Подготовка внутри цикла: меришь makePayload, а не Encode. И наоборот: sync.Pool и прогретые буферы дают ноль аллокаций на второй итерации, которых в проде не будет.
Среда: turbo boost, thermal throttling, шумный CI, соседи по ноде, разный GOMAXPROCS. Отсюда -count=10 и benchstat.

Дисциплина измерений

-run='^$', чтобы не запускать тесты вместе с бенчами.
-benchmem или b.ReportAllocs() ставь всегда.
-count=10 + benchstat обязательны, если делаешь вывод.
Варьируй вход: b.Run("size=1KB", ...), случайные данные, реальные payload-ы из прода.
Последнее слово не за бенчмарком, а за профилем прода после выката. Микробенчмарк доказывает, что функция стала быстрее; он не доказывает, что стало быстрее приложение.

Метрики рантайма

Инструмент	Что даёт	Цена	Когда
`runtime.MemStats` + `ReadMemStats`	плоская структура: `HeapAlloc`, `HeapInuse`, `NumGC`, `PauseNs`, `Mallocs`, `Frees`	делает STW на время снятия	легаси; разово в отладке
`runtime/metrics` 1.16+	версионированные метрики с единицами измерения, включая гистограммы пауз	без STW	штатный экспорт в проде
`expvar`	отдаёт JSON на `/debug/vars`, включая `memstats` и `cmdline`	дёшево, но тянет `ReadMemStats`	простые случаи; закрывать так же, как pprof
`debug.ReadGCStats`	история пауз GC и распределение по квантилям	дёшево	если нужны только паузы
`debug.SetTraceback`, `GOTRACEBACK`	подробность стека при падении	-	разбор паник в проде

// runtime/metrics: гистограмма пауз и live heap в Prometheus
var samples = []metrics.Sample{
    {Name: "/sched/pauses/total/gc:seconds"},    // бывшая /gc/pauses:seconds, устарела с Go 1.22
    {Name: "/gc/heap/live:bytes"},
    {Name: "/sched/latencies:seconds"},          // задержка планировщика, её зря недооценивают
    {Name: "/sched/goroutines/runnable:goroutines"}, // Go 1.26: готовы бежать, но P не досталось
    {Name: "/sched/threads/total:threads"},          // Go 1.26: сколько ОС-потоков держит рантайм
}

func collect() {
    metrics.Read(samples)
    h := samples[0].Value.Float64Histogram()
    live := samples[1].Value.Uint64()
    _ = h; _ = live
}

// список всех доступных метрик с описаниями
for _, d := range metrics.All() { fmt.Println(d.Name, "-", d.Description) }

// go1.27: в списке 107 метрик, первые восемь имён (без описаний):
//   /cgo/go-to-c-calls:calls
//   /cpu/classes/gc/mark/assist:cpu-seconds
//   /cpu/classes/gc/mark/dedicated:cpu-seconds
//   /cpu/classes/gc/mark/idle:cpu-seconds
//   /cpu/classes/gc/pause:cpu-seconds
//   /cpu/classes/gc/total:cpu-seconds
//   /cpu/classes/idle:cpu-seconds
//   /cpu/classes/scavenge/assist:cpu-seconds
// Список отсортирован по имени и растёт от версии к версии, поэтому имена метрик
// и проверяют через metrics.All(), а не хардкодят.

Go 1.26: метрики планировщика стали подробнее

До 1.26 про горутины была ровно одна цифра: сколько их живых (/sched/goroutines:goroutines, тогда то же самое, что runtime.NumGoroutine(); с 1.26 метрика считает и системные горутины рантайма, так что выходит больше). Счётчик показывал «тысяча горутин», но не говорил, чем они заняты. В Go 1.26 добавили разбивку по состояниям и метрики потоков:

/sched/goroutines/running:goroutines: горутины, которые прямо сейчас выполняются на ядре; их не больше /sched/gomaxprocs:threads.
/sched/goroutines/runnable:goroutines: такие горутины готовы бежать, но им не досталось P. Из четырёх эта самая ценная: устойчиво ненулевая runnable при running ≈ GOMAXPROCS означает, что процессора не хватает, и объясняет выросшую /sched/latencies.
/sched/goroutines/waiting:goroutines: ждут ввод-вывод или синхронизацию. Если эта метрика растёт, а running нет, упёрлись не в CPU, а в чужой сервис или в замок.
/sched/goroutines/not-in-go:goroutines: сидят в сисколле или в cgo-вызове.
/sched/goroutines-created:goroutines считает горутины, созданные за всё время работы, и по производной виден темп, а не только остаток.
/sched/threads/total:threads показывает, сколько ОС-потоков (M) держит рантайм. Раньше это узнавали только из threadcreate-профиля; если число растёт, ищи блокирующие сисколлы или cgo.

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

Вопросы

Суть: восемь профилей, из которых block и mutex выключены по умолчанию, а goroutineleak появился в Go 1.27. С прода снимаются HTTP-ручкой из net/http/pprof, поднятой на отдельном локальном порту. Читаются через top -cum → list → флеймграф.

Профили

cpu: сэмплирование стеков по SIGPROF 100 раз в секунду. Снимается за интервал, обязательно под нагрузкой.
heap про аллокации, у него четыре режима: inuse_space, inuse_objects, alloc_space, alloc_objects. Сэмплирование по умолчанию раз в 512 КБ.
goroutine даёт полный снимок стеков всех живых горутин. Долго был главным инструментом против утечки горутин.
goroutineleak 1.27 показывает только те горутины, которые заблокированы навсегда: ждут канал, мьютекс или WaitGroup, до которого из живой части программы уже не дотянуться. Эвристики «висит подозрительно долго» тут нет, недостижимость считает сборщик мусора. Экспериментом был в 1.26, с 1.27 лежит в pprof.Profiles() и на /debug/pprof/goroutineleak. На практике раньше в проде смотрели растущий счётчик горутин и вручную разбирали goroutine?debug=2, а теперь есть готовый список виновных.
block: где горутины ждали синхронизацию; ожидания дольше заданного rate пишутся все, короткие выборочно. Включается runtime.SetBlockProfileRate.
mutex ловит контеншен: кто заставил других ждать. Включается runtime.SetMutexProfileFraction.
threadcreate объясняет, почему рантайм создал ОС-поток (cgo, блокирующие сисколлы).
trace вообще не профиль, а полный лог событий на таймлайне.

Как снять с прода

import _ "net/http/pprof"
// отдельный слушатель на loopback, а не публичный порт приложения
go func() { log.Println(http.ListenAndServe("127.0.0.1:6060", nil)) }()

$ kubectl port-forward pod/api-7f9 6060:6060
$ go tool pprof -http=:8080 'http://localhost:6060/debug/pprof/profile?seconds=30'
$ go tool pprof -http=:8080 'http://localhost:6060/debug/pprof/heap?gc=1'
$ curl -s 'http://localhost:6060/debug/pprof/goroutine?debug=1' | head -30

Как читать

top -cum отвечает на вопрос «в каком поддереве проблема», top (по flat) на вопрос «в какой конкретно функции», list Func на «в какой строке», peek на «кто это вызывает». Флеймграф: ширина = доля выборок, высота = глубина стека, а ось X к времени отношения не имеет. Ищем широкие плато на стороне листьев (в pprof это низ картинки, корень там сверху): там процессор реально работает; узкий длинный шпиль означает глубокий, но дешёвый стек.

Безопасность: почти обязательная добивка

Импорт net/http/pprof вешает хендлеры в глобальный http.DefaultServeMux. Если основной сервер стартовал с nil-хендлером, /debug/pprof/* торчит в интернет вместе с API. Оттуда утекают полные стеки, имена функций, /debug/pprof/cmdline с флагами и секретами; плюс любой желающий может запустить profile?seconds=600 или heap?gc=1 и получить готовый DoS. Правильно: отдельный listener на 127.0.0.1 + port-forward, либо свой ServeMux с авторизацией, либо build tag для отладочных образов.

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

Много CPU

Подтвердить: kubectl top pod, user-time именно нашего процесса, не iowait, не сосед по ноде, не throttling из-за CPU-лимита (container_cpu_cfs_throttled).
Снять CPU-профиль под нагрузкой: profile?seconds=30.
top -cum + флеймграф. Три диагноза по тому, что широкое:
- gcBgMarkWorker, mallocgc, memmove → это аллокационная проблема, переходим к heap-профилю в режиме alloc_space;
- encoding/json, reflect, mapaccess, growslice → сериализация и структуры данных;
- futex, lock2, selectgo, chanrecv → синхронизация: снимаем mutex, block, trace.
list по функции, чтобы увидеть конкретные строки.
Написать бенчмарк на горячий путь, зафиксировать базу (-count=10).
Починить, сравнить benchstat, выкатить, снять профиль ещё раз.
Если код уже оптимален, подняться на уровень выше: кэш, батчинг, отказ от лишней работы, другой формат обмена. Быстрее всего выполняется работа, которую не делают.

Много памяти

Разделить три диагноза: растёт /gc/heap/live, или растёт только RSS (память просто не отдана ОС, и это не утечка), или это нормальный профиль нагрузки.
Сразу проверить горутины: goroutine?debug=1. Растущее число означает утечку горутин, и дальше ищи каналы без читателя и запросы без таймаута.
Два heap-снапшота с интервалом 10–30 минут, сравнить: go tool pprof -base h1.pprof h2.pprof, режим inuse_space.
Отличить кэш от утечки: кэш выходит на плато, утечка растёт линейно от числа запросов.
list / traces по подозреваемому: кто именно держит ссылку.
Пройтись по типовому списку: глобальные мапы без вытеснения, подслайсы большого массива, забытые Ticker, незакрытые resp.Body, хвост слайса, жирные замыкания.
Если утечки нет, снижать аллокации, ставить GOMEMLIMIT, крутить GOGC. Именно в таком порядке.

Что интервьюер хочет услышать

Не список команд, а ветвление: «если в профиле широкий gcBgMarkWorker, то дело не в CPU, а в аллокациях, и лечится оно в другом месте». И честную границу: «сначала я подтверждаю проблему метрикой, потому что половина обращений „сервис тормозит“ оказывается проблемой соседнего сервиса или сети». Ответ «я бы посмотрел pprof» без ветвления считается слабым.

Суть: pprof показывает, где горит CPU; trace показывает, почему ничего не происходит. Это полный лог событий рантайма с наносекундной точностью, разложенный на таймлайн: планировщик, GC, сеть, сисколлы, блокировки.

Что видно

Goroutine analysis раскладывает время каждой горутины: выполнение, ожидание планировщика, ожидание сети, синхронизации, GC, сисколла. Это главный экран.
Таймлайн по P: какая горутина на каком процессоре и когда; сразу видно, если вся работа села на один P.
Фазы GC прямо на оси: STW-паузы, работа mark-воркеров, mark assist конкретных горутин.
Scheduler latency: горутина готова, а P нет. Так проявляется нехватка GOMAXPROCS или длинные неотдающие участки.
Syscall / Network blocking показывает, сколько ждали ОС и сеть.
Пользовательские регионы и задачи: trace.NewTask, trace.WithRegion, trace.Log выводят свой код на ту же ось.

$ curl -so trace.out 'http://localhost:6060/debug/pprof/trace?seconds=5'
$ go tool trace trace.out       # откроет браузер

Когда именно

«Латентность плавает, а CPU низкий»: почти всегда это случай для trace.
Подозрение, что латентность коррелирует с циклами GC (mark assist).
Подозрение на голодание горутин или на неудачную нарезку работы.
Долгий сисколл / cgo-вызов, который блокирует M.
Проверка, что worker pool реально загружает все ядра.

Цена и flight recorder

Трассировка не бесплатна, но в Go 1.21 оверхед упал до 1–2%, а в 1.22 её переписали, так что включать её на проде на несколько секунд реально. Файлы получаются большими: 5 секунд нагруженного сервиса занимают десятки мегабайт, и дольше 10–20 секунд снимать бессмысленно. Отдельно назови flight recorder (Go 1.22 в golang.org/x/exp/trace, с Go 1.25 в runtime/trace): кольцевой буфер последних секунд трейса, который сбрасывается на диск по внешнему событию. Он ловит редкие всплески латентности, которые «снятием трейса вручную» не поймать.

Суть: b.N - число итераций текущего прогона. testing запускает функцию несколько раз с растущим b.N, пока прогон не займёт -benchtime (1 с), и печатает результат последнего прогона. С Go 1.24 вместо ручного цикла пишут for b.Loop().

Как подбирается b.N

Первый прогон с b.N = 1.
Если прогон занял меньше benchtime, следующее N считается как N × (benchtime / elapsed) × 1.2 без округления (круглые числа были до Go 1.13) и не растёт больше чем в 100 раз за шаг.
Так до тех пор, пока прогон не дотянет до benchtime (потолок 1e9 итераций).
Отчёт печатается по последнему прогону: ns/op = elapsed / b.N. Все предыдущие прогоны выбрасываются, они и служат прогревом.

Практическое следствие для цикла по b.N: функция вызывается целиком несколько раз. Значит, глобальное состояние между прогонами надо сбрасывать, а дорогую подготовку нельзя делать внутри цикла, иначе она умножится на миллионы итераций.

Dead code elimination

// врёт: результат не используется, компилятор выкидывает вызов, получаем 0.3 ns/op
for i := 0; i < b.N; i++ { Hash("x") }

// старый рабочий приём: «слив» в пакетную переменную
var sink uint64
func BenchmarkHash(b *testing.B) {
    var acc uint64
    for i := 0; i < b.N; i++ { acc = Hash("x") }
    sink = acc
}

// Go 1.24: тело b.Loop() компилятор выкинуть не вправе
func BenchmarkHash(b *testing.B) {
    payload := makePayload()   // не попадёт в измерение: таймер стартует внутри Loop
    b.ReportAllocs()
    for b.Loop() { Hash(payload) }
}

b.Loop() решает сразу три вещи: результаты вызовов в теле не выкидываются оптимизатором, функция бенчмарка вызывается один раз, и подготовка до цикла автоматически исключается из времени (не нужен ResetTimer). От свёртки констант он не спасает: с Go 1.26 вызов с литералом в аргументах инлайнится и может посчитаться при компиляции, так что вход бери из переменной. И сам цикл не дешевле ручного: счётчик лежит в полях структуры B, и пустая итерация выходит в разы дороже, чем у цикла по b.N.

К ответу хорошо добавить уточнение по версиям: в Go 1.24–1.25 защита от DCE побочно выключала инлайн вызовов внутри тела цикла, и бенчмарк мерил неинлайненный вариант функции, так что расходились и ns/op, и allocs/op. С Go 1.26 это исправлено: тело for b.Loop() компилируется как обычный код, инлайн работает.

Инструменты вокруг

b.ReportAllocs() добавляет B/op и allocs/op, как флаг -benchmem. Ставить всегда: аллокации важнее наносекунд, потому что за ними стоит будущая работа GC.
b.ResetTimer() обнуляет таймер после подготовки (при b.Loop() не нужен).
b.StopTimer()/b.StartTimer() ставят вокруг дорогой подготовки внутри цикла; сама пара стоит десятки микросекунд (каждый вызов делает ReadMemStats с остановкой мира), и для микроопераций это уже искажение.
b.RunParallel гоняет тело в GOMAXPROCS горутин и так измеряет контеншен.
b.SetBytes и b.ReportMetric добавляют MB/s и свои единицы.

$ go test -run='^$' -bench=Encode -benchmem -count=10 > old.txt
$ go test -run='^$' -bench=Encode -benchmem -count=10 > new.txt
$ benchstat old.txt new.txt      # golang.org/x/perf/cmd/benchstat

Про benchstat одной фразой

Один прогон даёт одно измерение шумной величины. benchstat берёт -count=N прогонов, считает медиану, разброс и p-value; если разница статистически незначима, он печатает ~. Кто говорит «стало быстрее на 3%» без benchstat, тот говорит про шум, и на собесе это слышно.

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

Что искажает результат

Dead code elimination. Результат не используется, поэтому вызова просто нет. Симптом: подозрительно круглые доли наносекунды.
Constant folding. Аргумент задан литералом, и компилятор посчитал всё на этапе компиляции. Лечится входом из переменной, которую компилятор не видит насквозь.
Инлайнинг, которого не будет в проде. В бенчмарке функция вызывается напрямую и инлайнится; в приложении она спрятана за интерфейсом: вызов косвенный, инлайна нет, и escape analysis решает иначе.
Идеальная локальность. Один и тот же вход миллион раз лежит в L1. В проде это промах в память: 1 нс против 80 нс. Разница в разы, и она не в коде.
Идеальный предсказатель ветвлений. Одинаковые данные делают все if бесплатными, а на реальном распределении получаешь mispredict на каждой второй итерации.
Прогретое состояние. sync.Pool, преаллоцированные буферы, заполненные мапы дают ноль аллокаций со второй итерации. В проде каждый запрос и есть первая итерация.
Подготовка внутри цикла: измеряешь генератор данных, а не функцию. И обратная ошибка: StopTimer/StartTimer на каждой итерации сами по себе дороже измеряемой операции.
Среда. Turbo boost, тепловой троттлинг, шумный CI, соседи по ноде, разный GOMAXPROCS, включённый профайлер. Отсюда обязательные -count=10 и benchstat.
Не тот масштаб. Функцию ускорили в 10 раз, но она занимала 0.5% профиля, и выигрыш составил 0.45%. Закон Амдала никто не отменял.

Самый частый реальный случай

Кандидат «ускоряет» функцию, гоняя её на одном и том же коротком входе. В проде входы разной длины, и после оптимизации на маленьких данных большие стали медленнее. Правильно гонять b.Run("size=64", ...) / "size=4K" / "size=1M" и реальные payload-ы, снятые с прода. И финальная проверка всегда одна: профиль прода после выката. Бенчмарк доказывает, что функция стала быстрее; он не доказывает, что стало быстрее приложение.

Суть: три поколения одного и того же. MemStats - старое и делает STW; expvar - обёртка, отдающая JSON на /debug/vars; runtime/metrics (Go 1.16+) - современный, без STW, с версионированными именами и гистограммами. Для нового кода - только третий.

runtime.MemStats

Плоская структура: HeapAlloc (живые + ещё не подметённые байты), HeapInuse, HeapReleased (возвращено ОС), NumGC, PauseTotalNs, кольцо PauseNs[256], счётчики Mallocs и Frees. Читается через runtime.ReadMemStats, и это его главный минус: вызов останавливает мир на время копирования. На сервисе с тысячами горутин и экспортом раз в секунду мониторинг сам начинает создавать паузы.

runtime/metrics

samples := []metrics.Sample{
    {Name: "/gc/heap/live:bytes"},               // живые данные
    {Name: "/gc/heap/goal:bytes"},               // цель pacer-а
    {Name: "/sched/pauses/total/gc:seconds"},    // гистограмма пауз
    {Name: "/cpu/classes/gc/total:cpu-seconds"}, // доля CPU на GC
    {Name: "/memory/classes/total:bytes"},       // минус heap/released: то, что ограничивает GOMEMLIMIT
    {Name: "/sched/goroutines:goroutines"},      // число горутин
    {Name: "/sched/latencies:seconds"},          // задержка планировщика
    {Name: "/sched/goroutines/runnable:goroutines"}, // Go 1.26: стоят в очереди за P
    {Name: "/sched/threads/total:threads"},          // Go 1.26: число ОС-потоков рантайма
}
metrics.Read(samples)

Имена версионированные, единицы измерения зашиты в имя после двоеточия.
Кроме счётчиков, есть гистограммы, так что p99 пауз можно считать честно.
metrics.All() перечисляет всё доступное в текущей версии Go с описаниями.
Go 1.26 добавил разбивку по планировщику: /sched/goroutines/running, /runnable, /waiting, /not-in-go, счётчик созданных /sched/goroutines-created и число ОС-потоков /sched/threads/total:threads. До этого была одна цифра «сколько горутин живо», и по ней нельзя было отличить «ждут базу» от «стоят в очереди за P».
Читается без STW, дёшево, годится для экспорта раз в секунду.
В prometheus/client_golang подключается через collectors.NewGoCollector(collectors.WithGoCollectorRuntimeMetrics(...)).

expvar

Пакет отдаёт JSON на /debug/vars и по умолчанию публикует memstats и cmdline. Удобно для быстрого дебага и своих счётчиков (expvar.NewInt, expvar.Publish), но он тянет ReadMemStats со всеми последствиями, регистрируется в http.DefaultServeMux (та же проблема безопасности, что у pprof) и публикует командную строку. В проде его закрывают так же, как pprof.

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

Минимальный набор для Go-сервиса: /gc/heap/live (утечки), /sched/goroutines (утечка горутин, ловится раньше памяти), /cpu/classes/gc/total (перегруз сборщика), /sched/pauses/total/gc p99, /memory/classes/total без отданного ОС против GOMEMLIMIT и /sched/latencies p99 (нехватка P, а с Go 1.26 её же подтверждает ненулевая /sched/goroutines/runnable). Отдельно заведи алерт на рост числа горутин: он срабатывает за часы до того, как память станет заметной проблемой.

Что стоит запомнить

CPU profile отвечает на вопрос о потребителях CPU.
Heap profile помогает различить allocation и удержание.
Trace показывает расписание, блокировки и ожидания.

Частые ошибки

Данные относятся к измеренному окну.
Профиль памяти не объясняет CPU время.

Самопроверка

Сначала реши задачу самостоятельно, затем открой ответ и сравни ход рассуждений.

Чтение кода

1. Разбери результат

Сервис ест CPU только в пике. Код ниже выбирает профиль. Что он напечатает и поможет ли профиль найти горячие CPU функции?

fmt.Println(pprof.Lookup("heap").Name())

Ответ и разбор

Печатается heap. Этот фрагмент выбирает heap profile и не отвечает на вопрос о CPU. Для CPU нужны pprof.StartCPUProfile/StopCPUProfile вокруг репрезентативной нагрузки или CPU profile через pprof endpoint; снять его надо в том самом пиковом окне.

Код-ревью

2. Проверь жизненный цикл CPU-профиля

Функцию вызывают несколько раз за время работы процесса. Первая запись профиля начинается, а следующая возвращает ошибку. Найди пропущенный шаг.

func profile(w io.Writer) error {
    if err := pprof.StartCPUProfile(w); err != nil { return err }
    work()
    return nil
}

Ответ и разбор

После успешного StartCPUProfile добавь defer pprof.StopCPUProfile(). Одновременно работает только один CPU-профиль процесса; StopCPUProfile завершает сбор и дожидается записи накопленных данных. Пока первый профиль не остановлен, следующий запуск сообщает, что профилирование уже включено. Ошибку StartCPUProfile надо обработать до регистрации defer.

Применение

3. Реши сценарий

Нагрузка с высоким CPU завершается быстрее обычного запроса. Как снять профиль, который покажет горячие функции именно под этим сценарием?

Ответ и разбор

Запусти ограниченный CPU profile вокруг воспроизводимого пикового сценария или сними его через pprof endpoint под той же нагрузкой. Сравни top и flame graph; profile показывает выборки CPU в интервале, поэтому отдельно проверь задержки и ожидание через trace, если CPU profile их не объясняет.

Применение

4. Разбери другое ограничение

CPU profile почти пустой, но запросы медленные и trace показывает долгие ожидания канала. Куда направить разбор?

Ответ и разбор

Исследуй execution trace: CPU profile семплирует время выполнения и не объясняет длительные блокировки. Trace показывает состояния goroutine и события ожидания; затем свяжи ожидание с владельцем канала/lock и проверь сценарий отдельным тестом или нагрузкой.