анализ производительности go pprof

задняя часть Go Debug SVG

1. выборка данных pprof

Существует три основных способа получения данных выборки pprof:

  • runtime/pprof: ручной вызовruntime.StartCPUProfileилиruntime.StopCPUProfileи другие API для создания и записи образцов файлов с высокой гибкостью
  • net/http/pprof: Получите файл выборки профиля через службу http, которая проста в использовании и подходит для общего мониторинга приложения. Реализовано через runtime/pprof
  • go test: пройти черезgo test -bench . -cpuprofile prof.cpuСоздание образцов файлов для целевого тестирования функций

1.1 net/http/pprof

Импорт в приложенииimport _ "net/http/pprof"и запустите http-сервер:

// net/http/pprof 已经在 init()函数中通过 import 副作用完成默认 Handler 的注册
go func() {
    log.Println(http.ListenAndServe("localhost:6060", nil))
}()

затем может пройтиhttp://localhost:6060/debug/pprof/CMDПолучите соответствующие данные выборки. Поддерживаемые CMD:

  • goroutine: получить информацию о стеке всех текущих goroutine программы.
  • куча: содержит размер выделения горутины, выделенный стек и т. д. Выборка данных производится каждый раз, когда выделяется время выполнения. MemProfileRate (по умолчанию — 512 КБ).
  • threadcreate: получить стек goroutine, который вызвал создание потока ОС
  • block: получить стек goroutine, который вызывает блокировку (например, канал, мьютекс и т. д.), вам нужно вызвать его перед использованием.runtime.SetBlockProfileRate
  • mutex: получите стек goroutine, вызвавший конфликт мьютекса, вам нужно вызвать его перед использованием.runtime.SetMutexProfileFraction

Все пять вышеперечисленных CMD пройденыruntime/pprof ProfileСтруктура управляется унифицированным образом, обеспечивая единый интерфейс запросов с поиском, с похожими возвращаемыми значениями (стек горутин), и все они поддерживают параметр URL-адреса отладки, который по умолчанию равен 0. В сочетании с инструментом pprof для восстановления имя функции. При отладке=1 адрес функции будет преобразован в имя функции, то есть она будет просматриваться прямо в браузере без pprof. Для goroutine CMD также поддерживается debug=2, в это время стек будет печататься в формате unrecovered panic, что более читабельно. Если включеноnet/http/pprofЗадний,http://localhost:6060/debug/pprof/goroutine?debug=2Формат ответа:

goroutine 18 [chan receive, 8 minutes]:
ngs/core/glog.logWorker(0x18b548a, 0x4, 0x7fff5fbffb0e, 0x0, 0x3, 0xc4200e31a0, 0xc4203627c4)
    /Users/wudaijun/go/src/ngs/core/glog/worker.go:43 +0x19c
created by ngs/core/glog.newLogger
    /Users/wudaijun/go/src/ngs/core/glog/glog.go:51 +0xe4

goroutine 6 [syscall, 8 minutes]:
os/signal.signal_recv(0x0)
    /usr/local/Cellar/go/1.9.1/libexec/src/runtime/sigqueue.go:131 +0xa7
os/signal.loop()
    /usr/local/Cellar/go/1.9.1/libexec/src/os/signal/signal_unix.go:22 +0x22
created by os/signal.init.0
    /usr/local/Cellar/go/1.9.1/libexec/src/os/signal/signal_unix.go:28 +0x41

goroutine 50 [select, 8 minutes]:
context.propagateCancel.func1(0x1cfcee0, 0xc42017a1e0, 0x1cf3820, 0xc42005b480)
    /usr/local/Cellar/go/1.9.1/libexec/src/context/context.go:260 +0x113
created by context.propagateCancel
    /usr/local/Cellar/go/1.9.1/libexec/src/context/context.go:259 +0x1da

...

Вышеуказанные профили можно найти вhttp://localhost:6060/debug/pprof/В дополнение к этому, CMD go pprof также включает в себя:

  • cmdline: получить параметры запуска программы из командной строки
  • profile: получить cpuprof в течение указанного времени (с момента запроса) и вернуть автоматически после окончания обратного отсчета. Параметры: секунды, значение по умолчанию 30. cpuprofile выполняет выборку 100 раз в секунду для сбора информации о стеке запущенных в данный момент горутин.
  • символ: используется для преобразования списка адресов в список имен функций, адреса разделены символом «+», например URL/debug/pprof?0x18d067f+0x17933e7
  • trace: выполнение трассировки приложения, параметр: секунды, значение по умолчанию 1 с.

