Deep Engineering

MEASUREMENT

bench/goprof/internals.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

312 lines
//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 — нет.")
}