关于golang:如何借助go-pprof分析真实场景问题

作者: 名扬

前言

本文将分享一个 笔者在理论业务开发当中遇到的 一个乏味的问题。并且本文还会讲述笔者是如何借助 go tool pprof 剖析和定位问题起因的。心愿本篇的分享 可能给读者在日常开发与定位问题方面 带来一些启发。本文如有任何纰漏与倡议欢送在评论区斧正与探讨（笔芯）。

浏览本文后，心愿你能播种：

• 1. 把握剖析与定位问题的办法。
• 2. 可能应用 pprof 定位问题或优化性能。
• 3. 理解 value context 的实现机制。

整个问题的剖析及定位步骤如下，通过下图，读者能够对全篇文章 定位问题的流程有个整体的意识，便于后续文章的浏览与了解。

步骤一：编写 demo。

定位特定问题时，我喜爱独自写个污浊的 demo。1 这样能够去除业务等其余代码带来的烦扰。2 便于 debug 调试。3. 便于控制变量，这里的控制变量 就相似 咱们在做科学实验时，如果影响试验后果的因素很多，咱们心愿管制一些变量不变，只变动个别变量，这样更容易找出科学实验中的 因果关系，其实咱们日常定位问题也常常应用这种办法。控制变量法。写个 demo 能够更不便的去控制变量。

步骤二：查看 git 提交日志。

当定位问题时，这其实是一个很天然的想法，如果之前的代码没问题，当初呈现问题了，那么可能是某个谬误的提交造成的。通过查看 git 的提交日志能够疾速的缩写问题定位的范畴。这里举荐个 git 好用的工具 git bisect，git bisect 借助二分查找法，可能在海量的提交里疾速定位到问题的起因。尽管本文没用到这个工具，但理论工作中 git bisect 还是十分实用的，感兴趣的小伙伴倡议自行搜寻理解下。

步骤三：引入 pprof 工具。

pprof 工具是 go 官网提供的一个可能监控 go 程序 cpu、内存、协程、block 等信息的工具，pprof 常被用于问题定位、性能优化、过程监控等方面。pprof 简直是代码无侵入的，任何 go 程序都能够十分轻松的应用此工具，后文会具体介绍。
步骤四：剖析源代码。
任何的问题定位，要想齐全理解其背地的起因，都逃不过应用 最奢侈 简略的形式，看代码。

1、问题形容

背景形容：公司外部有个 redisdao 插件，是基于开源库 go-redis 进行的封装。其目标是提供更加敌对的接口及引入了配置管理、日志记录等性能。读者只须要晓得 redisdao 是基于 go-redis 开源库封装的即可。

问题形容：在开发一个须要频繁向 redis 写入数据的需要时，发现了一个乏味的景象：通过 redisdao 循环向 redis 写入数据会越来越慢（留神这里是越来越慢。慢的速度是线性增长的）。这就有些不堪设想了，查看云端 redis 服务的负载并不高，应用本地 redis 试验也是如此。为了简化问题定位，去除业务逻辑，写了一个纯正的从 redis 中的循环读取数据的 demo。伪代码如下。通过重复验证发现（上文提到的控制变量法），问题出在 redisdao 1.0.21 之后的版本（1.0.21 版本没有问题的）。但应用 redisdao 1.0.24 版本则能够复现此问题。

func main(){
   ...
   key := "testRedisDao"
   // 获取 redis 实例
   r := redisdao.NewSimpleXesRedis(context.Background(), "rediscon")
   i :=0
   t1,t2 := time.Now(),time.Now()
   for {val, err := r.Get(key, nil)
      if err == redis.Nil { // 此 key 不存在
         fmt.Printf("not exist key\n")
      } else if err != nil { // 异样
         fmt.Printf("error :%s\n",err.Error())
      }
      i++
      if i % 10000 ==0{t2 = time.Now()
         fmt.Printf("get value :%s cost: %d ms\n",val,t2.Sub(t1).Milliseconds())
         t1 = time.Now()}
   }
}

其实定位到这里，很天然的会想到就是 redisdao 在降级过程中引入了 bug。

然而这个问题比拟 诡异，不是整个过程始终慢，而是越往后执行越慢，如下所示，首次执行 1w 主要 5s，到最初曾经变成了 162s。

因为这个问题景象比拟乏味，所以就想理解下为啥会这样，于是去翻了下 redisdao 这个期间的提交记录。

1.0.21 之后提交了挺多代码，不过最重要的是引入了go-redis 的 v8 版本（这点很重要，前面会用到）。在这么屡次提交中寻找起因，无异于海底捞针（这里其实能够应用 git bisect 工具）。

因为执行慢属于 性能类问题 ，很天然的想到了应用 go tools 中的 pprof 定位下 到底是哪里耗时了。
于是开始了新一轮的定位。

