一看就懂系列之Golang的pprof

Posted 2022-10-17 咖啡色的羊驼

前言

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

正文

1.一句话简介

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

参考文献

1.Golang 大杀器之性能剖析 PProf

2.golang pprof 实战

3.Go 程序的性能监控与分析 pprof

4.go pprof 性能分析

5.如何监控 golang 程序的垃圾回收