Команда Go for Devs подготовила перевод статьи о том, как оптимизация аллокаций в Go может снизить нагрузку на сборщик мусора и ускорить приложение почти в два раза. Автор показывает на примере реального веб-приложения, как профилировать кучу, находить «горячие» места и убирать лишние аллокации, чтобы снизить задержки и повысить пропускную способность.

Впервые опубликованная в 2019 году, эта статья — вторая из трёх в серии, посвящённой сборщику мусора в Go. Хотя рантайм Go с тех пор продолжает развиваться, принципы производительности, описанные здесь, остаются актуальными и сегодня. В этом материале мы сосредоточимся на практических приёмах анализа и снижения накладных расходов на сборку мусора (GC) в реальных Go-приложениях. Мы разберём, как интерпретировать GC-трейсы с помощью GODEBUG=gctrace=1 и как находить места интенсивных аллокаций с помощью pprof, с ключевым посылом: сокращение лишних аллокаций, особенно в тесных циклах, напрямую и заметно снижает задержки и повышает пропускную способность. Независимо от того, оптимизируете ли вы высоконагруженные сервисы или просто начинаете разбираться в работе GC, приведённые здесь идеи актуальны как никогда.

Вступление

Это второй материал из серии из трёх статей, цель которой — помочь вам понять механику и семантику работы сборщика мусора в Go. Здесь мы разберём, как генерировать GC-трейсы и как их интерпретировать.

Содержание серии:

Сборщик мусора в Go. Часть 1: Stop The World, пейсинг и оптимизация

Введение

В первой статье я подробно описал поведение сборщика мусора и показал задержки, которые он добавляет в работу приложения. Я рассказал, как сгенерировать и интерпретировать GC-трейсы, показал, как меняется память в куче, и объяснил различные фазы работы GC и то, как они влияют на задержки.

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

В этом материале я проведу вас через запуск настоящего веб-приложения, покажу, как сгенерировать GC-трейсы и профили приложения. Затем мы разберём, как интерпретировать вывод этих инструментов, чтобы вы могли находить точки роста производительности своих приложений.

Запуск приложения

Посмотрите на это веб-приложение, которое я использую на тренингах по Go.

На рисунке 1 показан интерфейс приложения. Оно загружает три набора RSS-лент от разных новостных провайдеров и позволяет пользователю выполнять поиск по ним. После сборки веб-приложение запускается.

Листинг 1

$ go build
$ GOGC=off ./project > /dev/null

В листинге 1 показано, как запустить приложение с переменной GOGC, установленной в off, что полностью отключает сборку мусора. Логи перенаправляются в устройство /dev/null. После запуска приложения можно отправлять запросы на сервер.

Листинг 2

$ hey -m POST -c 100 -n 10000 "http://localhost:5000/search?term=topic&cnn=on&bbc=on&nyt=on"

В листинге 2 показано, как с помощью утилиты hey выполнить 10 000 запросов через сервер, используя 100 одновременных соединений. После завершения всех запросов получается следующий результат.

На рисунке 2 представлена визуализация обработки 10 000 запросов при выключенном сборщике мусора. На выполнение всех запросов ушло 4 188 мс, что соответствует ~2 387 обработанным запросам в секунду.

Включение сборки мусора

Что произойдет, если включить сборку мусора для этого приложения?

Листинг 3

$ GODEBUG=gctrace=1 ./project > /dev/null

В листинге 3 показано, как запустить приложение с включённой генерацией GC-трейсов. Переменная GOGCудалена и заменена на GODEBUG. Значение GODEBUG настроено так, чтобы рантайм выводил GC-трейс каждый раз, когда выполняется сборка мусора. Теперь можно снова прогнать те же 10 000 запросов через сервер. После их выполнения мы получим GC-трейсы и информацию от утилиты hey, которые можно проанализировать.

Листинг 4

$ GODEBUG=gctrace=1 ./project > /dev/null
gc 3 @3.182s 0%: 0.015+0.59+0.096 ms clock, 0.19+0.10/1.3/3.0+1.1 ms cpu, 4->4->2 MB, 5 MB goal, 12 P
.
.
.
gc 2553 @8.452s 14%: 0.004+0.33+0.051 ms clock, 0.056+0.12/0.56/0.94+0.61 ms cpu, 4->4->2 MB, 5 MB goal, 12 P

