Создание кастомных Go-профилей с помощью pprof. Запоминаем стеки

Кадр из сериала «Коломбо»

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

Профили

Из документации по pprof ^[1]:

Профиль – это набор стек-трейсов, показывающий порядок вызовов, которые привели к какому-либо событию. Например, выделению памяти. Пакеты могут создавать и поддерживать свои собственные профили. Самая распространенная причина – слежение за какими-либо ресурсами, которые требуют явного закрытия: файлами, сетевыми соединениями.

Другим потенциальным применением профилей может быть слежение не за чем-то, что нужно явно закрыть, а за функцией или ресурсом, который может блокировать выполнение при вызове, и вам нужно понять, где такие вызовы, сколько их и так далее. Профили особенно полезны там, где полезны стек-трейсы, и основным преимуществом является простая интеграция с go tool pprof.

Предостережения при использовании профилей

Пакет profile паникует практически при любом неверном его использовании. Например:

• Создание профиля, который уже существует
• Привязывание профиля к одному и тому же объекту дважды
• Удаление стека, который до этого не был добавлен
• Удаление стека, который уже был удален

Постарайтесь избегать таких ситуаций.

Создание профиля

var libProfile *pprof.Profile
func init() {
   profName := "my_experiment_thing"
   libProfile = pprof.Lookup(profName)
   if libProfile == nil {
       libProfile = pprof.NewProfile(profName)
   }
}

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

// Warning: /vendor panic possibilities
var panicProfile = pprof.NewProfile("this_unique_name")

Но такое использование чревато тем, что выбранное вами имя уже может быть использовано. Даже если вы уверены, что оно уникально, если вашу библиотеку вендорят ^[2] несколько раз (что вполне возможно), приложение запаникует при старте. Т.к. профили являются thread safe, а init()-функция выполняется один раз, подход проверить-и-создать – это правильный подход.

Godoc упоминает, что общепринятый способ создавать уникальные имена – это использование префикса ‘import/path.’, но, если следовать совету, это приведет к тому, что вы наткнетесь на известный баг в cmd/pprof. Так что используйте путь и имя вашего пакета, но только со следующими символами [a-zA-Z0–9_].

Использование профиля

type someResource struct {
      *os.File
}

func MustResource() *someResource {
      f, err := os.Create(...)
      if err != nil {
             panic(err)
      }
      r := &someResource{f}
      libProfile.Add(r, 1)
      return r
}

func (r *someResource) Close() error {
      libProfile.Remove(r)
      return r.File.Close()
}

Главными функциями пакета являются Add ^[3] и Remove ^[4]. В этом примере я буду следить за всеми созданными ресурсами, которые не закрыты, так что я добавлю стек-трейс, в тот момент, когда создаю ресурс, и удалю его, когда закрываю его. Функция «Add» требует уникальный объект при каждом вызове, так что я могу использовать сам ресурс в качестве ключа. Иногда не существует хорошего ключа, в таком случае вы можете создать фиктивный байт и использовать его адрес.

func usesAResource() {
      pprofKey := new(byte)
      libProfile.Add(pprofKey, 1)
      defer libProfile.Remove(pprofKey)
      // ....
}

Экспортирование нового профиля в pprof

Если вы подключите библиотеку http pprof ^[5], Go зарегистрирует http-обработчики для пакета profile. Обычно это делают добавлением «пустого» импорта в файле main.go.

import _ "net/http/pprof"

Добиться того же самого можно с помощью ручной регистрации pprof-обработчика.

httpMux.Handle("/debug/pprof/", http.HandlerFunc(pprof.Index))

Использование pprof

Я создал тестовое приложение для демонстрации всего того, о чем говорю.

package main

import (
	"fmt"
	"log"
	"net/http"
	_ "net/http/pprof"
	"os"
	"runtime/pprof"
	"sync/atomic"
	"time"
)

var libProfile *pprof.Profile

func init() {
	profName := "my_experiment_thing"
	libProfile = pprof.Lookup(profName)
	if libProfile == nil {
		libProfile = pprof.NewProfile(profName)
	}
}

type someResource struct {
	*os.File
}

var fileIndex = int64(0)

func MustResource() *someResource {
	f, err := os.Create(fmt.Sprintf("/tmp/%d.txt", atomic.AddInt64(&fileIndex, 1)))
	if err != nil {
		panic(err)
	}
	r := &someResource{f}
	libProfile.Add(r, 1)
	return r
}

func (r *someResource) Close() error {
	libProfile.Remove(r)
	return r.File.Close()
}

