一看就懂系列之Golang的pprof

这是一篇给网友的文章，正好最近在研究分析golang的性能，我觉得是时候来一个了断了。

Golang 自带 的一款开箱即用的 性能监控 和 分析 工具。

（全篇看的过程中没必要特意记忆、看完自然让你有不一样的感觉）

2.使用姿势？

2.1 runtime/pprof

手动调用runtime.StartCPUProfile/runtime.StopCPUProfile等 API 来进行数据的采集。

优点： 灵活性高 、按需采集。

使用场景： 工具型应用 （比如说定制化的分析小 工具 、集成到公司监控系统）

2.2 net/http/pprof

通过 http 服务来获取Profile采样文件。 import _ "net/http/pprof"

优点：简单易用。

使用场景：在线服务（一直运行着的程序）

(net/http/pprof中只是使用runtime/pprof包来进行封装了一下，并在http端口上暴露出来)

2.3 go test

通过命令 go test -bench . -cpuprofile cpu.prof 来进行采集数据。

优点： 针对性强 、细化到函数

使用场景：进行某函数的性能测试

3 分析姿势？

3.1 数据采集

分析的基础是得到相应的采集文件。 runtime/pprof 和 go test 这两个均为命令行采集得到（下文以 分析cpu 的进行举例））。而 net/http/pprof 通过接口的方式将数据突出。

1.go test的方式很简单，命令： go test -bench . -cpuprofile cpu.prof 就可以生成。

2.runtime/pprof，直接上一个最简单的代码。

package main

import (
	"fmt"
	"os"
	"runtime/pprof"
	"time"
)

// 一段有问题的代码
func do() {
	var c chan int
	for {
		select {
		case v := <-c:
			fmt.Printf("我是有问题的那一行，因为收不到值：%v", v)
		default:
		}
	}
}

func main() {

	// 创建分析文件
	file, err := os.Create("./cpu.prof")
	if err != nil {
		fmt.Printf("创建采集文件失败, err:%v\n", err)
		return
	}

	// 进行cpu数据的获取
	pprof.StartCPUProfile(file)
	defer pprof.StopCPUProfile()

	// 执行一段有问题的代码
	for i := 0; i < 4; i++ {
		go do()
	}
	time.Sleep(10 * time.Second)
}
复制代码

执行命令：

go run pprof.go
复制代码

然后会得到数据采集文件：cpu.prof。(这个文件后文会用到)

3.http的方式，上代码：

package main

import (
	"fmt"
	"net/http"
    _ "net/http/pprof"  // 第一步～
)

// 一段有问题的代码
func do() {
	var c chan int
	for {
		select {
		case v := <-c:
			fmt.Printf("我是有问题的那一行，因为收不到值：%v", v)
		default:
		}
	}
}

func main() {
	// 执行一段有问题的代码
	for i := 0; i < 4; i++ {
		go do()
	}
	http.ListenAndServe("0.0.0.0:6061", nil)
}
复制代码

通过代码中的关键两步，执行起来就可以通过 http://127.0.0.1:6061/debug/pprof/ 看到对应的数据啦～

3.2 数据内容

不管是前文哪种方式获取，都可以进行分析。这里http的方式把可以看到的信息全部都列出来了。

类型	描述
allocs	内 存分配情况的采样信息
blocks	阻塞 操作情况的采样信息
cmdline	显示程序启动 命令参数 及其参数
goroutine	显示当前所有 协程 的堆栈信息
heap	堆 上的内存分配情况的采样信息
mutex	锁 竞争情况的采样信息
profile	cpu 占用情况的采样信息，点击会下载文件
threadcreate	系统 线程 创建情况的采样信息
trace	程序 运行跟踪 信息

通过加粗的关键字，很直观可以看到能分析到的数据。

（后文将重点根据cpu的采样信息展开命令行和图形化页面的讨论，其余项将在实战中应用）

3.3 数据分析

