ЗАМЕР
bench/goprof/interfere.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.
Скрипт
150 строк//go:build ignore
// Измерительный инструмент не нейтрален: цена «записывать всё» у профилей
// блокировок, мьютексов и памяти и то, как один профиль искажает другой.
//
// ЗАЧЕМ. Урок говорит, что SetBlockProfileRate(1) и
// SetMutexProfileFraction(1) удобны для отладки, но в сервисе их включают
// выборкой, и что подробный профиль памяти виден в профиле CPU. Здесь это
// измерено, а не сказано:
//
// 1. Пинг-понг по каналу без буфера: время с профилем блокировок и без.
// 2. Четыре горутины на одном мьютексе: время с профилем мьютексов и без.
// 3. Поток мелких выделений: время при MemProfileRate по умолчанию и при 1,
// и доля учёта выделений (runtime.mProf_Malloc) в профиле CPU.
//
// В каждой строке — лучший из 5 кругов, по три серии на сравнение: кратность
// шумит, и одна серия выдала бы шум за результат. Нагрузки намеренно
// крайние — почти одни блокировки, захваты, выделения; на реальном сервисе
// доля будет меньше, а направление — то же.
//
// ЗАПУСК:
//
// go run bench/goprof/interfere.go
package main
import (
"fmt"
"os"
"os/exec"
"path/filepath"
"runtime"
"runtime/pprof"
"strings"
"sync"
"time"
)
func best(f func()) time.Duration {
lo := time.Duration(1 << 62)
for i := 0; i < 5; i++ {
start := time.Now()
f()
if d := time.Since(start); d < lo {
lo = d
}
}
return lo
}
func pingpong() {
a, b := make(chan int), make(chan int)
go func() {
for v := range a {
b <- v
}
close(b)
}()
for i := 0; i < 200000; i++ {
a <- i
<-b
}
close(a)
<-b
}
func contended() {
var mu sync.Mutex
var wg sync.WaitGroup
n := 0
for g := 0; g < 4; g++ {
wg.Add(1)
go func() {
defer wg.Done()
for i := 0; i < 200000; i++ {
mu.Lock()
n++
mu.Unlock()
}
}()
}
wg.Wait()
}
var sink []byte
func allocs() {
for i := 0; i < 2000000; i++ {
sink = make([]byte, 64)
}
}
func ms(d time.Duration) float64 { return float64(d.Microseconds()) / 1000 }
func mprofShare(rate int) string {
runtime.MemProfileRate = rate
defer func() { runtime.MemProfileRate = 512 * 1024 }()
path := filepath.Join(os.TempDir(), fmt.Sprintf("goprof-interfere-%d.out", rate))
f, _ := os.Create(path)
pprof.StartCPUProfile(f)
for i := 0; i < 3; i++ {
allocs()
}
pprof.StopCPUProfile()
f.Close()
out, err := exec.Command("go", "tool", "pprof", "-top", "-cum", "-nodecount=200", path).CombinedOutput()
if err != nil {
panic(fmt.Sprintf("%v\n%s", err, out))
}
for _, line := range strings.Split(string(out), "\n") {
if strings.HasSuffix(strings.TrimSpace(line), "runtime.mProf_Malloc") {
fields := strings.Fields(line)
return fields[4] // cum%
}
}
return "нет в профиле"
}
func main() {
fmt.Printf("%s %s/%s, GOMAXPROCS=%d | цена и взаимное влияние профилей\n",
runtime.Version(), runtime.GOOS, runtime.GOARCH, runtime.GOMAXPROCS(0))
measure := func(title string, label string, f func(), set func(on bool)) {
fmt.Println()
fmt.Println(title)
fmt.Println(strings.Repeat("─", len([]rune(title))))
fmt.Printf(" %-6s %-28s %11s %11s %s\n", "серия", "", "выключен", "«всё»", "кратн.")
for series := 1; series <= 3; series++ {
set(false)
off := best(f)
set(true)
on := best(f)
set(false)
fmt.Printf(" %-6d %-28s %8.1f мс %8.1f мс x%.2f\n", series, label, ms(off), ms(on), float64(on)/float64(off))
}
}
measure("1) ПРОФИЛЬ БЛОКИРОВОК: SetBlockProfileRate(1)", "пинг-понг, 200 000 обменов", pingpong,
func(on bool) { runtime.SetBlockProfileRate(map[bool]int{true: 1, false: 0}[on]) })
measure("2) ПРОФИЛЬ МЬЮТЕКСОВ: SetMutexProfileFraction(1)", "4 горутины × 200 000 захватов", contended,
func(on bool) { runtime.SetMutexProfileFraction(map[bool]int{true: 1, false: 0}[on]) })
measure("3) ПРОФИЛЬ ПАМЯТИ: MemProfileRate = 1", "2 000 000 выделений по 64 Б", allocs,
func(on bool) { runtime.MemProfileRate = map[bool]int{true: 1, false: 512 * 1024}[on] })
fmt.Println()
fmt.Println(" доля runtime.mProf_Malloc в профиле CPU той же нагрузки (cum%):")
fmt.Printf(" MemProfileRate по умолчанию: %s\n", mprofShare(512*1024))
fmt.Printf(" MemProfileRate = 1: %s\n", mprofShare(1))
fmt.Println()
fmt.Println(" Профиль памяти, записывающий каждое выделение, сам становится")
fmt.Println(" заметной строкой в профиле CPU: один инструмент искажает то,")
fmt.Println(" что показывает другой.")
}