Golang pprof 性能问题分析优化和实战经验

go pprof 中各种 profiler 介绍

Go 自带了一个 pprof 的性能优化和分析的工具，这个工具包括 cpuprof 、memprof ，并且还提供了 Lookup 功能用于获取堆状态信息、线程状态信息、 goroutine 状态信息等。官方的博客有一篇文章介绍用法：《Profiling Go Programs》[1]

CPU profiler

CPU 的主频，即 CPU 内核工作的时钟频率（CPU Clock Speed）[2]，主频的基本单位是赫兹（Hz），但更多的是以兆赫兹（MHz）或吉赫兹（GHz）为单位。时钟频率的倒数即为时钟周期，时钟周期的基本单位为秒（s），但更多的是以毫秒（ms）、微妙（us）或纳秒（ns）为单位。在一个时钟周期内，CPU 会执行一条运算指令；在 1000 Hz 的 CPU 主频下，每 1毫秒可以执行一条CPU运算指令；在1 MHz的CPU主频下，每1微妙可以执行一条CPU运算指令，以此类推。

在默认情况下，Go 语言的运行时系统会以 100 Hz 的的频率对 CPU 的使用情况进行取样，也就是说每秒取样 100 次，为什么使用这个频率呢？因为 100 Hz 既足够产生有用的数据，又不至于让系统产生停顿。在启动 CPU 使用情况记录操作之后，运行时系统就会以每秒100次的频率将取样数据写入到 CPU 概要文件中，通过pprof.StopCPUProfile 函数可以把 CPU 使用情况取样的频率设置为 0 从而来停止取样操作。

Memory profiler

Go 语言运行时系统会对用户应用程序运行期间的所有的堆内存分配进行记录，不管在取样的时候堆内存已用字节数是否有增长，只要有字节被分配且数量足够，内存分析器就会对其进行取样。runtime/pprof.WriteHeapProfile[3] 里面记录了相关使用方法。

Blocking Profile

net/http/pprof, runtime/pprof

goroutine 阻塞的情况要根据业务的实际应用场景去分析，如果业务场景下就是那种需要耗时很久的逻辑，那么就是正常的，比如一些异步定时处理的耗时的任务。一般下线实时请求的服务，goroutine 阻塞的情况就要特别引起重视，避免因为是阻塞而导致协程泄漏，或者因为阻塞而消耗掉过多的 CPU 时间，从而使得正常服务逐步开始响应变慢。

Goroutine Profiler

goroutine 分析器可以分析并查看到进程里面所有活跃 goroutine 的当前堆栈，这个对于线上调试尤其是是阻塞、死锁等问题会十分方便。

关于 Goroutine Profiler 的分析结果，这里需要说明一下，只有显示 “syscall" 状态的 goroutine 才会消费掉我们的操作系统级别的线程，其他的状态比如 ”io wait“ 状态的 goroutine，或者其他状态的协程都不会消费掉我们的操作系统级别的线程，”io wait“ 状态的goroutine 是依附于非阻塞的网络轮询器上的。

go pprof 相关操作和命令介绍

go tool pprof

go pprof 支持在本地运行，但是一般我们很少这样使用，更多的通过 pprof 去分析线上环境的服务情况，也就是应用程序的真实的实时情况。

pprof 工具并不是用 Go 语言编写的，而是由 Perl 语言编写的， go tool pprof 命令会分析指定的概要文件并使得我们能够以交互式的方式访问其中的信息。但是光有概要文件还不够，我们还需要概要文件中信息的来源——命令源码文件的可执行文件。毕竟，概要文件中的信息是对在运行期间的用户程序取样的结果。而可以运行的Go语言程序只能是编译命令源码文件后生成的可执行文件。比如：

  • • cpupprof 就是我们的应用程序的二进制程序
  • • cpupprof.prof 就是这个程序所生成的 cpu prof 文件

更详细的用法和使用示例，可以继续往下看下面的演示过程。

net/http/pprof【推荐使用】

net/http/pprofhttp://localhost:6060/debug/pprof/goroutine?debug=2

svg 矢量图

通过 pprof 工具可以生成一个 svg 的矢量图，查看 svg 矢量图可以帮助我们确认代码的执行流程和调用情况。

brew install graphviz yum -y install graphviz

pprof 实战验证和验证

runtime/pprof【CPU profiling】

代码示例

cpupprof.go 源文件如下：

编译和 go tool pprof 运行分析

go build cpupprof.go 
./cpupprof -cpuprofile=cpupprof.prof
go tool pprof cpupprof cpupprof.prof
  • • top N ：表示采样时间间隔内，耗时最长的 top N
  • • top5 -cum ：cum 表示按第4和第5列排序
  • • web： 表示生成 svg 图


实战说明

net/http/pprof

net/http/pprof

代码示例

http 访问查看和分析 pprof

通过网络访问来查看相关信息 http://localhost:6060/debug/pprof/

go tool pprof 运行分析

go tool pprof 查看 CPU 信息

go tool pprof http://localhost:6060/debug/pprof/profile

go tool pprof 查看内存堆栈信息

go tool pprof http://localhost:6060/debug/pprof/heap 查看内存堆栈信息：

go tool pprof http://localhost:6060/debug/pprof/block

go tool pprof http://localhost:6060/debug/pprof/block 查看 goroutine blocking profile

go pprof 实战经验

常见 Profile 性能分析经验

关于 Profile 分析结果的一些经验，参考 Golang 核心开发者关于性能剖析[4]

  1. 1. 如果在 Profile 分析中，看到有大量时间花费在 runtime.mallocgc 函数中，那么我们的应用程序可能做了过多的小内存分配，并且 profile 还会告诉我们这些分配来自哪里，那么我们就可以根据这些结果来定位并优化我们的应用程序
  2. 2. 如果在 Profile 分析中，看到有大量时间花费在 channel sync.Mutex 、或者其他同步原语，或者系统组件上，那么我们的应用程序可能存在资源的竞争。这个时候，我们就需要去优化我们的代码架构，减少共享资源的访问。
  3. 3. 如果在 Profile 分析中，看到有大量时间花费在 syscall.Read/Write，那么我们的应用程序可能产生了太多小数据量读写操作，可考虑使用 bufio 来代替 os.File or net.Conn。
  4. 4. 如果在 Profile 分析中，看到有大量时间花费在 GC 上，要么是程序分配了太多的临时对象，要么是堆内存太小，导致垃圾收集操作运行频繁。

引入 net/http/pprof，暴露详细信息并采集

在我们的应用程序中，通过引入 net/http/pprof，然后可以提供详细的信息，包括堆栈信息，goroutine 数量等，这个在线上运行时，可以实时观察，并且最好能够结合 Prometheus 数据进行采集和监控。

对外暴露相关接口，示例使用如下：

这些信息，有助于观察线上环境的运行时情况，比如 goroutine 当前数量、goroutine 有没有泄漏、内存有没有泄漏 or 暴增、CPU 最耗时的是哪个函数等。

gops 是由 Google 官方出品的一个命令行工具，与 ps 命令的功能类似，能够查看并诊断当前系统中 Go 程序的运行状态及内部情况。如果我们的应用程序引用了 gops 包，那么就可以针对 golang 的程序进行特定的分析，包括 CPU、MEM、 堆栈、Goroutine 、runtime、GC 等都可以搞定。

gops 和 http/pprof 我们可以任选一样来使用。

引用链接

[1]
[2]
[3]
[4]