Deep Engineering

ЗАМЕР

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

Скрипт

141 строк
//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("  попасть вовсе: профиль — выборка, а не учёт каждого вызова.")
}