Эти CMD не интегрированы в структуру Профиля по разным причинам, но с точки зрения использования разницы нет.Формат URL-адреса одинаков, поэтому его можно рассматривать как единое целое, а систему можно сэмплировать и анализировать из разных углы анализировать.

1.2 runtime/pprof

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

1.3 go test

обычно используетсяnet/http/pprofилиruntime/pprofВыполните общий анализ приложения, выясните горячие точки, а затем используйтеgo testСравнительный анализ для дальнейшего выявления горячих точек для оптимизации и сравнения тестов.

# 生成 test 二进制文件， pprof 工具需要用到
▶ go test -c -o tmp.test 
# 执行基准测试 BenchAbc，并忽略任何单元测试，test flag前面需要加上'test.'前缀
▶ tmp.test -test.bench BenchAbc -test.run XXX test.cpuprofile cpu.prof     
# 与上面两条命令等价，只不过没有保留 test 二进制文件
▶ go test -bench BenchAbc -run XXX -cpuprofile=cpu.prof .

go testможно добавить напрямую-cpuprofile -mutexprofilefractionи другие параметры для осуществления выборки и генерации профессиональных данных.Для получения дополнительных параметров см.go test -h.

2. анализ данных pprof

Несмотря на то чтоnet/http/pprofПредоставленный анализ данных можно просмотреть непосредственно в браузере после настройки параметров, но данные выборки pprof в основном используются для инструмента pprof, особенно для cpuprof, memprof, blockprof и т. д., нам нужно интуитивно получить всю цепочку взаимосвязей вызовов и каждый раз Детали звонка, которые требуются черезgo tool pprofкоманда для анализа:

go tool pprof [binary] [binary.prof]
# 如果使用的 net/http/pprof 可以直接接 URL
go tool pprof http://localhost:6060/debug/pprof/profile

Данные выборки Go pprof очень богаты, в большинстве случаев мы используем только анализ процессора и памяти, поэтому вот четыре анализа данных pprof: процессор, куча, блок и мьютекс.

2.1 cpuprofile

отProfiling Go Programsсерединаобразец кодаНапример:

