Хабрахабр

[Перевод] Профилирование кода Go-проекта и решение проблемы с выделением памяти

Пожалуй, каждому программисту известны слова Кента Бека: «Make it work, make it right, make it fast». Сначала надо сделать так, чтобы программа работала, дальше — надо заставить её работать правильно, а уже потом можно переходить к оптимизации. 

Он хотел найти в проекте код, который можно было бы без особых усилий оптимизировать и тем самым ускорить программу. Автор статьи, перевод которой мы публикуем, говорит, что недавно он решил заняться профилированием своего опенсорсного Go-проекта Flipt. В итоге удалось снизить объём памяти, выделяемой приложением в процессе работы, в 100 раз. В ходе профилирования он обнаружил некоторые неожиданные проблемы в популярном проекте с открытым исходным кодом, который в приложении Flipt использовался для организации маршрутизации и поддержки промежуточного ПО. Вот как это было.
Это, в свою очередь, привело к уменьшению количества операций по сборке мусора и улучшило общую производительность проекта.

Генерирование большого объёма трафика

Прежде чем я мог бы приступить к профилированию, я знал, что сначала мне нужно сгенерировать большой объём трафика, поступающего в приложение, что помогло бы мне увидеть некие шаблоны его поведения. Тут я сразу же столкнулся с проблемой, так как у меня нет ничего, что использовало бы Flipt в продакшне и получало бы некий объём трафика, позволяющий оценить работу проекта под нагрузкой. В результате я обнаружил отличный инструмент для нагрузочного тестирования проектов. Это — Vegeta. Авторы проекта говорят, что Vegeta — это универсальный HTTP-инструмент для нагрузочного тестирования. Этот проект родился из необходимости нагружать HTTP-сервисы большим количеством запросов, поступающих к сервисам с заданной частотой.

Этими запросами можно было «обстреливать» приложение столько, сколько нужно для того, чтобы выяснить такие показатели, как выделение/использование памяти в куче, особенности работы горутин, время, затраченное на сборку мусора. Проект Vegeta оказался именно тем инструментом, который был мне нужен, так как он позволял создать непрерывный поток запросов к приложению.

После проведения некоторых экспериментов я вышел на следующую конфигурацию запуска Vegeta:

echo 'POST http://localhost:8080/api/v1/evaluate' | vegeta attack -rate 1000 -duration 1m -body evaluate.json

Эта команда запускает Vegeta в режиме attack, отправляя HTTP POST-запросы REST API Flipt со скоростью 1000 запросов в секунду (а это, надо признать, серьёзная нагрузка) в течение минуты. JSON-данные, отправляемые Flipt, не особенно важны. Они нужны только для правильного формирования тела запроса. Такой запрос принимался Flipt-сервером, который мог выполнить процедуру проверки запроса.

Дело в том, что в ней выполняется большая часть кода, реализующего логику проекта и выполняющего «сложные» серверные вычисления. Обратите внимание на то, что сначала я решил подвергнуть испытанию конечную точку Flipt /evaluate. Я полагал, что анализ результатов работы этой конечной точки даст мне наиболее ценные данные о тех областях приложения, которые можно улучшить.

Измерения

Теперь, когда у меня появился инструмент для генерирования достаточно большого объёма трафика, мне нужно было найти способ измерения того воздействия, которое этот трафик оказывал на работающее приложение. К счастью, в Go имеется довольно хороший стандартный набор инструментов, которые позволяют измерять производительность программ. Речь идёт о пакете pprof.

Не думаю, что сделаю это лучше Джулии Эванс, которая написала эту замечательную статью о профилировании Go-программ с помощью pprof (если вы её не читали — я определённо рекомендую вам на неё взглянуть). Я не будут вдаваться в подробности использования pprof.

Так как HTTP-маршрутизатор во Flipt реализован с помощью go-chi/chi, мне было совсем несложно включить pprof, воспользовавшись соответствующим промежуточным обработчиком Chi.

Я запустил третье окно терминала для того, чтобы собрать и исследовать данные профилирования кучи: Итак, в одном окне у меня работал Flipt, а Vegeta, заваливая Flipt запросами, работала в другом окне.

pprof -http=localhost:9090 localhost:8080/debug/pprof/heap

Тут используется инструмент Google pprof, который может визуализировать данные профилирования прямо в браузере.

Однако ничего примечательного мне обнаружить не удалось. Сначала я проверил показатели inuse_objects и inuse_space для того, чтобы понять, что происходит в куче. Но когда я решил взглянуть на показатели alloc_objects и alloc_space, кое-что меня насторожило.

Анализ результатов профилирования (оригинал)

NewWriter, выделило в течение минуты 19370 Мб памяти. Возникало такое ощущение, что нечто, называемое flate. Тут, явно, происходило что-то странное. А это, кстати более 19 гигабайт! Если всмотреться в оригинал вышеприведённой схемы, то окажется, что flate. Но что именно? Write, вызываемом, в свою очередь, из middleware.(*compressResponseWriter). NewWriter вызывается из кода gzip.(*Writer). Я быстро понял, что происходящее не имеет ничего общего с кодом Flipt. Write. Проблема находилась где-то в коде промежуточного обработчика Chi, используемого для сжатия ответов от API.

// проблемная строка
r.Use(middleware.Compress(gzip.DefaultCompression))

