pprof 性能分析

Posted 2021-09-15 StaticAuto

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了pprof 性能分析相关的知识，希望对你有一定的参考价值。

pprof 是一个强大的性能分析工具,可以捕捉到多维度的运行状态的数据,在程序运行过程中可以获取cpu、heap、block、traces等执行信息

一般情况下使用下列三种pprof分析

runtime/pprof：采集程序（非 Server）的运行数据进行分析
net/http/pprof：采集 HTTP Server 的运行时数据进行分析
runtime/trace：采集Go程序运行中的所有的运行时事件

通常使用pprof做的事情

CPU 分析，按照一定的频率采集所监听的应用程序 CPU（含寄存器）的使用情况，可确定应用程序在主动消耗 CPU 周期时花费时间的位置
内存分析，在应用程序进行堆分配时记录堆栈跟踪，用于监视当前和历史内存使用情况，以及检查内存泄漏
阻塞分析，记录 goroutine 阻塞等待同步（包括定时器通道）的位置
互斥锁分析，报告互斥锁的竞争情况

例子：

package main

import (
	"iotcomm/app"
	"log"
	"net/http"
	_"net/http/pprof"
)

func main()  {
	go func() {
		log.Println(http.ListenAndServe(":8080", nil))
	}()

	app.Run() //业务代码
}

通过浏览器查看pprof

通过打开浏览器http://localhost:8080/debug/pprof/我们可以得到

/debug/pprof/

Types of profiles available:
Count	Profile
15	allocs
0	block
0	cmdline
23	goroutine
15	heap
0	mutex
0	profile
17	threadcreate
0	trace
full goroutine stack dump
Profile Descriptions:

allocs: A sampling of all past memory allocations
block: Stack traces that led to blocking on synchronization primitives
cmdline: The command line invocation of the current program
goroutine: Stack traces of all current goroutines
heap: A sampling of memory allocations of live objects. You can specify the gc GET parameter to run GC before taking the heap sample.
mutex: Stack traces of holders of contended mutexes
profile: CPU profile. You can specify the duration in the seconds GET parameter. After you get the profile file, use the go tool pprof command to investigate the profile.
threadcreate: Stack traces that led to the creation of new OS threads
trace: A trace of execution of the current program. You can specify the duration in the seconds GET parameter. After you get the trace file, use the go tool trace command to investigate the trace.

allocs :过去所有内存分配的采样
heap profile: 4: 7584 [107: 422856] @ heap/1048576
1: 5376 [1: 5376] @ 0xec672d 0xec66ea 0xec5813 0xec5f3e 0xec5deb 0xf23dba 0xf23d6b 0xef0bb7 0xf05c30 0xf24a71 0x8645a1

#	0xec672c	math/rand.NewSource+0x12c										C:/Users/DELL/go/pkg/mod/github.com/nats-io/nats.go@v1.11.1-0.20210623165838-4b75fc59ae30/nats.go:3505
#	0xec66e9	github.com/nats-io/nats%2ego.(*Conn).initNewResp+0xe9							C:/Users/DELL/go/pkg/mod/github.com/nats-io/nats.go@v1.11.1-0.20210623165838-4b75fc59ae30/nats.go:3505
#	0xec5812	github.com/nats-io/nats%2ego.(*Conn).createNewRequestAndSend+0x492					C:/Users/DELL/go/pkg/mod/github.com/nats-io/nats.go@v1.11.1-0.20210623165838-4b75fc59ae30/nats.go:3348
#	0xec5f3d	github.com/nats-io/nats%2ego.(*Conn).newRequest+0xdd							C:/Users/DELL/go/pkg/mod/github.com/nats-io/nats.go@v1.11.1-0.20210623165838-4b75fc59ae30/nats.go:3430
#	0xec5dea	github.com/nats-io/nats%2ego.(*Conn).request+0x26a							C:/Users/DELL/go/pkg/mod/github.com/nats-io/nats.go@v1.11.1-0.20210623165838-4b75fc59ae30/nats.go:3419
#	0xf23db9	github.com/nats-io/nats%2ego.(*Conn).Request+0x419							C:/Users/DELL/go/pkg/mod/github.com/nats-io/nats.go@v1.11.1-0.20210623165838-4b75fc59ae30/nats.go:3398
#	0xf23d6a	iotcomm/app/system/admin/internal/service.(*varsSdk).JudgeIfNotifySDK+0x3ca				D:/IotComm/trunk/app/system/admin/internal/service/varsSdk.go:404
#	0xef0bb6	iotcomm/app/system/admin/internal/service.(*channelEntityVariableSubscribe).VariableChangedNotify+0xeb6	D:/IotComm/trunk/app/system/admin/internal/service/channelEntityVariableSubscribe.go:337
#	0xf05c2f	iotcomm/app/system/admin/internal/service.(*entityvarService).UpdateEntityVarValue+0x5af		D:/IotComm/trunk/app/system/admin/internal/service/entityVar.go:779
#	0xf24a70	iotcomm/app/system/admin/internal/service.NatsReport.func1.1+0x150					D:/IotComm/trunk/app/system/admin/internal/service/varsSdk.go:52

