pprof性能排查 | 青训营

1.pprof工具介绍即使用

简介：

pprof是golang的内置可视化性能分析工具，可以展示出当前程序运行状态的画像，直观的让我们知道程序在什么地方耗费了多少CPU，memory等资源，可以生成多种类型的性能分析，每种分析都会给出详细的程序执行流程和资源消耗情况；并且提供内置的http服务器用于可视化性能分析，通过web端交互式探索分析，利用调用图、火焰图等性能视图，让开发者精准定位性能瓶颈。

pprof主要分析指标：

• CPU Profiling：CPU性能分析，按一定频率采样监听程序的CPU使用情况，确定花费CPU时间最长的函数或代码路径；
• Memory Profiling：内存性能分析，监测内存的分配和回收情况，每分配指定大小时记录一次，同时检查内存泄漏和非必要内存分配；
• Block Profiling：阻塞性能分析，分析记录goroutine协程的阻塞情况，记录阻塞次数和耗时，耗时每超过阈值就记录一次；
• Mutex Profiling：互斥锁性能分析，监测互斥锁的使用情况，提示锁竞争。

pprof记录指标数据：

CPU指标：

• flat :当前函数本身在CPU运行的耗时；
• flat% ：flat占CPU总时间的比例；
• sum% ：当前代码行以前的flat%总和；
• cum ：指当前函数本身加上其调用函数的总耗时，应>=flat；
• cum% ：cum占cpu总时间的比例；
• flat==cum：函数中没有调用其他函数；
• flat==0：函数中只有对其他函数的调用；

内存指标：

• alloc_objects：程序累计申请的对象数，即所有申请的对象数不论是否释放；
• alloc_space：程序累计申请的内存大小，即所有申请的内存量不论是否释放；
• inuse_objects：程序当前持有的对象数，即已分配但未释放的对象数；
• inuse_space：程序当前占有的内存大小，即已分配但未释放的内存量；

其他：

• flamegraph火焰图：
  • 由上到下表示调用顺序；
  • 每一块代表一个函数，越长代表占用cpu时间越长；
  • 火焰图是动态的，支持点检块进行分析；
• block：导致阻塞的堆栈跟踪信息；
• mutex：锁资源竞争的堆栈信息；
• threadcreate：系统线程的使用情况；
• trace：当前系统的代码执行链路。

使用：

1. 使用runtime/pprof包进行性能分析：

• 导入：import "runtime/pprof"

• CPU分析：使用 pprof.StartCPUProfile 开始收集 CPU 分析数据，并使用 pprof.StopCPUProfile 停止收集数据并生成 CPU 分析报告；

• 内存分析：使用 pprof.WriteHeapProfile 生成内存分析报告；

• 阻塞和互斥锁分析：pprof.Lookup("block").WriteTo(file, 0)和pprof.Lookup("mutex").WriteTo(file, 0)生成阻塞和互斥锁分析报告；

• 示例代码：

func main() {
	//cpu分析:
	// 创建cpu分析文件
	fc, err := os.Create("./cpu.prof")
	if err != nil {
		fmt.Println("create cpu.prof err:", err.Error())
		return
	}
	defer fc.Close()

	// 开始分析cpu
	err = pprof.StartCPUProfile(fc)
	if err == nil {
		defer pprof.StopCPUProfile()
	}
	//分析代码块：
	var count int
	for i := 0; i < 10000; i   {
		count  
	}

	//内存分析
	fm, err := os.Create("./memory.prof")
	if err != nil {
		fmt.Println("create memory.prof err:", err.Error())
		return
	}
	defer fm.Close()

	// 开始分析内存
	err = pprof.WriteHeapProfile(fm)
	if err != nil {
		fmt.Println("write heap prof err:", err.Error())
		return
	}
	//分析代码块
	for i := 0; i < 10000; i   {
		count  
	}
}

• 运行结果：

• 命令行交互模式：go tool pprof ./memory.prof top list 函数名：

  • top中找出占比最大的函数，list分析函数，定位函数中占比最大的语句。

• web页面模式：go tool pprof -http=:8080 ./memory.prof:
  • 事先安装配置好Graphviz：graphviz.org/download/

2.使用net/http/pprof包进行性能分析：

• 在服务内部匿名引入net/http/pprof包，通过http访问pprof页面；
• 匿名导入：import _ "net/http/pprof"；
• 常用方式：通过协程另起一个http服务，单独用作pprof分析：

	go func() {
		if err := http.ListenAndServe(":6060", nil); err != nil {
			log.Fatal(err)
		}
		os.Exit(0)
	}()

• 运行后访问http://localhost:6060/debug/pprof/ 获取概况信息，选择分析指标：

3.常用终端命令：

• http://localhost:6060/debug/pprof/ 获取概况信息；

  • 以下命令go tool pprof后加-http=:8080则直接转到web界面；

