Профилирование в Go (гостевой пост Владимира Солонина)
15 апреля 2015
Рантайм Go содержит встроенный профайлер, но по умолчанию он выключен. Существует несколько способов его эксплуатации, самый «низкоуровневый» — через библиотеку runtime/pprof. Russ Cox, один из главных разработчиков Go, разместил хорошую статью по ее использованию. Однако я бы порекомендовал пакет-обертку profile, он чуть проще в настройке.
Важно! Данная статья потеряла актуальность и представляет разве что историческую ценность. Описанный в ней профайлер прекратил свое существование.
Для начала его надо установить:
Теперь нужно внести его в список импорта и активировать профайлер в начале функции main:
func main() {
//запустит CPU-профайлер
defer profile.Start(profile.CPUProfile).Stop()
// ...
}
Чтобы изменить некоторые опции или активировать другие счетчики, можно использовать расширенную форму:
config := profile.Config{
CPUProfile: true,
MemProfile: true,
BlockProfile: true,
ProfilePath: "./pro",
}
defer profile.Start(&config).Stop()
// ...
}
Здесь я активировал все три вида счетчиков, доступных в этой библиотеке, и изменил каталог для записи профайлов относительно каталога запуска. Но вообще так делать не рекомендуется. Лучше запускать по одному, поскольку несколько работающих счетчиков снижают точность результатов. Теперь осталось собрать программу с помощью go build и запустить. В ProfilePath появятся три файла: block.pprof, cpu.pprof и mem.pprof.
Сначала рассмотрим CPU-профайлер. Вывод визуализированной информации в браузер в виде графа:
В системе должен быть установлен Graphviz.
Сохранение графического представления в заданный файл, доступны форматы png, svg, pdf, ps, gif:
Запуск интерактивной оболочки:
Здесь после приглашения (pprof) попробуйте ввести команду top. Она выведет функции, вызванные вашей программой, в порядке убывания времени выполнения. Для многопоточной программы из моего предыдущего поста это выглядит так:
53.38s of 53.85s total (99.13%)
Dropped 2 nodes (cum <= 0.27s)
Showing top 10 nodes out of 13 (cum >= 0.37s)
flat flat% sum% cum cum%
20.81s 38.64% 38.64% 40.44s 75.10% crypto/md5.(*digest).Write
18.78s 34.87% 73.52% 18.78s 34.87% crypto/md5.block
6.45s 11.98% 85.50% 45.17s 83.88% crypto/md5.(*digest).checkSum
1.99s 3.70% 89.19% 49.95s 92.76% crypto/md5.Sum
1.39s 2.58% 91.77% 1.76s 3.27% main.nextPass
1.20s 2.23% 94.00% 53.84s 100% main.worker
1.07s 1.99% 95.99% 1.07s 1.99% runtime.duffzero
0.85s 1.58% 97.57% 0.85s 1.58% runtime.memmove
0.47s 0.87% 98.44% 0.93s 1.73% runtime.memequal
0.37s 0.69% 99.13% 0.37s 0.69% main.nextByte
Первые две колонки показывают время выполнения каждой функции в секундах и в процентах. Третья колонка содержит суммарное время выполнения функций, начиная сверху. Четвертая и пятая колонки показывают полное время выполнения каждой функции, включая время ожидания возврата из других функций, чем и отличаются от первых двух. По умолчанию вывод сортируется по первым столбцам. Это можно изменить, дополнив команду top опцией -cum. Хочу обратить внимание, что вывод основан не на реальном времени, а на процессорном. Оно составляет сумму интервалов работы каждого ядра. Не удивляйтесь также, если не все функции будут выведены в списке или на диаграмме. Быстрые и редко вызываемые функции могут быть отброшены, как незначительные.
Для программ с большим количеством функций полезна будет команда topN, где N — любое натуральное число. Например, top7 выведет первые 7 строк.
В интерактивном режиме также легко вывести графическое представление программы в браузер, для этого выполните команду web, или для сохранения в файл — png > cpu.png:
С помощью команды list или ее аналога weblist можно рассмотреть любую функцию в деталях. Вбейте, например, list worker, и вывод покажет, какие участки функции worker (точнее тех функций, что подходят под это регулярное выражение) выполняются достаточно долго:
Total: 53.34s
ROUTINE ======================== main.worker in main.go
1.24s 53.30s (flat, cum) 99.93% of Total
. . 42: var p part
. . 43: var b []byte
. . 44: for {
. . 45: p = <-in
. . 46: b = []byte(p.start)
80ms 80ms 47: for b[0] != p.end {
1.09s 51.44s 48: if md5.Sum(b) == hash {
. . 49: out <- string(b)
. . 50: return
. . 51: }
70ms 1.78s 52: nextPass(b)
. . 53: }
. . 54: }
. . 55:}
. . 56:
. . 57:func generator(in chan<- part) {
Команда disasm function аналогичным образом позволяет получить ассемблерный листинг. Команда web function покажет в браузере часть графа, относящуюся в выбранной функции.
По умолчанияю профайлер разделяет статистику по функциям (--functions), но это можно изменить с помощью параметров запуска: -files, -lines, -addresses сделают разбиение пофайловым, построчным и поадресным соответственно.
Используйте команду help в интерактивном режиме или параметр командной строки -h, чтобы узнать об остальных возможностях профайлера.
Профайлер памяти имеет несколько дополнительных опций:
- -inuse_space — показывает количество памяти, занятое в текущий момент (для работающих приложений), применяется по умолчанию;
- -inuse_objects — то же самое, но показывает количество объектов;
- -alloc_space — показывает количество памяти, выделенное за все время работы программы;
- -alloc_objects — аналогично, только для объектов;
Количество выделенных в памяти объектов важно еще тем, что влияет на производительность приложения, поскольку чем больше аллокаций, тем больше работы у сборщика мусора.
Запуск в интерактивном режиме:
или:
В остальном работа с профайлером памяти мало чем отличается от таковой для CPU-профайлера, за исключением того, что вместо времени работы ядра процессора учитывается количество выделенной памяти или объектов.
Профайлер блокировок позволяет увидеть, где в программе происходят остановки горутин из-за блокировок, вызванных объектами синхронизации, такими как каналы, мьютексы и т.д.
Запуск в интерактивном режиме:
Сами блокировки не всегда являются поводом для беспокойства, поскольку нижележащий поток операционной системы в таком случае переключается на другую горутину. Но есть возможность простоя, если работающих горутин меньше, чем ядер процессора. Также надо учитывать и дороговизну частых блокировок/разблокировок.
Другой способ активации профайлера удобен для веб-приложений и других программ с длительным или произвольным временем работы. Для этого используется пакет net/http/pprof. Он позволяет анализировать характеристики приложения, не прерывая его работу. Сначала нужно импортировать следующие пакеты:
_ "net/http/pprof"
"net/http"
"log"
)
Символ _ перед названием пакета означает, что сам он не будет импортирован, но будет выполнена инициализация переменных и выполнена init-функция этого пакета, которая, в данном случае, регистрирует несколько обработчиков в стандартном web-сервере Go.
Кроме того, необходимо добавить несколько строк в начало функции main:
go func() {
log.Println(http.ListenAndServe("localhost:6060", nil))
}()
// ...
}
Этот код запускает в отдельной горутине web-сервер Go, с помощью которого собранная информация будет отображаться в браузере. Соберите программу с помощью go build и запустите.
Следующая команда запустит 30-секундный сбор информации об использовании процессора, по окончании которого запустит CPU-профайлер в интерактивном режиме:
А эта команда запустит профайлер памяти:
Профайлер блокировок:
У меня он, правда, выдал ошибку parsing profile: unrecognized profile format, но, может быть, вам повезет.
Увидеть всю доступную статистику в «сыром» виде можно по адресу:
Дополнительную информацию об использовании профайлера, а также о техниках оптимизации Go-кода, можно найти в замечательной статье Дмитрия Вьюкова, еще одного разработчика Go.
От себя я хочу уже в который раз поблагодарить Владимира за то, что он не перестает радовать нас гостевыми постами о языке Go, а также призвать читателей задавать вопросы и предлагать темы для будущих статей.
Дополнение: Go и работа с базами данных, в частности с PostgreSQL
Метки: Go, Оптимизация.
Вы можете прислать свой комментарий мне на почту, или воспользоваться комментариями в Telegram-группе.