pprof 性能分析
Posted 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 性能分析的主要内容,如果未能解决你的问题,请参考以下文章