Golang程序性能pprof使用介绍

Mar 29, 2021 · 4 min read

对于Golang程序性能分析，pprof 可以说是一大利器，它是用来性能分析的工具，主要可以分析CPU使用情况、内存使用情况、阻塞情况、竞争互斥锁等性能问题。整个分析主要分为三个部分：

项目中引入相关的包；
编译程序运行并收集运行时的数据；
分析相关数据

引入并收集数据

Golang标准库中提供了两种引入方式：

runtime/pprof: 将程序运行时的性能分析数据写入到文件中，然后可通过pprof可视化分析工具进行分析；支持使用标准测试包构建的性能分析基准测试；
net/http/pporf: 通过HTTP Server的方式提供pprof可视化工具所需要的性能分析数据；

runtime/pprof

支持基准测试：以下命令在当前目录中运行基准测试并将 CPU 和内存配置文件写入 cpu.prof 和 mem.prof：

1 go test -cpuprofile cpu.prof -memprofile mem.prof -bench .

独立程序分析：需要将以下代码添加到主函数中：

 1var cpuprofile = flag.String("cpuprofile", "", "write cpu profile `file`")
 2var memprofile = flag.String("memprofile", "", "write memory profile to `file`")
 3
 4func main() {
 5    flag.Parse()
 6    if *cpuprofile != "" {
 7        f, err := os.Create(*cpuprofile)
 8        if err != nil {
 9            log.Fatal("could not create CPU profile: ", err)
10        }
11        if err := pprof.StartCPUProfile(f); err != nil {
12            log.Fatal("could not start CPU profile: ", err)
13        }
14        defer pprof.StopCPUProfile()
15    }
16
17    // ... rest of the program ...
18
19    if *memprofile != "" {
20        f, err := os.Create(*memprofile)
21        if err != nil {
22            log.Fatal("could not create memory profile: ", err)
23        }
24        runtime.GC() // get up-to-date statistics
25        if err := pprof.WriteHeapProfile(f); err != nil {
26            log.Fatal("could not write memory profile: ", err)
27        }
28        f.Close()
29    }
30}

net/http/pporf

通过 import _ "net/http/pprof" 可以引入该包，如果你的程序没有http server,则需要添加类似以下代码：

1go func() {
2	log.Println(http.ListenAndServe("localhost:6060", nil))
3}()

http server所有路径都是以 /debug/pprof/ 开头；本地访问 http://localhost:6060/debug/pprof 可以看到一个概览，展示的是pprof可以采集数据；

 1/debug/pprof/
 2
 3Types of profiles available:
 4Count	Profile
 51	allocs              ## 内存分配情况的采样
 60	block               ## 阻塞情况的采样
 70	cmdline             ## 显示命令启动信息
 87	goroutine           ## 当前所有goroutines的堆栈信息
 91	heap                ## 堆上内存申请情况的采样
100	mutex               ## 锁竞争的采样信息
110	profile             ## CPU使用情况的采样
128	threadcreate        ## 系统线程创建的堆栈跟踪信息
130	trace               ## 程序运行跟踪信息
14full goroutine stack dump
15Profile Descriptions:
16
17allocs: A sampling of all past memory allocations
18block: Stack traces that led to blocking on synchronization primitives
19cmdline: The command line invocation of the current program
20goroutine: Stack traces of all current goroutines
21heap: A sampling of memory allocations of live objects. You can specify the gc GET parameter to run GC before taking the heap sample.
22mutex: Stack traces of holders of contended mutexes
23profile: CPU profile. You can specify the duration in the seconds GET parameter. After you get the profile file, use the go tool pprof command to investigate the profile.
24threadcreate: Stack traces that led to the creation of new OS threads
25trace: A trace of execution of the current program. You can specify the duration in the seconds GET parameter. After you get the trace file, use the go tool trace command to investigate the trace.

分析

无论是 runtime/pprof 还是net/http/pporf 都是为收集程序运行时的采样数据，对于分析数据我们还要借助工具 go tool pprof，以下以http server为例：

CPU分析 Demo如下：

 1package main
 2
 3import (
 4	"log"
 5	"net/http"
 6	_ "net/http/pprof"
 7	"time"
 8)
 9
