pprof на практике: профилирование CPU и памяти в Go

Сервис на Go начал есть память, и никто не знает почему. Или CPU внезапно упёрся в потолок, а код вроде не менялся. В обоих случаях гадать бесполезно. Нужен профиль. В Go для этого есть штатный инструмент pprof: он встроен в рантайм, в стандартную библиотеку и в тулчейн. В этой статье я разбираю его целиком: какие профили бывают, как снять их с тестов и с живого сервиса, как читать вывод go tool pprof и flame graph, как найти утечку памяти и горячую точку CPU. Все примеры рабочие, их можно повторить локально.

В моей практике pprof это второй по частоте инструмент диагностики после логов. Бенчмарки отвечают на вопрос «стало быстрее или медленнее», а pprof отвечает на вопрос «где именно тратятся ресурсы». Эти инструменты дополняют друг друга, про первый я писал в статье про бенчмарки и оптимизацию.

Какие профили умеет снимать Go

Рантайм Go собирает несколько типов профилей. У каждого своя задача.

• cpu. Где программа тратит процессорное время. Рантайм примерно 100 раз в секунду прерывает выполнение и записывает стек. Функции, которые попадают в выборку чаще, и есть горячие точки.
• heap. Кто держит память в куче прямо сейчас. Главный профиль для поиска утечек.
• allocs. Кто и сколько аллоцировал за всё время работы программы. Тот же профиль, что heap, но с другим представлением по умолчанию. Полезен, когда нужно снизить нагрузку на GC.
• goroutine. Стеки всех живых горутин. Главный профиль для поиска утечек горутин.
• block. Где горутины ждут: на каналах, на мьютексах, на select. По умолчанию выключен.
• mutex. Кто держит мьютексы, из-за которых ждут другие. Тоже по умолчанию выключен.

Есть ещё threadcreate и трассировка исполнения go tool trace, но в повседневной работе вам почти всегда хватит первых шести.

Правило выбора простое. Сервис ест CPU: снимаете cpu. Растёт память: heap. Растёт число горутин: goroutine. Сервис не грузит CPU, но медленный: block и mutex.

Три способа снять профиль

Из тестов и бенчмарков

Самый простой вход. Флаги go test пишут профиль рядом с результатами:

$ go test -bench=BenchmarkParse -cpuprofile=cpu.out -memprofile=mem.out ./parser

Вместе с профилями появится бинарник parser.test. Он пригодится pprof для дизассемблирования, но для базового анализа достаточно самого файла профиля.

Вручную через runtime/pprof

Для CLI-утилит и разовых скриптов профиль включают прямо в коде:

package main

import (
	"log"
	"os"
	"runtime"
	"runtime/pprof"
)

func main() {
	f, err := os.Create("cpu.out")
	if err != nil {
		log.Fatal(err)
	}
	defer f.Close()

	if err := pprof.StartCPUProfile(f); err != nil {
		log.Fatal(err)
	}
	defer pprof.StopCPUProfile()

	doWork() // полезная работа программы

	// снимок кучи в конце: сначала собираем мусор,
	// чтобы в профиле осталась только живая память
	hf, err := os.Create("heap.out")
	if err != nil {
		log.Fatal(err)
	}
	defer hf.Close()
	runtime.GC()
	if err := pprof.WriteHeapProfile(hf); err != nil {
		log.Fatal(err)
	}
}

Важно, чтобы pprof.StopCPUProfile() успел отработать до выхода. Если программа завершается через os.Exit или падает по сигналу, defer не сработает и файл останется пустым.

С живого сервиса через net/http/pprof

Основной способ для продакшена. Достаточно одного импорта с подчёркиванием:

package main

import (
	"log"
	"net/http"
	_ "net/http/pprof" // регистрирует хендлеры /debug/pprof/*
)

func main() {
	// debug-эндпоинты слушают отдельный порт,
	// наружу его не публикуем
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()

	runService() // основной сервис на своём порту
}

Импорт регистрирует хендлеры в http.DefaultServeMux по пути /debug/pprof/. Откройте http://localhost:6060/debug/pprof/ в браузере и увидите индекс со всеми профилями. А go tool pprof умеет забирать их по URL напрямую:

$ go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=30"
$ go tool pprof http://localhost:6060/debug/pprof/heap

Первая команда собирает CPU-профиль 30 секунд. Вторая забирает мгновенный снимок кучи. Скачанные профили pprof складывает в ~/pprof/, так что снимок «с инцидента» останется у вас и после перезапуска сервиса.

go tool pprof: рабочий минимум

Открываем профиль в интерактивном режиме:

$ go tool pprof cpu.out

Внутри вам нужны четыре команды.

top показывает функции с наибольшим потреблением:

(pprof) top
Showing nodes accounting for 4.02s, 87.6% of 4.59s total
      flat  flat%   sum%        cum   cum%
     1.92s 41.83% 41.83%      1.92s 41.83%  regexp.(*machine).match
     0.71s 15.47% 57.30%      2.85s 62.09%  regexp.Compile
     0.54s 11.76% 69.06%      0.54s 11.76%  runtime.mallocgc
     ...

Здесь важно понимать разницу между flat и cum. flat это время внутри самой функции, без вложенных вызовов. cum (cumulative) это время функции вместе со всем, что она вызвала. Функция с маленьким flat и огромным cum сама ничего не делает, но вызывает что-то тяжёлое. Отсортировать по cum можно командой top -cum.

list показывает время построчно по исходнику:

(pprof) list handleRequest

Аргумент это регулярное выражение по имени функции. Для вывода исходника pprof нужны файлы с кодом на той же машине.

peek показывает, кто вызывает функцию и что вызывает она. Полезно, когда top показал runtime.mallocgc, а вам нужно понять, чьи это аллокации.

web рисует граф вызовов в браузере, для этого нужен установленный graphviz.

Но чаще всего я вообще не захожу в интерактивный режим, а сразу поднимаю веб-интерфейс:

$ go tool pprof -http=:8080 cpu.out

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

CPU-профиль: реальный кейс

Разберём типичную горячую точку. HTTP-хендлер валидирует входные данные регулярным выражением:

// плохо: регулярка компилируется на каждый запрос
func validateEmail(s string) bool {
	re := regexp.MustCompile(`^[a-zA-Z0-9._%+\-]+@[a-zA-Z0-9.\-]+\.[a-zA-Z]{2,}$`)
	return re.MatchString(s)
}

Под нагрузкой сервис упирается в CPU. Снимаем профиль на 30 секунд и смотрим top:

(pprof) top5
      flat  flat%   sum%        cum   cum%
     0.98s 21.03% 21.03%      3.12s 66.95%  regexp/syntax.parse
     0.61s 13.09% 34.12%      0.61s 13.09%  runtime.mallocgc
     0.44s  9.44% 43.56%      3.71s 79.61%  regexp.Compile
     0.15s  3.22% 46.78%      3.95s 84.76%  main.validateEmail
     0.09s  1.93% 48.71%      0.42s  9.01%  regexp.(*Regexp).MatchString

Картина характерная. Сама проверка MatchString занимает 9% времени, а компиляция регулярки почти 80%. Смотрим list validateEmail, видим MustCompile внутри функции. Исправление очевидное:

// хорошо: компилируем один раз при старте
var emailRe = regexp.MustCompile(`^[a-zA-Z0-9._%+\-]+@[a-zA-Z0-9.\-]+\.[a-zA-Z]{2,}$`)

func validateEmail(s string) bool {
	return emailRe.MatchString(s)
}

Пример нарочно простой, но схема работы всегда одна. Снять профиль под реальной нагрузкой, найти широкое плато в flame graph, дойти через list до конкретных строк, исправить, снять профиль ещё раз и убедиться, что плато исчезло.

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

Профиль памяти: где течёт

Вопрос «golang pprof память» это, по моему опыту, самая частая причина знакомства с профилировщиком. Разберём подробно.

inuse и alloc

Профиль кучи хранит четыре метрики, и путаница между ними порождает большинство неверных выводов:

• inuse_space показывает, сколько байт живо в куче сейчас;
• inuse_objects показывает, сколько объектов живо сейчас;
• alloc_space показывает, сколько байт аллоцировано за всё время работы;
• alloc_objects показывает, сколько объектов аллоцировано за всё время.

Ищете утечку: смотрите inuse_space. Хотите снизить нагрузку на GC: смотрите alloc_space. Эндпоинт /debug/pprof/heap по умолчанию показывает inuse, эндпоинт /debug/pprof/allocs показывает те же данные, но по умолчанию в разрезе alloc. Переключиться можно и внутри pprof:

(pprof) sample_index=alloc_space

Ещё одна деталь: профиль кучи выборочный. По умолчанию рантайм сэмплирует в среднем одну аллокацию на 512 КБ (runtime.MemProfileRate), а pprof восстанавливает из выборки полные значения. Для поиска крупных потребителей этого достаточно, но мелкие редкие аллокации в профиль могут не попасть.

Ищем утечку

Классический источник утечки это кеш без вытеснения:

// плохо: кеш только растёт
type sessionCache struct {
	mu   sync.Mutex
	data map[string][]byte
}

func (c *sessionCache) Put(key string, payload []byte) {
	c.mu.Lock()
	defer c.mu.Unlock()
	c.data[key] = payload // никто никогда не удаляет записи
}

Память сервиса растёт день за днём. Снимаем снимок кучи и смотрим:

$ go tool pprof http://localhost:6060/debug/pprof/heap
(pprof) top3
Showing nodes accounting for 1.42GB, 96.4% of 1.47GB total
      flat  flat%   sum%        cum   cum%
    1.31GB 89.12% 89.12%     1.31GB 89.12%  main.(*sessionCache).Put
    0.07GB  4.76% 93.88%     0.07GB  4.76%  bytes.growSlice
    0.04GB  2.72% 96.60%     0.04GB  2.72%  bufio.NewReaderSize

Профиль показывает стек аллокации, то есть место, где память была выделена, а не место, где на неё держится ссылка. Обычно этого хватает: видно, что 1.3 ГБ живых данных выделены в Put, дальше вы читаете код и находите, что записи не удаляются. Лечится TTL, LRU или периодической зачисткой.

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

И помните про GC. Снимок кучи включает и мусор, который ещё не собран. Эндпоинт умеет принудительно запускать сборку перед снимком: /debug/pprof/heap?gc=1. Так в профиле останется только действительно живая память.

Куча это не вся память процесса

RSS процесса почти всегда больше, чем показывает heap-профиль. Туда входят стеки горутин, память рантайма, ещё не возвращённые операционной системе страницы. Если heap-профиль маленький, а RSS большой, смотрите профиль goroutine и метрики runtime.ReadMemStats, а не ищите несуществующую утечку в куче.

Goroutine-профиль: утечки горутин

Горутины текут чаще, чем память. Типичный сценарий: горутина заблокировалась на канале, из которого никто не читает, и повисла навсегда. Как писать конкурентный код так, чтобы этого не случалось, я разбирал в статье про паттерны конкурентности. А pprof помогает найти уже случившееся.

$ go tool pprof http://localhost:6060/debug/pprof/goroutine
(pprof) top
Showing nodes accounting for 4801, 99.85% of 4808 total
      flat  flat%   sum%        cum   cum%
      4790 99.63% 99.63%       4790 99.63%  runtime.gopark
         0     0% 99.63%       4785 99.52%  main.fetchWithTimeout.func1

Почти пять тысяч горутин, и практически все стоят в одном и том же месте. Вместо секунд здесь числа: единица измерения в этом профиле это количество горутин с таким стеком. Для быстрой диагностики удобен и текстовый вид: /debug/pprof/goroutine?debug=1 группирует горутины по стекам, а ?debug=2 выдаёт полный дамп, как при панике.

Здоровое число горутин зависит от сервиса, но динамика важнее абсолюта. Если график числа горутин монотонно растёт под ровной нагрузкой, у вас утечка.

block и mutex: где сервис ждёт

Бывает и обратная ситуация. CPU свободен, память в норме, а latency плохая. Значит, горутины где-то ждут. Для этого есть два профиля, и оба по умолчанию выключены, потому что их сбор не бесплатный. Включаются они в коде:

import "runtime"

func init() {
	runtime.SetBlockProfileRate(1)     // писать каждое событие блокировки
	runtime.SetMutexProfileFraction(1) // писать каждый конфликт на мьютексе
}

Единица у SetBlockProfileRate это наносекунды: рантайм сэмплирует в среднем одно событие на указанное число наносекунд блокировки. Значение 1 означает «писать всё» и подходит для отладки, в проде лучше поставить порог повыше или включать профиль временно. У SetMutexProfileFraction семантика другая: записывается в среднем каждое n-е событие.

Дальше та же схема:

$ go tool pprof http://localhost:6060/debug/pprof/block
$ go tool pprof http://localhost:6060/debug/pprof/mutex

Block-профиль показывает, где горутины проводят время в ожидании каналов и мьютексов. Mutex-профиль показывает виновника: кто держал мьютекс, пока остальные ждали. В моей практике mutex-профиль однажды за десять минут нашёл глобальный мьютекс вокруг медленной операции, который несколько месяцев портил хвосты latency. По графикам это выглядело как случайные всплески, и без профиля причину не видели.

Сравнение профилей: до и после

Убедиться, что оптимизация помогла, или доказать утечку можно сравнением двух профилей. Для этого есть флаг -base:

$ curl -so heap1.out http://localhost:6060/debug/pprof/heap
$ sleep 600
$ curl -so heap2.out http://localhost:6060/debug/pprof/heap
$ go tool pprof -base heap1.out heap2.out

Вывод покажет разницу: что выросло за десять минут между снимками. Стек, который стабильно в плюсе от снимка к снимку, и есть ваша утечка. Тот же приём работает для CPU-профилей до и после оптимизации. Есть и вариант -diff_base, он считает разницу в процентах от base-профиля, что удобнее для отчётов.

Для микрооптимизаций сравнение профилей дополняет benchstat: бенчмарк говорит, что стало быстрее на 30%, а diff двух профилей показывает, за счёт чего именно.

pprof в проде

Держать pprof включённым в продакшене можно и нужно. Инцидент нельзя запланировать, а профиль, снятый во время инцидента, ценнее десяти снятых после. Но есть три правила.

Отдельный порт. Импорт net/http/pprof вешает хендлеры на http.DefaultServeMux. Если ваш основной сервер тоже использует DefaultServeMux, debug-эндпоинты окажутся доступны снаружи вместе с API. Правильно поднять для отладки отдельный сервер на localhost или на внутреннем интерфейсе, как в примере выше, и закрыть его сетевыми политиками. Профили содержат имена функций и путей исходников, а CPU-профиль по запросу нагружает сервис. Наружу это торчать не должно.

Знать цену. Снятие CPU-профиля добавляет небольшие накладные расходы только на время снятия. Снимок кучи и горутин почти бесплатен, но ?debug=2 и gc=1 на большом сервисе вызывают паузу. Block и mutex с агрессивным rate могут заметно замедлить горячие пути, включайте их осознанно.

Автоматизировать. Следующий шаг после ручных снимков это continuous profiling: агент постоянно снимает профили со всех инстансов и складывает в хранилище с историей. Это дают Grafana Pyroscope, Parca и профилировщики облачных провайдеров. Когда история профилей есть, вопрос «что изменилось после вчерашнего релиза» решается сравнением за минуту.

Типичные ошибки

• Профиль пустой или обрывается. Программа вышла через os.Exit, и defer pprof.StopCPUProfile() не сработал. Останавливайте профиль явно на пути завершения.
• alloc_space приняли за утечку. Функция аллоцировала 50 ГБ за неделю работы, но всё давно собрано GC. Это нагрузка на аллокатор, а не утечка. Утечку ищут по inuse_space.
• Профиль без нагрузки. 30 секунд CPU-профиля простаивающего сервиса покажут только служебные горутины. Снимайте под боевым или воспроизведённым трафиком.
• Сравнение heap-профиля с RSS. Куча это только часть памяти процесса. Расхождение с RSS само по себе не проблема.
• Оптимизация по flat без взгляда на cum. Верхняя строка top по flat часто runtime.mallocgc или memmove. Это не значит, что нужно чинить рантайм. Смотрите top -cum и peek, чтобы найти своего вызывающего.
• /debug/pprof доступен из интернета. Проверяется одной командой curl с внешнего хоста. Проверьте сегодня.

FAQ

Как посмотреть, что ест память в Go-сервисе? Подключите net/http/pprof, снимите снимок командой go tool pprof http://localhost:6060/debug/pprof/heap и выполните top. По умолчанию вы увидите inuse_space, то есть живую память с группировкой по месту аллокации.

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

Чем pprof отличается от бенчмарков? Бенчмарк измеряет скорость конкретной функции и отвечает «быстрее или медленнее». Профиль показывает, куда уходят ресурсы всей программы, и отвечает «где именно». Обычно pprof находит место, а бенчмарк проверяет исправление.

Почему в CPU-профиле нет моей функции? Либо она выполняется слишком быстро и не попадает в выборку на 100 Гц, либо компилятор её заинлайнил, либо во время снятия профиля этот код просто не вызывался. Увеличьте длительность снятия и убедитесь, что нагрузка задевает нужный путь.

Итог

Профилировщик pprof закрывает почти всю диагностику производительности Go-сервиса. CPU-профиль находит горячие точки, heap-профиль с метрикой inuse_space находит утечки памяти, goroutine-профиль ловит подвисшие горутины, block и mutex объясняют плохой latency при свободном CPU. Снимать профили удобнее всего через net/http/pprof на отдельном закрытом порту, а смотреть через go tool pprof -http с flame graph. Два правила, которые сэкономят вам больше всего времени: профилируйте под реальной нагрузкой и сравнивайте профили через -base вместо разглядывания одного снимка. А когда место найдено, исправление проверяется бенчмарком, как я описывал в статье про бенчмарки и оптимизацию в Go.