В листинге 4 показан GC-трейс третьей и последней сборки мусора во время теста. Первые две не показаны, так как нагрузка на сервер была отправлена уже после их выполнения. Последняя строка говорит, что для обработки 10 000 запросов понадобилось 2551 сборка мусора (отняв первые две, которые не считаются).

Давайте разберём каждую часть трейса.

Листинг 5

gc 2553 @8.452s 14%: 0.004+0.33+0.051 ms clock, 0.056+0.12/0.56/0.94+0.61 ms cpu, 4->4->2 MB, 5 MB goal, 12 P

gc 2553     : The 2553 GC runs since the program started
@8.452s     : Eight seconds since the program started
14%         : Fourteen percent of the available CPU so far has been spent in GC

// wall-clock
0.004ms     : STW        : Write-Barrier - Wait for all Ps to reach a GC safe-point.
0.33ms      : Concurrent : Marking
0.051ms     : STW        : Mark Term     - Write Barrier off and clean up.

// CPU time
0.056ms     : STW        : Write-Barrier
0.12ms      : Concurrent : Mark - Assist Time (GC performed in line with allocation)
0.56ms      : Concurrent : Mark - Background GC time
0.94ms      : Concurrent : Mark - Idle GC time
0.61ms      : STW        : Mark Term

4MB         : Heap memory in-use before the Marking started
4MB         : Heap memory in-use after the Marking finished
2MB         : Heap memory marked as live after the Marking finished
5MB         : Collection goal for heap memory in-use after Marking finished

// Threads
12P         : Number of logical processors or threads used to run Goroutines.

В листинге 5 показаны реальные цифры из последней сборки мусора. Благодаря данным от hey можно свести результаты выполнения теста в таблицу.

Листинг 6

Requests            : 10,000
------------------------------------------------------
Requests/sec        : 1,882 r/s   - Hey
Total Duration      : 5,311ms     - Hey
Percent Time in GC  : 14%         - GC Trace
Total Collections   : 2,551       - GC Trace
------------------------------------------------------
Total GC Duration   : 744.54ms    - (5,311ms * .14)
Average Pace of GC  : ~2.08ms     - (5,311ms / 2,551)
Requests/Collection : ~3.98 r/gc  - (10,000 / 2,511)

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

Рисунок 3 наглядно показывает, что произошло. Когда сборщик включён, ему пришлось отработать примерно 2,5 тысячи раз, чтобы обработать те же 10 тысяч запросов. В среднем каждая сборка запускается с интервалом около 2,0 мс, а суммарное выполнение всех этих сборок добавило примерно 1,1 секунды задержки.

Рисунок 4 показывает сравнение двух прогонов приложения на текущем этапе.

Сокращаем аллокации

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

Листинг 7

go tool pprof http://localhost:5000/debug/pprof/allocs

В листинге 7 показано, как с помощью инструмента pprof обратиться к эндпоинту /debug/pprof/allocs, чтобы получить профиль памяти работающего приложения. Этот эндпоинт доступен благодаря следующему коду.

Листинг 8

import _ "net/http/pprof"

go func() {
    http.ListenAndServe("localhost:5000", http.DefaultServeMux)
}()

В листинге 8 показано, как «привязать» эндпоинт /debug/pprof/allocs к любому приложению. Импорт net/http/pprofподключает эндпоинты к умолчальному mux веб-сервера. Затем вызов http.ListenAndServe с http.DefaultServerMux делает этот эндпоинт доступным.

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

Листинг 9

(pprof) top 6 -cum
Showing nodes accounting for 0.56GB, 5.84% of 9.56GB total
Dropped 80 nodes (cum <= 0.05GB)
Showing top 6 nodes out of 51
      flat  flat%   sum%        cum   cum%
         0     0%     0%     4.96GB 51.90%  net/http.(*conn).serve
    0.49GB  5.11%  5.11%     4.93GB 51.55%  project/service.handler
         0     0%  5.11%     4.93GB 51.55%  net/http.(*ServeMux).ServeHTTP
         0     0%  5.11%     4.93GB 51.55%  net/http.HandlerFunc.ServeHTTP
         0     0%  5.11%     4.93GB 51.55%  net/http.serverHandler.ServeHTTP
    0.07GB  0.73%  5.84%     4.55GB 47.63%  project/search.rssSearch