• go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=10":分析10s内CPU的使用情况，可以通过更改参数指定数据采集时间；

• go tool pprof http://localhost:6060/debug/pprof/allocs:分析内存分配；

• go tool pprof http://localhost:6060/debug/pprof/block:分析堆栈跟踪导致阻塞的语句；

• go tool pprof http://localhost:6060/debug/pprof/cmdline:分析命令行调用的程序，web下调用报错；

• go tool pprof http://localhost:6060/debug/pprof/goroutine:分析当前goroutine的堆栈信息；

• go tool pprof http://localhost:6060/debug/pprof/heap:分析当前活动对象内存分配；

• go tool pprof http://localhost:6060/debug/pprof/mutex:分析跟踪竞争状态互斥锁的位置；

• go tool pprof http://localhost:6060/debug/pprof/threadcreate:分析堆栈跟踪系统新线程的创建；

• go tool pprof http://localhost:6060/debug/pprof/trace:分析追踪当前程序的执行状况。

2.pprof性能分析实战：

实战源码：

源码地址：github.com/wolfogre/go…

main.go（注释版）

func main() {
	log.SetFlags(log.Lshortfile | log.LstdFlags)
	log.SetOutput(os.Stdout)

	runtime.GOMAXPROCS(1) //限制CPU数量，避免过载
	runtime.SetMutexProfileFraction(1) //跟踪锁调用
	runtime.SetBlockProfileRate(1)  //跟踪阻塞
        
        // 在新建Goroutine中启动http服务器，监听在端口 6060，用于性能分析
	go func() {
		if err := http.ListenAndServe(":6060", nil); err != nil {
			log.Fatal(err)
		}
		os.Exit(0)
	}()

	for {
		for _, v := range animal.AllAnimals {
			v.Live()
		}
                //每秒暂停一次循环
		time.Sleep(time.Second)
	}
}

运行并访问http://localhost:6060/debug/pprof/：

性能问题排查流程：

1.CPU性能分析

1. 运行程序后查看任务管理器，发现程序CPU占用最高：

2. 终端输入指令go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=10"，进入交互终端后，输入top指令，查看CPU占用较高的调用:

3. 定位github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat占用CPU最高，使用list Eat指令查看占用过高的具体语句：

