Golang性能分析工具pprof使用总结
优采云 发布时间: 2022-08-31 10:01Golang性能分析工具pprof使用总结
pprof是Golang自带的一款开箱即用的性能监控和分析工具, 使用非常简单方便。
1. pprof使用
pprof使用主要有两种方式，一种是在项目中导入runtime/pprof，另一种是导入net/http/pprof, 两者的差异如下：
使用示例如下:
1<br />2<br />3<br />4<br />5<br />6<br />7<br />8<br />9<br />10<br />11<br />12<br />13<br />14<br />15<br />16<br />17<br />18<br />19<br />20<br />21<br />22<br />23<br />24<br />
package main<br /><br />import (<br /> "fmt"<br /> "os"<br /> "runtime/pprof"<br /> "time"<br />)<br /><br />func main() {<br /> // 创建分析文件<br /> file, err := os.Create("./cpu.prof")<br /> if err != nil {<br /> fmt.Printf("创建采集文件失败, err:%v\n", err)<br /> return<br /> }<br /><br /> // 进行cpu数据的获取<br /> pprof.StartCPUProfile(file)<br /> defer pprof.Sto*敏*感*词*UProfile()<br /><br /> time.Sleep(10 * time.Second)<br />}<br /><br />
之后通过命令行分析cpu.prof文件进行性能分析，由于该方式使用不多，这里不进行深度总结，感兴趣可以查阅相关文章，这次我们重点总结http形式采集数据。
http形式使用十分简单，importnet/http/pprof即可，会自动调用package里面的init方法，进行初始化，如下：
1<br />2<br />3<br />4<br />5<br />
import _ "net/http/pprof"<br /><br />go func() {<br /> http.ListenAndServe("localhost:8080", nil)<br />}()
之后就可以通过:8080/debug/pprof/[类型]获取对应的采样数据。支持的”[类型]”有:
类型描述
allocs
内存分配情况的采样信息
blocks
阻塞操作情况的采样信息
cmdline
显示程序启动命令参数及其参数
goroutine
显示当前所有协程的堆栈信息
heap
堆上的内存分配情况的采样信息
mutex
锁竞争情况的采样信息
profile
cpu占用情况的采样信息，点击会下载文件
threadcreate
系统线程创建情况的采样信息
trace
程序运行跟踪信息
重点我们关注以下几种类型:
2. 分析实践2.1 CPU使用分析
通过以下命令分析CPU使用情况。
1<br />
go tool pprof http://localhost:8080/debug/pprof/profile
等待30秒后，执行top命令可以看到如下结果:
先简单了解一下结果中flat,sum,cum的含义:
类型描述举例
flat
该函数占用CPU的耗时
selectnbrecv占用CPU的耗时是12.29s
flat%
该函数占用CPU的耗时的百分比
selectnbrecv耗时：12.29s，cpu总耗时：29.14，12.29/29.14=42.18
sum%
top命令中排在它上面的函数以及本函数flat%之和
chanrecv：42.18%+30.47% = 72.65%
cum
当前函数加上该函数调用之前的累计CPU耗时
chanrecv：8.88+0.54=9.42
cum%
当前函数加上该函数调用之前的累计CPU耗时的百分比
9.42/29.14=32.33%
通过以上结果，我们可以看到占用CPU比较高的方法，接下来可以通过list WirteString(list+方法名)查看占用CPU最高的方法代码明细:
通过代码明细我们可以看到，字符串拼接占用的CPU资源最多，可以针对这行代码进行优化。
2.2 内存使用分析
内存使用分析我们可以直接在网页上点击heap标签进行查看，如下:
直接在网页上查看并不是特别便利，一般情况下我们采用go tool pprof命令下载Profile采样文件进行可视化分析, 可采用如下命令:
1<br />
go tool pprof --http=:1234 go tool pprof http://localhost:8080/debug/pprof/heap<br />
以上命令会打开一个网页，页面效果如下:
左上的下拉条可以选择不同的可视化方式查看不同的数据:
选项卡SAMPLE中space相关是展示内存大小，单位是Byte；而objects相关展示的对象，单位是个，是有差异的。例如inuse_space展示的是现在正在使用的内存，被分配但是还没有被释放，alloc_space展示的是程序启动到现在的分配内存，包括那些已经被释放的内存，我们一般用这个来定位代码中创建临时变量的大户;
通过VIEW选项卡，我们可以切换不同的视图形式来查看分析结果。
Top
源码形式
火焰图形式
2.3 协程分析
协程分析我们可以直接在网页上点击goroutine标签进行查看, 也可以采用go tool pprof命令下载采样文件进行可视化分析。
在goroutine分析页面我们可以看到协程数量和每个方法产生的协程数量。
1<br />2<br />3<br />4<br />5<br />6<br />7<br />8<br />9<br />10<br />11<br />12<br />13<br />14<br />15<br />16<br />17<br />18<br />19<br />20<br />21<br />22<br />23<br />24<br />25<br />26<br />27<br />28<br />29<br />30<br />31<br />32<br />33<br />34<br />35<br />36<br />37<br />38<br />39<br />40<br />41<br />42<br />
goroutine profile: total 108<br />83 @ 0x438196 0x40666c 0x406098 0xc10cbd 0x4687c1<br /># 0xc10cbc jzserver/core/os/gtimer.(*Timer).loop.func1+0x7c /Documents/gotest/core/os/gtimer/gtimer_timer_loop.go:15<br /><br />11 @ 0x438196 0x447f32 0x91ac0c 0x4687c1<br /># 0x91ac0b jzserver/core/net/gnet.(*MsgHandler).startOneWorker+0xab /Documents/gotest/core/net/gnet/gnet_msg_handler.go:76<br /><br />1 @ 0x40bb54 0x464f18 0xc13279 0x4687c1<br /># 0x464f17 os/signal.signal_recv+0x97 /go/go1.17.6/src/runtime/sigqueue.go:169<br /># 0xc13278 os/signal.loop+0x18 /go/go1.17.6/src/os/signal/signal_unix.go:24<br /><br />1 @ 0x438196 0x40666c 0x406098 0xc1509c 0xd8a1a5 0x437dc7 0x4687c1<br /># 0xc1509b jzserver/main/internal.WaitStopSignal+0xbb /Documents/gotest/main/internal/signal.go:15<br /># 0xd8a1a4 main.main+0x144 /Documents/gotest/main/game_server.go:75<br /># 0x437dc6 runtime.main+0x226 /go/go1.17.6/src/runtime/proc.go:255<br /><br />1 @ 0x438196 0x40666c 0x406098 0xc1536c 0x4687c1<br /># 0xc1536b jzserver/main/internal.WaitReloadConfigSignal.func1+0x2b /Documents/gotest/main/internal/signal.go:47<br /><br />1 @ 0x438196 0x40666c 0x4060d8 0xc45431 0x4687c1<br /># 0xc45430 jzserver/core/net/gwebsocket.(*Server).Run+0x30 /Documents/gotest/core/net/gwebsocket/gwebsocket_server.go:152<br /><br />1 @ 0x438196 0x430813 0x463069 0x4cecf2 0x4d005a 0x4d0048 0x5f5829 0x602685 0x4abb3a 0xc0c1d3 0xc0c1ae 0x4687c1<br /># 0x463068 internal/poll.runtime_pollWait+0x88 /go/go1.17.6/src/runtime/netpoll.go:234<br /># 0x4cecf1 internal/poll.(*pollDesc).wait+0x31 /go/go1.17.6/src/internal/poll/fd_poll_runtime.go:84<br /># 0x4d0059 internal/poll.(*pollDesc).waitRead+0x259 /go/go1.17.6/src/internal/poll/fd_poll_runtime.go:89<br /># 0x4d0047 internal/poll.(*FD).Read+0x247 /go/go1.17.6/src/internal/poll/fd_unix.go:167<br /># 0x5f5828 net.(*netFD).Read+0x28 /go/go1.17.6/src/net/fd_posix.go:56<br /># 0x602684 net.(*conn).Read+0x44 /go/go1.17.6/src/net/net.go:183<br /># 0x4abb39 io.ReadAtLeast+0x99 /go/go1.17.6/src/io/io.go:328<br /># 0xc0c1d2 io.ReadFull+0x132 /go/go1.17.6/src/io/io.go:347<br /># 0xc0c1ad jzserver/core/net/gtcp.(*Connection).StartReader+0x10d /Documents/gotest/core/net/gtcp/gtcp_connection.go:100<br /><br />1 @ 0x438196 0x430813 0x463069 0x4cecf2 0x4d005a 0x4d0048 0x5f5829 0x602685 0x6c57df 0x4687c1<br /># 0x463068 internal/poll.runtime_pollWait+0x88 /go/go1.17.6/src/runtime/netpoll.go:234<br /># 0x4cecf1 internal/poll.(*pollDesc).wait+0x31 /go/go1.17.6/src/internal/poll/fd_poll_runtime.go:84<br /># 0x4d0059 internal/poll.(*pollDesc).waitRead+0x259 /go/go1.17.6/src/internal/poll/fd_poll_runtime.go:89<br /># 0x4d0047 internal/poll.(*FD).Read+0x247 /go/go1.17.6/src/internal/poll/fd_unix.go:167<br /># 0x5f5828 net.(*netFD).Read+0x28 /go/go1.17.6/src/net/fd_posix.go:56<br /># 0x602684 net.(*conn).Read+0x44 /go/go1.17.6/src/net/net.go:183<br /># 0x6c57de net/http.(*connReader).backgroundRead+0x3e /go/go1.17.6/src/net/http/server.go:672<br /><br />
我们将链接后面的debug=1改为debug=2(以unrecovered panic的格式打印堆栈，可读性更高)，可以见到各协程等待时长，可用于分析goroutine泄漏
1<br />2<br />3<br />4<br />5<br />6<br />7<br />8<br />9<br />10<br />11<br />12<br />13<br />14<br />15<br />16<br />17<br />18<br />19<br />20<br />21<br />22<br />23<br />24<br />25<br />26<br />27<br />28<br />29<br />30<br />31<br />32<br />33<br />34<br />35<br />36<br />37<br />38<br />39<br />40<br />41<br />42<br />43<br />44<br />45<br />
goroutine 57914819 [running]:<br />runtime/pprof.writeGoroutineStacks({0x10a4760, 0xc000990fc0})<br /> /gotest/go1.17.6/src/runtime/pprof/pprof.go:693 +0x70<br />runtime/pprof.writeGoroutine({0x10a4760, 0xc000990fc0}, 0x0)<br /> /gotest/go1.17.6/src/runtime/pprof/pprof.go:682 +0x2b<br />runtime/pprof.(*Profile).WriteTo(0xeadca0, {0x10a4760, 0xc000990fc0}, 0xc)<br /> /gotest/go1.17.6/src/runtime/pprof/pprof.go:331 +0x14b<br />net/http/pprof.handler.ServeHTTP({0xc000952191, 0x1822580}, {0x10bd528, 0xc000990fc0}, 0xc000952184)<br /> /gotest/go1.17.6/src/net/http/pprof/pprof.go:253 +0x49a<br />net/http/pprof.Index({0x10bd528, 0xc000990fc0}, 0xc000ca8300)<br /> /gotest/go1.17.6/src/net/http/pprof/pprof.go:371 +0x12e<br />net/http.HandlerFunc.ServeHTTP(0x0, {0x10bd528, 0xc000990fc0}, 0x0)<br /> /gotest/go1.17.6/src/net/http/server.go:2047 +0x2f<br />net/http.(*ServeMux).ServeHTTP(0xc00095219b, {0x10bd528, 0xc000990fc0}, 0xc000ca8300)<br /> /gotest/go1.17.6/src/net/http/server.go:2425 +0x149<br />net/http.serverHandler.ServeHTTP({0xc00168d800}, {0x10bd528, 0xc000990fc0}, 0xc000ca8300)<br /> /gotest/go1.17.6/src/net/http/server.go:2879 +0x43b<br />net/http.(*conn).serve(0xc0015f5220, {0x10c06c0, 0xc000472210})<br /> /gotest/go1.17.6/src/net/http/server.go:1930 +0xb08<br />created by net/http.(*Server).Serve<br /> /gotest/go1.17.6/src/net/http/server.go:3034 +0x4e8<br /><br />goroutine 1 [chan receive, 7547 minutes]:<br />jzserver/main/internal.WaitStopSignal()<br /> /gotest/main/internal/signal.go:15 +0xbc<br />main.main()<br /> /gotest/main/game_server.go:75 +0x145<br /><br />goroutine 50 [select, 48 minutes]:<br />database/sql.(*DB).connectionCleaner(0xc0000a24e0, 0xc0001ca8d0)<br /> /gotest/go1.17.6/src/database/sql/sql.go:1068 +0xbd<br />created by database/sql.(*DB).startCleanerLocked<br /> /gotest/go1.17.6/src/database/sql/sql.go:1055 +0x105<br /><br />goroutine 49 [chan receive]:<br />jzserver/core/os/gtimer.(*Timer).loop.func1()<br /> /gotest/core/os/gtimer/gtimer_timer_loop.go:15 +0x7d<br />created by jzserver/core/os/gtimer.(*Timer).loop<br /> /gotest/core/os/gtimer/gtimer_timer_loop.go:7 +0x5b<br /><br />goroutine 6 [select, 7547 minutes]:<br />database/sql.(*DB).connectionOpener(0xc0000a24e0, {0x10c0618, 0xc00021c440})<br /> /gotest/go1.17.6/src/database/sql/sql.go:1196 +0x93<br />created by database/sql.OpenDB<br /> /gotest/go1.17.6/src/database/sql/sql.go:794 +0x188
3. 其他总结
1<br />
brew install graphviz<br />
其他系统安装参考Graphviz Download。
