lenec ru

← все посты

Профилирование Go-сервиса с pprof: пошагово на реальном примере

18K

Раз в полгода у меня случается ситуация, когда сервис на Go начинает жрать CPU или память сильнее обычного, и непонятно, откуда. Каждый раз спасает net/http/pprof. Но из раза в раз вижу коллег, которые либо не подключают его в проде, либо подключают, но не знают, как читать результаты.

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

Подключение pprof

В простом случае всё подключается одной строкой:

import _ "net/http/pprof"

func main() {
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()
	// ... основной сервис на 8080
}

Импорт с blank identifier регистрирует хендлеры на дефолтном http.DefaultServeMux: /debug/pprof/profile, /debug/pprof/heap и так далее. Слушать на localhost:6060 — обязательно. Никогда не выставляй pprof наружу: профайл может выдать информацию о коде, путях, фронтенде. В проде доступ через kubectl port-forward или sidecar с авторизацией.

Если основной сервер у тебя на собственном http.ServeMux, импортируй net/http/pprof и зарегистрируй хендлеры явно:

mux.HandleFunc("/debug/pprof/", pprof.Index)
mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
mux.HandleFunc("/debug/pprof/heap", pprof.Handler("heap").ServeHTTP)
mux.HandleFunc("/debug/pprof/goroutine", pprof.Handler("goroutine").ServeHTTP)

CPU профиль: типичный сценарий

Сервис ест CPU больше, чем должен. Подключаемся:

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

30 секунд снимаем CPU profile. Дальше открывается интерактивный shell:

(pprof) top
Showing nodes accounting for 23.45s, 78.16% of 30.01s total
      flat  flat%   sum%        cum   cum%
     8.12s 27.06% 27.06%      8.12s 27.06%  encoding/json.(*decodeState).object
     5.34s 17.79% 44.85%      5.34s 17.79%  runtime.scanobject
     2.99s  9.96% 54.81%      4.55s 15.16%  github.com/jackc/pgx/v5.scanRow

flat — время в самой функции, cum — включая её вызовы. Я обычно начинаю с flat: где сервис реально проводит CPU-такты. В этом примере четверть времени уходит на парсинг JSON. Дальше можно посмотреть, кто эти вызовы инициирует:

(pprof) list decodeState

Покажет hot lines в исходниках. Полезно, чтобы убедиться, что время уходит именно на парсинг, а не на выделение слайсов внутри.

Для визуализации:

(pprof) web

Откроет SVG в браузере. Толщина стрелок — доля CPU. По таким графам быстро видно горячий стек.

Heap профиль: ловим утечки

Если RSS пода растёт со временем, причин обычно три:

  • Реальная утечка: мы куда-то складываем объекты и не отпускаем.
  • Утечка горутин: горутины зависают, держат свои стеки и захваченные переменные.
  • Естественный рост buffers/cache: дошёл до плато и перестал расти.

Heap profile показывает первое. Снимать удобно так:

go tool pprof -alloc_space http://localhost:6060/debug/pprof/heap

Флаги: -inuse_space — сколько памяти выделено сейчас, -alloc_space — сколько всего выделялось за время жизни процесса. Для утечек смотрят inuse, для оптимизации аллокаций — alloc.

Реальный пример из практики: сервис обработки вебхуков. RSS рос на 50 МБ в час. Сняли heap, увидели:

(pprof) top
     flat  flat%  cum%
  450MB  68%    68%   github.com/somelib/cache.(*Cache).Set
  120MB  18%    86%   ... 

Кэш без эвикции, накапливал записи. Поправили на LRU с лимитом, RSS встал на 600 МБ и перестал расти.

Goroutine profile: зависшие горутины

Когда количество горутин растёт линейно со временем, профайл goroutine показывает, где они зависают:

curl http://localhost:6060/debug/pprof/goroutine?debug=2 > goroutines.txt

debug=2 — это полный текстовый дамп со всеми стеками. По нему видно, какие функции массово стоят на одних и тех же select/chan-операциях. Например:

goroutine 1234 [chan receive, 15 minutes]:
main.worker(0xc000...)
        /app/worker.go:42 +0x123

15 минут на chan receive — значит, никто не пишет в этот канал. Дальше идёшь читать worker.go:42 и понимаешь, почему producer молчит.

Альтернатива — http://localhost:6060/debug/pprof/goroutine?debug=1, она показывает агрегированно, сколько горутин в каком стеке. Удобно, когда дамп большой.

Block и mutex profile

Эти включаются по требованию — они снижают производительность:

runtime.SetBlockProfileRate(10000) // 1 семпл на каждые 10мкс блокировки
runtime.SetMutexProfileFraction(100) // 1 из 100 событий на mutex

Дальше:

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

Block показывает блокировки на каналах, mutex — contention на sync.Mutex и sync.RWMutex. Оба нужны нечасто, но если у тебя по pprof CPU всё ровно, а latency большая — стоит проверить mutex profile.

Continuous profiling

На долгоживущих сервисах удобно собирать профили постоянно: Pyroscope, Parca, Datadog Continuous Profiler. Идея — каждые 10–30 секунд скидывать pprof на сервер, потом искать по тегам и сравнивать «до» и «после» инцидента.

Сам пользуюсь Pyroscope: легковесно, есть Go SDK, поднимается в k8s одним хелм-чартом. Полезно, потому что в момент инцидента редко успеваешь руками подключиться по pprof — а тут всё есть в истории.

Чек-лист подхода к проблеме

Когда в Slack приходит «сервис тормозит, посмотри», обычно прохожу по пунктам:

  1. Открыть Grafana, посмотреть RSS, CPU, GC pause, число горутин. Что растёт?
  2. Если CPU — снять profile?seconds=30, посмотреть top.
  3. Если RSS — снять heap с -inuse_space, найти самый жирный объект.
  4. Если число горутин — снять goroutine?debug=2, посмотреть стеки.
  5. Если latency — снять profile и mutex, найти контеншн.

Большинство проблем в Go-сервисах ловится этими пятью шагами. Незакрытые тикеры, незавершённые горутины, кэши без эвикции, JSON в горячем пути — это самый частый набор.

Парочка не очевидных вещей

Когда снимаешь CPU профиль на 30 секунд в проде — это даёт нагрузку. Не катастрофическую, но 1–2% CPU. На low-RPS сервисах профиль будет шумным: 30 секунд может быть мало. Снимай seconds=120 или больше, если можешь себе позволить.

Heap-профиль на запросе блокирует мир ненадолго (миллисекунды). На сервисах с очень жёстким SLA снимай в часы наименьшей нагрузки.

И не забывай, что pprof показывает только Go-runtime. Если у тебя проблемы в cgo или в сетевом стеке ядра — будут белые пятна. В таких случаях я подключаю eBPF (через bpftrace или perf), но это уже отдельная большая тема.

Pprof — единственный инструмент в стандартной поставке Go, без которого я не запускаю в продакшен ни один сервис. Если у тебя его до сих пор нет — добавь сегодня. Стоит трёх строчек кода, спасёт несколько часов в момент следующего инцидента.

Комментарии 1

  • Дмитрий Орлов

    У нас pprof выручал, когда искали утечку в long-running gRPC-сервисе: 30 секунд heap profile дали стек на закешированных protobuf-объектах, которые не освобождались между вызовами. По cum_alloc_objects сразу видно. Один вопрос: ты на проде делаешь endpoint /debug/pprof открытым только в kube-network, или прячешь за авторизацией? У нас был случай, когда внутренний LB случайно прокинул его наружу.

Войдите, чтобы оставить комментарий.