Я закомментировал вышеприведённую строку и снова запустил тесты. Как и следовало ожидать, огромное количество операций по выделению памяти исчезло.

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

Я предположил, что это так из-за того, что на моём компьютере было установлено слишком низкое значение ulimit, но мне тогда не хотелось в это углубляться. Для эффективного сбора сведений о работающей программе мне нужно было сократить число запросов в секунду, отправляемых приложению с помощью Vegeta, так как сервер регулярно выдавал мне ошибки socket: too many open files.

Итак, я перезапустил Vegeta такой командой:

echo 'POST http://localhost:8080/api/v1/evaluate' | vegeta attack -rate 100 -duration 2m -body evaluate.json

В результате, если сравнить это с предыдущим сценарием, на сервер поступала только десятая часть запросов, но делалось это в течение более длительного периода времени. Это позволило мне собрать качественные данные о работе программы.

В ещё одном окне терминала я запустил такую команду:

wget 'http://localhost:8080/debug/pprof/trace?seconds=60' -O profile/trace

В результате в моём распоряжении оказался файл с трассировочными данными, собранными за 60 секунд. Исследовать этот файл можно было с помощью такой команды:

go tool trace profile/trace

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

Подробности о go tool trace можно почитать в этом хорошем материале.

Результаты трассировки Flipt. Отчётливо виден пилообразный график выделения памяти в куче (оригинал)

При этом после роста следует резкое падение. На этом графике несложно заметить то, что объём памяти, выделяемой в куче, имеет тенденцию к довольно быстрому росту. Тут можно заметить и ярко выраженные синие столбцы в области GC, представляющие время, затраченное на сборку мусора. Места падения объёма выделенной памяти — это операции по сборке мусора.

Теперь я собрал все необходимые мне улики «преступления» и мог приступать к поиску решения проблемы с выделением памяти.

Решение проблемы

Для того чтобы выяснить причину, по которой вызов flate.NewWriter приводил к столь большому количеству операций по выделению памяти, мне нужно было взглянуть на исходный код Chi. Для того чтобы узнать о том, какую версию Chi я использую, я выполнил следующую команду:

go list -m all | grep chi
github.com/go-chi/chi v3.3.4+incompatible

Добравшись до исходного кода chi/middleware/compress.go @v3.3.4, я смог найти следующий метод:

func encoderDeflate(w http.ResponseWriter, level int) io.Writer return dw
}

В ходе дальнейших исследований я выяснил, что метод flate.NewWriter, через промежуточный обработчик, вызывался для каждого ответа. Это соответствовало огромному количеству операций по выделению памяти, которые я видел ранее, нагружая API тысячей запросов в секунду.

Поэтому я, в первую очередь, решил выяснить, можно ли справиться с моей проблемой, просто обновив Chi. Мне не хотелось ни отказываться от сжатия ответов API, ни искать новый HTTP-маршрутизатор и новую библиотеку поддержки промежуточного ПО.

0. Я выполнил команду go get -u -v "github.com/go-chi/chi", обновился до версии Chi 4. Когда я снова запустил тесты, проблема никуда не делась. 2, но код промежуточного обработчика для сжатия данных выглядел, как мне показалось, таким же, как раньше.

Мне попался один PR со следующим заголовком: «Re-wrote the middleware compression library» (Переписывание промежуточной библиотеки сжатия). Прежде чем поставить точку в этом вопросе, я решил поискать в репозитории Chi сообщения о проблемах или PR, в которых упоминалось бы нечто вроде «compression middleware». Pool для кодировщиков, который имеет метод Reset(io. Автор этого PR говорил следующее: «Кроме того, тут используется sync. Writer), позволяющий снизить нагрузку на память».

К моему счастью, что этот PR был добавлен в ветку master, но, так как не было создано нового релиза Chi, мне нужно было обновляться так: Вот оно!

go get -u -v "github.com/go-chi/chi@master"

Обновление это, что очень меня порадовало, было обратно совместимым, его использование не потребовало изменений в коде моего приложения.

Результаты

Я запустил нагрузочные тесты и профилирование ещё раз. Это позволило мне убедиться в том, что обновление Chi решило проблему.

Теперь flate.NewWriter использует сотую часть от ранее использованного объёма выделяемой памяти (оригинал)

Кроме того, уменьшилось и время, необходимое на сборку мусора. Взглянув ещё раз на результаты трассировки, я увидел, что размер кучи растёт теперь гораздо медленнее.

Прощай — «пила» (оригинал)

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

Итоги

Вот какие выводы я сделал после того, как мне удалось найти и устранить вышеописанные проблемы:

  1. Не стоит полагаться на предположения о том, что опенсорсные библиотеки (даже популярные) были оптимизированы, или о том, что в них нет очевидных проблем.
  2. Невинная проблема способна привести к серьёзным последствиям, к проявлениям «эффекта домино», особенно — под большой нагрузкой.
  3. Если есть возможность — стоит пользоваться sync.Pool.
  4. Полезно держать под рукой средства для тестирования проектов под нагрузкой и для их профилирования.
  5. Инструментарий Go и опенсорс — это замечательно!

Уважаемые читатели! Как вы исследуете производительность своих Go-проектов?

Теги
Показать больше

Похожие статьи

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *

Кнопка «Наверх»
Закрыть