func trackAFunction() {
	tracked := new(byte)
	libProfile.Add(tracked, 1)
	defer libProfile.Remove(tracked)
	time.Sleep(time.Second)
}

func usesAResource() {
	res := MustResource()
	defer res.Close()
	for i := 0; i < 10; i++ {
		time.Sleep(time.Second)
	}
}

func main() {
	http.HandleFunc("/nonblock", func(rw http.ResponseWriter, req *http.Request) {
		go usesAResource()
	})
	http.HandleFunc("/functiontrack", func(rw http.ResponseWriter, req *http.Request) {
		trackAFunction()
	})
	http.HandleFunc("/block", func(rw http.ResponseWriter, req *http.Request) {
		usesAResource()
	})
	log.Println("Running!")
	log.Println(http.ListenAndServe("localhost:6060", nil))
}

Запустив эту программу, вы можете зайти на http://localhost:6060/debug/pprof/ ^[6] и увидеть все доступные профили.

Подайте немного трафика на /nonblock и /block, затем нажмите на ссылку my_example_thing, чтобы увидеть профиль.

my_experiment_thing profile: total 6
4 @ 0x2245 0x5d961
#	0x2244	main.usesAResource+0x64	/Users/.../pproftest.go:64

2 @ 0x2245 0x2574 0x9c184 0x9d56f 0x9df7d 0x9aa07 0x5d961
#	0x2244	main.usesAResource+0x64			/Users/.../pproftest.go:64
#	0x2573	main.main.func3+0x13			/Users/.../pproftest.go:79
#	0x9c183	net/http.HandlerFunc.ServeHTTP+0x43	/usr/local/Cellar/go/1.7.1/libexec/src/net/http/server.go:1726
#	0x9d56e	net/http.(*ServeMux).ServeHTTP+0x7e	/usr/local/Cellar/go/1.7.1/libexec/src/net/http/server.go:2022
#	0x9df7c	net/http.serverHandler.ServeHTTP+0x7c	/usr/local/Cellar/go/1.7.1/libexec/src/net/http/server.go:2202
#	0x9aa06	net/http.(*conn).serve+0x4b6		/usr/local/Cellar/go/1.7.1/libexec/src/net/http/server.go:1579

Граф вызовов

Я использовал brew ^[7], чтобы установить Graphviz ^[8] на мой Mac: он нужен, чтобы pprof мог создать png-картинки.

brew install Graphviz

После установки graphviz я могу использовать pprof, чтобы сгенерировать png-картинку с графом вызовов.

go tool pprof -png /tmp/mybinary ‘localhost:6060/debug/pprof/my_experiment_thing?debug=1’ > /tmp/exp.png

Я использовал PNG для удобства вставки в эту статью, но обычно SVG удобнее для просмотра в браузере. Сгенерируйте svg вместо png, добавив -svg вместо -png при вызове команды pprof.
Готовая картинка – ниже.

Эта картинка показывает мне стек-трейсы создания тех ресурсов, которые не были закрыты. Когда я генерировал эту картинку, я послал в два раза больше неблокирующих запросов, и это видно по трейсу. Все стек-трейсы заканчиваются в MustResource. Если вам это не нравится, вы можете передать целое число при вызове Profile.Add ^[3].

Еще вы можете использовать интерактивную консоль, которая доступна при запуске pprof из терминала. Ниже я запустил pprof и использую команду top, чтобы увидеть, какие вызовы встречаются чаще среди всех моих стек-трейсов.

> go tool pprof 'localhost:6060/debug/pprof/my_experiment_thing?debug=1'

Fetching profile from http://localhost:6060/debug/pprof/my_experiment_thing?debug=1
Saved profile in /Users/.../pprof/pprof.localhost:6060.my_experiment_thing.007.pb.gz
Entering interactive mode (type "help" for commands)

(pprof) top30

6 of 6 total (  100%)

     flat  flat%   sum%        cum   cum%
        6   100%   100%          6   100%  main.usesAResource
        0     0%   100%          2 33.33%  main.main.func3
        0     0%   100%          2 33.33%  net/http.(*ServeMux).ServeHTTP
        0     0%   100%          2 33.33%  net/http.(*conn).serve
        0     0%   100%          2 33.33%  net/http.HandlerFunc.ServeHTTP
        0     0%   100%          2 33.33%  net/http.serverHandler.ServeHTTP
        0     0%   100%          6   100%  runtime.goexit

(pprof)

Заключение

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

Автор: Badoo

Источник ^[9]