由上可以看出，nats.go过去的一段时间内申请内存的操作最多

block：协程阻塞的情况，可以用来分析和查找死锁等性能瓶颈，默认不开启，可以调用runtime.SetBlockProfileRate开启来今行查看

列如：

func main()  {
	runtime.SetBlockProfileRate(1)
	go func() {
		log.Println(http.ListenAndServe(":8080", nil))
	}()

	app.Run()
}

可以得到以下block信息

--- contention:
cycles/second=3078668017
69212761621 34 @ 0x6fea9f 0xd50f7f 0x6f4641
#	0x6fea9e	sync.(*Cond).Wait+0x9e					C:/Program Files/Go/src/sync/cond.go:56
#	0xd50f7e	github.com/nats-io/nats%2ego.(*Conn).waitForMsgs+0x4de	C:/Users/DELL/go/pkg/mod/github.com/nats-io/nats.go@v1.11.1-0.20210623165838-4b75fc59ae30/nats.go:2525

38995547732 126 @ 0x6868ab 0x87cce5 0x6f4641
#	0x6868aa	runtime.chanrecv1+0x2a					C:/Program Files/Go/src/runtime/chan.go:439
#	0x87cce4	github.com/gogf/gf/os/gtimer.(*Timer).loop.func1+0x84	C:/Users/DELL/go/pkg/mod/github.com/gogf/gf@v1.16.2/os/gtimer/gtimer_timer_loop.go:21

38794859460 22 @ 0x6868eb 0xd51ff0 0x6f4641
#	0x6868ea	runtime.chanrecv2+0x2a					C:/Program Files/Go/src/runtime/chan.go:444
#	0xd51fef	github.com/nats-io/nats%2ego.(*Conn).flusher+0xef	C:/Users/DELL/go/pkg/mod/github.com/nats-io/nats.go@v1.11.1-0.20210623165838-4b75fc59ae30/nats.go:2799

cmdline：主要是调用os.Args，获取程序启动时的命令及参数
goroutine：协程相关的报告信息
heap：堆以及一些垃圾回收的信息

heap profile: 6: 73120 [402: 2941872] @ heap/1048576
1: 32768 [2: 65536] @ 0x94b0a8 0x94c07e 0x94eafc 0x952c34 0x9536a5 0x960c9e 0x960db6 0xe2d7a5 0xe1b425 0xe08d68 0xe3c22a 0xe38a86 0xef002b 0xeeff33 0xf05c30 0xf24a71 0x8645a1
#	0x94b0a7	regexp.(*bitState).reset+0x227										C:/Program Files/Go/src/regexp/backtrack.go:91
#	0x94c07d	regexp.(*Regexp).backtrack+0x11d									C:/Program Files/Go/src/regexp/backtrack.go:319
#	0x94eafb	regexp.(*Regexp).doExecute+0x45b									C:/Program Files/Go/src/regexp/exec.go:535
#	0x952c33	regexp.(*Regexp).replaceAll+0x1b3									C:/Program Files/Go/src/regexp/regexp.go:617
#	0x9536a4	regexp.(*Regexp).ReplaceAllFunc+0xc4									C:/Program Files/Go/src/regexp/regexp.go:698
#	0x960c9d	github.com/gogf/gf/text/gregex.ReplaceFunc+0xbd								C:/Users/DELL/go/pkg/mod/github.com/gogf/gf@v1.16.2/text/gregex/gregex.go:97
#	0x960db5	github.com/gogf/gf/text/gregex.ReplaceStringFunc+0xb5							C:/Users/DELL/go/pkg/mod/github.com/gogf/gf@v1.16.2/text/gregex/gregex.go:121
#	0xe2d7a4	github.com/gogf/gf/database/gdb.FormatSqlWithArgs+0xc4							C:/Users/DELL/go/pkg/mod/github.com/gogf/gf@v1.16.2/database/gdb/gdb_func.go:783
#	0xe1b424	github.com/gogf/gf/database/gdb.(*Core).DoQuery+0x2e4							C:/Users/DELL/go/pkg/mod/github.com/gogf/gf@v1.16.2/database/gdb/gdb_core_underlying.go:49
#	0xe08d67	github.com/gogf/gf/database/gdb.(*Core).DoGetAll+0xe7							C:/Users/DELL/go/pkg/mod/github.com/gogf/gf@v1.16.2/database/gdb/gdb_core.go:127
#	0xe3c229	github.com/gogf/gf/database/gdb.(*Model).doGetAllBySql+0x209						C:/Users/DELL/go/pkg/mod/github.com/gogf/gf@v1.16.2/database/gdb/gdb_model_select.go:486
#	0xe38a85	github.com/gogf/gf/database/gdb.(*Model).doGetAll+0x165							C:/Users/DELL/go/pkg/mod/github.com/gogf/gf@v1.16.2/database/gdb/gdb_model_select.go:55
#	0xef002a	github.com/gogf/gf/database/gdb.(*Model).All+0x32a							C:/Users/DELL/go/pkg/mod/github.com/gogf/gf@v1.16.2/database/gdb/gdb_model_select.go:40
#	0xeeff32	iotcomm/app/system/admin/internal/service.(*channelEntityVariableSubscribe).VariableChangedNotify+0x232	D:/IotComm/trunk/app/system/admin/internal/service/channelEntityVariableSubscribe.go:330
#	0xf05c2f	iotcomm/app/system/admin/internal/service.(*entityvarService).UpdateEntityVarValue+0x5af		D:/IotComm/trunk/app/system/admin/internal/service/entityVar.go:779
#	0xf24a70	iotcomm/app/system/admin/internal/service.NatsReport.func1.1+0x150					D:/IotComm/trunk/app/system/admin/internal/service/varsSdk.go:52


