golang pprof

Go

听说火山引擎出开发者社区了,来捧个场,搬运一篇我之前的文章

大家好啊,今天外边真的是热爆了,根本不想出去走动,这个天气在空调房里拿个小勺子🥄挖着冰镇西瓜吃,真的是绝了😄,正当我一边看着奥运一边恰西瓜时,我突然想到,这大夏天的不能光我自己凉快,也得给我们的程序“降降温“,而降温的关键是要找到“升温点”,而golang就提供了非常好用的工具来帮助我们来定位程序中的很多问题,它就是pprof

pprof简介

pprof提供运行时程序的profiling,profiling一般翻译为画像。在互联网中,各个app一般都会有自己的用户画像,用户画像会包含年龄、性别、视频偏好等多项特征,从而更方便的为用户去推荐用户可能会感兴趣的内容。而计算机领域的profile指的就是进程的运行时特征,一般会包括CPU、内存、锁等多项运行时特征,从而让我们更方便的去优化我们程序的性能。

golang是一个非常注重性能的语言(虽然有gc😂),所以golang内置了pprof工具来帮助我们了解我们程序的各项profiling数据,同时结合插件也可以可视化的看到程序的各项pprofing,golang提供了两种pprof的使用方式。

  1. runtime/pprof

对应的场景是脚本/工具类的程序,一般运行一段时间就会停止,不会持续运行,这种情况下直接使用runtime包的pprof工具来采集进程的性能数据是最方便,直接在进程运行中持续写入pprof文件或者在结束后将各项性能数据写入文件即可。

  1. net/http/pprof

对应的场景是在线的程序,一般需要持续运行(提供服务),只有在服务需要升级时才会停止,这种情况下使用net包的pprof更合适一点,net/http/pprof会对外暴露一个端口,我们通过它提供的各项api就可以持续/动态/实时的采集,当然net/http/pprof只是为了方便我们通过外部接口来更方便的使用,其底层调用的也是runtime/pprof提供的各个接口。

基本使用

下文中使用的go代码和pprof工具都是基于golang 1.16

runtime/pprof

package main



import (

    "fmt"

    "os"

    "runtime/pprof"

    "time"

)



func main() {

    fi, err := os.Create("cpu.pprof")

    if err != nil {

        panic(err)

    }

    pprof.StartCPUProfile(fi)



    go infLoop()

    time.Sleep(time.Second)



    pprof.StopCPUProfile()

}



func infLoop() {

    for {

        fmt.Println("abcd")

    }

}

执行上述程序,会生成cpu的profiling写入到cpu.pprof文件。

然后我们再执行 go tool pprof cpu.pprof,就可以进入到pprof的交互式终端。

首先有几行信息,分别是

  • Type:当前pprof文件的类型,目前的取值是cpu,后续我们可以看到更多类型的性能分析数据
  • Time:pprof文件采集开始的时间,精确到min
  • Duration:pprof持续的时间,后边的Total samples是样本数采集的时间

执行top命令可以可以看到占用量逆序排列的函数,如下。

可以看到总共有6列信息,这六列分别是

列名解释
flat当前函数占用的cpu时间(因为这里分析的是cpu,所以单位是时间单位,在分析内存时单位就会换成空间单位)
flat%当前函数占用的cpu时间百分比
sum%flat%从上到下依次累加的结果,所以第一行的sum%会等于第一行的flat%,而第二行的sum%就会是第一行的flat%加第二行的flat%,后边依次类推
cumcumulative,当前函数及当前函数的子函数占用的cpu时间
cum%当前函数及当前函数的子函数占用的cpu时间百分比
(最后一列)函数的路径,格式为Package.{Package}.{Function}

除了top命令外,使用help可以看到pprof支持的全部交互式命令,当前版本(golang 1.16)共支持以下几种,其中比较常用的已经用灰色标记出来。