2、Pprof 剖析

应用 pprof 分析程序，可分为 4 步：

• (1)后期筹备，装置相干工具，graphviz 用户可视化剖析，ppof 用于 web 剖析。
• (2)程序中植入 pprof 埋点，目前有三种罕用的形式，go test bench、引入 runtime/pprof 包、引入 net/http/pprof 包。
• (3)生成监控信息，不同植入形式对应不同的文件生成办法，后文会介绍。
• (4)剖析监控信息，剖析监控工具包含 原生的 go tool pprof 以及 更加先进的 pporf。
  整体流程如下所示：
  

2.1 后期配备

2.1.1 装置 graphviz

go pprof 的图形化剖析依赖于 graphviz

// 情谊提醒：装置 graphviz 须要迷信上网
brew install graphviz

2.1.2 装置 pprof

pprof 提供了网页版本的剖析界面，并反对应用火焰图剖析性能。

go get -u github.com/google/pprof

2.2 程序中启用 pprof 监控

在程序中启用 pprof 监控，罕用的办法用三种：

• (1)go test benchmart，联合 go test 应用。实用于 对性能要求较高的函数进行性能优化剖析。
• (2)runtime/pprof，将 pprof 监控信息以文件模式输入，在程序进行后进行剖析。实用于剖析一次性工作性程序，如 worker 类过程。
• (3)net/http/pprof，启用 web 监控，长处能够在程序运行整个生命周期进行监控。

2.2.1 搭配 go test 应用

编写单元测试代码如下

// add.go
func Add(a,b int) (sum int){
   for i:=0;i<a;i++{sum += Add(i,b)
      sum = sum % 1000000009
   }
   return sum
}
 // add_test.go
func BenchmarkAdd(b *testing.B) {
   for i:=0;i<b.N;i++{Add(10,i+1)
   }
}

运行如下命令，输入 cpu.prof 文件。

go test -bench=. -cpuprofile=profile

profile 文件的剖析，后文会具体介绍。

2.2.2 runtime/pprof 文件模式输入

引入 “runtime/pprof” 包，创立 profile 文件，并采样 cpu 数据。

import (_ "runtime/pprof")

func main(){
    // 创立 profile 文件 
    file, err := os.Create("./profile") 
    if err != nil {return} 
   // 采样 cpu 数据
   pprof.StartCPUProfile(file) 
   defer pprof.StopCPUProfile() 
    
    // 业务代码
    ...
    
}

失常启动程序即可，程序运行完结后会输入 profile 文件。

go run main.go

2.2.3 net/http/pprof http 监控

(1) 引入 “net/http/pprof” 包，并 监听一个可用端口。伪代码如下：

import (_ "net/http/pprof")

func main(){
    // 监听一个可用端口，若程序自身为 web 程序，则此步骤可省了，pprof 会应用程序已监听的端口
    go func() {_ = http.ListenAndServe("0.0.0.0:6060", nil)
    }()
    
    // 业务代码
    ...
    
}

(2) 像平常一样启动程序

// 运行时同平常一样，无需减少任何额定参数
go run main.go

（3）应用浏览器关上如下网址，网址中的 6060 端口号即为程序中监听的端口号：

http://localhost:6060/debug/pprof/

关上网址后能够看到许多信息，如下图所示，包含 内存调配、运行的携程数量、互斥锁等。每个选项上面还有简略的形容。
多说一句，从下图能够看出 pprof 监控的弱小，pprof 能够用来做 CPU 运行剖析、内存剖析、协程泄露、阻塞剖析、互斥剖析 等问题。

点击 profile 可输入 profile 文件。点击后要期待 30 秒（默认 30 秒），将在这 30 秒过程中采集 cpu 运行信息。

2.3 剖析监控信息

2.3.1 go tool pprof 剖析

应用 go tool pprof 工具剖析上文通过三种形式生成的 prfile。

go tool pprof ./profile

程序将会进入一个交互式终端，能够应用 help 命令，终端将会输入反对的命令。
本文次要用到了 top 命令。

go tool 还反对其余丰盛的性能，如通过 web、pdf 等命令，输入调用图

有趣味的能够自行 google 理解丰盛的 go tool pprof 性能。

针对上文的 net/http/pprof 形式，实际上能够间接联网剖析，无需生成文件，命令如下：

go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60

2.3.2 pprof 剖析

应用 pporf 工具进行剖析，须要先下载 pprof 工具，下载办法见 2.1 章节。
运行如下命令进行剖析：

pprof -http=:8080 ./profile 

浏览器将主动关上，如下界面，pprof 性能十分弱小。包含 top、graph、flame graph、peek、source、disassemble。

本次定位次要用到了，top、source、peek、graph 性能。想要深刻理解可自行 google。
top 显示占用 cpu 最多的几个函数。