10func Bug() {
11	for {
12		for i := 0; i < 10000000000; i++ {
13		}
14		time.Sleep(1 * time.Second)
15	}
16}
17func main() {
18	go Bug()
19	log.Println(http.ListenAndServe("localhost:6060", nil))
20}

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

执行以上命令，可以通过http 获取到CPU的采样信息并通过go tool pprof进行分析，在进入交互式命令行后，可以输入top来查看占用CPU较高的函数

 1(pprof) top
 2Showing nodes accounting for 19990ms, 99.65% of 20060ms total
 3Dropped 19 nodes (cum <= 100.30ms)
 4      flat  flat%   sum%        cum   cum%
 5   18740ms 93.42% 93.42%    19760ms 98.50%  main.Bug
 6    1010ms  5.03% 98.45%     1010ms  5.03%  runtime.asyncPreempt
 7     240ms  1.20% 99.65%      240ms  1.20%  runtime.nanotime1
 8         0     0% 99.65%      250ms  1.25%  runtime.mstart
 9         0     0% 99.65%      250ms  1.25%  runtime.mstart1
10         0     0% 99.65%      240ms  1.20%  runtime.nanotime (inline)
11         0     0% 99.65%      250ms  1.25%  runtime.sysmon

flat：当前函数上运行耗时；
flat%：当前函数的运行耗时占 CPU 运行耗时比例；
sum%：前面每一行的 flat 占比总和；
cum：当前函数加上该函数调用函数的总耗时；
cum%：当前函数加上该函数调用函数的总耗时占用CPU运行耗时的比例；

通过top 可以看到占用CPU较高的函数，然后可以通过 list 函数名 命令来查看某个函数的更细致的分析

 1(pprof) list Bug
 2Total: 20.06s
 3ROUTINE ======================== main.Bug in /Users/xiefei/repo/post/debug/main.go
 4    18.74s     19.76s (flat, cum) 98.50% of Total
 5         .          .      6:	_ "net/http/pprof"
 6         .          .      7:	"time"
 7         .          .      8:)
 8         .          .      9:
 9         .          .     10:func Bug() {
10         .      770ms     11:	for {
11    18.74s     18.98s     12:		for i := 0; i < 10000000000; i++ {
12         .          .     13:		}
13         .       10ms     14:		time.Sleep(1 * time.Second)
14         .          .     15:	}
15         .          .     16:}
16         .          .     17:
17         .          .     18:func main() {
18         .          .     19:	go Bug()

由该命令可以看出 for 循环那段代码占用的CPU较高，从而定位问题；

另外我们还可以通过web 命令查看将采样数据图形化展示出来；

图中的箭头代表的是函数的调用，箭头上的值代表的是该方法的采样值，这里是CPU耗时，框越大的函数CPU占用就越高，框内表示的就是 flat、flat%、cum、cum%.

另外我们还可以通过以下命令获取Profile并在启动一个web服务在浏览器中进行分析：

1go tool pprof -http=:8888 http://localhost:6060/debug/pprof/profile?second=10s

从浏览器中可以看到top、source、graph、火焰图等信息；

top 与命令行top显示是基本一致;

source 与命令行list 显示基本一致；

graph 与命令web 显示一致；

火焰图的Y轴表示函数调用栈。X轴表示该函数占用的CPU时间的百分比，越宽代表占用的CPU时间就越多。

内存

1go tool pprof http://localhost:6060/debug/pprof/heap

1go tool pprof -http=:8888 http://localhost:6060/debug/pprof/heap

内存分析通过以上命令获取相应的数据，分析方法与CPU基本一样，不过有几个术语需要解释以下：
inuse_space:正在使用的分配空间;
inuse_objects:正在使用的分配对象数;
aloc_objects:累计的分配对象数;
aloc_space:累计的分配空间;

总结

pprof 确实是分析Golang程序的一大利器，我们一般使用基本分为三步： 1.将代码加入到项目中 2. 收集相关数据 3.分析数据；在分析时我们也一般使用top list 或者火焰图来分析；

参考

runtime/pprof
net/http/pprf
Profiling your Golang app in 3 steps