383 lines
17 KiB
Markdown
383 lines
17 KiB
Markdown
|
# [Golang 性能评测之 pprof](https://zhuanlan.zhihu.com/p/141640004)
|
|||
|
|
|
|||
|
|
本文主要讲解 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 的性能评测。
|
|||
|
|
|
|||
|
|
```go
|
|||
|
|
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 的采样数据，然后就可以利用相关工具进行分析。
|
|||
|
|
|
|||
|
|
```bash
|
|||
|
|
$: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 下通过如下命令安装渲染工具。
|
|||
|
|
|
|||
|
|
```bash
|
|||
|
|
brew install graphviz
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
安装完成后在 pprof 的命令行中输入 web 即可生成一个 svg 格式的文件，将其用浏览器打开即可得到如下所示：
|
|||
|
|
|
|||
|
|
|
|||
|
|
|
|||
|
|
由于文件过大，我们只截取部分重要内容如下图所示。可以看出其基本信息和命令行下的信息相同，但是可以明显看出 runtime.memmove 耗时 380ms，由图逆向推断 main.counter 是主要的优化方向。图中各个方块的大小也代表 cpu 占用的情况，方块越大说明占用 cpu 时间越长。
|
|||
|
|
|
|||
|
|
|
|||
|
|
|
|||
|
|
同理，我们可以分析 mem.pprof 文件，从而得出内存消耗的主要原因进一步进行改进。
|
|||
|
|
|
|||
|
|
上述 main.counter 占用 cpu 时间过多的问题，实际上是 append 函数中内存的重新分配造成的，那简单的做法就是事先申请一个大的内存，避免频繁的进行内存分配。所以将 counter 函数进行改造：
|
|||
|
|
|
|||
|
|
```go
|
|||
|
|
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 包。类似上述代码，我们编写如下代码：
|
|||
|
|
|
|||
|
|
```go
|
|||
|
|
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
|
|||
|
|
go tool pprof main http://localhost:8000/debug/pprof/heap
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
采集完成后利用 web 指令得到 svg 文件
|
|||
|
|
|
|||
|
|
|
|||
|
|
|
|||
|
|
通过浏览器查看 svg 文件，如下图所示。该图表明所有的 heap 空间均由 counter 产生；同时我们可以生成 cpu 的 svg 文件同步进行分析优化方向。
|
|||
|
|
|
|||
|
|
|
|||
|
|
|
|||
|
|
上述方法在工具型应用中可以使用，然而在服务型应用时，仅仅只是采样了部分代码段；而只有当有大量请求时才能看到应用服务的主要优化信息，同时 Uber 开源的火焰图工具 go-torch 能够辅助我们直观的完成测评。要想实现火焰图的效果，需要安装如下 3 个工具：
|
|||
|
|
|
|||
|
|
```bash
|
|||
|
|
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。
|
|||
|
|
|
|||
|
|
```bash
|
|||
|
|
./wrk -t500 -c2000 -d30s http://localhost:8000/get
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
同时开启 go-torch 工具对<http://localhost:8000>采集 30s 信息，采集完毕后会生成 svg 的文件，用浏览器打开就是火焰图，如下所示：
|
|||
|
|
|
|||
|
|
```bash
|
|||
|
|
go-torch -u http://localhost:8000 -t 30
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
|
|||
|
|
|
|||
|
|
火焰图形似火焰，故此得名，其横轴是 CPU 占用时间，纵轴是调用顺序。由上图可以看出 main.counter 占用将近 50%的 CPU 时间。通过 wrk 的压测后，我们可以再查看内存等信息：
|
|||
|
|
|
|||
|
|
```bash
|
|||
|
|
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 核运行程序：
|
|||
|
|
|
|||
|
|
```go
|
|||
|
|
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 图：
|
|||
|
|
|
|||
|
|
```bash
|
|||
|
|
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 图：
|
|||
|
|
|
|||
|
|
```go
|
|||
|
|
runtime.GOMAXPROCS(5)
|
|||
|
|
```
|
|||
|
|
|
|||
|
|
|
|||
|
|
|
|||
|
|
从上图可以看到，3 个 counter 协程再 0、2、3 核上执行，同时程序的运行时间为 0.28ms，运行时间大大降低，可见提高 cpu 核数是可以提高效率的，但是也不是所有场景都适合提高核数，还是需要具体分析。同时为了减少内存的扩容，同样可以预先分配内存，获得 trace 图如下所示：
|
|||
|
|
|
|||
|
|
|
|||
|
|
|
|||
|
|
由上图看到，由于我们提前分配好足够的内存，系统不需要进行多次扩容，进而进一步减小开销。从 slice 的源码中看到其实现中包含指针，即其内存是堆内存，而不是 C/C++中类似数组的栈空间的分配方式。另外也能看到程序的运行时间为 0.18ms，进一步提高运行速度。
|
|||
|
|
|
|||
|
|
另外，trace 图还有很多功能，例如查看事件的关联信息等等，通过点击 All connected 即可生成箭头表示相互关系，大家可以自己探究一下其他功能。
|
|||
|
|
|
|||
|
|
|
|||
|
|
|
|||
|
|
如果我们对 counter 函数的循环中加上锁会发生什么呢？
|
|||
|
|
|
|||
|
|
```go
|
|||
|
|
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 协程加锁呢？
|
|||
|
|
|
|||
|
|
```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 天时间研究研究，一定会获益匪浅的。
|
|||
|
|
|
|||
|
|
参考：
|
|||
|
|
|
|||
|
|
1. <https://golang.org/src/>
|
|||
|
|
2. <https://blog.csdn.net/u013474436/article/details/105232768/>
|
|||
|
|
3. <https://studygolang.com/articles/28298?fr=sidebar>
|
|||
|
|
4. <https://blog.csdn.net/u013474436/article/details/105232768/>
|
|||
|
|
5. <https://www.cnblogs.com/nickchen121/p/11517452.html>
|
|||
|
|
6. <https://segmentfault.com/a/1190000018161588>
|