4. 定位到for i := 0; i < loop; i {执行100亿次空循环导致占用CPU过高，注释掉for循环语句后再查看占用情况发现恢复正常：

2.内存性能分析

1. 运行程序查看任务管理器，发现程序内存占用率最高：

2. 终端输入指令go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/heap进入web端图形化界面查看内存占用情况，默认SAMPLE中选择的是inuse_space即程序当前占用的未释放内存大小，则此时的Graph调用图展示的是内存占用情况：

3. 通过以上Graph调用图能很清楚的知道是mouse.(*Mouse).Steal占用了绝大部分内存，点击VIEW选项卡中的Source，在搜索框中输入mouse，出现的源码根据内存占用量，可以直观看到m.buffer = append(m.buffer, [constant.Mi]byte{})语句是导致内存占用的问题所在，这个循环会一直向m.buffer里追加长度为1 MB的数组，直到总容量到达1 GB为止，并且没有任何释放内存的操作，导致了占用大部分内存；

4. 注释循环代码后再进入界面进行查看，内存占用的调用图不再显示；接下来将SAMPLE选择为alloc_space，即查看程序申请的总内存量，防止程序不断的申请又释放内存的操作，也会降低程序性能:

5. 通过以上Graph调用图，存在不断申请释放内存的情况，即dog.(*Dog).run多次申请释放内存，点击VIEW选项卡中的Source，在搜索框中输入dog，出现的源码根据内存占用量，可以直观看_=make([]byte, 16*constant.Mi)进行无意义的内存申请，通过不断调用申请了大部分内存；

6. 注释掉代码后再查看任务管理器发现内存占用明显降低：

3.协程泄露排查

1. 使用go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/goroutine"进入web端可视化查看协程创建的情况，但是Graph图不能很好的展示具体问题，则要使用到Flame Graph火焰图：

2.根据上述火焰图，mouse.(*Mouse).pee和wolf.(*Wolf).Drink创建了大部分协程，特别是wolf.(*Wolf).Drink，长度最长，占用CPU时间最长，点击VIEW选项卡中的Source，在搜索框中输入wolf和mouse定位协程创建的位置和会产生的问题：

3. 可以看到，wolf.(*Wolf).Drink 函数每次会释放 10 个协程出去，每个协程会睡眠 30 秒再退出，而 wolf.(*Wolf).Drink 函数中的go func(){time.Sleep(30 * time.Second)}() 又会被反复调用，导致了大量协程泄露；

4. 而在mouse.(*Mouse).pee函数中每次调用Pee()方法都会启动一个新的子协程，如果这个函数被频繁调用，大量的协程会被创建，可能导致协程泄露或过多的并发负担；

   • 子协程中的循环会不断地向slowBuffer中添加新的一兆字节的数组，这个过程没有限制，经过不断的调用，slowBuffer的大小会不断增加，可能占用大量的内存资源，甚至导致内存溢出问题，大幅降低内存性能;
   • 子协程中的循环中，每次追加一兆字节的数组都会进行append操作。随着slowBuffer的增长，这些append操作会变得越来越慢，因为Go语言的append操作可能需要重新分配和复制整个数组；
   • 在每次追加操作之后，循环都会有500毫秒的延迟。这样的延迟会导致整个填充过程变得非常缓慢，特别是当slowBuffer需要增长很多次时，整个过程可能需要较长的时间，会降低CPU性能。

5. 注释掉这两段代码可以进一步优化内存和CPU性能，并且避免协程泄露：

4.排查锁竞争

1. 终端输入指令go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/mutex"查看锁竞争情况：

2. 排查到wolf.(*Wolf).Howl存在锁竞争问题，进入source查询wolf可以定位到锁竞争的具体位置并解读代码：

func (w *Wolf) Howl() {
	log.Println(w.Name(), "howl")

	m := &sync.Mutex{} //创建互斥锁
	m.Lock()           //加锁，只允许一个协程通过
	go func() {
		time.Sleep(time.Second) //睡眠1秒
		m.Unlock()              //等待睡眠结束后解锁
	}()
	m.Lock()  //再次加锁
}

3. 根据代码逻辑在这段代码中，主协程在两个地方对互斥锁进行加锁操作，并且在子协程内部中执行解锁操作；出现问题：

   • 第一次加锁：m.Lock()
   • 启动协程并睡眠一秒：time.Sleep(time.Second)
   • 解锁互斥锁：m.Unlock()
   • 第二次加锁：m.Lock()

由于子协程在解锁操作之前睡眠了一秒钟，这就导致在这一秒钟内，主协程在第二次加锁时会被阻塞，直到子协程中的解锁操作完成；而协程中的解锁操作又是在睡眠结束后进行的，因此，在这种情况下，第二次加锁操作会被迫阻塞等待，在不断的调用下会大大降低代码性能；

4. 注释掉这段互斥锁代码，互斥锁竞争和阻塞之一问题解决：

5.排查阻塞

1. 除了上述锁竞争导致的阻塞外还有其他阻塞问题存在，通过命令go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/block查看阻塞出现的情况；

2. 分析调用图看出cat.(*Cat).Pee出现了阻塞，在source中查找cat定位阻塞语句<-time.After(time.Second)，这是一个接收操作，从time.After()返回的通道中获取值，然而，在这段代码中，并没有对该值做任何操作，因为它没有被赋给任何变量或用于其他计算，它只是简单地阻塞了当前的Pee()方法，等待这个接收操作完成，由于这个接收操作没有任何处理，这就导致了阻塞。整个Pee()方法在这一秒钟的阻塞期间无法继续执行，直到这个接收操作完成，也就是一秒钟后通道才能收到时间值；

3. 注释代码后发现仍然存在一个阻塞问题，再次使用命令打开pprof界面服务时，定位到是net/http/server.go的问题：

4. 也就是该阻塞是net/http包刻意设置的一个阻塞，在http服务器处理请求期间，可能存在并发的读取操作，如果在处理请求的过程中关闭连接，未完成的读取操作可能会导致问题，如资源泄漏，这段代码设置的阻塞能够保证在连接中止时，对正在进行的读取操作进行合理的处理，防止因为未完成读取而导致的问题，是必要的阻塞，无需优化，剩余其他资源使用情况经过排查也都是包内函数或者内置函数导致的资源占用，属于可接受可控范围，无需进一步优化。

3.总结

• 解决这个排查实战后，对于pprof性能分析工具的使用有了更深入的了解，不论是工具型应用还是web服务型应用都能够精准定位到对应指标的性能问题所在，能够理解指标数据的含义，能够看懂调用图，火焰图等，同时深入了解了这些性能问题出现的可能原因，知道了在哪些情况下容易出现这些性能问题；

• 同时由于这个项目的特殊性，找出性能问题后都是简单粗暴的注释掉代码，没有进一步思考如何不影响功能实现的前提下解决性能问题，需要进一步了解性能问题出现的原因和对应的处理方法，不仅仅要找出性能瓶颈更需要加以解决或改善；

• 第一次接触性能调优的知识，很让人感慨一个真正的优秀的项目绝不是写好代码那么简单，不仅仅要符合各种代码规范，更要能满足性能需求，Go语言又是追求极致性能的语言，性能调优更是非常重要，还有很多的知识需要学习，很长的路要走！

这篇好文章是转载于：学新通技术网