Deep Engineering

ЗАМЕР

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("  что показывает другой.")
}