Command解释
callgrind以callgrind格式输出图,callgrind是linux valgrind工具集提供的一个性能分析工具。
comments输出所有profile的注释
disasm选择或过滤程序中的汇编调用并输出展示
dot以dot格式输出图,dot是linux提供的一个绘图
eog通过eog来展示图(需要安装graphviz)
evince通过evince来展示图(需要安装graphviz)
gif以gif格式输出图(需要安装graphviz)
kcachegrind用KCachegrind来可视化的展示报告(KCacheGrind是一个性能可视化的工具)
list需要给到一个正则,输出符合对应正则的函数的源代码
pdf以pdf格式输出图
peek需要给到一个正则,输出符合对应正则的函数的caller/callee
png以png格式输出图
proto以proto压缩格式输出profile
ps以ps格式生成图(需要安装Graphviz)
raw以文本格式输出profile源文件
svg以svg格式生成图(需要安装Graphviz)
tags输出profile文件中的全部tag
text与top相同
top以文本格式输出占用量前n的函数
topproto以protobuf格式输出top的每个节点
traces以文本格式输出所有的profile样本
tree输出函数调用栈
web以浏览器来浏览pprof生成的图(需要安装Graphviz)
weblist以浏览器来浏览函数及对应的代码
o/options列表输出全部的options及对应的值
q/quit/exit/^d退出pprof命令行交互模式

net/http/pprof

package main



import (

    "net/http"

    _ "net/http/pprof"

)



func main() {

    http.HandleFunc("/", func(resp http.ResponseWriter, req *http.Request) {

        resp.Write([]byte("hellp net pprof"))

    })

    err := http.ListenAndServe("127.0.0.1:8000", http.DefaultServeMux)

    if err != nil {

        panic(err)

    }

}

如果使用的是http package的默认serveMux,在pprof包init时会自动注册几个路由到我们的mux中,如果用的不是http.DefaultServeMux,我们自己注册一下以下几个serveMux就好啦。

//src/net/http/pprof/pprof.go

package pprof

//...

func init() {

    http.HandleFunc("/debug/pprof/", Index)

    http.HandleFunc("/debug/pprof/cmdline", Cmdline)

    http.HandleFunc("/debug/pprof/profile", Profile)

    http.HandleFunc("/debug/pprof/symbol", Symbol)

    http.HandleFunc("/debug/pprof/trace", Trace)

}

//...

注意,一般来说,在真正的线上服务里,为了与我们的对外服务端口隔离开,要用一个新的端口(debug port)来作为pprof的端口。

编译程序后直接运行,访问http://localhost:8000即可看到我们根目录。

接下来我们再看下pprof注册的这几个路由。

  1. /debug/pprof/cmdline

很简单,就是输出当前进程的命令行参数,如下。

  1. /debug/pprof/symbol

根据传入的函数地址(PC),获取对应的函数名,如果是http POST方法,则从body中读取数据,如果是http GET方法,则读取url query。如果需要传多个函数地址,则用加号做连接,如下。

  1. /debug/pprof/trace

获取程序运行中的各种事件追踪信息,例如系统调用、GC、Goroutine等等,可以接一个second参数,代表要采样的时长(单位:秒),执行完成后会自动下载一个文件,如下。

在这里,我们进行5s的采样,采样结束后会自动下载采样的trace文件。

使用go tool trace tracefile即可看到采样信息,如下:

在这也可以看到比较多的信息,不过trace不在我们这篇文章的范畴内,可以放到后边再做深一步的学习。

  1. /debug/pprof/profile

采集cpu的profiling,与trace一致,也可以跟一个seconds参数来指定采集的时长(单位:秒),执行完成后,会自动下载一个文件,如下。

然后再使用go tool pprof profile就可以进入交互模式,剩下的操作和runtime/pprof一节介绍的就一样了。

/debug/pprof/profile的底层实现和我们runtime/pprof的demo是一致的,在内部调用了StartCPUProfile和StopCPUProfile。

  1. /debug/pprof

列出pprof支持的profile,当前版本(go 1.16)支持的profile如下。

包括我们刚才介绍的profile操作,各profile及解释如下:

profile说明
allocs程序运行到现在的内存申请情况
block处于阻塞的协程的栈帧,默认不开启,需要调用runtime.SetBlockProfileRate来开启
goroutine全部协程的栈帧。使用?debug=2会展示更详细的信息(例如goroutine状态)
heap堆上对象的内存申请情况
mutexmutex的竞争状态,默认不开启, 需要调用runtime.SetMutexProfileFraction来开启
profilecpu 状态,采样完成后,使用go tool pprof来分析
threadcreate系统线程的创建情况
trace程序的追踪状态

图形化

在runtime/pprof,我们可以看到有非常多的命令(大部分都是各种生成图形化的命令)都依赖一个组件才可以使用,这个组件就是graphviz,下面我们来介绍下graphviz及用graphviz后的生成的各种图形。

Graphviz

Graphviz 是一个开源的图可视化工具,非常适合绘制结构化的图标和网络。Graphviz 使用一种叫 DOT 的语言来表示图形。

而golang pprof就可以生成dot数据,再使用graphviz打开即可看到各种精美的图形,Graphviz大家直接去http://www.graphviz.org/安装即可。

