17 KiB
Golang 性能评测之 pprof
本文主要讲解 golang 程序的性能测评，包括 pprof、火焰图和 trace 图的使用，进而通过测评结果指导调优方向。本文篇幅比较长，建议大家使用电脑观看，手机不太方便，超大屏手机除外。
1.runtime/pprof
pprof 是 golang 官方提供的性能测评工具，包含在 net/http/pprof 和 runtime/pprof 两个包中，分别用于不同场景。
runtime/pprof 主要用于可结束的代码块，如一次编解码操作等； net/http/pprof 是对 runtime/pprof 的二次封装，主要用于不可结束的代码块，如 web 应用等。
首先利用 runtime/pprof 进行性能测评，下列代码主要实现循环向一个列表中 append 一个元素，只要导入 runtime/pprof 并添加 2 段测评代码就可以实现 cpu 和 mem 的性能评测。
package main
import (
"flag"
"log"
"os"
"runtime/pprof"
"sync"
)
func counter() {
slice := make([]int, 0)
c := 1
for i := 0; i < 100000; i++ {
c = i + 1 + 2 + 3 + 4 + 5
slice = append(slice, c)
}
}
func workOnce(wg *sync.WaitGroup) {
counter()
wg.Done()
}
func main() {
var cpuProfile = flag.String("cpuprofile", "", "write cpu profile to file")
var memProfile = flag.String("memprofile", "", "write mem profile to file")
flag.Parse()
// 采样 cpu 运行状态
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(100)
for i := 0; i < 100; i++ {
go workOnce(&wg)
}
wg.Wait()
// 采样 memory 状态
if *memProfile != "" {
f, err := os.Create(*memProfile)
if err != nil {
log.Fatal(err)
}
pprof.WriteHeapProfile(f)
f.Close()
}
}
通过编译、执行后获得 pprof 的采样数据，然后就可以利用相关工具进行分析。
$:go build main.go
$:./main --cpuprofile=cpu.pprof
$:./main --memprofile=mem.pprof
$:go tool pprof cpu.pprof
至此就可以获得 cpu.pprof 和 mem.pprof 两个采样文件，然后利用 go tool pprof 工具进行分析，见下方详情图。
如上图所示，分别有 Type 和 Time 字段就不过多解释了。下面解释一下其他字段：
Duration:程序执行时间。在本例中 golang 自动分配任务给多个核执行程序，总计耗时 301.04ms，而采样时间为 690ms；也就是说假设有 10 核执行程序，平均每个核采样 69ms 的数据。
(pprof)：命令行提示。表示当前在 go tool 的 pprof 工具命令行中，go tool 还包括 cgo、doc、pprof、test2json、trace 等多种命令
top：pprof 的指令之一，显示 pprof 文件中的前 10 项数据，可以通过 top 20 等方式显示 20 行数据；当然 pprof 下有很多指令，例如 list，pdf、eog 等等
flat/flat%：分别表示在当前层级 cpu 的占用时间和百分比。例如 runtime.memmove 在当前层级占用 cpu 时间 380ms，占比本次采集时间的 55.07%。
cum/cum%：分别表示截止到当前层级累积的 cpu 时间和占比。例如 main.counter 累积占用时间 510ms，占本次采集时间的 73.91%。
sum%：所有层级的 cpu 时间累积占用，从小到大一直累积到 100%，即 690ms。
从上图中的 cum 数据可以看到，counter 函数的 cpu 占用时间最多，那就利用 list 命令查看占用的主要因素。
从上图中看到，程序的 16 行和 14 行分别占用 490ms 和 20ms，这就是我们优化的主要方向。通过分析程序发现，由于 slice 的初始容量为 0，导致在循环中 append 时将发生多次扩容。slice 的扩容方式是：申请 2 倍或者 1.25 倍的原来长度的新 slice，再将原来的 slice 拷贝进去。
相信大家也注意到 runtime.usleep 了，占用 CPU 时间将近 20%，但是程序中明明没有任何 sleep 相关的代码，那为什么会出现，并且还占用这么高呢？大家可以先思考一下，后文将揭晓。
当然，也可以使用 web 指令获得更加直观的信息，MacOS 下通过如下命令安装渲染工具。
brew install graphviz
安装完成后在 pprof 的命令行中输入 web 即可生成一个 svg 格式的文件，将其用浏览器打开即可得到如下所示：
由于文件过大，我们只截取部分重要内容如下图所示。可以看出其基本信息和命令行下的信息相同，但是可以明显看出 runtime.memmove 耗时 380ms，由图逆向推断 main.counter 是主要的优化方向。图中各个方块的大小也代表 cpu 占用的情况，方块越大说明占用 cpu 时间越长。
同理，我们可以分析 mem.pprof 文件，从而得出内存消耗的主要原因进一步进行改进。
上述 main.counter 占用 cpu 时间过多的问题，实际上是 append 函数中内存的重新分配造成的，那简单的做法就是事先申请一个大的内存，避免频繁的进行内存分配。所以将 counter 函数进行改造：
func counter() {
slice := [100000]int{0}
c := 1
for i := 0; i < 100000; i++ {
c = i + 1 + 2 + 3 + 4 + 5
slice[i] = c
}
}
通过编译、运行、采集 pprof 信息后如下图所示，发现已经采集不到占用 cpu 比较多的函数，即已经完成优化。同学们可以试试如果在 counter 中添加一个 fmt.Println 函数后，对 cpu 占用会有什么影响呢？
2.net/http/pprof
针对后台服务型应用，服务一般不能停止，我们需要使用 net/http/pprof 包。类似上述代码，我们编写如下代码：
package main
import (
"time"
"net/http"
_ "net/http/pprof"
)
func counter() {
slice := make([]int, 0)
c := 1
for i := 0; i < 100000; i++ {
c = i + 1 + 2 + 3 + 4 + 5
slice = append(slice, c)
}
}
func workForever() {
for {
go counter()
time.Sleep(1 * time.Second)
}
}
func httpGet(w http.ResponseWriter, r *http.Request) {
counter()
}
func main() {
go workForever()
http.HandleFunc("/get", httpGet)
http.ListenAndServe("localhost:8000", nil)
}
首先导入 net/http/pprof 包，注意该包利用下划线"_"导入，意味着我们只需要该包运行其 init() 函数即可，如此该包将自动完成信息采集并保存在内存中。所以在服务上线时需要将 net/http/pprof 包移除，其不仅影响服务的性能，更重要的是会造成内存的不断上涨。
通过编译、运行，我们便可以访问：http://localhost:8000/debug/pprof/ 查看服务的运行情况，本文给出如下示例，大家可以自行探究查看，同时不断刷新网页可以发现采样结果也在不断更新中。
当然我们也可以利用 web 形式查看，现在以查看 memory 为例，在服务程序运行时，执行下列命令采集内存信息。
go tool pprof main http://localhost:8000/debug/pprof/heap
采集完成后利用 web 指令得到 svg 文件
通过浏览器查看 svg 文件，如下图所示。该图表明所有的 heap 空间均由 counter 产生；同时我们可以生成 cpu 的 svg 文件同步进行分析优化方向。
上述方法在工具型应用中可以使用，然而在服务型应用时，仅仅只是采样了部分代码段；而只有当有大量请求时才能看到应用服务的主要优化信息，同时 Uber 开源的火焰图工具 go-torch 能够辅助我们直观的完成测评。要想实现火焰图的效果，需要安装如下 3 个工具：
go get -v github.com/uber/go-torch
git clone https://github.com/brendangregg/FlameGraph.git
git clone https://github.com/wg/wrk
其中下载 FlameGraph 和 wrk 后需要进行编译，如果需要长期使用，需要将二者的可执行文件路径放到系统环境变量中。FlameGraph 是画图需要的工具，而 wrk 是模拟并发访问的工具。通过如下命令进行模拟并发操作：500 个线程并发，每秒保持 2000 个连接，持续时间 30s。
./wrk -t500 -c2000 -d30s http://localhost:8000/get
同时开启 go-torch 工具对http://localhost:8000采集 30s 信息，采集完毕后会生成 svg 的文件，用浏览器打开就是火焰图，如下所示：
go-torch -u http://localhost:8000 -t 30
火焰图形似火焰，故此得名，其横轴是 CPU 占用时间，纵轴是调用顺序。由上图可以看出 main.counter 占用将近 50%的 CPU 时间。通过 wrk 的压测后，我们可以再查看内存等信息：
go tool pprof main http://localhost:8000/debug/pprof/heap // 采集内存信息
go tool pprof main http://localhost:8000/debug/pprof/profile // 采集 cpu 信息
利用 web 指令看到内存的使用情况如下。其中 counter 函数占用 67.20%，且包含 2 部分，因为我们的代码中有 2 处调用 counter 函数。如果大家觉得 web 框图更加清晰，完全可以摒弃火焰图，直接使用 go tool pprof 工具。
针对上述分析，我们同样通过分配初始内存，降低内存扩容次数方法进行优化。即将 counter 函数修改成与上文所示，再次进行 cpu 和内存的性能评测，火焰图和 web 框图分别如下：
从上面的两幅图中可以看到，cpu 和堆空间的使用大大降低；同时在 web 框图中看到 pprof 也会使用堆空间，所以在服务上线时应该将 pprof 关闭。
3.trace
trace 工具也是 golang 支持的 go tool 工具之一，能够辅助我们跟踪程序的执行情况，进一步方便我们排查问题，往往配合 pprof 使用。trace 的使用和 pprof 类似，为了简化分析，我们首先利用下列代码进行讲解，只是用 1 核运行程序：
package main
import (
"os"
"runtime"
"runtime/trace"
"sync"
"flag"
"log"
)
func counter(wg *sync.WaitGroup) {
wg.Done()
slice := []int{0}
c := 1
for i := 0; i < 100000; i++ {
c = i + 1 + 2 + 3 + 4 + 5
slice = append(slice, c)
}
}
func main(){
runtime.GOMAXPROCS(1)
var traceProfile = flag.String("traceprofile", "", "write trace profile to file")
flag.Parse()
if *traceProfile != "" {
f, err := os.Create(*traceProfile)
if err != nil {
log.Fatal(err)
}
trace.Start(f)
defer f.Close()
defer trace.Stop()
}
var wg sync.WaitGroup
wg.Add(3)
for i := 0; i < 3; i ++ {
go counter(&wg)
}
wg.Wait()
}
同样，通过编译、执行和如下指令得到 trace 图：
go tool trace -http=127.0.0.1:8000 trace.pprof
如果大家从浏览器上看不到上述图像，首先请更换 chrome 浏览器，因为目前官方只适配了 chrome；如果依旧无法查看改图像，MacOS 请按照下述方法进行操作。 1、登录 google 账号，访问https://developers.chrome.com/origintrials/#/register_trial/2431943798780067841，其中 web Origin 字段为此后你需要访问的 web 网址，例如我使用的 127.0.0.1:8000。如此你将获得一个 Active Token 并复制下来。 2、在你的 go 的安装目录{$GOROOT}/src/cmd/trace/trace.go 文件中，找到元素范围，并添加 3、在该目录下分别执行 go build 和 go install，此后重启 Chrome 浏览器即可查看上图。
在上图中有几个关键字段，下面进行讲解：
Goroutines：运行中的协程数量；通过点击图中颜色标识可查看相关信息，可以看到在大部分情况下可执行的协程会很多，但是运行中的只有 0 个或 1 个，因为我们只用了 1 核。 Heap：运行中使用的总堆内存；因为此段代码是有内存分配缺陷的，所以 heap 字段的颜色标识显示堆内存在不断增长中。 Threads：运行中系统进程数量；很显然只有 1 个。 GC：系统垃圾回收；在程序的末端开始回收资源。 syscalls：系统调用；由上图看到在 GC 开始只有很微少的一段。 Proc0：系统进程，与使用的处理器的核数有关，1 个。
另外我们从图中可以看到程序的总运行时间不到 3ms。进一步我们可以进行放大颜色区域，查看详细信息，以下图为例：
可以看到在 Proc0 轨道上，不同颜色代表不同协程，各个协程都是串行的，执行 counter 函数的有 G7、G8 和 G9 协程，同时 Goroutines 轨道上的协程数量也相应再减少。伴随着协程的结束，GC 也会将内存回收，另外在 GC 过程中出现了 STW（stop the world）过程，这对程序的执行效率会有极大的影响。STW 过程会将整个程序通过 sleep 停止下来，所以在前文中出现的 runtime.usleep 就是此时由 GC 调用的。
下面我们使用多个核来运行，只需要改动 GOMAXPROCS 即可，例如修改成 5 并获得 trace 图：
runtime.GOMAXPROCS(5)
从上图可以看到，3 个 counter 协程再 0、2、3 核上执行，同时程序的运行时间为 0.28ms，运行时间大大降低，可见提高 cpu 核数是可以提高效率的，但是也不是所有场景都适合提高核数，还是需要具体分析。同时为了减少内存的扩容，同样可以预先分配内存，获得 trace 图如下所示：
由上图看到，由于我们提前分配好足够的内存，系统不需要进行多次扩容，进而进一步减小开销。从 slice 的源码中看到其实现中包含指针，即其内存是堆内存，而不是 C/C++中类似数组的栈空间的分配方式。另外也能看到程序的运行时间为 0.18ms，进一步提高运行速度。
另外，trace 图还有很多功能，例如查看事件的关联信息等等，通过点击 All connected 即可生成箭头表示相互关系，大家可以自己探究一下其他功能。
如果我们对 counter 函数的循环中加上锁会发生什么呢？
func counter(wg *sync.WaitGroup, m *sync.Mutex) {
wg.Done()
slice := [100000]int{0}
c := 1
for i := 0; i < 100000; i++ {
mutex.Lock()
c = i + 1 + 2 + 3 + 4 + 5
slice[i] = c
mutex.Unlock()
}
}
生成 trace 图如下：
可以看到程序运行的时间又增加了，主要是由于加 / 放锁使得 counter 协程的执行时间变长。但是并没有看到不同协程对 cpu 占有权的切换呀？这是为什么呢？主要是这个协程运行时间太短，而相对而言采样的频率低、粒度大，导致采样数据比较少。如果在程序中人为 sleep 一段时间，提高采样数量就可以真实反映 cpu 占有权的切换。例如在 main 函数中 sleep 1 秒则出现下图所示的 trace 图：
如果对 go 协程加锁呢？
for i := 0; i < 3; i ++ {
mutex.Lock()
go counter(&wg)
time.Sleep(time.Millisecond)
mutex.Unlock()
}
从得到的 trace 图可以看出，其 cpu 主要时间都是在睡眠等待中，所以在程序中应该减少此类 sleep 操作。
race 图可以非常完整的跟踪程序的整个执行周期，所以大家可以从整体到局部分析优化程序。我们可以先使用 pprof 完成初步的检查和优化，主要是 CPU 和内存，而 trace 主要是用于各个协程的执行关系的分析，从而优化结构。
本文主要讲解了一些性能评测和 trace 的方法，仍然比较浅显，更多用法大家可以自己去探索。
更新： 这几天又研究了下 trace 的相关功能，很强大，希望大家好好研究。因为分析 trace 图需要动态操作，不易在知乎上用图片说明，就不继续发文详述了，只要大家花 1-2 天时间研究研究，一定会获益匪浅的。
参考：