Jude's Vuepress

本讲介绍 Go 程序性能分析的技能。

在业务需求初期，其体量往往比较小，即使做了性能优化，收益却并不大。随着业务量的上升，情况随之发生变化。哪怕某个重量级的业务需要几十上百台服务器支撑，哪怕性能优化只提升约 20% 的效益。收益不仅是节省下来的运行时间，更是硬件成本的投入和运行稳定性的保证。这足以证明性能优化的重要性。

性能优化的原则遵循二八定律。在进行优化时，想要尽善尽美往往是非常难的。我们应优先处理亟需优化的关键部分，如此便可获得大部分效益了。剩下的部分很可能投入较多，但收益并不大。

Go 语言本身是面向服务端软件设计的，在 Go SDK 中自带了 pprof 性能分析工具。具体说来，有两个相关的包：runtime/pprof 和 net/http/pprof。后者是对前者的封装，用于提供网络侧访问。

本讲内容将从 CPU 和内存分析两方面介绍 pprof 的使用。

# 生成运行报告

假设现在有如下代码，它实现了对 10000 个随机整数的排序：

go
复制代码func randomIntCreator() []int {
   var arr []int
   for i := 0; i < 10000; i++ {
      arr = append(arr, rand.Intn(100000000))
   }
   return arr
}
func sort() {
   arr := randomIntCreator()
   var n = len(arr)
   for i := 0; i <= n-1; i++ {
      for j := i; j <= n-1; j++ {
         if arr[i] > arr[j] {
            t := arr[i]
            arr[i] = arr[j]
            arr[j] = t
         }
      }
   }
}

若要对其进行压力测试，观察其运行 100 次的稳定性和耗时情况，仅需如下调用即可：

go
复制代码func main() {
   f, _ := os.OpenFile("cpu.pprof", os.O_CREATE|os.O_RDWR, 0644)
   pprof.StartCPUProfile(f)
   defer f.Close()
   defer pprof.StopCPUProfile()
   for i := 0; i < 100; i++ {
      sort()
   }
}
💡 提示：压力测试是非常实用的测试方法，它能模拟高并发、大流量等情况，从而衡量程序运行的稳定性和正确性。某些问题可能尽在运行压力较大时才会显现，某些性能问题在程序反复执行后更加明显。

如上代码所示，main() 函数中创建了 cpu.pprof 文件并将返回的 *File 值赋给变量 f，紧接着调用 pprof.StartCPUProfile() 函数传入 f 变量，开始执行 CPU 运行分析。

在之后使用断言关闭文件，调用 pprof.StopCPUProfile() 停止 CPU 运行分析。最后是循环 100 次调用 sort() 函数，进行测试。程序运行时，首先会尝试打开 cpu.pprof 文件，当该文件不存在时则会创建它。紧接着便会开始 CPU 分析。随后开始 100 次执行 sort() 函数。执行后停止 CPU 分析，关闭文件。

运行上述代码，稍等片刻，控制台便会输出：

Process finished with the exit code 0

表示程序正常退出，结束运行。此时来到项目根目录下，可以看到 cpu.pprof 文件。文件中记录着从开始 CPU 分析到停止 CPU 分析之间的函数耗时情况。

# 交互式终端视图

打开终端，定位到项目根目录下，执行：

shell
复制代码go tool pprof cpu.pprof

便可启动交互式终端视图，获取文件中保存的各种信息了，运行结果示例如下：

Type: cpu

Time: May 18, 2022 at 10:11am (CST)

Duration: 12.73s, Total samples = 8.28s (65.03%)

Entering interactive mode (type "help" for commands, "o" for options)

(pprof)

可以看到，上述文字说明：测试类型是 CPU，测试时间是 2022 年 5 月 18 日 早上 10:11，程序运行总时长是 12.73 秒，测试采样时间是 8.28 秒，占总时长的 65.03%。倒数第 2 行是命令说明：输入 help 显示帮助信息，列出支持的命令；输入 o 进行选项设置。最后一行是等待用户输入行。

较为常用的是 top 命令，它能列出函数的执行时长，当我们成功进入交互式终端，并执行 top 命令后，可以看到如下结果输出：

Showing nodes accounting for 8.14s, 98.31% of 8.28s total

Dropped 29 nodes (cum <= 0.04s)

Showing top 10 nodes out of 18

flat flat% sum% cum cum%

7.97s 96.26% 96.26% 8.06s 97.34% main.sort

0.09s 1.09% 97.34% 0.09s 1.09% runtime.asyncPreempt

0.05s 0.6% 97.95% 0.05s 0.6% runtime.stdcall1

0.02s 0.24% 98.19% 0.10s 1.21% runtime.findrunnable

0.01s 0.12% 98.31% 0.05s 0.6% runtime.wakep

0 0% 98.31% 8.06s 97.34% main.main

0 0% 98.31% 0.05s 0.6% runtime.bgscavenge.func2

0 0% 98.31% 0.05s 0.6% runtime.checkTimers

0 0% 98.31% 8.06s 97.34% runtime.main

0 0% 98.31% 0.15s 1.81% runtime.mcall

我们从上往下对上述输出进行解读：

  • 第 1 行的意思是以下信息显示了总计耗时 8.14 秒的函数执行情况，占总耗时的 98.31%。
  • 第 2 行的意思是被省略的执行函数总计个数：29，它们的总耗时小于等于 0.04 秒。
  • 第 3 行的意思是以下表格列出了被执行的 18 个函数，以耗时从长到短排序，前 10 个函数。

