ЗАМЕР

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

Скрипт

85 строк

//go:build ignore

// Профиль CPU на одной и на двух занятых горутинах: почему «Total samples»
// бывает больше 100 %.
//
// ЗАЧЕМ ОТДЕЛЬНАЯ ПРОГРАММА. В internals.go профиль CPU снят с одной
// горутины, и процент в строке «Total samples» там меньше 100. Урок говорит,
// что он бывает и больше, — это утверждение должно опираться на прогон, а
// перезапуск internals.go поменял бы числа, которые урок уже цитирует.
//
// ЧТО ДЕЛАЕТ. Дважды по 2 секунды стенных часов крутит вычисления — в одной
// горутине и в двух — под профилем CPU и печатает строку заголовка из
// `go tool pprof -top`.
//
// ЗАПУСК:
//
//	go run bench/goprof/cores.go
package main

import (
	"crypto/sha256"
	"fmt"
	"os"
	"os/exec"
	"path/filepath"
	"runtime"
	"runtime/pprof"
	"strings"
	"sync"
	"time"
)

var sink [32]byte

func burn(d time.Duration) {
	b := make([]byte, 64)
	for end := time.Now().Add(d); time.Now().Before(end); {
		for i := 0; i < 1000; i++ {
			sink = sha256.Sum256(b)
			b = sink[:]
		}
	}
}

func profile(goroutines int) string {
	path := filepath.Join(os.TempDir(), fmt.Sprintf("goprof-cores-%d.out", goroutines))
	f, err := os.Create(path)
	if err != nil {
		panic(err)
	}
	if err := pprof.StartCPUProfile(f); err != nil {
		panic(err)
	}
	var wg sync.WaitGroup
	for g := 0; g < goroutines; g++ {
		wg.Add(1)
		go func() { defer wg.Done(); burn(2 * time.Second) }()
	}
	wg.Wait()
	pprof.StopCPUProfile()
	f.Close()

	out, err := exec.Command("go", "tool", "pprof", "-top", "-nodecount=1", path).CombinedOutput()
	if err != nil {
		panic(fmt.Sprintf("%v\n%s", err, out))
	}
	for _, line := range strings.Split(string(out), "\n") {
		if strings.HasPrefix(line, "Duration:") {
			return line
		}
	}
	return "нет строки Duration"
}

func main() {
	fmt.Printf("%s %s/%s, GOMAXPROCS=%d | профиль CPU на одной и двух горутинах\n\n",
		runtime.Version(), runtime.GOOS, runtime.GOARCH, runtime.GOMAXPROCS(0))
	fmt.Println("  одна занятая горутина: ", profile(1))
	fmt.Println("  две занятые горутины:  ", profile(2))
	fmt.Println()
	fmt.Println("  Одна горутина занимает не больше одного ядра, и процессорного")
	fmt.Println("  времени набирается не больше, чем прошло по часам. Две горутины")
	fmt.Println("  на двух ядрах набирают почти вдвое больше: процент выше 100.")
}