Flame Graph🔥

Flame graphs are a visualization of hierarchical data, created to visualize stack traces of profiled software so that the most frequent code-paths to be identified quickly and accurately.

图片摘自 https://www.brendangregg.com/FlameGraphs/cpu-mysql-updated.svg 可以访问源网站去体验一下火焰图的详细交互,下面简单说一下如何看火焰图(以cpu火焰图为例)。

火焰图是一个二维展示的svg图形。

y 轴表示函数调用栈,每一层都是一个函数。调用栈越深,火焰就越高,顶部就是正在执行的函数,下方都是它的父函数。

x 轴表示样本数,如果一个函数在 x 轴占据的宽度越宽,就表示它被抽到的次数多,即执行的时间长。注意,x 轴不代表函数调用时间,并不意味着出现在越靠前的函数代表是先调用的,而是将所有的函数调用栈合并后,按函数名字母顺序排列的。

火焰图就是看哪个函数占据的宽度最大。只要有"平顶",就表示该函数可能存在性能问题。

"平顶" 的意思是没有再次进行子函数调用,"平顶" 段越长,证明该函数在采样期间调用时间更长.

颜色没有特殊含义,因为火焰图表示的是 CPU 的繁忙程度,所以一般选择暖色(🔥)。

Graph

Graph,我一般叫他调用图(为了和火焰图区分开,不清楚是否准确😀),图中每一个方形都代表一个函数实体,而有向边则是函数调用,源节点是caller,目标节点是callee。有向边越粗代表调用开销越大,节点越大代表当前函数开销越大。

pprof实战

纸上得来终觉浅,觉知此事要躬行。

看过了基本使用,下面让我们用一个demo来巩固下pprof的学习。

实战源码:https://github.com/wolfogre/go-pprof-practice,感谢wolfgre提供的实战代码🙏。

clone下来直接go build,然后运行即可(源仓库没有基于go mod构建,我们这里也就先off掉mod)。

export GO111MODULE=off && go build

我们先来简单看一下main.go文件。

程序设置可GOMAXPROCS,可以限制P的数量为1,变相的限制了cpu核数,开启了mutex和block的追踪信息,同时程序的pprof地址为:localhost:6060

注意实战代码直接构造了各种性能case,是比较简单的,很多异常情况都可以通过肉眼看出来,但这里不要直接通过看代码的方式来解决问题,要借助pprof工具来发现程序中的问题。

进程启动起来后,我们可以看到终端里不停的有输出。

下面让我们来从各个方面来分析这个炸弹程序。

profile

我这里是mac os,所以直接用活动监视器来看进程情况了,可以看到我们的实战程序已经占了非常高的cpu😱。

接下来让我们使用pprof进行30s的cpu信息采样。

go tool pprof ``http://127.0.0.1:6060/debug/pprof/profile``?seconds=30

采样结束后就可以直接用前边介绍的命令行工具来查看top调用了,这里我们使用新的方式,我们使用图形化的形式来观测。

go tool pprof --http=:8080 xxxx/pprof.samples.cpu.001.pb.gz

这里会启动一个8080端口来支持我们可视化的访问cpu采样信息。

  1. flame graph

  1. top

  1. graph

通过top、graph和flame graph都可以看到“平顶”出现在*Tiger.Eat这里(就这三幅图来说,graph给人的视觉冲击力应该更明显一些)。

现在我们已经定位到问题出现在Tiger.Eat这里,我们再切换到source这个tab,来看一下详细的代码。

可以看到,在Eat每次被调用时都会执行1e10次的调用,这里我们注释掉这里的loop代码,重新运行。

可以看到cpu的耗用已经完全降下来了,🎉已经解决了cpu问题,下面让我们再来看第二个问题。

heap

还是使用活动监视器,可以看到,我们的进程目前吃掉了接近2G的内存。

我们与cpu章一致,先采集再分析。

go tool pprof --http=:8080 127.0.0.1:6060/debug/pprof/heap

通过heap调用图,我们可以看到是🐀偷走了我们的内存😁,主要发生在Mouse.Steal这里,我们接着再去看source。

发现这里在循环的append slice,每次append 1MB,直到达到1G,且后续也没有释放操作。

这里留个小习题,为什么程序中只append了1G的内存,最终我们在应用监视器里看到的是2G。提示一下,与slice append的实现机制相关。

我们注释掉问题代码,再次编译运行,可以看到内存已经降下来了,我们又解决了一个问题🎉!但是内存相关的问题已经完全解决了吗🤔?

