威威牛依赖前提
程序中引入pprof包后可以直接查看线上的服务性能数据
import (
_ "net/http/pprof"
)
触发方法
# 比如程序对外暴露8001端口
go tool pprof http://127.0.0.1:8001/debug/pprof/profile?seconds=60
结果解读
如果没有添加统计时间参数，则触发之后会默认进入30s统计阶段，之后进入交互是界面，可以查看性能数据。我们先这样看，top -cum，是按照cum列按占用时间顺序显示前10个。
[@zyz-4 ~]$ go tool pprof http://localhost:8001/debug/pprof/profile
Fetching profile from http://localhost:8001/debug/pprof/profile
Please wait... (30s)
Saved profile in /data/home/jiyalei/pprof/pprof.localhost:8001.samples.cpu.002.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top -cum
10ms of 80ms total (12.50%)
Showing top 10 nodes out of 55 (cum >= 10ms)
flat flat% sum% cum cum%
0 0% 0% 60ms 75.00% runtime.goexit
0 0% 0% 30ms 37.50% dproxy/helper.(*DataManager).StartRun
0 0% 0% 30ms 37.50% dproxy/helper.(*DataManager).realRun
10ms 12.50% 12.50% 30ms 37.50% dproxy/helper.(*DataManager).startRealTimer
0 0% 12.50% 20ms 25.00% dproxy/helper.(*RpcClient).RealGetFunc
0 0% 12.50% 10ms 12.50% dproxy/helper.(*RpcClient).GetNewClient
0 0% 12.50% 10ms 12.50% encoding/gob.(*Encoder).Encode
0 0% 12.50% 10ms 12.50% encoding/gob.(*Encoder).EncodeValue
0 0% 12.50% 10ms 12.50% encoding/gob.(*Encoder).encode
0 0% 12.50% 10ms 12.50% encoding/gob.(*Encoder).encodeStruct
(pprof)
top命令默认显示10个，可以通过topN的方式显示N个，cum参数表示按照cum列排序。
flat的意思是本地取样计数，cum的意思是累积取样计数，具体含义引用自官方文档：
本地取样计数和累积取样计数。本地取样计数的含义是当前函数在取样中直接出现的次数。累积取样计数的含义是当前函数以及当前函数直接或间接调用的函数在取样中直接出现的次数。所以，存在这样一种场景：对于一个函数来说，它的本地取样计数是0。因为它没有在取样中直接出现过。但是，由于它直接或间接调用的函数频繁的直接出现在取样中，所以这个函数的累积取样计数却会很高。我们以上图中的函数mian.main为例。由于main.main函数在所有取样中都没有直接出现过，所以它的本地取样计数为0。但又由于它是命令源码文件中的入口函数，程序中其他的函数都直接或间接的被它调用。所以，它的累积取样计数是所有函数中最高的。注意，不论是本地取样计数还是累积取样计数都没有把函数对自身的调用计算在内。函数对自身的调用又被称为递归调用.
我们通常看累计取样计数cum的时间，可以大致体现出来当前的耗时。可以通过list + 函数名的方式查看具体函数内部的占用时间，仅限于“触发方法二”：
(pprof) list StartRun
Total: 70ms
ROUTINE ======================== dproxy/helper.(*DataManager).StartRun in /home/jiyalei/serving_clean/backend/src/dproxy/helper/dataManager.go
0 10ms (flat, cum) 14.29% of Total
. . 72:}
. . 73:
. . 74://run DataManager on caller's gorountine, so caller will be blocked
. . 75:func (self *DataManager) StartRun() {
. . 76: go self.startTotal()
. 10ms 77: self.realRun()
. . 78:}
. . 79:
. . 80:func (self *DataManager) realRun() {
. . 81: if self.RealInval > 0 {
. . 82: self.startRealTimer()
(pprof)
可以看出主要耗时在realRun,我们继续list realRun
(pprof) list realRun
Total: 70ms
ROUTINE ======================== dproxy/helper.(*DataManager).realRun in /home/jiyalei/serving_clean/backend/src/dproxy/helper/dataManager.go
0 10ms (flat, cum) 14.29% of Total
. . 77: self.realRun()
. . 78:}
. . 79:
. . 80:func (self *DataManager) realRun() {
. . 81: if self.RealInval > 0 {
. 10ms 82: self.startRealTimer()
. . 83: } else {
. . 84: //This is useless, program should exit
. . 85: Log.Error("realInval must > 0 !")
. . 86: Log.Close()
. . 87: panic("realInval must > 0 !")
(pprof)
会看到主要耗时在startRealTimer,依次继续，可以看到RealGetFunc处理，继续往里层找，最后发现主要在远程调用耗时，这个就可以理解了。
(pprof) list RealGetFunc
Total: 70ms
ROUTINE ======================== dproxy/helper.(*RpcClient).RealGetFunc in /home/jiyalei/serving_clean/backend/src/dproxy/helper/dataRpcClient.go
0 10ms (flat, cum) 14.29% of Total
. . 110: defer client.Close()
. . 111: req := &RpcRealRequest{
. . 112: VersionId: self.versionId,
. . 113: SeqId: seqId,
. . 114: }
. 10ms 115: if err = client.Call("RpcServer.RpcGetItems", req, &reply); err != nil {
. . 116: return nil, err
. . 117: }
. . 118:
. . 119: switch reply.Status {
. . 120: case STATUS_UPDATED:
(pprof)
扩展用法
- web命令
会生成一个统计矢量图，有详细调用关系，更容易查看。依赖安装包graphviz（ubuntu下这样安装sudo apt-get install graphviz）。有GUI界面会自动打开改图，无GUI会提示生成路径。
# 输出所有调用关系
(pprof) web
# 只输出和指定函数相关的调用关系图
(pprof) web GetNewClient
类似下图：
