Бенчмарки и профилирование

Шестнадцатый урок закрыл вопрос «правильно ли работает код»; этот урок закрывает вопрос «насколько быстро». Разница между ними принципиальная, потому что у скорости есть коварное свойство: она почти всегда не там, где вы думаете. Программист трижды переписывает парсер — а тормозит печать в лог; команда переезжает на новый фреймворк — а девяносто процентов времени съедает сериализация, которая была и в старом. По запросу «бенчмарки go» обычно ищут инструмент, который поставит точку в спорах, и он действительно есть, причём в той же стандартной библиотеке: пакет testing умеет не только проверять, но и измерять.

Бенчмарка — это функция в файле с суффиксом _test.go (да, рядом с тестами, в том же каталоге), имя которой начинается с префикса Benchmark и продолжается с заглавной буквы: BenchmarkConcat, BenchmarkNormalizePhone. Единственный параметр — указатель на testing.B, «руль» измерения: через него фреймворк сообщает число итераций (b.N), управляет таймером (ResetTimer, StopTimer, StartTimer) и просит печатать аллокации (ReportAllocs). Внутри — цикл по b.N, тело которого и есть измеряемая операция. Запускается всё той же командой go test, только с флагом -bench: никакой отдельной инфраструктуры, второй мир живёт в первом.

Что будет в уроке. Сначала контракт: сигнатура, файл, и главное — кто и зачем подбирает b.N, потому что именно здесь новички теряются (число в отчёте меняется от запуска к запуску, и это нормально). Затем чтение отчёта go test -bench по столбцам: ns/op, флаг -benchmem и его подарки B/op и allocs/op. Потом гигиена замера: ResetTimer, StopTimer и StartTimer для честного окна измерения. Затем pprof профилирование — снятие CPU-профиля и профиля памяти, чтение top и list, базовый flame graph. Финал — живой кейс: строковая конкатенация против strings.Builder, где квадратичный алгоритм на глазах становится линейным, а отчёт -benchmem объясняет почему.

Оговорка о песочнице, как в прошлом уроке. Настоящий бенчмарк — это работа команды go test: она собирает пакет, находит Benchmark-функции и прогоняет их с подобранным b.N. Ни один движок песочницы этого не делает (у резервного пакета testing нет вовсе, у основного нет команды test), поэтому Benchmark-функции урока — листинги для локального запуска, а интерактивы честно гоняют то, что движкам по силам: ручные счётчики операций, симуляцию подгонки b.N, фальшивые часы для ResetTimer и битву конкатенаций. Принцип тот же, что в шестнадцатом уроке: смотрите на настоящие листинги — тут же трогайте их логику руками.

Хорошая новость: половину контракта вы уже сдали. Файл с суффиксом _test.go — тот же, go build его молча пропускает, go test — компилирует. Префикс имени Benchmark с заглавным продолжением — по образцу префикса Test; флаг -bench фильтрует бенчмарки регуляркой так же, как -run фильтрует тесты. Возвращать функция ничего не должна — измерение выражается не return, а самим фактом прогонки цикла. Меняется только руль: вместо testing.T приходит testing.B, и у него своя задача — не фиксировать провалы, а крутить счётчик итераций.

Центральное действующее лицо — b.N. Это число повторов измеряемой операции, и его задаёт НЕ программист: его подбирает фреймворк по ходу запуска. Механика честная и простая: testing запускает бенчмарку с малым N, смотрит на затраченное время, затем удваивает (и повторяет этот подгон, отрезая неудачные прогоны), пока суммарное время не станет достаточно долгим для надёжного измерения — по умолчанию около секунды на бенчмарку (управляется флагом -benchtime). Финальный прогон с последним N и попадает в отчёт: поэтому число итераций в выводе каждый раз разное — 4908816, 5102311, 4782195 — и это не шум, а следствие подгонки. Писать b.N = 1000 руками бессмысленно и не нужно: фреймворк сам обеспечит и достаточную длительность, и деление на N при расчёте наносекунд на операцию.

Отсюда и классическая форма, которую вы увидите в миллионах строк по всему миру:

for i := 0; i < b.N; i++ { // измеряемая операция }

Честности ради: начиная с Go 1.24 у testing.B появился метод b.Loop() — новый стиль, где ручной счётчик не нужен (for b.Loop() { ... }), а компилятору проще не выбрасывать неиспользуемый результат. Но классическая форма с b.N остаётся универсальной: она работает во всех версиях, встречается в любом старом коде и документации, и именно её мы разбираем по буквам. Выучив её, вы прочитаете b.Loop за минуту — это просто оболочка над тем же контрактом.

Единственная ловушка внутри цикла — компилятор и мёртвый код. Если результат операции никак не используется, компилятор теоретически вправе выкинуть работу (в старых версиях так и было), и бенчмарк начнёт измерять пустоту. Лечится чтением результата: присвойте его внешней переменной и добавьте _ = result после цикла — как в листинге ниже. Новый b.Loop решает это автоматически, но в классической форме дисциплина на вас.

Запуск — та же команда go test с флагом -bench и регуляркой: -bench=. запускает все бенчмарки пакета, -bench=Concat — только совпавшие с именем. Первая тонкость: обычные тесты при этом всё равно выполнятся, и их время разбавит прогон; если они вам сейчас не нужны, отключите их фильтром, которому не совпадает ни один тест: go test -bench=. -run='^$'. Это каноническая команда бенчмаркинга — запомните её парой с флагом -benchmem, о котором ниже.

Отчёт печатается столбцами, и каждый столбец имеет точный смысл. Строка BenchmarkConcat-8 4908816 245.3 ns/op читается так: имя бенчмарки и суффикс -8 — это GOMAXPROCS, число логических процессоров, при котором шёл прогон (полезно, когда сравниваете машины); 4908816 — подобранное b.N, число итераций финального прогона; 245.3 ns/op — средняя стоимость ОДНОЙ итерации в наносекундах, главный столбец урока. Перед данными go test печатает паспорт окружения — goos, goarch, pkg, cpu — и это не украшение: абсолютные наносекунды сравнивают только на одном железе, поэтому паспорт нужен в каждом отчёте.

Флаги управления прогоном продолжают знакомую логику. -benchtime=2s заставит фреймворк крутить подгон дольше — полезно для шумных сред, где секунды не хватает; -benchtime=100x задаёт фиксированное число итераций — быстро проверить, что бенчмарка вообще живая. -count=5 повторяет весь прогон пять раз: ОДИН прогон — это анекдот, пять — статистика. Между повторами разброс неизбежен (планировщик, кэш, соседние процессы), поэтому всерьёз выводы делают не по одному числу, а по медиане нескольких прогонов; у benchstat — маленькой утилиты из golang.org/x/perf — для этого есть готовый отчёт с процентами и вердиктом «отличие статистически значимо или нет».

И последнее: бенчмарка, которая печатает в stdout, портит и прогон, и отчёт. Печать — самая дорогая операция на свете относительно арифметики, и ваши 245.3 ns/op мгновенно станут 4200 ns/op от одного fmt.Println внутри цикла. Правило то же, что у тестов: молчи, пока здоров — печать только в prepare-фазе или за пределами измеряемого окна.

Наносекунды говорят «сколько», но не говорят «почему». Для «почему» в go test есть флаг -benchmem, и это самый информативный символ на весь бенчмаркинг: go test -bench=. -benchmem=-run='^$' дописывает к отчёту два столбца. 10 B/op — сколько БАЙТ аллокировал один проход измеряемой операции; 4 allocs/op — сколько РАЗ за один проход вызвался аллокатор. Это средние значения по всем итерациям, и читать их нужно в связке: allocs/op показывает количество походов к аллокатору (каждый — фиксированная цена и потенциальный pressure на GC), B/op — объём трафика.

Почему аллокации — главный подозреваемый любого торможения в Go? Потому что память в куче дорогая не сама по себе, а последствиями: аллокатор должен найти свободный блок (а при фрагментации — и поискать), GC со временем обязан эти объекты собрать, а кэш процессора — промахнуться по разбросанным данным. Две функции с одинаковым ns/op «здесь и сейчас» могут вести себя совершенно по-разному под нагрузкой: у первой аллокаций ноль, вторая каждую итерацию мусорит — и именно вторая утопит сервис под процентами GC. Отсюда правило бенчмаркинга: сравнивая варианты, смотрите на allocs/op РАНЬШЕ, чем на ns/op — столбец аллокаций почти всегда называет виновника быстрее, чем наносекунды.

Аллокации считают и без флага: метод b.ReportAllocs() внутри бенчмарки включает столбцы только для неё — удобно, когда флаг для всего пакета не нужен. А чтобы увидеть не только количество, но и ЛИЦА виновников, аллокации подключаются к профилированию памяти: флаг -memprofile, о котором через два раздела, сохранит по стекам, КТО именно аллокирует эти байты. ns/op отвечает «медленно ли», allocs/op — «кто виноват», flame graph — «где именно»: три вопроса, три инструмента, один go test.

И честная оговорка про кэш и warming-up: первый прогон бенчмарки греет кэши, подгружает страницы кода и словари, и потому всегда медленнее стабильных. Фреймворк знает это и неудачные короткие прогоны при подгоне отбрасывает, но при -count=5 первый повтор может выбиваться — не паникуйте и не выбрасывайте его руками без причины: сначала посмотрите на медиану.

Бенчмарка измеряет ВСЁ, что происходит между началом и концом цикла — и туда легко попадает мусор, который к операции отношения не имеет. Классическая ловушка: подготовка данных. parts := prepareParts(1000000) внутри бенчмарки до цикла кажется безобидным — но если prepareParts аллокирует и считает десятки миллисекунд, а сама операция стоит микросекунды, то ns/op будет измерять в основном подготовку... нет, стоп: подготовка ДО цикла в суммарное время не попадает — таймер стартует с началом замера. Попадает в замер она тогда, когда вы делаете её ВНУТРИ цикла, когда каждый кейс требует свежих данных, или когда таймер уже тикает из-за подгоночных прогонов. Точнее и опаснее всего второй случай: любое одноразовое дорогое действие после старта замера — подключение к базе, чтение файла, генерация входа — размазывается по всем итерациям и врёт вам в каждом ns/op.

b.ResetTimer() — лечение по умолчанию: обнуляет таймер (и счётчики аллокаций) в точке вызова. Подготовили данные — вызовите ResetTimer — крутите цикл: замер начнётся с чистого листа, подгоночные прогоны и подготовка не попадут в отчёт. Это стандартный хвост любой бенчмарки с setup-фазой, и его отсутствие — самая частая причина «почему у меня в отчёте 8000 ns/op, а операция-то копеечная».

Когда подготовка нужна КАЖДОЙ итерации (свежий буфер, чистое состояние), флагов «до цикла» недостаточно — и на сцену выходит пара b.StopTimer() / b.StartTimer(): первый замирает счёт времени, второй запускает снова. Подготовка внутри итерации оборачивается в StopTimer-подготовку-StartTimer, и в ns/op попадает только операция. Цена честности — сама пара вызовов: они не бесплатные, и при копеечных операциях их накладные расходы могут быть заметны. Поэтому иерархия такая: подготовка вне цикла и без таймеров — идеал; ResetTimer после одноразового setup — норма; StopTimer/StartTimer на каждую итерацию — приём с оговоркой, для дорогих операций. Отдельный бонус ResetTimer: он сбрасывает и счётчики аллокаций, так что B/op и allocs/op после него тоже чистые.

Бенчмарка отвечает «сколько стоит операция», но когда операция дороже ожиданий, начинается поиск виновника — и вот здесь начинается pprof профилирование. Профайлер — это инструмент, который в ходе работы программы периодически записывает, в какой функции она находится (CPU-профиль), и кто сколько памяти аллокирует (профиль памяти). Результат — не средние наносекунды, а РАЗЛОЖЕНИЕ времени и памяти по стекам вызовов: конкретные функции с конкретными долями. Философия простая: бенчмарк нашёл боль, профиль назвал её адрес.

Снять профиль с бенчмарок проще всего: go test -bench=Concat -cpuprofile=cpu.out соберёт бенчмарки как обычно и попутно запишет CPU-профиль в файл cpu.out; флаг -memprofile=mem.out тем же манером сохранит профиль памяти (аллокации по стекам). Файл называется профилем и хранит семплы; читать его будет утилита go tool pprof, о ней ниже. Тонкость, которую стоит знать: CPU-профиль собирается семплированием — примерно сто раз в секунду рантайм прерывает программу и записывает текущий стек; поэтому в профиле попадают только функции, которые реально выполнялись достаточно долго, а микроскопические вызовы тонут в шуме. Это не баг, а дизайн: профайлер показывает, где программа ЖИВЁТ, а не где она побывала мимоходом.

Если профилировать нужно не бенчмарку, а обычную программу или сервер, на сцену выходит пакет runtime/pprof из стандартной библиотеки: pprof.StartCPUProfile(f) включает запись семплов в файл f, defer pprof.StopCPUProfile() выключает по выходу; pprof.WriteHeapProfile(mf) снимает снимок кучи. HTTP-серверы получают то же самое в подарок: import _ "net/http/pprof" добавляет к default serve mux эндпоинт /debug/pprof/, с которого профиль живого сервера снимается по требованию — но это тема про HTTP, а здесь важно другое: источник профиля может быть любым, формат один, и go tool pprof читает все.

Осторожность одна: профиль без нагрузки — пустой профиль. CPU-профиль снимается только с того кода, который РЕАЛЬНО крутится во время записи: запустите бенчмарку под -cpuprofile — и семплы соберутся; снимите профиль с программы, которая спит в ожидании сети, — и top покажет рантайм-ожидания, а не вашу логику. Правило: сначала нагрузка (бенчмарка или реальный трафик), потом запись, потом чтение.

Файл профиля читает go tool pprof: go tool pprof cpu.out открывает интерактивную сессию, где три команды закрывают девяносто процентов потребностей. top — таблица функций-рекордсменов: top5 покажет пять функций, на которые ушло больше всего времени, столбцом flat — время непосредственно в теле функции, столбцом cum (cumulative) — время в ней и во всём, что она вызывала. Первая строка top с большим flat — это и есть виновник: в нашем кейсе строка вида 1.31s 72.78% 72.78% example.com/concat.Concat скажет всё — три четверти времени прогона сидит в Concat. Если flat маленький, а cum большой — время живёт в callee, спускайтесь по стеку.

list — второй уровень точности: list Concat печатает исходник функции построчно с процентом времени на каждую строку. Это уже не «функция дорогая», а «вот эта строка с конкатенацией — 70%, а вот эта проверка — 2%»: уровень детализации, после которого оптимизация перестаёт быть гаданием. Третья команда — flame graph: go tool pprof -http=:8080 cpu.out откроет браузерный интерфейс, где вкладка VIEW → Flame Graph нарисует стеки столбиками: ширина столбика пропорциональна доле времени, глубина — стеку вызовов. Читается базово за минуту: широкий плоский столбик наверху — дорогая функция, широкая башня — дорогая ветка вызовов; ищите самый широкий столбик, который ВЫ контролируете (не рантайм и не syscall), — это и есть точка приложения усилий.

flame graph любит два вопроса: «широкий столбик наверху» и «странный хребет посередине». Первый — прямая дорога к оптимизации; второй (узкая, но глубокая башня одинаковых вызовов) — часто признак рекурсии или бесконечных обёрток, и он тоже виден мгновенно. Не углубляйтесь дальше первого широкого столбика: профилирование — не коллекционирование, а поиск ДВЕРИ, за которой сидит половина времени; найдя её, закрывайте сессию и идите писать бенчмарк для проверки правки.

И держите в голове честную иерархию инструментов, чтобы не путаться: ns/op из go test -bench отвечает «дорого ли»; allocs/op из -benchmem отвечает «сколько мусора»; top и list из pprof отвечают «кто и в какой строке»; flame graph — «как через стек это пришло». Четыре ответа, четыре команды — весь бенчмаркинг стандартной библиотеки.

Всё из этого урока сходится в один классический кейс, который стоит пройти целиком: строковая конкатенация в цикле. Строки в Go неизменяемы — это фундаментальное свойство, а не реализация: строка — пара (указатель, длина) на непрозрачные байты, и «изменить» её нельзя, можно только построить новую. Поэтому каждый s += p делает честную работу: аллокирует НОВЫЙ байтовый блок нужной длины, копирует туда ВСЁ старое содержимое и добавляет кусочек. На пяти кусочках это незаметно; на тысячах — суммарно копируется квадратичное число байтов: 1 + 2 + 3 + ... + n, то есть n(n-1)/2.

Противопоставим ему strings.Builder — тип из стандартной библиотеки, созданный ровно для этой задачи (Go 1.10). Builder держит внутренний []byte, который растёт с запасом (удвоением ёмкости, как срезы из ранних уроков), метод WriteString дописывает в конец без копирования всего накопленного, а финальный String() отдаёт результат. Итог: одна цепочка растущего буфера вместо n новых строк — линейное число копируемых байтов вместо квадратичного, и в разы меньше походов к аллокатору.

Как это доказать, а не постулировать? Тремя шагами этого урока. Шаг первый: счётчик копирований — ручной раннер ниже посчитает суммарные байты, скопированные при +=, и вы увидите квадратичный рост своими глазами: удвоили вход — работа выросла вчетверо. Шаг второй: настоящий go test -bench=. -benchmem по листингам BenchmarkConcat и BenchmarkBuilder покажет столбцы вида 245.3 ns/op 10 B/op 4 allocs/op против 20.6 ns/op 8 B/op 1 allocs/op (числа с одного ноутбука; у вас абсолюты будут другими — разрыв сохранится): allocs/op упал вчетверо, ns/op — на порядок. Шаг третий: cpuprofile того же прогона — и top покажет, что в первой версии почти всё время сидело в runtime.memmove и mallocgc, то есть в копировании и аллокациях, а не в вашей «логике». Подозрение → измерение → адрес виновника → правка → повторный замер: полный цикл, который вы теперь умеете.

Мораль кейса шире строк. Когда бенчмарк называет виновником аллокации, лечение почти всегда одно из трёх: переиспользовать буфер (Builder, bytes.Buffer, срез с запасом через make с capacity), вытянуть работу за пределы горячего цикла, или сменить структуру данных. Пере-читайте этот абзац после каждого профиля, где top упрётся в mallocgc — это самый частый диагноз в реальных сервисах, и лечится он без экзотики.

Соберём урок в одну картину. Бенчмарка — функция func BenchmarkXxx(b testing.B) в файле _test.go: то же семейство, что тесты из шестнадцатого урока, только руль другой. Число итераций b.N подбирает фреймворк удвоениями до достаточной длительности, поэтому в отчёте оно меняется от запуска к запуску — и это честное поведение. Отчёт go test -bench читается по столбцам: подобранное N, ns/op — цена одной итерации; флаг -benchmem добавляет B/op и allocs/op, а ResetTimer после setup и пара StopTimer/StartTimer держат окно замера чистым. pprof профилирование раскладывает то же время по стекам: -cpuprofile и -memprofile при бенчмарках, runtime/pprof в обычных программах, чтение через top, list и flame graph. Кейс конкатенации прошёл весь путь: счётчик копирований показал квадратичность, -benchmem назвал виновником аллокации, strings.Builder свёл работу к линейной.

Тесты проверяют «правильно ли», бенчмарки — «быстро ли», а следующий вопрос звучит как «как программа видит саму себя в рантайме?». Восемнадцатый урок — рефлексия: reflect.TypeOf и reflect.ValueOf, как код осматривает чужие структуры во время выполнения, где это оправдано (энкодеры, драйверы баз, мапперы), и главное — цена, которую рефлексия берёт за гибкость. Цену вы теперь умеете измерять: напишите BenchmarkReflect и BenchmarkDirect рядом и сравните allocs/op — предсказываю, цифры вас неприятно удивят, и это лучший мотиватор выучить границы приёма.

До встречи на странице курса: а если понадобится освежить каркас проверок, вокруг которого встали сегодняшние бенчмарки, — вернитесь к уроку про тестирование и перечитайте раздел про table driven tests: бенчмарки с prepare-данными собираются по той же схеме «данные отдельно, каркас один». А при чтении чужих профилей пригодится привычка из урока про оборачивание ошибок: сначала личность причины (errors.Is к логу, top к стеку), потом лечение.