Профилирование Caddy

Профиль программы — это моментальный снимок использования ресурсов программой во время выполнения. Профили могут быть очень полезны для выявления проблемных областей, отладки ошибок и сбоев, а также оптимизации кода.

Caddy использует инструменты Go для захвата профилей, которые называются pprof, и они интегрированы в команду go.

Профили отображают потребителей процессорного времени и памяти, показывают трассировки стека горутин и помогают отслеживать тупики или высококонкурентные синхронизационные примитивы.

При сообщении об определённых ошибках в Caddy от вас может потребоваться профиль. Эта статья поможет. Она описывает как получить профили с Caddy, а также как использовать и интерпретировать полученные профили pprof в целом.

Два момента, которые нужно знать перед началом:

Профили Caddy НЕ являются конфиденциальными с точки зрения безопасности. Они содержат безобидные технические данные, а не содержимое памяти. Они не предоставляют доступ к системам. Их безопасно делиться.
Профили лёгкие и могут быть собраны в рабочей среде. На самом деле, это рекомендуемая лучшая практика для многих пользователей; см. далее в этой статье.

Получение профилей

Профили доступны через интерфейс администрирования по адресу /debug/pprof/. На машине, на которой работает Caddy, откройте его в браузере:

http://localhost:2019/debug/pprof/

Вы увидите простую таблицу подсчётов и ссылок, например:

Количество	Профиль
79	allocs
0	block
0	cmdline
22	goroutine
79	heap
0	mutex
0	profile
29	threadcreate
0	trace
	полный дамп стека горутин

Подсчёты — это удобный способ быстрого выявления утечек. Если вы подозреваете утечку, несколько раз обновите страницу, и вы увидите, что одно или несколько из этих значений постоянно увеличиваются. Если количество выделений памяти растёт, это потенциальная утечка памяти; если количество горутин растёт, это потенциальная утечка горутин.

Переходите по ссылкам на профили и смотрите, как они выглядят. Некоторые могут быть пустыми, и это нормально во многих случаях. Наиболее часто используемые — goroutine (стеки вызовов функций), heap (память) и profile (процессор). Другие профили полезны для устранения неполадок, связанных с конкурентным доступом к мьютексам или тупиками.

Внизу приведено простое описание каждого профиля:

allocs: Выборка всех прошлых выделений памяти
block: Трассировки стека, которые привели к блокированию на синхронизационных примитивах
cmdline: Вызов программы с командной строки
goroutine: Трассировки стека всех текущих горутин. Используйте debug=2 в качестве параметра запроса, чтобы экспортировать в том же формате, что и необработанный сбой.
heap: Выборка выделений памяти живых объектов. Вы можете указать параметр gc GET, чтобы выполнить сборку мусора перед взятием выборки кучи.
mutex: Трассировки стека держателей конкурирующих мьютексов
profile: Профиль процессора. Вы можете указать продолжительность в секундах в параметре GET. После получения файла профиля используйте команду go tool pprof, чтобы изучить профиль.
threadcreate: Трассировки стека, которые привели к созданию новых системных потоков
trace: Трассировка выполнения текущей программы. Вы можете указать продолжительность в секундах в параметре GET. После получения файла трассировки используйте команду go tool trace, чтобы изучить трассировку.

Загрузка профилей

Нажатие ссылок на странице индекса pprof выше предоставит вам профили в текстовом формате. Это полезно для отладки, и именно это мы предпочитаем в команде Caddy, так как мы можем сканировать его, чтобы найти очевидные подсказки, не используя дополнительных инструментов.

Но фактически по умолчанию используется двоичный формат. Ссылки HTML добавляют параметр запроса ?debug=, чтобы отформатировать их как текст, за исключением ссылки (CPU) "profile", которая не имеет текстового представления.

Это параметры запроса, которые вы можете установить (из документации Go):

debug=N (все профили, кроме cpu): формат ответа: N = 0: двоичный (по умолчанию), N > 0: текстовый
gc=N (heap-профиль): N > 0: запуск цикла сбора мусора перед профилированием
seconds=N (allocs, block, goroutine, heap, mutex, threadcreate профили): возврат профиля разницы
seconds=N (cpu, trace профили): профиль для заданной продолжительности