3.3.1 命令行

核心命令： go tool pprof <binary> <source>

binary：代表二进制文件路径。

source：代表生成的分析数据来源，可以是 本地文件 （前文生成的cpu.prof），也可以是 http地址 （比如： go tool pprof http://127.0.0.1:6060/debug/pprof/profile ）

需要注意的是：较大负载的情况下（要不就故意写故障代码，或者就模拟访问压力）获取的有效数据更有意义，如果处于空闲状态，得到的结果可能意义不大

开始分析前文生成的cpu.prof:

go tool pprof cpu.prof
复制代码

看到页面：

我们的目标是分析cpu那里耗时比较多，这里和 linux 命令有点像也是输入： top

这个图要好好说说！由于我在理的时候，我觉得要结合具体的图一起看，才更好理解，所以提供两种方式来生成图：

1.在前文的对话框中继续输入： web 。即可生成pprof001.svg的页面。

2.执行命令： go tool pprof -pdf cpu.prof ,会生成profile001.pdf的pdf文件。(参数可选text、pdf、svg)

不管哪种形式，都会得到以下图片：

类型	描述	举例
flat	该函数占用CPU的耗时	selectnbrecv占用CPU的耗时是12.29s
flat%	该函数占用CPU的耗时的百分比	selectnbrecv耗时：12.29s，cpu总耗时：29.14，12.29/29.14=42.18
sum%	top命令中排在它上面的函数以及本函数flat%之和	chanrecv：42.18%+30.47% = 72.65%
cum	当前函数加上该函数调用之前的累计CPU耗时	chanrecv：8.88+0.54=9.42
cum%	当前函数加上该函数调用之前的累计CPU耗时的百分比	9.42/29.14=32.33%
最后一列	当前函数名称	-

发现途中越粗代表越有问题耗时越高，越可能存在问题。发现do函数有点问题。此时通过命令： list funcName ，来进行查看具体的位置

发现有问题的行数在文中具体的位置，原来是卡住了，加上default休眠n秒即可解决。

关于mem的分析同cpu类似，本文不在赘述。

总结一下，至少要记住分析三步走： top -> list Func -> web

3.3.2 可视化页面

两种方式可以支持浏览器打开web站：

1.执行命令： go tool pprof -http=:6060 cpu.prof

• Top （同前文gdb交互页面的top命令）

• Graph（同前文gdb交互页面的web命令）

• Flame Graph（火焰图）

这里的颜色是随机分布的，只是看起来像火焰。

调用顺序 由上到下 ，每一块代表一个函数，越大代表占用 CPU 的时间更长。同时它也可以支持点击块深入进行分析。

• Peek（详细=树结构）

• Source（同前文gdb交互页面的list FuncName命令）

  

• Disassemble

4.游戏中实战

西游记中师徒四人西天取经，历经九九八十一难，方可取得真经。

这边已经为小伙伴弄好了取经小脚本： 点我

直接在浏览器中执行 ./xiyouji ，便可看到师徒四人一路上的吃喝拉撒。

4.1 第一难-CPU占用过高

首先先看看profile文件，看看有没有cpu的异常

go tool pprof http://localhost:6060/debug/pprof/profile
复制代码

猛然发现这个猪八戒在吃上面有点问题。

于是我们看看，执行命令： list Drink

原来吃上面有问题， 进行了1亿次的空循环，怪不得占CPU那么高 。

我们在看看大图： web

此时修复问题即可。（备注掉即可修复，后文同）

4.2 第二难-内存占用过高

重新编译过后，继续前行。接下来看看内存有没问题。

go tool pprof http://localhost:6060/debug/pprof/heap 
复制代码

发现沙和尚似乎吃的比较多？

进一步看看为什么： list Eat

原来这里进行了恶意的内存追加，直到容量见顶

继续看看图，再次确认下： web

修复代码即可。

4.3 第三难-频繁内存回收

