Go 库性能分析工具pprof

场景

我们一般没必要过度优化 Go 程序性能。但是真正需要时，Go 提供的 pprof 工具能帮我们快速定位到问题。比如，我们团队之前有一个服务，在本地和测试环境没问题，一到灰度环境，就报 cpu 负载过高，后经排查，发现某处代码死循环了。我把代码简化成如下：

// 处理某些业务，真实的代码中这个死循环很隐蔽
func retrieveSomeThing() {
for {}
}
// 处理其他的一些业务，无意义，用于后续做例子
func doSomeThing() {
do1()
for i := 0; i < 200000000; i++ {}
do2()
}
// 无意义
func do1() {
for i := 0; i < 200000000; i++ {}
}
// 无意义
func do2() {
for i := 0; i < 200000000; i++ {}
}
func main() {
go retrieveSomeThing()
 go doSomeThing()
// 阻塞一下
time.Sleep(3 * time.Second)
}

解决问题前，先介绍下 pprof。

pprof

pprof 包会输出运行时的分析数据(profiling data)，这些数据可以被 pprof 的可视化工具解析。Go 标准库主要提供了两个包：

• runtime/pprof 通过写入到文件的方式暴露 profile 数据；

• net/http/pprof 通过 http 服务暴露 profile 数据，适用于守护进程。

生成 profile 文件

CPU 性能分析

在 runtime/pprof 中，使用StartCPUProfile开启 CPU 性能分析。退出程序前，需要调用StopCPUProfile把采样数据 flush 到输出文件。

采样的频率默认是 100 Hz（每秒 100 次）。

// 输出到标准输出，一般是指定文件
if err := pprof.StartCPUProfile(os.Stdout); err != nil {
   log.Fatal("could not start CPU profile: ", err)
}
defer pprof.StopCPUProfile()

内存性能分析

调用 WriteHeapProfile 开启内存性能分析：

// 输出到标准输出，一般是指定文件
if err := pprof.WriteHeapProfile(os.Stdout); err != nil {
   log.Fatal("could not write memory profile: ", err)
}
}

分析 profile 文件 && 优化代码

以开篇的代码为例，由于是 CPU 过载，我们可以在 main 函数开启 CPU Profile：

// 通过参数指定 cpu profile 输出的文件
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to `file`")
func main() {
flag.Parse()
if *cpuprofile != "" {
f, err := os.Create(*cpuprofile)
if err != nil {
log.Fatal("could not create CPU profile: ", err)
}
// 开启 CPU 分析
if err := pprof.StartCPUProfile(f); err != nil {
log.Fatal("could not start CPU profile: ", err)
}
defer pprof.StopCPUProfile()
}
// 业务代码
go retrieveSomeThing()
 go doSomeThing()
// 模拟阻塞
time.Sleep(5 * time.Second)
}

我们执行命令，输出 profile 文件到 cpu.prof。

go run main.go -cpuprofile cpu.prof

go tool pprof

Go 提供性能解析工具：go tool pprof。我们使用 go tool 打开 profile 文件。

> go tool pprof cpu.prof
Type: cpu
Time: Nov 16, 2022 at 1:40pm (CST)
Duration: 5.17s, Total samples = 4.54s (87.75％)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

这是个交互式的界面，输入help可以查看所有命令。

top 命令

我们使用 topN 命令，查看根据 flat 从大到小排序的前 N 条数据。

(pprof) top10
Showing nodes accounting for 4650ms, 100％ of 4650ms total
     flat  flat％   sum％        cum   cum％
   4220ms 90.75％ 90.75％     4450ms 95.70％  main.retrieveSomeThing
    230ms  4.95％ 95.70％      230ms  4.95％  runtime.asyncPreempt
     80ms  1.72％ 97.42％      200ms  4.30％  main.doSomeThing
     70ms  1.51％ 98.92％       70ms  1.51％  main.do2 (inline)
     50ms  1.08％   100％       50ms  1.08％  main.do1 (inline)

top 命令返回数据有5个指标：

• flat : 本函数占用的 CPU 时间，不包括调用函数的时间；

• flat％ : flat 占的百分比；

• sum％ : 前面 flat％ 的总和；

• cum : 累计时间，包括调用的函数的时间；

• cum％ : cum 的百分比。

以main.doSomeThing（排第三的函数）为例子，耗时为：

func doSomeThing() {                   // flat: 80ms  cum: 200ms
do1()                                // 执行时间 50ms
for i := 0; i < 200000000; i++ {}    // 执行时间 80ms
do2()                                // 执行时间 70ms
}

doSomeThing 的 flat 的值为：

for i := 0; i < 200000000; i++ {}的执行时间（80ms），不包括do1和do2的时间。

doSomeThing 的 cum 的值为：

cum(200ms) = doSomething的flat(80ms) + do1的flat(50ms) + do2的flat(70ms)

ps: top 可以使用 -cum 参数来指定，根据 cum 排序。

list 命令

明白了 top 的指标的意思，我们关注到，排在 top1 的函数是 retrieveSomeThing。可以使用 list 命令，查看 retrieveSomeThing 耗时：

(pprof) list retrieveSomeThing
Total: 4.65s
ROUTINE ======================== main.retrieveSomeThing in /xxxx/pprof_note/pprof/main.go
    4.22s      4.45s (flat, cum) 95.70％ of Total
     10ms       10ms      1:package main
        .          .      2:
        .          .      3:import (
        .          .      4:   "flag"
        .          .      5:   "log"
        .          .      6:   "os"
        .          .      7:   "runtime/pprof"
        .          .      8:   "time"
        .          .      9:)
        .          .     10:
        .          .     11:// 处理某些业务，真实的代码中这个死循环很隐蔽
        .          .     12:func retrieveSomeThing() {
    4.21s      4.44s     13:   for {
        .          .     14:   }
        .          .     15:}
        .          .     16:
        .          .     17:// 处理其他的一些业务，无意义，用于后续做例子
        .          .     18:func doSomeThing() {

我们定位到13行需要优化。

来源：https://juejin.cn/post/7166518730514497543