go tool pprof 性能追踪[推荐]

[TOC] > [参考](https://www.jianshu.com/p/927d800021f4) > [一看就懂系列之Golang的pprof](https://studygolang.com/articles/26918#reply0) ## 概述 性能分析执行时,需要去访问待分析的程序,莱获取分析数据 ## 安装 ### 1. 安装 graphviz 可视化 ``` //安装图形化界面 //win choco install -y graphviz //mac brew install graphviz //centos yum install graphviz ``` ### 2. 安装 http/pprof ``` import _ "net/http/pprof" ``` demo ``` func main() { go func() { log.Println(http.ListenAndServe("0.0.0.0:6060", nil)) }() //业务代码 } ``` 运行程序 `go run main.go` ### 3. 安装 pprof web ui pprof web ui 已经集成 top, svg, list, disassemble, regex search, go-torch。最方便使用 ``` go get github.com/google/pprof ``` ## pprof web ui 使用 **启动业务程序后** ### 查看web端报告 `http://127.0.0.1:6060/debug/pprof/` ### 快速生成 web ui 1. 方法一 [推荐] ``` pprof -seconds 60 -http 127.0.0.1:6061 http://127.0.0.1:6060/debug/pprof/profile ``` 2. 方法二 ``` go tool pprof http://localhost:6060/debug/pprof/profile?second=60 pprof -http 0.0.0.0:7070 binaryfile xxx.pb.gz(profile_file) //profile_file 为上条命令产生的文件,可在命令行中查看到 ``` ## 名词分析 ### 6060/debug/pprof/ 界面  | 类型 | 描述 | | --- | --- | | allocs | **内**存分配情况的采样信息 | | blocks | **阻塞**操作情况的采样信息 | | cmdline | 显示程序启动**命令参数**及其参数 | | goroutine | 显示当前所有**协程**的堆栈信息 | | heap | **堆**上的内存分配情况的采样信息 | | mutex | **锁**竞争情况的采样信息 | | profile | **cpu**占用情况的采样信息，点击会下载文件 | | threadcreate | 系统**线程**创建情况的采样信息 | | trace | 程序**运行跟踪**信息 | ### top 指令分析  | 类型 | 描述 | 举例 | | --- | --- | --- | | 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% | ## 问题 > [参考网站](https://studygolang.com/articles/26918#reply0) ### 问题:cpu过高  1.`go tool pprof http://localhost:6060/debug/pprof/profile?second=60` 2. 输入 `top` ``` (pprof) top flat flat% sum% cum cum% 49.75s 83.88% 83.88% 51.29s 86.48% runtime.cgocall 0.88s 1.48% 85.37% 1.04s 1.75% runtime.deferreturn ``` 3. 查找 `cgocall` 进行 ``` (pprof) list cgocall Total: 59.31s ROUTINE ======================== runtime.cgocall in C:\Go\src\runtime\cgocall.go 49.75s 51.29s (flat, cum) 86.48% of Total . . 102: . . 103: if raceenabled { . . 104: racereleasemerge(unsafe.Pointer(&racecgosync)) ``` ### 问题:内存占用过高 ``` > go tool pprof http://localhost:6060/debug/pprof/heap (pprof) top (pprof) list cgocall ``` ### 频繁垃圾回收 ``` > gc 1 @2.104s 0%: 0.018+1.3+0.076 ms clock, 0.054+0.35/1.0/3.0+0.23 ms cpu, 4->4->3 MB, 5 MB goal, 4 P 1 表示第一次执行 @2.104s 表示程序执行的总时间 0% 垃圾回收时间占用的百分比，（不知道和谁比？难道是和上面的程序执行总时间，这样比较感觉没意义） 0.018+1.3+0.076 ms clock 垃圾回收的时间，分别为STW（stop-the-world）清扫的时间, 并发标记和扫描的时间，STW标记的时间 0.054+0.35/1.0/3.0+0.23 ms cpu 垃圾回收占用cpu时间 4->4->3 MB 堆的大小，gc后堆的大小，存活堆的大小 5 MB goal 整体堆的大小 4 P 使用的处理器数量 > scvg0: inuse: 426, idle: 0, sys: 427, released: 0, consumed: 427 (MB) 426 使用多少M内存 0 剩下要清除的内存 427 系统映射的内存 0 释放的系统内存 427 申请的系统内存 ``` 可以查看切片所占的内存,分析内存占用最大的代码 ``` //linux GODEBUG=gctrace=1 ./xiyouji 2>&1|grep gc //window Set GODEBUG=gctrace=1 ./xiyouji | findstr gc > gc 1 @3.503s 0%: 0+0.99+0 ms clock, 0+0.99/0.99/1.9+0 ms cpu, 4->4->1 MB, 5 MB goal, 4 P > go tool pprof http://localhost:6060/debug/pprof/allocs (pprof) top flat flat% sum% cum cum% 688.56kB 54.71% 54.71% 688.56kB 54.71% bigant/servers/login.newTcpClient 570.04kB 45.29% 100% 570.04kB 45.29% bigant/servers/login.newConList 0 0% 100% 688.56kB 54.71% bigant/servers/login.(*App).HandleCient 0 0% 100% 570.04kB 45.29% bigant/servers/login.init 0 0% 100% 570.04kB 45.29% runtime.doInit 0 0% 100% 570.04kB 45.29% runtime.main (pprof) list newTcpClient ROUTINE ======================== bigant/servers/login.newTcpClient in D:\go\bignat-go\servers\login\client.go 688.56kB 688.56kB (flat, cum) 54.71% of Total . . 74: return &tcpClient{ . . 75: app: app, . . 76: conn: conn, . . 77: nid: uuid, . . 78: quit: make(chan struct{}, 1), 688.56kB 688.56kB 79: sendChan: make(chan servers.Trans, 1024), . . 80: recChan: make([]byte, 2048), . . 81: } ``` ### 协程泄露  ``` > go tool pprof http://localhost:6060/debug/pprof/goroutine (pprof) top Showing nodes accounting for 40, 100% of 40 total Showing top 10 nodes out of 70 flat flat% sum% cum cum% 38 95.00% 95.00% 38 95.00% runtime.gopark 1 2.50% 97.50% 1 2.50% runtime.notetsleepg 1 2.50% 100% 1 2.50% runtime/pprof.writeRuntimeProfile 0 0% 100% 1 2.50% bigant/lib/rpc.NewRpcServer //无异常,使用web 查看 (pprof) web ``` **提示** 通过多次使用`go tool pprof http://localhost:6060/debug/pprof/goroutine` 和`(pprof) web` 即可在UI中详细看到哪个协程增加了 ### 锁的争用 ``` > go tool pprof localhost:6060/debug/pprof/mutex (prof) top ``` 错误实例  ### 阻塞操作 ``` > go tool pprof localhost:6060/debug/pprof/block ```   ### 问题:访问 6060 显示 404 在入口文件中**手动**指定函数 ``` func init() { http.Handle("/debug/pprof/", http.HandlerFunc(pprof.Index)) http.Handle("/debug/pprof/cmdline", http.HandlerFunc(pprof.Cmdline)) http.Handle("/debug/pprof/profile", http.HandlerFunc(pprof.Profile)) http.Handle("/debug/pprof/symbol", http.HandlerFunc(pprof.Symbol)) http.Handle("/debug/pprof/trace", http.HandlerFunc(pprof.Trace)) } func main() { go func() { log.Info(http.ListenAndServe("0.0.0.0:6060", nil)) }() app := login.NewApp() app.Run() } ```