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

23.04.2020 профилирование pprof бенчмарк ab процессор аллокации удаленно

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

GO изначально предоставлял разработчику богатые средства для профилирования программ — пакет pprof и одноименную консольную утилиту go tool pprof. Давайте разберемся, зачем нужно профилирование, как его использовать и что нового по этой теме в GO.

Для чего нужно профилировать код

При отладке с дебаггером можно найти важные, но простые баги — ошибки в логике, неверные операции с переменными.

Программа может работать правильно, но иметь различные побочные эффекты:

  • длительная работа различных частей программы;
  • высокое потребление памяти;
  • высокое потребление ресурсов процессора;

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

В любой момент при росте нагрузки различные "больные места" сервиса могут стать причиной его падения — памяти сервиса перестанет хватать и программа начнет падать; потребление процессора станет настолько серьезным, что сервер перестанет отвечать даже на подключения по ssh, и вы уже не сможете за короткие сроки привести сервис в нормальное состояние.

Определить неоптимальности подобного уровня и позволяет профайлер.

Какие есть средства профилирования

Стандартный профилировщик GO — pprof, представляет исчерпывающий функционал. Далее будем использовать pprof.

Как работать с профилировщиком

Работа с профилировщиком состоит из двух этапов:

  • 1. собрать статистику по работе сервиса;
  • 2. визуализировать и проанализировать ее;

Для сбора статистики нужно:

  • собрать метрики, вручную добавив вызовы пакета pprof в код, либо:
  • запустить http-сервер из пакета net/http/pprof, который позволит нам затем собрать любую статистику через запросы;

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

Для запуска http-сервера из пакета net/http/pprof, необходимо:

  • добавить импорт import _ "net/http/pprof" в ваш код;
  • если у вас уже запускается http-сервер из стандартной библиотеки GO (net/http), ничего более не надо;
  • если стандартный http-сервер не запускается, необходимо добавить его запуск:
go func() {
	log.Println(http.ListenAndServe("localhost:6060", nil))
}()

Если посмотреть в исходники net/http/pprof, то становится ясно, что именно делает его импортирование:

func init() {
	http.HandleFunc("/debug/pprof/", Index)
	http.HandleFunc("/debug/pprof/cmdline", Cmdline)
	http.HandleFunc("/debug/pprof/profile", Profile)
	http.HandleFunc("/debug/pprof/symbol", Symbol)
	http.HandleFunc("/debug/pprof/trace", Trace)
}

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

Я буду профилировать веб-сервис, запустив его на localhost:8090.

Я импортировал net/http/pprof и добавил запуск net/http-сервера.

Получение данных профайлинга

Поскольку профилируется именно веб-сервис, то какая-либо деятельность в нем начинается при получении http-запросов.
Поэтому перед профилированием я создаю нагрузку на сервисе с помощью утилиты apache benchmark (ab):

ab -n 1000 -c10 http://localhost:8090/

ab выведет статистику по времени запросов, но на данном этапе нам интересны только данные профайлинга GO.

Пока сервис нагружен, запускаем сбор данных профайлинга CPU, указав кол-во секунд, в течение которых мы профилируем:

curl http://localhost:6060/debug/profile/?seconds=5 > ./profile

Мы скачали файл profile. На этом сбор статистики закончен. Теперь приступим к ее анализу.

Анализ профиля CPU

Откроем скачанный профиль с помощью консольной утилиты go tool pprof:

tool pprof ./profile 
Type: cpu
Time: Apr 19, 2020 at 9:28pm (+03)
Duration: 5.40s, Total samples = 400ms ( 7.41%)
Entering interactive mode (type "help" for commands, "o" for options)

Мы можем сразу вывести графическую информацию с помощью следующей команды:

(pprof) web

Данная опция потребует установки утилиты graphviz.

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

На рисунке видим, что наибольшее время потрачено на вызовы шаблонизатора html/template, что сразу вовлекает нас в исходники GO.
В этом особенность работы с профайлером — он не различает пользовательские функции и исходный код GO.

Вернемся в консоль pprof и посмотрим топ 15 функций по времени выполнения:

(pprof) top15
Showing nodes accounting for 0, 0% of 400ms total
Showing top 15 nodes out of 147
flat  flat%   sum%        cum   cum%
 0     0%     0%      260ms 65.00%  net/http.(*conn).serve
 0     0%     0%      240ms 60.00%  github.com/labstack/echo.(*Echo).ServeHTTP
 0     0%     0%      240ms 60.00%  github.com/labstack/echo.(*Echo).ServeHTTP.func1
 0     0%     0%      240ms 60.00%  github.com/labstack/echo.(*Echo).add.func1
 0     0%     0%      240ms 60.00%  github.com/labstack/echo.(*context).Render
 0     0%     0%      240ms 60.00%  github.com/labstack/echo/middleware.AddTrailingSlashWithConfig.func1.1
 0     0%     0%      240ms 60.00%  github.com/labstack/echo/middleware.CORSWithConfig.func1.1
 0     0%     0%      240ms 60.00%  net/http.serverHandler.ServeHTTP
 0     0%     0%      220ms 55.00%  html/template.(*Template).Execute
 0     0%     0%      220ms 55.00%  text/template.(*Template).Execute
 0     0%     0%      220ms 55.00%  text/template.(*Template).execute
 0     0%     0%      220ms 55.00%  text/template.(*state).walk
 0     0%     0%      220ms 55.00%  text/template.(*state).walkTemplate