显然，sort() 函数耗时 7.97秒，自身占比 96.26%。其次还可以找到 main() 函数，其中并没有什么实际的逻辑，但 sort() 函数在其中，所以总时长是 8.06 秒，累计占比 98.31%，但自身时长和占比都是 0。

表格中的 5 列数据的含义如下：

列名 含义
flat 函数的执行耗时
flat% 函数的执行耗时占 CPU 总时间的比例
sum% 前面每一行的函数的执行耗时占比的总和
cum 该函数加上该函数调用的函数的总耗时
cum% 该函数加上该函数调用的函数的总耗时占 CPU 总时间的比例

可见，通过在代码的特定位置启动和停止 CPU 分析，可以很好地测量被其包含的代码运行状况。非常适用于一次运行的情况，即只跑一次程序，手动采集性能数据。

# Web 可视化视图

Web 可视化视图提供了查看性能分析结果的另一种方式，它更加直观。特别是对于函数调用的层次结构而言，看上去会更加方便。

对于本例，在进入终端交互视图后，执行 web 命令，便会打开系统默认的浏览器，显示如下内容：

image-20220518111057034.png

为了方便查看，网页支持使用鼠标左键拖拽视图显示的内容，也支持通过滚轮进行视图缩放。

💡 提示：正常情况下，上图所示的分析结果与终端输出的结果相同。在编写本讲时，我运行了两次，所以结果略有不同。

# 实时性能分析

正如前文中所述：在代码特定的位置进行 CPU 检测可以达到只跑一次程序，便能采集性能数据的情况。但现实中往往还需要实时观测内存的占用情况，此时，net/http/pprof 包就派上用场了。

还是对随机数排序的案例，将 main() 函数稍加修改，便能通过 Web 页观测内存使用情况了，具体如下：

go
复制代码import _ "net/http/pprof"
func main() {
   go func() {
      err := http.ListenAndServe("127.0.0.1:9090", nil)
      if err != nil {
         panic(err)
      }
   }()
   for i := 0; i >= 0; i++ {
      fmt.Printf("运行第%d次\n", i+1)
      sort()
      time.Sleep(1 * time.Second)
   }
}

可以看到，程序一上来启动了一个协程，目的是开启本地 http 服务器，响应 9090 端口。然后便是 for 循环了，请大家特别留意 for 循环的终止条件，此处改为 i>=0。显然这个循环将一直持续下去，直到程序被强行停止。循环体的内容也做了一些调整，即每隔 1 秒执行一次随机数的生成和排序，并输出运行次数。

❗️ 注意：通过 Web 观察 pprof 实时内存测试结果，必须导入 net/http/pprof 包。

运行上述代码，可以看到控制台有稳定的文字输出。然后适用浏览器打开：http://localhost:9090/debug/pprof/ (opens new window) ，可以看到如下页面：

image-20220518112555878.png

我们可以点击上方的链接进入某个具体的项目查看详情。以下是我在程序刚开始运行和循环体执行了 10 次后的内存占用概览信息：

程序刚开始运行：

# runtime.MemStats

# Alloc = 1123208

# TotalAlloc = 1123208

# Sys = 8407496

# Lookups = 0

# Mallocs = 2138

# Frees = 143

# HeapAlloc = 1123208

# HeapSys = 4030464

# HeapIdle = 1818624

# HeapInuse = 2211840

# HeapReleased = 1818624

# HeapObjects = 1995

# Stack = 163840 / 163840

# MSpan = 37400 / 49152

# MCache = 4672 / 16384

# BuckHashSys = 1447574

# GCSys = 1931744

# OtherSys = 768338

# NextGC = 4473924

# LastGC = 0

循环体执行约 10 次后：

# runtime.MemStats

# Alloc = 1130216

# TotalAlloc = 4646560

# Sys = 13588888

# Lookups = 0

# Mallocs = 2606

# Frees = 1442

# HeapAlloc = 1130216

# HeapSys = 8192000

# HeapIdle = 6242304

# HeapInuse = 1949696

# HeapReleased = 3850240

# HeapObjects = 1164

# Stack = 196608/ 196608

# MSpan = 46104/ 49152

# MCache = 4672/ 16384

# BuckHashSys = 1448454

# GCSys = 2638432

# OtherSys = 1047858

# NextGC = 4194304

# LastGC = 1652842675951237400

需要特别说明的是 trace，当我们点击 trace 后，会下载到一个文件。这个文件的名称默认为 trace。通过在终端执行：

shell
复制代码go tool trace trace

这句命令中，第 2 个trace 指文件名。执行后，可以观测到完整的跟踪等信息，这些信息同样通过浏览器查看：

image-20220518113304636.png

如上图所示，在完整的 trace 文件中包含了众多实用的状态数据。比如，当我们点击 View Trace 时，可以看到具体的函数调用时长等信息，如下图所示：

image-20220518114238745.png

# 小结

🎉 恭喜，您完成了全部课程的学习！

📌 以下是本次课程的重点内容总结：

  1. Go 程序性能分析工具的使用

正如本讲开头所述：进行性能优化的收益不仅是节省下来的运行时间，更是硬件成本的投入和运行稳定性的保证。在进行性能优化时，应遵循二八原则，首要任务是解决最影响性能的问题点。

Go SDK 中包含了进行性能分析的工具：pprof。本讲主要介绍了使用它来进行 CPU 和内存的性能分析。此外，pprof 还能获取锁竞争状态、线程/协程创建情况等数据，这里就不再一一赘述了。

35-个性化golang设置