一看就懂系列之Golang的pprof

13,637 阅读10分钟

前言

这是一篇给网友的文章,正好最近在研究分析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/pprofgo 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 程序的垃圾回收