allocs

heap查看的只是当前堆上存活对象的情况,大部分的内存问题都可以通过heap命令解决,但是他覆盖不到一种特殊情况,这种情况就是申请、再释放内存。golang是带gc的语言,频繁的申请内存/GC也会导致我们的程序性能有很大的下降。

使用go tool pprof --http=:8080 127.0.0.1:6060/debug/pprof/allocs可以看到历史的内存申请情况。

可以看到“平顶”出现在Dog.Run这里,我们再用source看下源代码。

这里dog.Run被inline了,所以在source这里看不到Run的代码,我们使用pprof换一种方式来看(这里是为了演示下list的调用,工作中下直接去看源代码可能更方便)。

使用go tool pprof ${filename}来进入pprof的交互式命令终端,然后使用list Run就可以看到有问题的地方,dog.Run每次调用都会申请16MB的内存,然后不使用,自然就会被GC掉,我们注释掉这里。

这里也可以留第二个小习题,这里申请了内存,又没有其他地方引用,为什么依然会在堆上进行内存申请?而不是在栈上申请?

让程序稍微运行一会,然后再查看alloc_spaces,发现已经没有大量的申请了🎉。

goroutine

golang从语言层面就支持了并发(goroutine),在go里用goroutine写并发程序是一件非常简单的事情,但是goroutine一旦使用不当也会发生问题。使用过不带GC语言(例如C++)的同学可能都经历过内存泄露的问题,而golang是带gc的语言,一般情况下不会出现内存泄露,但是如果goroutine使用不当,也会发生goroutine泄露,进而导致cpu/内存的飙升。

打开http://127.0.0.1:6060/debug/pprof/

可以看到程序中有100多个goroutine,100多个goroutine对于我们这样的小程序来说肯定是不正常的。

使用go tool pprof --http=:8080 127.0.0.1:6060/debug/pprof/goroutine来查看我们程序中的goroutine分配/使用情况。

可以看到wolf.Drink这里申请了101个goroutine,我们再查看一下source。

发现wolf.Drink这里每次调用都会申请10个goroutine,每个goroutine sleep 30秒,我们注释掉这里,重新运行程序。

可以看到已经只有5个goroutine了🎉。

mutex

上述我们解决的问题都是资源相关的,但是除了资源相关的,大量的同步操作(例如互斥锁mutex)也会导致虽然资源利用率很低,但是程序的性能非常差。

依然是老一套,先采样观测。

go tool pprof --http=:8080 127.0.0.1:6060/debug/pprof/mutex

可以看到锁的竞争出现在了Wolf.Howl这里,然后接下来相比大家已经熟悉了,还是source操作去查看源代码。

这里要说明一下,程序中出现mutex是非常正常的事情,并不是每一个mutex都有问题,这里mutex只是为了演示锁竞争情况,并不是mutex的推荐用法(mutex详解可以看这里:📚mutex ),这里我们简单把sleep注释掉就可以了。

可以看到锁竞争等待的时间已经非常少了🎉。

block

golang支持了并发操作,但是本质上还是一个同步的语言(相对于node.js事件回调),必然会有一些阻塞的操作,而阻塞操作也是影响我们程序性能的很大一个点。

使用go tool pprof --http=:8080 127.0.0.1:6060/debug/pprof/block

可以看到阻塞操作发生在chanrecv上,向上追溯到我们的业务代码就是Cat.Pee

在源码这,我们可以看到Cat.Pee在每次调用时都会去读chan,而这个chan直到1秒后才可以读到。把这里注掉就可以啦🎉。

总结

首先,我们介绍了profile的基本定义。其次,我们介绍了golang pprof的基本使用,golang pprof对外暴露的api包括runtime/pprof和net/http/pprof两部分,net/http/pprof是对runtime/pprof的http调用封装。pprof常用的命令是list、top和web。然后,图形化的pprof可以帮助我们更直观的观测go进程的各项profile数据。最后通过实战,解决了一个程序的cpu、内存、锁等方面的性能问题。总而言之,pprof是一个非常强大的工具,更多的用法和特性还有待大家去探索,希望pprof可以使你的golang程序也能"清凉一夏"。

参考文档
  1. 深度解密Go语言之 pprof - Stefno - 博客园 (cnblogs.com)
  2. golang pprof 实战 | Wolfogre's Blog
1127
4
0
0
关于作者
相关产品
评论
未登录
看完啦,登录分享一下感受吧~
暂无评论