ЗАМЕР
bench/goprof/internals.go
Скрипт, которым получены числа в статье, и запись прогона. Файл читается на сборке из репозитория — это тот самый код, который запускали, а не его копия.
- Цитируется в статье
- /ru/interview/golang/profiling
- Как запустить
go run bench/goprof/internals.go go run bench/goprof/cores.go go run bench/goprof/interfere.go go run bench/goprof/exposure.go go run bench/goprof/practice.go
Запись прогона
Замеры для урока «Профилирование»
| Файл | Что делает |
|---|---|
internals.go |
одна нагрузка и шесть профилей: CPU и его частота, flat против cum, куча (alloc_space против inuse_space), выключенные по умолчанию профили блокировок и мьютексов, профиль горутин на утечке, цена профиля CPU |
cores.go |
профиль CPU на одной и на двух занятых горутинах: почему «Total samples» бывает больше 100 % |
interfere.go |
цена режимов «записывать всё» у профилей блокировок, мьютексов и памяти и то, как профиль памяти искажает профиль CPU |
exposure.go |
что отдаёт /debug/pprof на DefaultServeMux без проверки доступа |
practice.go |
источник ответов двух практических задач урока |
go run bench/goprof/internals.go
go run bench/goprof/cores.go
go run bench/goprof/interfere.go
go run bench/goprof/exposure.go
go run bench/goprof/practice.go
Программы сами вызывают go tool pprof, поэтому нужен установленный Go.
Записи прогонов — в runs/, go1.24.7 linux/amd64, GOMAXPROCS=2.
Что здесь важно прочитать правильно
Таблицы — вывод go tool pprof -top. Строки File:, Build ID:,
Time: и Type: из них убраны: они меняются от запуска к запуску.
Наносекунды и миллисекунды не переносятся. Переносится форма: у какой
функции flat почти ноль, а cum — почти всё; какая функция есть в alloc_space
и отсутствует в inuse_space.
Надбавка профиля CPU — в пределах шума. Три серии: −4,0 %, +0,1 %, −0,5 %. Знак не устойчив, устойчиво, что она мала.
Что получилось
Частота профиля CPU — 100 сэмплов в секунду. Она зашита в исходнике
runtime/pprof (const hz = 100). Замер: 203 сэмпла за 2,11 с работы одной
горутины, 96 в секунду.
flat и cum. У main.handle flat 0, cum 1800 мс — 86,96 %: сам он ничего не
делает, под ним hashAll.
Куча. main.churn выделил 596,83 МБ и в inuse_space отсутствует
вовсе; main.retain выделил 16,19 МБ и держит их все.
Блокировки и мьютексы. Без настройки — 0 записей в обоих профилях при
настоящей конкуренции; после SetBlockProfileRate(1) и
SetMutexProfileFraction(1) — 3 и 2.
Утечка горутин. Сто горутин, ждущих канала, в который никто не пишет:
горутин до: 1, после: 101, все сто — под одним стеком.
Процент в «Total samples» — доля процессорного времени от стенного. Одна
занятая горутина: 93,39 %; две на двух ядрах: 181,35 % (cores.go). Одна
горутина занимает не больше одного ядра; несколько — могут набрать больше
процессорного времени, чем прошло по часам.
«Записывать всё» не бесплатно. На крайних нагрузках (interfere.go, три
серии): SetBlockProfileRate(1) — ×1,64–1,90, SetMutexProfileFraction(1) —
×1,35–1,61, MemProfileRate = 1 — ×50–62. При MemProfileRate = 1
runtime.mProf_Malloc занимает 76,64 % профиля CPU той же нагрузки: один
профиль искажает другой. Нагрузки намеренно крайние; переносится направление,
а не кратность.
/debug/pprof на рабочем порту отдаёт всё без проверки доступа.
exposure.go: сервис, зарегистрировавший только /hello на DefaultServeMux,
отдал аргументы запуска (с выдуманным паролем), стеки горутин с путями к
исходникам и профиль кучи — все со статусом 200.
Скрипт
312 строк//go:build ignore
// Профилирование в Go: что именно показывает каждый профиль и чего он не
// показывает по умолчанию.
//
// ЗАЧЕМ ЭТА ПРОГРАММА. «Сними pprof и посмотри» — совет, на котором ответ
// обычно заканчивается. А вопросы начинаются с того, ЧТО именно снимать и как
// читать: чем flat отличается от cum, почему функция, которая выделила
// гигабайт, не видна в профиле кучи, почему профиль блокировок пуст. Всё это
// здесь не пересказывается, а получается на одной нагрузке.
//
// ШЕСТЬ СЮЖЕТОВ:
//
// 1. Профиль CPU и частота сэмплов: 100 в секунду, по исходнику runtime/pprof.
// 2. flat против cum на одной и той же функции.
// 3. Профиль кучи: alloc_space против inuse_space.
// 4. Профили блокировок и мьютексов выключены по умолчанию.
// 5. Профиль горутин находит утечку.
// 6. Цена профиля CPU для самой программы.
//
// Таблицы печатает `go tool pprof -top`; строки с путями к файлам и временем
// снятия убраны — они меняются от запуска к запуску и к сути не относятся.
//
// ЗАПУСК:
//
// go run bench/goprof/internals.go
package main
import (
"bytes"
"crypto/sha256"
"fmt"
"os"
"os/exec"
"path/filepath"
"runtime"
"runtime/pprof"
"strings"
"sync"
"time"
)
func show(title string) {
fmt.Println()
fmt.Println(title)
fmt.Println(strings.Repeat("─", len([]rune(title))))
}
// ----------------------------------------------------------------- нагрузка
var sink []byte
// hashAll — тяжёлая работа процессора: свой собственный flat.
//
//go:noinline
func hashAll(rounds int) {
b := make([]byte, 64)
for i := 0; i < rounds; i++ {
s := sha256.Sum256(b)
b = s[:]
}
sink = b
}
// parse — лёгкая работа: малая доля сэмплов.
//
//go:noinline
func parse(rounds int) int {
n := 0
for i := 0; i < rounds; i++ {
n += i % 7
}
return n
}
// handle сам почти ничего не делает — только зовёт двоих. Его flat около
// нуля, а cum — почти всё время.
//
//go:noinline
func handle() int {
hashAll(2000)
return parse(20000)
}
// churn выделяет много короткоживущей памяти: ничего не удерживает.
//
//go:noinline
func churn(n int) {
for i := 0; i < n; i++ {
sink = make([]byte, 4096)
}
}
var kept [][]byte
// retain выделяет немного, но держит всё выделенное до конца программы.
//
//go:noinline
func retain(n int) {
for i := 0; i < n; i++ {
kept = append(kept, make([]byte, 1<<20))
}
}
// ----------------------------------------------------------------- pprof top
var dropPrefixes = []string{"File:", "Build ID:", "Time:", "Type:"}
func top(profile string, extra ...string) string {
args := append([]string{"tool", "pprof", "-top", "-nodecount=6"}, extra...)
args = append(args, profile)
out, err := exec.Command("go", args...).CombinedOutput()
if err != nil {
panic(fmt.Sprintf("%v\n%s", err, out))
}
var keep []string
for _, line := range strings.Split(strings.TrimRight(string(out), "\n"), "\n") {
skip := false
for _, p := range dropPrefixes {
if strings.HasPrefix(line, p) {
skip = true
}
}
if !skip {
keep = append(keep, " "+line)
}
}
return strings.Join(keep, "\n")
}
func grepLine(text, fn string) string {
for _, line := range strings.Split(text, "\n") {
if strings.HasSuffix(strings.TrimSpace(line), fn) {
return line
}
}
return " в выводе нет строки " + fn
}
func cpuWork(d time.Duration) int {
n := 0
for start := time.Now(); time.Since(start) < d; {
n += handle()
churn(50)
}
return n
}
func main() {
fmt.Printf("%s %s/%s, GOMAXPROCS=%d | профилирование\n",
runtime.Version(), runtime.GOOS, runtime.GOARCH, runtime.GOMAXPROCS(0))
dir, _ := os.MkdirTemp("", "goprof")
defer os.RemoveAll(dir)
// ---------------------------------------------------------- 1 и 2: CPU
cpuPath := filepath.Join(dir, "cpu.pprof")
f, _ := os.Create(cpuPath)
pprof.StartCPUProfile(f)
cpuWork(2 * time.Second)
pprof.StopCPUProfile()
f.Close()
cpuTop := top(cpuPath, "-unit=ms")
show("1) ПРОФИЛЬ CPU: 2 СЕКУНДЫ РАБОТЫ ОДНОЙ ГОРУТИНЫ")
fmt.Println(cpuTop)
fmt.Println()
fmt.Println(" Сэмпл снимается 100 раз в секунду, то есть каждый весит 10 мс.")
fmt.Println(" «Total samples» — это не число сэмплов, а сумма их времени.")
show("2) FLAT ПРОТИВ CUM НА ОДНОЙ И ТОЙ ЖЕ ЦЕПОЧКЕ")
full := top(cpuPath, "-nodecount=40", "-unit=ms")
fmt.Println(" flat flat% sum% cum cum%")
for _, fn := range []string{"main.hashAll", "main.parse", "main.handle"} {
fmt.Println(grepLine(full, fn))
}
fmt.Println()
fmt.Println(" flat — время в самой функции, cum — вместе со всеми, кого она")
fmt.Println(" вызвала. handle почти ничего не делает сам, и по flat его не")
fmt.Println(" видно; по cum он наверху, потому что под ним hashAll.")
// ---------------------------------------------------------- 3: куча
churn(20000) // ≈ 80 МиБ выделено и выброшено
retain(16) // 16 МиБ выделено и удержано
runtime.GC() // профиль кучи отражает состояние на последнюю сборку
heapPath := filepath.Join(dir, "heap.pprof")
h, _ := os.Create(heapPath)
pprof.Lookup("heap").WriteTo(h, 0)
h.Close()
show("3) ПРОФИЛЬ КУЧИ: alloc_space ПРОТИВ inuse_space")
alloc := top(heapPath, "-sample_index=alloc_space", "-nodecount=40", "-unit=MB")
inuse := top(heapPath, "-sample_index=inuse_space", "-nodecount=40", "-unit=MB")
fmt.Println(" alloc_space — сколько выделено за всё время:")
fmt.Println(grepLine(alloc, "main.churn"))
fmt.Println(grepLine(alloc, "main.retain"))
fmt.Println(" inuse_space — сколько удерживается сейчас:")
fmt.Println(grepLine(inuse, "main.churn"))
fmt.Println(grepLine(inuse, "main.retain"))
fmt.Println()
fmt.Println(" churn выделил больше всех, но ничего не держит — в inuse его")
fmt.Println(" нет. Утечку ищут по inuse, нагрузку на сборщик — по alloc.")
fmt.Printf(" Профиль кучи сэмплирует: в среднем одно выделение на\n")
fmt.Printf(" runtime.MemProfileRate = %d байт.\n", runtime.MemProfileRate)
// ---------------------------------------------------------- 4: блокировки
show("4) ПРОФИЛИ БЛОКИРОВОК И МЬЮТЕКСОВ ПО УМОЛЧАНИЮ")
contend := func() {
var mu sync.Mutex
var wg sync.WaitGroup
ch := make(chan int)
wg.Add(4)
for g := 0; g < 4; g++ {
go func() {
defer wg.Done()
for i := 0; i < 2000; i++ {
mu.Lock()
time.Sleep(time.Microsecond)
mu.Unlock()
}
}()
}
go func() { time.Sleep(20 * time.Millisecond); ch <- 1 }()
<-ch
wg.Wait()
}
contend()
fmt.Printf(" без настройки: block %d записей, mutex %d записей\n",
pprof.Lookup("block").Count(), pprof.Lookup("mutex").Count())
runtime.SetBlockProfileRate(1)
runtime.SetMutexProfileFraction(1)
contend()
fmt.Printf(" после SetBlockProfileRate(1) и SetMutexProfileFraction(1):\n")
fmt.Printf(" block %d записей, mutex %d записей\n",
pprof.Lookup("block").Count(), pprof.Lookup("mutex").Count())
runtime.SetBlockProfileRate(0)
runtime.SetMutexProfileFraction(0)
fmt.Println()
fmt.Println(" Оба профиля выключены, пока их не включить в коде. Снятый")
fmt.Println(" без этого профиль пуст — и пустой не значит «блокировок нет».")
// ---------------------------------------------------------- 5: горутины
show("5) ПРОФИЛЬ ГОРУТИН НАХОДИТ УТЕЧКУ")
before := pprof.Lookup("goroutine").Count()
block := make(chan int)
for i := 0; i < 100; i++ {
go func() { <-block }() // никто никогда не отправит
}
time.Sleep(50 * time.Millisecond)
after := pprof.Lookup("goroutine").Count()
var buf bytes.Buffer
pprof.Lookup("goroutine").WriteTo(&buf, 1)
fmt.Printf(" горутин до: %d, после: %d\n", before, after)
for _, line := range strings.Split(buf.String(), "\n") {
if strings.HasPrefix(line, "100 @") {
fmt.Println(" в профиле:", strings.Fields(line)[0], "горутин с одним и тем же стеком:")
}
}
inStack := false
for _, line := range strings.Split(buf.String(), "\n") {
if strings.HasPrefix(line, "100 @") {
inStack = true
continue
}
if inStack {
if !strings.HasPrefix(strings.TrimSpace(line), "#") {
break
}
parts := strings.Fields(line) // # адрес функция+смещение файл:строка
fn := parts[2]
if i := strings.Index(fn, "+0x"); i >= 0 {
fn = fn[:i]
}
fmt.Printf(" %-28s %s\n", fn, filepath.Base(parts[3]))
}
}
fmt.Println()
fmt.Println(" Профиль горутин группирует их по стеку. Сотня одинаковых стеков,")
fmt.Println(" стоящих на одном и том же приёме из канала, — и есть утечка.")
// ---------------------------------------------------------- 6: цена
show("6) ЦЕНА ПРОФИЛЯ CPU ДЛЯ САМОЙ ПРОГРАММЫ")
measure := func(profiled bool) float64 {
best := 1e18
for r := 0; r < 5; r++ {
if profiled {
pprof.StartCPUProfile(&bytes.Buffer{})
}
start := time.Now()
for i := 0; i < 400; i++ {
handle()
}
el := float64(time.Since(start).Microseconds()) / 1000
if profiled {
pprof.StopCPUProfile()
}
if el < best {
best = el
}
}
return best
}
fmt.Printf(" %-7s %22s %18s %10s\n", "серия", "400 вызовов без профиля", "с профилем CPU", "надбавка")
for series := 1; series <= 3; series++ {
off, on := measure(false), measure(true)
fmt.Printf(" %-7d %19.1f мс %15.1f мс %9.1f%%\n", series, off, on, 100*(on/off-1))
}
fmt.Println()
fmt.Println(" В каждой серии — лучший из 5 кругов. Надбавка в пределах шума: сэмпл")
fmt.Println(" берётся 100 раз в секунду, а не на каждом вызове. Поэтому")
fmt.Println(" профиль CPU снимают и в продакшене, а -race — нет.")
}