MEASUREMENT
bench/goprof/practice.go
The script that produced the numbers in the article, and the record of the run. The file is read from the repository at build time — this is the code that was run, not a copy of it.
- Cited in
- /en/interview/golang/profiling
- How to run it
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
The run below is recorded in Russian. It is a lab record, kept in the language it was written in; the numbers, the tables and the code read the same either way.
Record of the run
Замеры для урока «Профилирование»
| Файл | Что делает |
|---|---|
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.
Script
141 lines//go:build ignore
// Две задачи урока про профилирование: обе отвечают прогоном.
//
// ЗАДАЧА 1 — ПРЕДСКАЗАТЬ ВЫВОД. Три строки:
// - сколько записей в профиле блокировок, если его не включали, а
// блокировки были;
// - на сколько выросло число горутин в профиле после запуска сотни
// горутин, ждущих канала, в который никто не пишет;
// - есть ли в inuse_space функция, которая выделила много, но ничего не
// удержала.
//
// ЗАДАЧА 2 — ОЦЕНИТЬ ЧИСЛО. Сколько сэмплов наберёт профиль CPU за 2 секунды
// работы одной горутины. Число сэмплов печатает сам pprof в режиме -raw.
//
// ЗАПУСК:
//
// go run bench/goprof/practice.go
package main
import (
"crypto/sha256"
"fmt"
"os"
"os/exec"
"path/filepath"
"runtime"
"runtime/pprof"
"strings"
"sync"
"time"
)
var sink []byte
//go:noinline
func churn(n int) {
for i := 0; i < n; i++ {
sink = make([]byte, 4096)
}
}
//go:noinline
func burn(d time.Duration) {
b := make([]byte, 64)
for start := time.Now(); time.Since(start) < d; {
s := sha256.Sum256(b)
b = s[:]
}
sink = b
}
func main() {
dir, _ := os.MkdirTemp("", "goprof-practice")
defer os.RemoveAll(dir)
fmt.Println("ЗАДАЧА 1 — предсказать вывод")
fmt.Println()
// Блокировки были: четыре горутины дерутся за мьютекс.
var mu sync.Mutex
var wg sync.WaitGroup
wg.Add(4)
for g := 0; g < 4; g++ {
go func() {
defer wg.Done()
for i := 0; i < 1000; i++ {
mu.Lock()
time.Sleep(time.Microsecond)
mu.Unlock()
}
}()
}
wg.Wait()
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()
heap := filepath.Join(dir, "heap.pprof")
h, _ := os.Create(heap)
pprof.Lookup("heap").WriteTo(h, 0)
h.Close()
out, _ := exec.Command("go", "tool", "pprof", "-top", "-nodecount=100",
"-sample_index=inuse_space", heap).CombinedOutput()
fmt.Println(strings.Contains(string(out), "main.churn"))
fmt.Println()
fmt.Println("ЗАДАЧА 2 — сколько сэмплов за 2 секунды работы одной горутины")
fmt.Println()
cpu := filepath.Join(dir, "cpu.pprof")
f, _ := os.Create(cpu)
start := time.Now()
pprof.StartCPUProfile(f)
burn(2 * time.Second)
pprof.StopCPUProfile()
wall := time.Since(start)
f.Close()
raw, err := exec.Command("go", "tool", "pprof", "-raw", cpu).CombinedOutput()
if err != nil {
panic(fmt.Sprintf("%v\n%s", err, raw))
}
// В выводе -raw после строки «Samples:» идёт строка с типами значений,
// а дальше — по строке на каждую уникальную трассу: « <count> <ns>: <адреса>».
samples := 0
inSamples := false
for _, line := range strings.Split(string(raw), "\n") {
t := strings.TrimSpace(line)
if strings.HasPrefix(t, "Samples:") {
inSamples = true
continue
}
if inSamples {
if t == "" || strings.HasPrefix(t, "Locations") {
break
}
var count int
if n, _ := fmt.Sscanf(t, "%d", &count); n == 1 && strings.Contains(t, ":") {
samples += count
}
}
}
fmt.Printf(" длительность работы %6.2f с\n", wall.Seconds())
fmt.Printf(" сэмплов в профиле %6d\n", samples)
fmt.Printf(" сэмплов в секунду %6.0f\n", float64(samples)/wall.Seconds())
fmt.Println()
fmt.Printf(" %s %s/%s, GOMAXPROCS=%d\n", runtime.Version(), runtime.GOOS, runtime.GOARCH, runtime.GOMAXPROCS(0))
fmt.Println()
fmt.Println(" Частота зашита в runtime/pprof: 100 сэмплов в секунду")
fmt.Println(" процессорного времени. Одна горутина, 2 секунды — около 200.")
fmt.Println(" Поэтому функция, которая работала 5 мс, в профиль может не")
fmt.Println(" попасть вовсе: профиль — выборка, а не учёт каждого вызова.")
}