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
goroutine 阻塞 profiler 展示 goroutine 阻塞等待同步原语(包括定时器channel)，出现在代码中哪些地方。阻塞剖析器默认没有被开启，goroutine 阻塞的情况，可以通过 pprof 工具来查看，使用 net/http/pprof, runtime/pprof包，然后手动开启，程序中调用 runtime.SetBlockProfileRate，开启阻塞剖析器，SetBlockProfileRate 控制 blocking profile 中阻塞时间的报告粒度。
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语言程序只能是编译命令源码文件后生成的可执行文件。比如：
$ go tool pprof cpupprof cpupprof.prof File: cpupprof Type: cpu Time: Dec 6, 2019 at 10:57am (CST) Duration: 3s, Total samples = 0 No samples were found with the default sample value type. Try "sample_index" command to analyze different sample values. Entering interactive mode (type "help" for commands, "o" for options) (pprof) top 10
- • cpupprof 就是我们的应用程序的二进制程序
- • cpupprof.prof 就是这个程序所生成的 cpu prof 文件
更详细的用法和使用示例，可以继续往下看下面的演示过程。
net/http/pprof【推荐使用】
最常见的方法是使用 net/http/pprof，在我们的代码中运行一个 http server，然后远程通过 http 的请求来访问获取到相关数据，比如可以在浏览器里输入 http://localhost:6060/debug/pprof/goroutine?debug=2，就会看到 goroutine 的一些情况
svg 矢量图
通过 pprof 工具可以生成一个 svg 的矢量图，查看 svg 矢量图可以帮助我们确认代码的执行流程和调用情况。
svg 是使用 graphviz 生成的，我一般都是用 mac 电脑，在 mac 下可以直接通过 brew install graphviz 命令来安装；其他的系统，比如 centos下，我们可以通过 yum -y install graphviz来安装。
pprof 实战验证和验证
runtime/pprof【CPU profiling】
代码示例
cpupprof.go 源文件如下：
package main import ( "flag" "log" "os" "runtime/pprof" "sync" "time" ) 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(err) } pprof.StartCPUProfile(f) defer pprof.StopCPUProfile() } var wg sync.WaitGroup wg.Add(10) for i := 0; i < 10; i++ { go work(&wg) } time.Sleep(3 * time.Second) wg.Wait() } func work(wg *sync.WaitGroup) { var counter int for i := 0; i < 1000; i++ { time.Sleep(time.Millisecond * 100) counter++ } wg.Done() }
编译和 go tool pprof 运行分析
先编译 cpupprof.go 源文件：go build cpupprof.go ，得到 cpupprof 二进制文件
然后，运行 ./cpupprof -cpuprofile=cpupprof.prof
最后，再在同一个目录，执行 go tool pprof cpupprof cpupprof.prof 开始分析：
- • top N ：表示采样时间间隔内，耗时最长的 top N
- • top5 -cum ：cum 表示按第4和第5列排序
- • web： 表示生成 svg 图
$ go tool pprof cpupprof cpupprof.prof File: cpupprof Type: cpu Time: Dec 6, 2019 at 10:57am (CST) Duration: 1.70mins, Total samples = 340ms ( 0.33%) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top 10 Showing nodes accounting for 340ms, 100% of 340ms total Showing top 10 nodes out of 34 flat flat% sum% cum cum% 100ms 29.41% 29.41% 100ms 29.41% runtime.pthread_cond_wait 60ms 17.65% 47.06% 60ms 17.65% runtime.nanotime 60ms 17.65% 64.71% 60ms 17.65% runtime.pthread_cond_signal 50ms 14.71% 79.41% 50ms 14.71% runtime.pthread_cond_timedwait_relative_np 20ms 5.88% 85.29% 30ms 8.82% runtime.notetsleep 20ms 5.88% 91.18% 20ms 5.88% runtime.usleep 10ms 2.94% 94.12% 10ms 2.94% runtime.pthread_mutex_unlock 10ms 2.94% 97.06% 160ms 47.06% runtime.semasleep 10ms 2.94% 100% 10ms 2.94% time.Sleep 0 0% 100% 10ms 2.94% main.work (pprof) top5 -cum Showing nodes accounting for 10ms, 2.94% of 340ms total Showing top 5 nodes out of 34 flat flat% sum% cum cum% 10ms 2.94% 2.94% 160ms 47.06% runtime.semasleep 0 0% 2.94% 130ms 38.24% runtime.mstart 0 0% 2.94% 120ms 35.29% runtime.mcall 0 0% 2.94% 120ms 35.29% runtime.park_m 0 0% 2.94% 120ms 35.29% runtime.schedule (pprof) web (pprof)
实战说明
一般而言，如果代码没有上线，那么可以在本地调试，然后我们可以本地编译、本地运行、本地调优。但是，如果代码已经上线运行，那么当然不能这样调试了，因此就需要用到 net/http/pprof包，通过 http 远程访问来调试
net/http/pprof
代码示例
package main import ( "flag" "log" "net/http" _ "net/http/pprof" "sync" "time" ) func main() { flag.Parse() //这里实现了远程获取pprof数据的接口 go func() { log.Println(http.ListenAndServe("localhost:6060", nil)) }() var wg sync.WaitGroup wg.Add(10) for i := 0; i < 10; i++ { go work(&wg) } wg.Wait() // Wait to see the global run queue deplete. time.Sleep(3 * time.Second) } func work(wg *sync.WaitGroup) { time.Sleep(time.Second) mem := make([]int, 10000) log.Println(mem) var counter int for i := 0; i < 1e10; i++ { time.Sleep(time.Millisecond * 100) counter++ } wg.Done() }
http 访问查看和分析 pprof
通过网络访问来查看相关信息 http://localhost:6060/debug/pprof/
go tool pprof 运行分析
go tool pprof 查看 CPU 信息
go tool pprof http://localhost:6060/debug/pprof/profile 查看 CPU 信息:
$ go tool pprof http://localhost:6060/debug/pprof/profile Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile Saved profile in /Users/wudebao/pprof/pprof.samples.cpu.002.pb.gz Type: cpu Time: Dec 6, 2019 at 11:22am (CST) Duration: 30s, Total samples = 90ms ( 0.3%) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top 5 Showing nodes accounting for 90ms, 100% of 90ms total Showing top 5 nodes out of 25 flat flat% sum% cum cum% 50ms 55.56% 55.56% 50ms 55.56% runtime.pthread_cond_wait 10ms 11.11% 66.67% 10ms 11.11% runtime.nanotime 10ms 11.11% 77.78% 10ms 11.11% runtime.pthread_cond_signal 10ms 11.11% 88.89% 10ms 11.11% runtime.pthread_cond_timedwait_relative_np 10ms 11.11% 100% 10ms 11.11% runtime.usleep (pprof) top5 -cum Showing nodes accounting for 0, 0% of 90ms total Showing top 5 nodes out of 25 flat flat% sum% cum cum% 0 0% 0% 60ms 66.67% runtime.findrunnable 0 0% 0% 60ms 66.67% runtime.mcall 0 0% 0% 60ms 66.67% runtime.park_m 0 0% 0% 60ms 66.67% runtime.schedule 0 0% 0% 60ms 66.67% runtime.semasleep (pprof) (pprof)
go tool pprof 查看内存堆栈信息
go tool pprof http://localhost:6060/debug/pprof/heap 查看内存堆栈信息：
$ go tool pprof http://localhost:6060/debug/pprof/heap Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap Saved profile in /Users/wudebao/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.004.pb.gz Type: inuse_space Time: Dec 6, 2019 at 11:33am (CST) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 3692.74kB, 100% of 3692.74kB total Showing top 10 nodes out of 17 flat flat% sum% cum cum% 1562.15kB 42.30% 42.30% 1562.15kB 42.30% fmt.(*buffer).WriteByte 1106.08kB 29.95% 72.26% 3180.24kB 86.12% main.work 512.50kB 13.88% 86.13% 512.50kB 13.88% sync.(*Pool).pinSlow 512.01kB 13.87% 100% 512.01kB 13.87% reflect.packEface 0 0% 100% 2074.16kB 56.17% fmt.(*pp).doPrintln 0 0% 100% 2074.16kB 56.17% fmt.(*pp).printArg 0 0% 100% 2074.16kB 56.17% fmt.(*pp).printValue 0 0% 100% 2074.16kB 56.17% fmt.Sprintln 0 0% 100% 2074.16kB 56.17% log.Println 0 0% 100% 512.50kB 13.88% net/http.(*conn).readRequest (pprof) (pprof) list FindLoops Total: 3.61MB (pprof)
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. 如果在 Profile 分析中，看到有大量时间花费在 runtime.mallocgc 函数中，那么我们的应用程序可能做了过多的小内存分配，并且 profile 还会告诉我们这些分配来自哪里，那么我们就可以根据这些结果来定位并优化我们的应用程序
- 2. 如果在 Profile 分析中，看到有大量时间花费在 channel sync.Mutex 、或者其他同步原语，或者系统组件上，那么我们的应用程序可能存在资源的竞争。这个时候，我们就需要去优化我们的代码架构，减少共享资源的访问。
- 3. 如果在 Profile 分析中，看到有大量时间花费在 syscall.Read/Write，那么我们的应用程序可能产生了太多小数据量读写操作，可考虑使用 bufio 来代替 os.File or net.Conn。
- 4. 如果在 Profile 分析中，看到有大量时间花费在 GC 上，要么是程序分配了太多的临时对象，要么是堆内存太小，导致垃圾收集操作运行频繁。
引入 net/http/pprof，暴露详细信息并采集
在我们的应用程序中，通过引入 net/http/pprof，然后可以提供详细的信息，包括堆栈信息，goroutine 数量等，这个在线上运行时，可以实时观察，并且最好能够结合 Prometheus 数据进行采集和监控。
对外暴露相关接口，示例使用如下：
// PProf profGroup := debugGroup.Group("/pprof") profGroup.GET("/", func(c *gin.Context) { pprof.Index(c.Writer, c.Request) }) profGroup.GET("/goroutine", gin.WrapH(pprof.Handler("goroutine"))) profGroup.GET("/block", gin.WrapH(pprof.Handler("block"))) profGroup.GET("/heap", gin.WrapH(pprof.Handler("heap"))) profGroup.GET("/threadcreate", gin.WrapH(pprof.Handler("threadcreate"))) profGroup.GET("/profile", func(c *gin.Context) { pprof.Profile(c.Writer, c.Request) }) profGroup.GET("/symbol", func(c *gin.Context) { pprof.Symbol(c.Writer, c.Request) }) profGroup.GET("/trace", func(c *gin.Context) { pprof.Trace(c.Writer, c.Request) })
这些信息，有助于观察线上环境的运行时情况，比如 goroutine 当前数量、goroutine 有没有泄漏、内存有没有泄漏 or 暴增、CPU 最耗时的是哪个函数等。
引入 https://github.com/google/gops
gops 是由 Google 官方出品的一个命令行工具，与 ps 命令的功能类似，能够查看并诊断当前系统中 Go 程序的运行状态及内部情况。如果我们的应用程序引用了 gops 包，那么就可以针对 golang 的程序进行特定的分析，包括 CPU、MEM、 堆栈、Goroutine 、runtime、GC 等都可以搞定。
gops 和 http/pprof 我们可以任选一样来使用。
引用链接
[1] 《Profiling Go Programs》: https://blog.golang.org/profiling-go-programs
[2] CPU 的主频，即 CPU 内核工作的时钟频率（CPU Clock Speed）: https://baike.baidu.com/item/%E4%B8%BB%E9%A2%91/103191
[3] runtime/pprof.WriteHeapProfile: https://golang.org/pkg/runtime/pprof/#WriteHeapProfile
[4] Golang 核心开发者关于性能剖析: https://my.oschina.net/evilunix/blog/371958