source 能够查看源代码的耗时，十分好用。

peek，显示内容与 top 相似。

graph，这个大家应该曾经相熟了。

flame grap 火焰图

3、对 Redisdao 剖析

上一节咱们简略的介绍了 pprof 性能剖析工具。上面就应用 pprof 剖析 redisdao 慢的起因
其实通过下面的 top 以及 graph 剖析，咱们能够显著的感觉到一个奇怪的中央，就是 context.value() 函数的耗时有点过于高了。

很惋惜，pprof 只能帮咱们到这了，它只能通知咱们程序哪里耗时多，不能通知咱们为什么。在这个问题上，只通知了咱们 where 但并未通知咱们 why。

对于 Why 的剖析，有时候只能凭教训和眉头一皱; 计上心来了。这里分享一下我定位的过程。

3.1 谜底揭晓

下面提到了，redisdao 之后更新了代码，减少了对 go-redis v8 的反对。对于 go-redis v8 我恰好理解下，go-redis v8 较 go-redis 减少了一个很重要的性能，就是 链路跟踪 trace。
而且 trace 性能在 golang 中的实现，基本上都是应用 context 来实现的（包含 rpcx、go-zero 等框架）。所以基于以上教训也能够揣测的确是因为引入 go-redis v8 导致的耗时。
但这里 就有意思了，难道这是 go-redis v8 的 bug，（原本想用 go-redis v8，而不是应用 redisdao 的封装，再写个 demo 测试下，不过还好，还没到这一步我就想到了问题的要害），对于这个高星我的项目我还是有些信念的（但开源我的项目也不能全信，定位 bug，肯定放弃着大胆猜想，小心求证的准则），而且这么显著的 bug，应该早就被发现了，所以还是要再排查下是不是因为咱们的应用形式不当导致的。

这里只能再认真研读 redisdao 的代码了。认真翻阅代码后，我发现了一个问题。上面贴出代码调用过程：

tracer.Start 调用了 contex.Withvalue 与 context.Value 函数，上面贴出两个函数的实现：

// 插入 value
func WithValue(parent Context, key, val interface{}) Context {
   if key == nil {panic("nil key")
   }
   if !reflectlite.TypeOf(key).Comparable() {panic("key is not comparable")
   }
   return &valueCtx{parent, key, val}
}
// 读取 value
func (c *valueCtx) Value(key interface{}) interface{} {
   if c.key == key {return c.val}
   return c.Context.Value(key)
}

这里要留神 context 的实现，context 实际上是 链表 数据结构 并非 hash 构造。这也是为什么 contex 能不加锁也能实现，并发平安拜访。

// A valueCtx carries a key-value pair. It implements Value for that key and
// delegates all other calls to the embedded Context.
type valueCtx struct {
   Context
   key, val interface{}}

相似如下构造：
3.2 context 引发的“血案”
contex.Withvalue 是向链表中插入值，链表会一直的增大。value 会遍历链表去取值，工夫复杂度是 O(N)。这里眉头一皱; 计上心来的想到：程序越跑越慢，应该就是因为 context 链表 越来越大导致的。那么有了这个想法，接下来就是验证了。

回头再去看 rediadao 的代码发现，果然 ctx 是在调用 newSimpleXesRedis 时传递的，而整个过程当中会始终应用这个 ctx。这就导致了，ctx 链表越来越长，value 时也就越来越耗时，进而导致程序会越来越慢。如下图，main 函数是 在循环里面调用的 newSimpleXesRedis。

那么如果咱们猜想正确，只有将 newSimpleXesRedis 放入 for 函数外面就没问题了。试了一下，果然如此：

再次启动程序果然快的飞起。

下面的后果再一次验证了咱们的猜想。好了，到此为止，问题的起因总算是上不着天; 下不着地了。整个过程好比破案[捂脸]。

总结
通过这个 RedisDao 越跑越慢的问题定位，咱们学习了 性能剖析工具 go tool pprof 以及 context 的实现。本次定位给我几点启发：

• (1)定位问题要有刨根问底的精力，如果定位到了是 redisdao 降级导致的，间接甩给 redisdao 开发者解决，可能就不会有前面的播种了。
• (2)很多时候一个好的工具可能帮忙咱们疾速定位问题。工欲善其事必先利其器。
• (3)问题定位很多时候也是要依赖直觉的，那么直觉如何造就，只能通过一直的教训积攒与刻意练习获取。
• (4)很多时候其实是 先想到后果，再通过数据与试验去验证。
• (5)本次的总结与输入后，温故而知新，对 pprof 与 context 常识的了解更加全面了，同时总结也是一个从新提取的过程，让本人把握的更加粗浅。其实总结也是下面说到的 造就直觉的刻意练习。