我们都知道gc的频繁处理会导致stw不断出现，是一个高性能的服务不能容忍的。

这边需要借助一个环境变量来启动gc的观察,

GODEBUG=gctrace=1 ./xiyouji 2>&1|grep gc
复制代码

这个信息的说明：

可以看到基本上3s左右就会触发一次gc，每次都会从16M->0，说明内存被不断的申请和释放。

通过 内存的分配情况 ，可以看gc是否存在异常，如果一直占着100%或者很大比例那说明是有问题的。

执行命令：

go tool pprof http://localhost:6060/debug/pprof/allocs
复制代码

继续查看悟空怎么回事： list Shit

看大图： web

同前文，备注掉代码即可继续前行。

知识点：这边需要注意的是 为什么设置16m 呢？简单说这样才能在逃逸分析的时候，内存的申请从栈跑到堆上，这样才能引起gc回收。（更多详情请查看我还没写的《一看就懂系列之Golang的逃逸分析》）

4.4 第四难-协程泄露

我们发像goroutine好像有点偏多？是不是协程泄漏了？继续往下看。

查看goroutine情况：

go tool pprof http://localhost:6060/debug/pprof/goroutine
复制代码

看到一个引起了很多goroutine的函数，但是似乎看不到人工添加的函数引发的问题。

继续追大图： web

原来是唐僧睡觉的时候有问题。

继续追查有问题的函数： list Sleep

解决掉问题，再看看 http://127.0.0.1:6060/debug/pprof/ ,发现已经恢复正常。

4.5 第五难-锁的争用

有发现一个异常：goroutine已经降到了4个，为什么还有一个锁的征用问题？

go tool pprof localhost:6060/debug/pprof/mutex
复制代码

可以看到，126行主协程在进行lock加锁后，立马再次加锁，但是解锁由另一个协程去unlock，另一个协程足足休眠1s，这里会导致阻塞，造成锁争用问题。

解决掉即可（备注它）

4.6 第六难-阻塞操作

解决完前文的问题后，发现：

除了锁造成阻塞外，竟然还有其他逻辑造成阻塞，继续往下看。

go tool pprof localhost:6060/debug/pprof/block
复制代码

可以明显看到，这里不同于前文的slepe阻塞，是一个channel阻塞，要等1s之后才有数据输出，导致这里程序阻塞了1s。

4.7 第七难-一场误会

解决完前文所有问题后，还是发现block有1个？抱着严谨的态度，继续追查。

go tool pprof localhost:6060/debug/pprof/block
复制代码

原来是http监听，符合预期。

4.8 第八难-取得真经

经过前文的多次操作，相信你已经很熟悉排查流程和能排查的内容了。

这里总结一下排查套路。

第一步：进入排除对应的gdb交互。

go tool pprof http://localhost:6060/debug/pprof/{填上你想查看的内容}
复制代码

内容关键字：

类型	描述
allocs	内 存分配情况的采样信息
blocks	阻塞 操作情况的采样信息
cmdline	显示程序启动 命令参数 及其参数
goroutine	显示当前所有 协程 的堆栈信息
heap	堆 上的内存分配情况的采样信息
mutex	锁 竞争情况的采样信息
profile	cpu 占用情况的采样信息，点击会下载文件
threadcreate	系统 线程 创建情况的采样信息
trace	程序 运行跟踪 信息

第二步：三联招，top->list FuncName->web

通过占用比分析，查看具体代码行数，看大图确认。

第三步：解决问题。

（细心的同学可能会发现没有对trace进行分析，这个请期待《一看就懂系列之Golang的trace》）

5.与测试命令共舞

测试分析特别简单，在原有的命令后加上 -cpuprofile=cpu.prof 或 -memprofile=mem.prof 就可以得到对应的数据采集文件啦，后面的事对于已经取得真经的你应该懂的

命令例子： go test -bench . -cpuprofile cpu.prof