▶ go build -o havlak1 havlak1.go 
▶ ./havlak1 --cpuprofile=havlak1.prof
# of loops: 76000 (including 1 artificial root node)
▶ go tool pprof havlak1 havlak1.prof
File: havlak1
Type: cpu
Time: Apr 3, 2018 at 3:50pm (CST)
Duration: 20.40s, Total samples = 23.30s (114.24%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top5
Showing nodes accounting for 9.60s, 41.20% of 23.30s total
Dropped 112 nodes (cum <= 0.12s)
Showing top 5 nodes out of 90
      flat  flat%   sum%        cum   cum%
     2.59s 11.12% 11.12%      2.78s 11.93%  runtime.mapaccess1_fast64 /usr/local/Cellar/go/1.9.1/libexec/src/runtime/hashmap_fast.go
     2.26s  9.70% 20.82%      4.97s 21.33%  runtime.scanobject /usr/local/Cellar/go/1.9.1/libexec/src/runtime/mgcmark.go
     2.06s  8.84% 29.66%     13.79s 59.18%  main.FindLoops /Users/wudaijun/Code/goprof/havlak/havlak1.go
     1.39s  5.97% 35.62%      1.39s  5.97%  runtime.heapBitsForObject /usr/local/Cellar/go/1.9.1/libexec/src/runtime/mbitmap.go
     1.30s  5.58% 41.20%      4.14s 17.77%  runtime.mapassign_fast64 /usr/local/Cellar/go/1.9.1/libexec/src/runtime/hashmap_fast.go

top5 используется для отображения пяти основных функций, потребляющих ресурсы ЦП, каждая строка представляет собой функцию, а каждый столбец является индикатором:

  • flat: при выборке количество раз, когда функция выполняется * частота выборки (10 мс), то есть расчетное время выполнения функции «время выборки». Сюда не входят функции, ожидающие возврата подфункций.
  • flat%: плоское/общее значение времени выборки
  • sum%: накопленное значение flat% всех предыдущих строк, например сумма второй строки% = 20,82% = 11,12% + 9,70%
  • cum: при выборке функция появляется во время выборки стека вызовов, включая функцию, ожидающую возврата подфункции. Такая плоская
  • cum%: cum / общее значение времени выборки

PS: Старая версия pprof, кажется, отображает количество выборок.Например, flat - это количество раз, когда функция выполняется при выборке.Это число * частота выборки - это время выборки.

go tool pprofОбщие команды:

  • topN: введите команду top, по умолчанию отображаются первые 10 вызовов функций flat, вы можете использовать -cum для сортировки по cum
  • list Func: отображать имена функций и образец анализа каждой строки кода.
  • web: генерировать изображения точек доступа svg, которые можно открывать в браузере и использовать web Func для фильтрации дерева вызовов, связанного с указанной функцией.

пройти черезtop5команда может видеть,mapaccess1_fast64Функция потребляет больше всего времени выборки ЦП, наweb mapaccess1_fast64Команда, чтобы открыть карту вызовов, проверить связь вызова функции, вы можете видеть, что она в основном вызывается в DFS и FindLoops, а затем передатьlist DFSПроверьте код функции и ключевые вызовы, получите структуру карты, которая является узким местом, попробуйте преобразовать в оптимизацию среза, ссылку на весь процессProfiling Go Programs. Общая идея состоит в том, чтобы пройтиtopиwebНайдите ключевую функцию, а затем передайтеlist FuncПосмотрите на код функции, найдите критические строки кода и подтвердите оптимизацию (дополнено тестом go test Benchmark).

2.2 memprofile

▶ go build -o havlak3 havlak3.go 
▶ ./havlak3 --memprofile=havlak3.mprof
▶ go tool pprof havlak3 havlak3.mprof
File: havlak3
Type: inuse_space
Time: Apr 3, 2018 at 3:44pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 57.39MB, 100% of 57.39MB total
      flat  flat%   sum%        cum   cum%
   39.60MB 69.00% 69.00%    39.60MB 69.00%  main.FindLoops /Users/wudaijun/Code/goprof/havlak/havlak3.go
   11.29MB 19.67% 88.67%    11.29MB 19.67%  main.(*CFG).CreateNode /Users/wudaijun/Code/goprof/havlak/havlak3.go
    6.50MB 11.33%   100%    17.79MB 31.00%  main.NewBasicBlockEdge /Users/wudaijun/Code/goprof/havlak/havlak3.go
         0     0%   100%    39.60MB 69.00%  main.FindHavlakLoops /Users/wudaijun/Code/goprof/havlak/havlak3.go
         0     0%   100%    17.79MB 31.00%  main.buildBaseLoop /Users/wudaijun/Code/goprof/havlak/havlak3.go

memprofile также является данными выборки кучи.Инструмент Go pprof отображает размер памяти, используемой по умолчанию.Если вы хотите отобразить количество используемых объектов кучи, передайтеgo tool pprof --inuse_objects havlak3 havlak3.mprof, а остальные параметры--alloc_objectsи--alloc_space, которые представляют собой выделенный размер памяти кучи и количество объектов соответственно. В этом примере функция FindLoops выделяет 39,60 МБ динамической памяти, что составляет 69%. Опять же, следующим шагом является передачаlist FindLoopsкод функции Просмотрите, найдите ключевые структуры данных и оптимизируйте их.

2.3 blockprofile

var mutex sync.Mutex
func main() {
    // rate = 1 时, 统计所有的 block event, 
    // rate <=0 时，则关闭block profiling
    // rate > 1 时，为 ns 数，阻塞时间t>rate的event 一定会被统计，小于rate则有t/rate 的几率被统计
    // 参考 https://github.com/golang/go/blob/release-branch.go1.9/src/runtime/mprof.go#L397
	runtime.SetBlockProfileRate(1 * 1000 * 1000)
	var wg sync.WaitGroup
	wg.Add(1)
	mutex.Lock()
	go worker(&wg)
	time.Sleep(2*time.Millisecond)
	mutex.Unlock()
	wg.Wait()
	writeProfTo("block", "block.bprof")
}
func worker(wg *sync.WaitGroup) {
	defer wg.Done()
	mutex.Lock()
	time.Sleep(1*time.Millisecond)
	mutex.Unlock()
}
func writeProfTo(name, fn string) {
	p := pprof.Lookup(name)
	if p == nil {
		fmt.Errorf("%s prof not found", name)
		return
	}
	f, err := os.Create(fn)
	if err != nil {
		fmt.Errorf("%v", err.Error())
		return
	}
	defer f.Close()
	err = p.WriteTo(f, 0)
	if err != nil {
		fmt.Errorf("%v", err.Error())
		return
	}
}

Запускаем программу и pprof:

▶ go build -o Temp tmp.go
▶ go tool pprof Temp block.bprof
(pprof) top
Showing nodes accounting for 3.37ms, 100% of 3.37ms total
      flat  flat%   sum%        cum   cum%
    2.04ms 60.52% 60.52%     2.04ms 60.52%  sync.(*Mutex).Lock /usr/local/Cellar/go/1.9.1/libexec/src/sync/mutex.go
    1.33ms 39.48%   100%     1.33ms 39.48%  sync.(*WaitGroup).Wait /usr/local/Cellar/go/1.9.1/libexec/src/sync/waitgroup.go
         0     0%   100%     1.33ms 39.48%  main.main /Users/wudaijun/go/src/ngs/test/tmp/tmp.go
         0     0%   100%     2.04ms 60.52%  main.worker /Users/wudaijun/go/src/ngs/test/tmp/tmp.go
         0     0%   100%     3.37ms   100%  runtime.goexit /usr/local/Cellar/go/1.9.1/libexec/src/runtime/asm_amd64.s
         0     0%   100%     1.33ms 39.48%  runtime.main /usr/local/Cellar/go/1.9.1/libexec/src/runtime/proc.go

Видно, что программа заблокировала 2,04 мс (рабочая горутина) на mutex.Lock и 1,33 мс (основная горутина) на WaitGroup.Wait.На более высоком уровне основная функция заблокировала всего 2,04 мс, рабочая функция заблокирована на 1,33 мс (включая столбец), черезwebКоманда генерирует изображение svg для просмотра в браузере:

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

2.4 mutexprofile

Все еще используйте код в 2.3, только нужно изменить два места,runtime.SetBlockProfileRate(1 * 1000 * 1000)Измените его на:

// 当 rate = 0 时，关闭 mutex prof (默认值)
// 当 rate = 1 时，表示记录所有的 mutex event
// 当 rate > 1 时，记录 1/rate 的 mutex event(随机)
runtime.SetMutexProfileFraction(1)

сноваwriteProfTo("block", "block.bprof")изменить наwriteProfTo("mutex", "mutex.mprof")Вот и все, скомпилируйте и запустите, и откройте инструмент pprof:

▶ go tool pprof bin/Temp mutex.mprof
(pprof) top
Showing nodes accounting for 2.55ms, 100% of 2.55ms total
      flat  flat%   sum%        cum   cum%
    2.55ms   100%   100%     2.55ms   100%  sync.(*Mutex).Unlock /usr/local/Cellar/go/1.9.1/libexec/src/sync/mutex.go
         0     0%   100%     2.55ms   100%  main.main /Users/wudaijun/go/src/ngs/test/tmp/tmp.go
         0     0%   100%     2.55ms   100%  runtime.goexit /usr/local/Cellar/go/1.9.1/libexec/src/runtime/asm_amd64.s
         0     0%   100%     2.55ms   100%  runtime.main /usr/local/Cellar/go/1.9.1/libexec/src/runtime/proc.go

Просмотрите SVG-изображение:

3. Практические советы

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

  1. Для часто размещаемых небольших объектов используйтеsync.PoolПул объектов позволяет избежать распределения
  2. Автоматическое DeepCopy требует очень много времени, включая отражение, выделение памяти, расширение контейнера (например, карты) и т. д., примерно на порядок медленнее, чем ручное копирование.
  3. Замените Mutex на atomic.Load/StoreXXX, atomic.Value, sync.Map и т. д. (снижение приоритета)
  4. Используйте эффективные сторонние библиотеки, такие какfasthttpАльтернатива сети/http
  5. добавить в среду разработки-raceВарианты компиляции для проверки гонки
  6. Откройте net/http/pprof в среде разработки, чтобы упростить pprof в реальном времени.
  7. Сделать все внешние операции ввода-вывода (сетевые операции ввода-вывода, дисковые операции ввода-вывода) асинхронными

Ссылаться на:

  1. Profiling Go Programs
  2. profiling-and-optimizing-go-web-applications
Категории