Видим, что в топе у нас находятся функции echo и рендер шаблона.

Мы можем посмотреть исходный код функции и в нем будут показано время на отдельные вызовы.
Сделаем это с помощью команды list и регуляного выражения, похожего на имя интересующей функции (его можно скопировать из таблицы выше): 

(pprof) list text/template.\(\*state\).walk$
Total: 400ms
ROUTINE ======================== text/template.(*state).walk in /usr/local/Cellar/go/1.14/libexec/src/text/template/exec.go
         0      830ms (flat, cum) 207.50% of Total
         .          .    250:	s.at(node)
         .          .    251:	switch node := node.(type) {
         .          .    252:	case *parse.ActionNode:
         .          .    253:		// Do not pop variables so they persist until next end.
         .          .    254:		// Also, if the action declares variables, don't print the result.
         .      160ms    255:		val := s.evalPipeline(dot, node.Pipe)
         .          .    256:		if len(node.Pipe.Decl) == 0 {
         .       20ms    257:			s.printValue(node, val)
         .          .    258:		}
         .          .    259:	case *parse.IfNode:
         .       40ms    260:		s.walkIfOrWith(parse.NodeIf, dot, node.Pipe, node.List, node.ElseList)
         .          .    261:	case *parse.ListNode:
         .          .    262:		for _, node := range node.Nodes {
         .      220ms    263:			s.walk(dot, node)
         .          .    264:		}
         .          .    265:	case *parse.RangeNode:
         .      170ms    266:		s.walkRange(dot, node)
         .          .    267:	case *parse.TemplateNode:
         .      220ms    268:		s.walkTemplate(dot, node)
         .          .    269:	case *parse.TextNode:
         .          .    270:		if _, err := s.wr.Write(node.Text); err != nil {
         .          .    271:			s.writeError(err)
         .          .    272:		}
         .          .    273:	case *parse.WithNode:

Делаем выводы:

  • используется рекурсия (263 строка);
  • используется пакет reflect, работа с которым считается длительной;

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

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

Повторяю тест и замеры и получаю следующую картину:

(pprof) top15
Showing nodes accounting for 90ms, 50.00% of 180ms total
Showing top 15 nodes out of 78
  flat  flat%   sum%        cum   cum%
	 0     0%     0%      100ms 55.56%  net/http.(*conn).serve
  90ms 50.00% 50.00%       90ms 50.00%  syscall.syscall
	 0     0% 50.00%       60ms 33.33%  bufio.(*Writer).Flush
	 0     0% 50.00%       60ms 33.33%  internal/poll.(*FD).Write
	 0     0% 50.00%       60ms 33.33%  net.(*conn).Write
	 0     0% 50.00%       60ms 33.33%  net.(*netFD).Write
	 0     0% 50.00%       60ms 33.33%  net/http.(*response).finishRequest
	 0     0% 50.00%       60ms 33.33%  net/http.checkConnErrorWriter.Write
	 0     0% 50.00%       60ms 33.33%  syscall.Write
	 0     0% 50.00%       60ms 33.33%  syscall.write
	 0     0% 50.00%       40ms 22.22%  runtime.findrunnable
	 0     0% 50.00%       40ms 22.22%  runtime.mcall
	 0     0% 50.00%       40ms 22.22%  runtime.schedule
	 0     0% 50.00%       30ms 16.67%  github.com/labstack/echo.(*Echo).Start

Мы видим то, что в топе теперь находятся системные вызовы Write. И использование шаблонизатора вовсе не фигурирует.

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

Теперь взглянем в вывод ab, на параметр Requests per second:
Было: Requests per second: 14.13 [#/sec] (mean)
Стало: Requests per second: 638.38 [#/sec] (mean)

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

Заключение

Мы можем открыть в браузере адрес net/http/prof — тот, который мы подключили для сбора статистики. На странице мы увидим ссылки для просмотра или скачивания профилей по различным метрикам:

/debug/pprof/

Types of profiles available:
Count	Profile
9	allocs
0	block
0	cmdline
9	goroutine
9	heap
0	mutex
0	profile
18	threadcreate
0	trace

Мы можем получать данные профайлинга по следующим метрикам:

  • аллокациях и потреблении памяти каждым вызовом функции;
  • вызовах sync.Mutex;
  • созданиях тредов;
и многом другом.

Наиболее полезными являются рассмотренный CPU profile, а также память.

Удаленное профилирование

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

// слушаем на всех сетевых интерфейсах
log.Println(http.ListenAndServe(":6060", nil))

Но необходимо быть внимательным, чтобы посторонние не имели доступа к этому адресу!

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

Что нового в профилировании

Механизм сбора статистики cобирает все необходимые данные и вряд ли нуждается в улучшении.

Улучшить здесь мы можем разве что информативность вывода для лучшего анализа. Из полезных для себя могу выделить flamegraph view.

В Goland IDE есть возможности для отображения данных профайлинга в различных видах.
Однако pprof предоставляет не только визуальные возможности, но и консольные — различные сортировки и фильтры полученных данных. В своем примере я почти обошел консольные возможности, но в статье в блоге GO они используются.

Другие статьи