小马别过河

V1

2022/11/16阅读:24主题:默认主题

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 162022 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.7590.75%     4450ms 95.70%  main.retrieveSomeThing
     230ms  4.9595.70%      230ms  4.95%  runtime.asyncPreempt
      80ms  1.7297.42%      200ms  4.30%  main.doSomeThing
      70ms  1.5198.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),不包括do1do2的时间。

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行需要优化。

总结

pprof 还有很多玩法,包括其他的性能指标,go tool 的其他命令,profile 文件的可视化等。这个留给读者自行扩展阅读。

本文主要参考了 Russ Cox 大神的文章:《Profiling Go Programs》 (https://go.dev/blog/pprof)。文章为反驳 "Go性能不如其他语言"的观点,借助 pprof 大幅度优化了程序的运行时间和内存。强烈推荐看一下。

分类:

后端

标签:

Golang

作者介绍

小马别过河
V1