# runtime.MemStats
# Alloc = 2465032
# TotalAlloc = 13052840
# Sys = 20343400
# Lookups = 0
# Mallocs = 193219
# Frees = 179358
# HeapAlloc = 2465032
# HeapSys = 11665408
# HeapIdle = 6758400
# HeapInuse = 4907008
# HeapReleased = 6471680
# HeapObjects = 13861
# Stack = 917504 / 917504
# MSpan = 165784 / 180224
# MCache = 14016 / 16384
# BuckHashSys = 1452585
# GCSys = 3215184
# OtherSys = 2896111
# NextGC = 4194304
# LastGC = 1630307387416162900
# PauseNs = [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
# PauseEnd = [1630307363484526700 1630307363640567200 1630307366356955300 1630307366377908700 1630307367513661900 1630307376617267500 1630307386409989000 1630307387416162900 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
# NumGC = 8
# NumForcedGC = 0
# GCCPUFraction = 0.00015986017033100297
# DebugGC = false

mutex:锁互斥的使用情况，默认不开启，需要调用需要在程序中调用runtime.SetMutexProfileFraction
例如：

func main()  {
	runtime.SetMutexProfileFraction(1)
	go func() {
		log.Println(http.ListenAndServe(":8080", nil))
	}()
	app.Run()
}

threadcreate：线程的创建信息

通过终端查看pprof

查看cpu在60s的使用情况
go tool pprof http://localhost:8080/debug/pprof/profile?seconds=60

D:\\IotComm\\trunk>go tool pprof http://localhost:8080/debug/pprof/profile?seconds=60
Fetching profile over HTTP from http://localhost:8080/debug/pprof/profile?seconds=60
Saved profile in C:\\Users\\DELL\\pprof\\pprof.samples.cpu.003.pb.gz
Type: cpu
Time: Aug 30, 2021 at 3:20pm (CST)
Duration: 1mins, Total samples = 450ms ( 0.75%)
Entering interactive mode (type "help" for commands, "o" for options)

注：在使用浏览器查看pprof的网址，均可以使用go tool pprof + url的方式进入pprof命令行模式
例如go tool pprof http://localhost:8080/debug/pprof/block

(pprof) top
Showing nodes accounting for 837.48MB, 100% of 837.48MB total
      flat  flat%   sum%        cum   cum%
  837.48MB   100%   100%   837.48MB   100%  main.main.func1

同样，使用top5，top10可以看到开销前5，前10占用率的函数
需要注意的是，通常情况下，占用率前5的一定是系统函数，如果发现自己写的函数占用率排在了前列，那就应该查一查时间，空间复杂度了

web可视化界面

func main()  {

	var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to `file`")
	var memprofile = flag.String("memprofile", "", "write memory profile to `file`")

	flag.Parse()
	if *cpuprofile != "" {
		f, err := os.Create(*cpuprofile)
		if err != nil {
			log.Fatal("could not create CPU profile: ", err)
		}
		if err := pprof.StartCPUProfile(f); err != nil {
			log.Fatal("could not start CPU profile: ", err)
		}
		defer pprof.StopCPUProfile()
	}
	
	if *memprofile != "" {
		f, err := os.Create(*memprofile)
		if err != nil {
			log.Fatal("could not create memory profile: ", err)
		}
		runtime.GC() // get up-to-date statistics
		if err := pprof.WriteHeapProfile(f); err != nil {
			log.Fatal("could not write memory profile: ", err)
		}
		f.Close()
	}
	
	runtime.SetMutexProfileFraction(1)
	go func() {
		log.Println(http.ListenAndServe(":8080", nil))
	}()

	app.Run()
}

可以通过go run main.go --memprofile=mem.prof生成了mem.prof
可以通过go run main.go --cpuprofile=cpu.prof生成了cpu.prof

启动pprof可视化界面

$ go tool pprof cpu.prof 
$ (pprof) web

或
$ go tool pprof -http=:8080 cpu.prof

在这里必须安装graphviz，移步graphviz安装教程

使用test的功能及压测生成pprof文件移步到go test文档

以上是关于pprof 性能分析的主要内容，如果未能解决你的问题，请参考以下文章

golang 性能剖析pprof

Golang pprof详解

Golang 大杀器之性能剖析 PProf

go语言学习笔记 — 基础 — go工具：性能分析，发现代码性能问题的具体位置 —— go pprof

golang 性能测试pprof

使用go tool pprof分析内存泄漏CPU消耗