Листинг 9 показывает, что внизу списка фигурирует функция rssSearch. Эта функция на текущий момент выделила 4,55 ГБ из 5,96 ГБ. Далее имеет смысл детально изучить rssSearch с помощью команды list.

Листинг 10

(pprof) list rssSearch
Total: 9.56GB
ROUTINE ======================== project/search.rssSearch in project/search/rss.go
   71.53MB     4.55GB (flat, cum) 47.63% of Total


         .          .    117:	// Capture the data we need for our results if we find ...
         .          .    118:	for _, item := range d.Channel.Items {
         .     4.48GB    119:		if strings.Contains(strings.ToLower(item.Description), strings.ToLower(term)) {
   48.53MB    48.53MB    120:			results = append(results, Result{
         .          .    121:				Engine:  engine,
         .          .    122:				Title:   item.Title,
         .          .    123:				Link:    item.Link,
         .          .    124:				Content: item.Description,
         .          .    125:			})

Листинг 10 показывает листинг и код. Строка 119 заметно выделяется как источник основной массы аллокаций.

Листинг 11

        .     4.48GB    119:		if strings.Contains(strings.ToLower(item.Description), strings.ToLower(term)) {

В листинге 11 показана проблемная строка. Одна эта строка даёт 4,48 ГБ из 4,55 ГБ памяти, которые на данный момент выделила функция. Далее стоит пересмотреть эту строку и понять, что можно сделать.

Листинг 12

117 // Capture the data we need for our results if we find the search term.
118 for _, item := range d.Channel.Items {
119     if strings.Contains(strings.ToLower(item.Description), strings.ToLower(term)) {
120         results = append(results, Result{
121             Engine:  engine,
122             Title:   item.Title,
123             Link:    item.Link,
124             Content: item.Description,
125        })
126    }
127 }

Листинг 12 показывает, что эта строка находится внутри плотного цикла. Вызовы strings.ToLower приводят к аллокациям, потому что создают новые строки, которые выделяются в куче. Эти вызовы лишние, их можно выполнить вне цикла.

Строку 119 можно изменить, чтобы избавиться от всех этих аллокаций.

Листинг 13

// Before the code change.
if strings.Contains(strings.ToLower(item.Description), strings.ToLower(term)) {

// After the code change.
if strings.Contains(item.Description, term) {

Примечание: Другие изменения, которые здесь не показаны, — это приведение Description к нижнему регистру перед тем, как лента попадает в кэш. Новостные ленты кэшируются каждые 15 минут. Приведение поискового запроса term к нижнему регистру выполняется сразу перед циклом.

В листинге 13 показано, как вызовы strings.ToLower были убраны. Проект заново собирается с этими изменениями, и те же 10 тысяч запросов снова прогоняются через сервер.

Листинг 14

$ go build
$ GODEBUG=gctrace=1 ./project > /dev/null
gc 3 @6.156s 0%: 0.011+0.72+0.068 ms clock, 0.13+0.21/1.5/3.2+0.82 ms cpu, 4->4->2 MB, 5 MB goal, 12 P
.
.
.
gc 1404 @8.808s 7%: 0.005+0.54+0.059 ms clock, 0.060+0.47/0.79/0.25+0.71 ms cpu, 4->5->2 MB, 5 MB goal, 12 P

Листинг 14 показывает, что после этого изменения кода на обработку тех же 10 тысяч запросов потребовалось 1402 сборки мусора. Ниже — сводные результаты обоих прогонов.

Листинг 15

With Extra Allocations              Without Extra Allocations
======================================================================
Requests            : 10,000        Requests            : 10,000
----------------------------------------------------------------------
Requests/sec        : 1,882 r/s     Requests/sec        : 3,631 r/s
Total Duration      : 5,311ms       Total Duration      : 2,753 ms
Percent Time in GC  : 14%           Percent Time in GC  : 7%
Total Collections   : 2,551         Total Collections   : 1,402
----------------------------------------------------------------------
Total GC Duration   : 744.54ms      Total GC Duration   : 192.71 ms
Average Pace of GC  : ~2.08ms       Average Pace of GC  : ~1.96ms
Requests/Collection : ~3.98 r/gc    Requests/Collection : 7.13 r/gc

Листинг 15 показывает результаты по сравнению с предыдущим прогоном. Далее будет наглядная визуализация того, что произошло.

Рисунок 5 наглядно показывает, что произошло. На этот раз сборщик мусора сработал на 1149 раз меньше (1 402 против 2 551), чтобы обработать те же 10 000 запросов. В результате процент времени, затраченного на GC, снизился с 14 % до 7 %. Это позволило приложению работать на 48 % быстрее при 74 % меньшем времени, затраченном на сборку мусора.

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

Чему мы научились

Как я писал в предыдущей статье, быть «доброжелательным» к сборщику мусора — значит снижать нагрузку на кучу. Напомню, что нагрузка — это скорость, с которой приложение аллоцирует всю доступную память кучи за определённое время. Если нагрузка снижается, то уменьшаются и задержки, которые добавляет сборщик. Именно эти задержки и тормозят ваше приложение.

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

Листинг 16

With Extra Allocations              Without Extra Allocations
======================================================================
Requests            : 10,000        Requests            : 10,000
----------------------------------------------------------------------
Requests/sec        : 1,882 r/s     Requests/sec        : 3,631 r/s
Total Duration      : 5,311ms       Total Duration      : 2,753 ms
Percent Time in GC  : 14%           Percent Time in GC  : 7%
Total Collections   : 2,551         Total Collections   : 1,402
----------------------------------------------------------------------
Total GC Duration   : 744.54ms      Total GC Duration   : 192.71 ms
Average Pace of GC  : ~2.08ms       Average Pace of GC  : ~1.96ms
Requests/Collection : ~3.98 r/gc    Requests/Collection : 7.13 r/gc

Листинг 16 показывает результаты двух версий приложения при включённой сборке мусора. Очевидно, что удаление 4,48 ГБ лишних аллокаций сделало приложение быстрее. Интересно, что средний темп каждой сборки (в обеих версиях) практически не изменился и остаётся около 2,0 мс. Фундаментальное различие между версиями — объём работы, выполняемой между сборками. Приложение перешло от 3,98 r/gc к 7,13 r/gc — это рост на 79,1 % по количеству работы между сборками.

Выполнение большего объёма работы между началом двух сборок помогло сократить их количество с 2 551 до 1 402 — снижение на 45 %. Время, проведённое в GC, уменьшилось на 74 %: с 745 мс до 193 мс, а доля времени в сборке упала с 14 % до 7 %. Если запустить оптимизированную версию приложения с полностью отключённой сборкой мусора, разница в производительности составит всего 13 % (2 753 мс против 2 398 мс).

Русскоязычное Go сообщество

Друзья! Эту статью перевела команда «Go for Devs» — сообщества, где мы делимся практическими кейсами, инструментами для разработчиков и свежими новостями из мира Go. Подписывайтесь, чтобы быть в курсе и ничего не упустить!

Заключение

Если вы уделяете время сокращению аллокаций, то делаете всё возможное как Go-разработчик, чтобы облегчить работу сборщику мусора. Написать приложение без единой аллокации не получится, поэтому важно отличать полезные аллокации (которые помогают приложению) от бесполезных (которые только вредят). После этого остаётся довериться сборщику мусора, который поддержит кучу в здоровом состоянии и обеспечит стабильную работу приложения.

Наличие сборщика мусора — это выгодный компромисс. Я готов заплатить за сборку мусора, чтобы не заниматься ручным управлением памятью. Go создан для того, чтобы разработчик оставался продуктивным и при этом писал достаточно быстрые приложения. Сборщик мусора — ключевой элемент, который делает это возможным. В следующем материале я покажу другую программу, которая демонстрирует, насколько эффективно сборщик анализирует ваши Go-приложения и находит оптимальный сценарий сборок.

Сборщик мусора в Go. Часть 2: GC Traces