Поскольку это HTTP-endpoints, вы также можете использовать любой HTTP-клиент, например, curl или wget, для загрузки профилей.

После загрузки профилей вы можете загрузить их в комментарий к вопросу на GitHub или использовать сайт, такой как pprof.me. Для профилей процессора, в частности, flamegraph.com — это ещё один вариант.

Удаленный доступ

Если вы уже можете получить доступ к API администрирования локально, пропустите этот раздел.

По умолчанию API администрирования Caddy доступен только через сокет обратной связи. Однако есть по крайней мере три способа получить доступ к удалённому /debug/pprof endpoint:

Обратный прокси через ваш сайт

Один из простых вариантов — просто использовать обратный прокси к нему со своего сайта:

reverse_proxy /debug/pprof/* localhost:2019 {
	header_up Host {upstream_hostport}
}

Это, конечно, сделает профили доступными для тех, кто может подключиться к вашему сайту. Если этого не нужно, вы можете добавить аутентификацию с помощью модуля аутентификации HTTP по вашему выбору.

(Не забудьте использовать /debug/pprof/* matcher, иначе вы проксируете весь API администрирования!)

SSH-туннель

Ещё один способ — использовать SSH-туннель. Это зашифрованное соединение с помощью протокола SSH между вашим компьютером и вашим сервером. Запустите на своём компьютере команду, подобную этой:

ssh -N username@example.com -L 8123:localhost:2019

Этот туннель localhost:8123 (на вашем локальном компьютере) к localhost:2019 на example.com. Не забудьте заменить username, example.com и порты по необходимости.

Затем в другом терминале вы можете запустить curl следующим образом:

curl -v http://localhost:8123/debug/pprof/ -H "Host: localhost:2019"

Вы можете избежать необходимости в -H "Host: ...", используя порт 2019 с обеих сторон туннеля (но это требует, чтобы порт 2019 не был занят на вашем компьютере, т.е. Caddy не запускается локально).

Пока туннель активен, вы можете получить доступ ко всем функциям API администрирования. Для закрытия туннеля наберите Ctrl+C в командной строке ssh.

Длительный туннель

Запуск туннеля с помощью вышеуказанной команды требует, чтобы терминал оставался открытым. Если вы хотите запустить туннель в фоновом режиме, вы можете запустить туннель так:

ssh -f -N -M -S /tmp/caddy-tunnel.sock username@example.com -L 8123:localhost:2019

Это запустится в фоновом режиме и создаст сокет управления по адресу /tmp/caddy-tunnel.sock. Затем вы можете использовать сокет управления, чтобы закрыть туннель, когда закончите с ним:

ssh -S /tmp/caddy-tunnel.sock -O exit e

Удаленный API администрирования

Вы также можете настроить API администрирования для приёма удалённых подключений авторизованных клиентов.

(TODO: Написать статью об этом.)

Профили горутин

Дамп горутин полезен для того, чтобы знать, какие горутины существуют и каковы их стеки вызовов. Другими словами, он даёт нам представление о коде, который в данный момент выполняется или заблокирован/ожидает.

Если вы нажмёте "goroutines" или перейдёте по ссылке /debug/pprof/goroutine?debug=1, вы увидите список горутин и их стеки вызовов. Например:

goroutine profile: total 88
23 @ 0x43e50e 0x436d37 0x46bda5 0x4e1327 0x4e261a 0x4e2608 0x545a65 0x5590c5 0x6b2e9b 0x50ddb8 0x6b307e 0x6b0650 0x6b6918 0x6b6921 0x4b8570 0xb11a05 0xb119d4 0xb12145 0xb1d087 0x4719c1
#	0x46bda4	internal/poll.runtime_pollWait+0x84			runtime/netpoll.go:343
#	0x4e1326	internal/poll.(*pollDesc).wait+0x26			internal/poll/fd_poll_runtime.go:84
#	0x4e2619	internal/poll.(*pollDesc).waitRead+0x279		internal/poll/fd_poll_runtime.go:89
#	0x4e2607	internal/poll.(*FD).Read+0x267				internal/poll/fd_unix.go:164
#	0x545a64	net.(*netFD).Read+0x24					net/fd_posix.go:55
#	0x5590c4	net.(*conn).Read+0x44					net/net.go:179
#	0x6b2e9a	crypto/tls.(*atLeastReader).Read+0x3a			crypto/tls/conn.go:805
#	0x50ddb7	bytes.(*Buffer).ReadFrom+0x97				bytes/buffer.go:211
#	0x6b307d	crypto/tls.(*Conn).readFromUntil+0xdd			crypto/tls/conn.go:827
#	0x6b064f	crypto/tls.(*Conn).readRecordOrCCS+0x24f		crypto/tls/conn.go:625
#	0x6b6917	crypto/tls.(*Conn).readRecord+0x157			crypto/tls/conn.go:587
#	0x6b6920	crypto/tls.(*Conn).Read+0x160				crypto/tls/conn.go:1369
#	0x4b856f	io.ReadAtLeast+0x8f					io/io.go:335
#	0xb11a04	io.ReadFull+0x64					io/io.go:354
#	0xb119d3	golang.org/x/net/http2.readFrameHeader+0x33		golang.org/x/net@v0.14.0/http2/frame.go:237
#	0xb12144	golang.org/x/net/http2.(*Framer).ReadFrame+0x84		golang.org/x/net@v0.14.0/http2/frame.go:498
#	0xb1d086	golang.org/x/net/http2.(*serverConn).readFrames+0x86	golang.org/x/net@v0.14.0/http2/server.go:818

1 @ 0x43e50e 0x44e286 0xafeeb3 0xb0af86 0x5c29fc 0x5c3225 0xb0365b 0xb03650 0x15cb6af 0x43e09b 0x4719c1
#	0xafeeb2	github.com/caddyserver/caddy/v2/cmd.cmdRun+0xcd2					github.com/caddyserver/caddy/v2@v2.7.4/cmd/commandfuncs.go:277
#	0xb0af85	github.com/caddyserver/caddy/v2/cmd.init.1.func2.WrapCommandFuncForCobra.func1+0x25	github.com/caddyserver/caddy/v2@v2.7.4/cmd/cobra.go:126
#	0x5c29fb	github.com/spf13/cobra.(*Command).execute+0x87b						github.com/spf13/cobra@v1.7.0/command.go:940
#	0x5c3224	github.com/spf13/cobra.(*Command).ExecuteC+0x3a4					github.com/spf13/cobra@v1.7.0/command.go:1068
#	0xb0365a	github.com/spf13/cobra.(*Command).Execute+0x5a						github.com/spf13/cobra@v1.7.0/command.go:992
#	0xb0364f	github.com/caddyserver/caddy/v2/cmd.Main+0x4f						github.com/caddyserver/caddy/v2@v2.7.4/cmd/main.go:65
#	0x15cb6ae	main.main+0xe										caddy/main.go:11
#	0x43e09a	runtime.main+0x2ba									runtime/proc.go:267

1 @ 0x43e50e 0x44e9c5 0x8ec085 0x4719c1
#	0x8ec084	github.com/caddyserver/certmagic.(*Cache).maintainAssets+0x304	github.com/caddyserver/certmagic@v0.19.2/maintain.go:67

...

Первая строка, goroutine profile: total 88, указывает, что мы смотрим и сколько горутин существует.

Следующий список горутин. Они сгруппированы по их стекам вызовов в порядке убывания частоты.

Строка горутины имеет такой синтаксис: <count> @ <addresses...>

Строка начинается с количества горутин, имеющих соответствующий стек вызовов. Символ @ указывает начало адресов инструкций вызова, т.е. указателей на функции, которые породили горутину. Каждый указатель — это вызов функции или кадр вызова.

Вы можете заметить, что многие ваши горутины имеют одинаковый адрес первого вызова. Это основной метод вашей программы или точка входа. Некоторые горутины не начинаются там, потому что в программах есть различные init() функции, а среда выполнения Go также может запускать горутины.

Следующие строки, начинающиеся с #, на самом деле являются комментариями для удобства чтения. Они содержат текущую трассировку стека горутин. Верхняя часть представляет собой верх стека, т.е. текущую строку кода, выполняемую горутиной. Нижняя часть представляет собой низ стека или код, с которого горутина начала выполнение.

Трассировка стека имеет такой формат:

<address> <package/func>+<offset> <filename>:<line>

Адрес — это указатель на функцию, затем вы увидите имя пакета и функции Go (с соответствующим именем типа, если это метод) и смещение инструкции в пределах функции. Затем, возможно, самая полезная часть информации, номер файла и строки, находятся в конце.

Полный дамп стека горутин

Если мы изменим параметр строки запроса на ?debug=2, мы получим полный дамп. Он включает подробную трассировку стека каждой горутины, и идентичные горутины не сворачиваются. Этот вывод может быть очень большим на загруженных серверах, но это интересная информация!

Посмотрим на одну, которая соответствует первому стеку вызовов выше (усечённый):

goroutine 61961905 [IO wait, 1 minutes]:
internal/poll.runtime_pollWait(0x7f9a9a059eb0, 0x72)
	runtime/netpoll.go:343 +0x85
...
golang.org/x/net/http2.(*serverConn).readFrames(0xc001756f00)
	golang.org/x/net@v0.14.0/http2/server.go:818 +0x87
created by golang.org/x/net/http2.(*serverConn).serve in goroutine 61961902
	golang.org/x/net@v0.14.0/http2/server.go:930 +0x56a

Несмотря на свою подробность, наиболее полезная информация, уникально предоставляемая этим дампом, — это первые и последние строки для каждой горутины.

Первая строка содержит номер горутины (61961905), состояние ("IO wait") и продолжительность ("1 минуты"):

Номер горутины: Да, у горутин есть номера! Но они не отображаются в нашем коде. Тем не менее, эти номера особенно полезны в трассировке стека, поскольку мы можем видеть, какая горутина запустила данную (см. в конце: «создана ... в горутине 61961902»). Инструменты, показанные ниже, помогут нам создавать визуальные графики.
Состояние: Это показывает, чем сейчас занимается горутина. Вот некоторые возможные состояния:
- running: Выполнение кода — отлично!
- IO wait: Ожидание сети. Не потребляет системную нить, поскольку приостановлена на неблокирующем обработчике сети.
- sleep: Нам всех этого не хватает.
- select: Блокировка на select; ожидание, пока case станет доступным.
- select (no cases): Блокировка на пустом select select {} конкретно. Caddy использует один в своём основном процессе для поддержания работы, поскольку завершения инициируются другими горутинами.
- chan receive: Блокировка на приём из канала (<-ch).
- semacquire: Ожидание получения семафора (базовый примитив синхронизации).
- syscall: Выполнение системного вызова. Потребляет системную нить.
Продолжительность: Сколько времени существует горутина. Полезно для поиска ошибок, таких как утечки горутин. Например, если мы ожидаем, что все сетевые подключения будут закрыты через несколько минут, что значит, когда мы находим много горутин netconn, живущих часами?

Интерпретация дампов горутин

Что мы можем узнать о вышеупомянутой горутине, не глядя на код?

Она была создана примерно минуту назад, ожидает данных через сетевой сокет, и её номер горутины довольно большой (61961905).

Из первого дампа (debug=1) мы знаем, что её стек вызовов выполняется относительно часто, а большая численность горутины в сочетании с небольшой продолжительностью работы свидетельствует о десятках миллионов таких относительно недолгоживущих горутин. Она находится в функции pollWait, а её история вызовов включает чтение кадров HTTP/2 из зашифрованного сетевого подключения с использованием TLS.

Таким образом, мы можем заключить, что эта горутина обслуживает запрос HTTP/2! Она ожидает данных от клиента. Более того, мы знаем, что горутина, её запустившая, не является одной из первых горутин процесса, поскольку у неё также большой номер; нахождение этой горутины в дампе показывает, что она была запущена для обработки нового потока HTTP/2 во время существующего запроса. В отличие от других горутин с высокими номерами, которые могут быть запущены низкоуровневой горутиной (например, 32), что указывает на совершенно новое подключение сразу после вызова Accept() из сокета.

Каждый программый проект уникален, но при отладке Caddy эти закономерности, как правило, соблюдаются.

Профили памяти

Профили памяти (или кучи) отслеживают выделения в куче, которые являются основными потребителями памяти в системе. Выделения также часто являются источником проблем с производительностью, поскольку выделение памяти требует системных вызовов, которые могут быть медленными.

Профили кучи очень похожи на профили горутин практически во всех аспектах, за исключением начала первой строки. Вот пример:

0: 0 [1: 4096] @ 0xb1fc05 0xb1fc4d 0x48d8d1 0xb1fce6 0xb184c7 0xb1bc8e 0xb41653 0xb4105c 0xb4151d 0xb23b14 0x4719c1
#	0xb1fc04	bufio.NewWriterSize+0x24					bufio/bufio.go:599
#	0xb1fc4c	golang.org/x/net/http2.glob..func8+0x6c				golang.org/x/net@v0.17.0/http2/http2.go:263
#	0x48d8d0	sync.(*Pool).Get+0xb0						sync/pool.go:151
#	0xb1fce5	golang.org/x/net/http2.(*bufferedWriter).Write+0x45		golang.org/x/net@v0.17.0/http2/http2.go:276
#	0xb184c6	golang.org/x/net/http2.(*Framer).endWrite+0xc6			golang.org/x/net@v0.17.0/http2/frame.go:371
#	0xb1bc8d	golang.org/x/net/http2.(*Framer).WriteHeaders+0x48d		golang.org/x/net@v0.17.0/http2/frame.go:1131
#	0xb41652	golang.org/x/net/http2.(*writeResHeaders).writeHeaderBlock+0xd2	golang.org/x/net@v0.17.0/http2/write.go:239
#	0xb4105b	golang.org/x/net/http2.splitHeaderBlock+0xbb			golang.org/x/net@v0.17.0/http2/write.go:169
#	0xb4151c	golang.org/x/net/http2.(*writeResHeaders).writeFrame+0x1dc	golang.org/x/net@v0.17.0/http2/write.go:234
#	0xb23b13	golang.org/x/net/http2.(*serverConn).writeFrameAsync+0x73	golang.org/x/net@v0.17.0/http2/server.go:851

Формат первой строки следующий:

<live objects> <live memory> [<allocations>: <allocation memory>] @ <addresses...>

В приведенном выше примере одно выделение выполнено bufio.NewWriterSize(), но в данный момент нет активных объектов из этого стека вызовов.

Интересно, что мы можем заключить из этого стека вызовов, что пакет http2 использовал пул 4 КБ для записи кадра(ов) HTTP/2 клиенту. В профилях памяти Go часто встречаются пули объектов, если горячие пути оптимизированы для повторного использования выделений. Это уменьшает новые выделения, и профиль кучи может помочь вам узнать, используется ли пул должным образом!

Профили процессора

Профили процессора помогают понять, где программа Go тратит большую часть времени в графическом процессоре.

Однако для них нет текстовой формы, поэтому в следующем разделе мы будем использовать команды go tool pprof для их чтения.

Для загрузки профиля процессора отправьте запрос на /debug/pprof/profile?seconds=N, где N — количество секунд, в течение которых нужно собрать профиль. Во время сбора профиля процессора производительность программы может быть незначительно затронута. (Другие профили практически не влияют на производительность.)

По завершении, он должен загрузить двоичный файл с говорящим названием profile. Затем нам нужно его изучить.

`go tool pprof`

Мы будем использовать встроенный анализатор профилей Go, чтобы прочитать профиль процессора как пример, но вы можете использовать его с любым типом профиля.

Запустите эту команду (заменив «profile» на фактический путь к файлу, если он отличается), которая откроет интерактивную среду:

go tool pprof profile
File: caddy_master
Type: cpu
Time: Aug 29, 2022 at 8:47pm (MDT)
Duration: 30.02s, Total samples = 70.11s (233.55%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

Это то, что вы можете изучить. Ввод help предоставит вам список команд, а o покажет вам текущие варианты. И если вы напечатаете help <command>, вы получите информацию о конкретной команде.

Команд много, но некоторые распространённые:

top: Показать, что использовало больше всего процессорного времени. Можно добавить число, например top 20, чтобы увидеть больше, или регулярное выражение, чтобы «сосредоточиться» на определённых элементах или игнорировать их.
web: Открыть диаграмму вызовов в вашем веб-браузере. Это отличный способ визуально увидеть использование процессора.
svg: Сгенерировать SVG-изображение диаграммы вызовов. Это то же самое, что web, но не открывает ваш веб-браузер, а SVG сохраняется локально.
tree: Табличный вид стека вызовов.

Давайте начнём с top. Мы видим вывод, похожий на:

(pprof) top
Showing nodes accounting for 38.36s, 54.71% of 70.11s total
Dropped 785 nodes (cum <= 0.35s)
Showing top 10 nodes out of 196
      flat  flat%   sum%        cum   cum%
    10.97s 15.65% 15.65%     10.97s 15.65%  runtime/internal/syscall.Syscall6
     6.59s  9.40% 25.05%     36.65s 52.27%  runtime.gcDrain
     5.03s  7.17% 32.22%      5.34s  7.62%  runtime.(*lfstack).pop (inline)
     3.69s  5.26% 37.48%     11.02s 15.72%  runtime.scanobject
     2.42s  3.45% 40.94%      2.42s  3.45%  runtime.(*lfstack).push
     2.26s  3.22% 44.16%      2.30s  3.28%  runtime.pageIndexOf (inline)
     2.11s  3.01% 47.17%      2.56s  3.65%  runtime.findObject
     2.03s  2.90% 50.06%      2.03s  2.90%  runtime.markBits.isMarked (inline)
     1.69s  2.41% 52.47%      1.69s  2.41%  runtime.memclrNoHeapPointers
     1.57s  2.24% 54.71%      1.57s  2.24%  runtime.epollwait

Десять главных потребителей процессора были в среде выполнения Go — в частности, много сборки мусора (помните, что для освобождения и выделения памяти используются системные вызовы). Это подсказка, что мы можем уменьшить выделения, чтобы улучшить производительность, и будет полезно изучить профиль кучи.

Хорошо, но что если мы хотим увидеть использование процессора из нашего собственного кода? Мы можем игнорировать шаблоны, содержащие «runtime», следующим образом:

(pprof) top -runtime  
Active filters:
   ignore=runtime
Showing nodes accounting for 0.92s, 1.31% of 70.11s total
Dropped 160 nodes (cum <= 0.35s)
Showing top 10 nodes out of 243
      flat  flat%   sum%        cum   cum%
     0.17s  0.24%  0.24%      0.28s   0.4%  sync.(*Pool).getSlow
     0.11s  0.16%   0.4%      0.11s  0.16%  github.com/prometheus/client_golang/prometheus.(*histogram).observe (inline)
     0.10s  0.14%  0.54%      0.23s  0.33%  github.com/prometheus/client_golang/prometheus.(*MetricVec).hashLabels
     0.10s  0.14%  0.68%      0.12s  0.17%  net/textproto.CanonicalMIMEHeaderKey
     0.10s  0.14%  0.83%      0.10s  0.14%  sync.(*poolChain).popTail
     0.08s  0.11%  0.94%      0.26s  0.37%  github.com/prometheus/client_golang/prometheus.(*histogram).Observe
     0.07s   0.1%  1.04%      0.07s   0.1%  internal/poll.(*fdMutex).rwlock
     0.07s   0.1%  1.14%      0.10s  0.14%  path/filepath.Clean
     0.06s 0.086%  1.23%      0.06s 0.086%  context.value
     0.06s 0.086%  1.31%      0.06s 0.086%  go.uber.org/zap/buffer.(*Buffer).AppendByte

Теперь ясно, что метрики Prometheus являются ещё одним основным потребителем, но вы заметите, что в совокупности они составляют на порядки меньше, чем GC выше. Такое резкое различие предполагает, что мы должны сосредоточиться на уменьшении GC.

Важно отметить, что профили процессора получают измерения путём периодического отбора проб, и пробы никогда не будут захватываться чаще, чем частота отбора проб, которая по умолчанию составляет 10 мс. Вот почему вы не увидите никаких суммарных временных интервалов, меньших 10 мс (они, вероятно, меньше, но округлены вверх). Для более точных временных данных можно выполнить трассировку выполнения, которая не использует выборку. (TODO: Добавить раздел о трассировке.)

Давайте используем q, чтобы выйти из этого профиля, и применим ту же команду к профилю кучи:

(pprof) top
Showing nodes accounting for 22259.07kB, 81.30% of 27380.04kB total
Showing top 10 nodes out of 102
      flat  flat%   sum%        cum   cum%
   12300kB 44.92% 44.92%    12300kB 44.92%  runtime.allocm
 2570.01kB  9.39% 54.31%  2570.01kB  9.39%  bufio.NewReaderSize
 2048.81kB  7.48% 61.79%  2048.81kB  7.48%  runtime.malg
 1542.01kB  5.63% 67.42%  1542.01kB  5.63%  bufio.NewWriterSize
 ...

Вот он. Почти половина памяти выделена исключительно для буферов чтения и записи из-за нашего использования пакета bufio. Таким образом, мы можем заключить, что оптимизация нашего кода для уменьшения буферизации будет очень полезной. (В ассоциированном патче Caddy https://github.com/caddyserver/caddy/pull/4978 это и делается).

Визуализации

Если мы вместо этого запустим команды svg или web, мы получим визуализацию профиля:

Это профиль процессора, но похожие графики доступны и для других типов профилей.

Чтобы узнать, как читать эти графики, прочитайте документацию pprof.

Сравнение профилей

После внесения изменений в код вы можете сравнить до и после с помощью анализа различий («diff»). Вот сравнение профилей кучи:

go tool pprof -diff_base=before.prof after.prof
File: caddy
Type: inuse_space
Time: Aug 29, 2022 at 1:21am (MDT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for -26.97MB, 49.32% of 54.68MB total
Dropped 10 nodes (cum <= 0.27MB)
Showing top 10 nodes out of 137
      flat  flat%   sum%        cum   cum%
  -27.04MB 49.45% 49.45%   -27.04MB 49.45%  bufio.NewWriterSize
      -2MB  3.66% 53.11%       -2MB  3.66%  runtime.allocm
    1.06MB  1.93% 51.18%     1.06MB  1.93%  github.com/yuin/goldmark/util.init
    1.03MB  1.89% 49.29%     1.03MB  1.89%  github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.glob..func2
       1MB  1.84% 47.46%        1MB  1.84%  bufio.NewReaderSize
      -1MB  1.83% 49.29%       -1MB  1.83%  runtime.malg
       1MB  1.83% 47.46%        1MB  1.83%  github.com/caddyserver/caddy/v2/modules/caddyhttp/reverseproxy.cloneRequest
      -1MB  1.83% 49.29%       -1MB  1.83%  net/http.(*Server).newConn
   -0.55MB  1.00% 50.29%    -0.55MB  1.00%  html.populateMaps
    0.53MB  0.97% 49.32%     0.53MB  0.97%  github.com/alecthomas/chroma.TypeRemappingLexer

Как видите, мы сократили выделение памяти примерно вдвое!

Различия также можно визуализировать:

Это очень наглядно демонстрирует, как изменения повлияли на производительность определённых частей программы.

Дополнительные материалы

Профилирование программ — обширная тема, и мы только затронули её поверхность.

Чтобы по-настоящему овладеть «про» в «профилировании», обратите внимание на эти ресурсы:

© 2015-2025 Matthew Holt and The Caddy Authors
Licensed under the Apache License 2.0.
Caddy is a registered trademark of Stack Holdings GmbH.
https://caddyserver.com/docs/profiling