golang中pprof的使用

IT圈老男孩1

基本介绍


pprof是go语言内置 的分析性能，分析数据的工具，pprof开启后，每隔一段时间（10ms）就会收集下当前的堆栈信息，获取格格函数占用的CPU以及内存资源；最后通过对这些采样数据进行分析，形成一个性能分析报告。pprof用 profile.proto 读取分析样本的集合，并声称可视化报告，以帮助分析数据 （支持文本和图形报告）
profile.proto 是一个 Protobuf v3的描述文件，它描述了一组 callstack和 symbolization 信息，它的作用是统计分析一组采样的调用栈，配置文件格式是 stacktrace

采样方式
runtime/pprof 采集程序 （非server）指定区块的运行数据进行分析net/http/pprof 基于 http server 运行，并且可以采集运行时的数据进行分析 （其实net/http/pprof中只是使用runtime/pprof包来进行封装了一下，并在http端口上暴露出来）go test 通过运行测试用例，指定所需标识进行采集
使用模式
Report Generation 报告生成InteractiveTerminal Use 交互式终端使用web interface web界面
可以做什么
CPU profiling cpu分析，按照一定的频率采集所监听的应用程序cpu（含寄存器）的使用情况，确定应用程序在主动消耗cpu周期时花费时间的位置Memory Profiling 内存分析,在应用程序进行堆分配记录堆栈跟踪，用于监听当前和历史内存使用情况，以及检查内存泄漏。Block Profiling 阻塞分析，记录goroutine 阻塞等待同步（包含定时器通道）的位置，默认不开启，需要调用 runtime.SetBlockProfileRate 进行设置Mutex Profiling 互斥锁分析。报告互斥锁的竞争情况，默认不开启，需要调用 runtime.SetMutexProfileFraction 进行设置
简单例子
package mainimport (   "log"   "net/http"   _ "net/http/pprof"   "time")var datas []stringfunc main() {   go func() {      for  {         log.Printf("len:%d",Add("gwyy"))         time.Sleep(time.Microsecond + 10)      }   }()   _ = http.ListenAndServe(":6060",nil)}func Add(str string) int {   data := []byte(str)   datas = append(datas,string(data))   return len(datas)}
为什么要初始化 net/http/pprof

在前面例子中，在引用上对 net/http/pprof 包进行了默认的初始化，（也就是 _） ，如果没在对该包进行初始化，则无法调用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)}
实际上，在初始化函数中， net/http/pprof 会对标准库中的 net/http 默认提供 DefaultServeMux 进行路由注册，源码如下
func HandleFunc(pattern string, handler func(ResponseWriter, *Request)) {   DefaultServeMux.HandleFunc(pattern, handler)}
我们在例子中使用的 HTTP Server,也是标准库默认提供的，因此便可以注册进去。
在实际项目中 我们有独立的 ServeMux的，这时候只需要将PProf对应的路由注册进去即可
mux := http.NewServeMux()mux.HandleFunc("/debug/pprof",pprof.Index)mux.HandleFunc("/debug/pprof/cmdline"，pprof.cmdline)mux.HandleFunc("/debug/pprof/profile", pprof.Profile)mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)mux.HandleFunc("/debug/pprof/trace", pprof.Trace)好了 我们运行了上面的程序后，浏览器直接访问：


http://127.0.0.1:6060/debug/pprof/

如果在访问路径上加上 ?debug=1 则可以直接在浏览器中访问。

这个页面中有许多子页面，咱们继续深究下去，看看可以得到什么？

profile（CPU Profiling）: $HOST/debug/pprof/profile，默认进行 30s 的 CPU Profiling，得到一个分析用的 profile 文件allocs 查看过去所有内存分配样本，访问路径为 /debug/pprof/allocscmdline 当前程序命令行的完整调用路径block（Block Profiling）：$HOST/debug/pprof/block，查看导致阻塞同步的堆栈跟踪goroutine：$HOST/debug/pprof/goroutine，查看当前所有运行的 goroutines 堆栈跟踪heap（Memory Profiling）: $HOST/debug/pprof/heap，查看活动对象的内存分配情况mutex（Mutex Profiling）：$HOST/debug/pprof/mutex，查看导致互斥锁的竞争持有者的堆栈跟踪threadcreate：$HOST/debug/pprof/threadcreate，查看创建新OS线程的堆栈跟踪

一般在线上环境，为了网络安全，通常不会这么做。另外debug的访问方式是具有时效性的，在实际场景中，我们常常需要及时将当前状态下的 profile文件给存储下来，便于二次分析。

通过终端访问
第二种是通过命令行完整对正在运行的程序 pprof进行抓取和分析
//在执行命令后，需要等待 60s （可以调整seconds的值） PProf 会进行 cpu Profiling , 结束后将默认进入PProf 的命令行交互模式，查看或者导出分析结果。// 如果是以TLS方式启动的HTTP Server 那么在调用需要改成 go tool pprof https+insecure://localhost:6060/debug/pprof/profile?seconds=60go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=60Saved profile in C:\Users\admin\pprof\pprof.samples.cpu.001.pb.gzType: cpuTime: Oct 12, 2020 at 11:40pm (CST)Duration: 1mins, Total samples = 13.53s (22.50%)Entering interactive mode (type "help" for commands, "o" for options)(pprof)
top命令
输入命令 top 10 查看对应资源开销 （例如 cpu就是执行耗时/开销 Memory 就是内存占用大小）排名前十的函数
(pprof) top 10Showing nodes accounting for 10.82s, 79.97% of 13.53s totalDropped 64 nodes (cum <= 0.07s)Showing top 10 nodes out of 61      flat  flat%   sum%        cum   cum%     7.50s 55.43% 55.43%      7.56s 55.88%  runtime.stdcall1     1.88s 13.90% 69.33%      1.90s 14.04%  runtime.cgocall     0.31s  2.29% 71.62%      2.25s 16.63%  runtime.timerproc     0.26s  1.92% 73.54%      0.26s  1.92%  runtime.(*mcache).prepareForSweep     0.20s  1.48% 75.02%      0.53s  3.92%  runtime.acquirep     0.18s  1.33% 76.35%      0.18s  1.33%  runtime.casgstatus     0.15s  1.11% 77.46%      1.18s  8.72%  runtime.exitsyscall     0.12s  0.89% 78.34%      0.52s  3.84%  runtime.goroutineReady     0.11s  0.81% 79.16%      8.79s 64.97%  runtime.systemstack     0.11s  0.81% 79.97%      0.11s  0.81%  runtime.unlockflat：当前函数上运行耗时flat%：函数自身占用的 CPU 运行耗时总比例sum%：函数自身累积使用 CPU 总比例cum：当前函数及其调用函数的运行总耗时cum%：函数自身及其调用函数占 CPU 运行耗时总比例最后一列为函数名称大多数情况下，我们可以得出一个应用程序的运行情况，知道当前是什么函数，正在做什么事情，占用了多少资源等。
Heap Profiling
PS C:\Users\admin> go tool pprof http://localhost:6060/debug/pprof/heapFetching profile over HTTP from http://localhost:6060/debug/pprof/heapSaved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gzType: inuse_spaceTime: Oct 12, 2020 at 11:50pm (CST)No samples were found with the default sample value type.Try "sample_index" command to analyze different sample values.Entering interactive mode (type "help" for commands, "o" for options)(pprof)
这个命令能够很快的拉取到结果。不需要采样等待， 需要注意的是 Type 这个选项默认是 inuse_space，实际上，它可以对多种内存情况进行分析。常见的有：
inuse_space 分析应用常驻内存的占用情况
PS C:\Users\admin> go tool pprof  -inuse_space http://localhost:6060/debug/pprof/heapFetching profile over HTTP from http://localhost:6060/debug/pprof/heapSaved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gzType: inuse_spaceTime: Oct 12, 2020 at 11:52pm (CST)Entering interactive mode (type "help" for commands, "o" for options)(pprof) topShowing nodes accounting for 3.38MB, 100% of 3.38MB total      flat  flat%   sum%        cum   cum%    2.38MB 70.40% 70.40%     2.38MB 70.40%  main.Add       1MB 29.60%   100%     3.38MB   100%  main.main.func1
alloc_objects 分析应用程序的内存临时分配情况
PS C:\Users\admin> go tool pprof  -alloc_objects http://localhost:6060/debug/pprof/heapFetching profile over HTTP from http://localhost:6060/debug/pprof/heapSaved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gzType: alloc_objectsTime: Oct 12, 2020 at 11:53pm (CST)Entering interactive mode (type "help" for commands, "o" for options)(pprof) topShowing nodes accounting for 98305, 100% of 98312 totalDropped 14 nodes (cum <= 491)      flat  flat%   sum%        cum   cum%     98305   100%   100%      98311   100%  main.main.func1(pprof)
另外还有 inuse_objects 和 alloc_space 类别，分别对应查看每个函数的对象数量和分配的内存空间大小。

Goroutine Profiling
PS C:\Users\admin> go tool pprof   http://localhost:6060/debug/pprof/goroutineFetching profile over HTTP from http://localhost:6060/debug/pprof/goroutineSaved profile in C:\Users\admin\pprof\pprof.goroutine.001.pb.gzType: goroutineTime: Oct 13, 2020 at 12:15am (CST)Entering interactive mode (type "help" for commands, "o" for options)(pprof)
在查看goroutine 时可以使用traces命令，这个命令会打印出对应的所有调用栈，以及指标信息，通过这个命令我们可以很方便的查看整改调用链路有什么，分别在哪里使用了多岁个goroutine,并且通过分析可以知道谁才是真正的调用方，输出结果如下：
(pprof) tracesType: goroutineTime: Oct 13, 2020 at 12:15am (CST)-----------+-------------------------------------------------------         1   runtime.cgocall             syscall.Syscall9             syscall.WSARecv             internal/poll.(*FD).Read.func1             internal/poll.(*ioSrv).ExecIO             internal/poll.(*FD).Read             net.(*netFD).Read             net.(*conn).Read             net/http.(*connReader).backgroundRead-----------+-------------------------------------------------------         1   runtime.gopark             runtime.netpollblock             internal/poll.runtime_pollWait             internal/poll.(*pollDesc).wait             internal/poll.(*ioSrv).ExecIO             internal/poll.(*FD).acceptOne             internal/poll.(*FD).Accept             net.(*netFD).accept             net.(*TCPListener).accept             net.(*TCPListener).Accept             net/http.(*Server).Serve             net/http.(*Server).ListenAndServe             net/http.ListenAndServe             main.main             runtime.main-----------+-------------------------------------------------------         1   runtime.gopark             runtime.goparkunlock             time.Sleep             main.main.func1-----------+-------------------------------------------------------         1   runtime/pprof.writeRuntimeProfile             runtime/pprof.writeGoroutine             runtime/pprof.(*Profile).WriteTo             net/http/pprof.handler.ServeHTTP             net/http/pprof.Index             net/http.HandlerFunc.ServeHTTP             net/http.(*ServeMux).ServeHTTP             net/http.serverHandler.ServeHTTP             net/http.(*conn).serve-----------+-------------------------------------------------------(pprof)
调用栈上的展示是自下而上的，也就是说 runtime.main方法调用了 main.main方法，而main.main方法又调用了 net/http.ListenAndServe 方法，排查起来比较方便。
每个调用栈信息都是用 ------- 分割，函数方法前面的是指标数据，例如，Gorutine Profiling 展示的是该方法占用的 goroutine的数量，而Heap Profiling 展示 的是占用内存大小。如图

image.png

实际上，PProf中的所有功能都会根据 Profile的不同类型展示不同的对应结果

Mutex Profiling
一般来说，在调用 chan （通道）、sync.Mutex （同步锁）或者 time.Sleep() 时会造成阻塞，下面看个例子：
func init() {   runtime.SetMutexProfileFraction(1)}func main() {   var m sync.Mutex   var datas = make(map[int]struct{})   for i:=0;i<999;i++ {      go func(i int) {         m.Lock()         defer m.Unlock()         datas = struct{}{}      }(i)   }   _ = http.ListenAndServe(":6060",nil)}
需要特别注意的是 runtime.SetMutexProfileFraction(1) 语句，如果未来希望对互斥锁进行采集，则需要调用该方法设置采集频率，如果没有设置，或者设置数值小于0，则不进行采集
接下里调用 go tool pprof 进行分析：
PS C:\Users\admin> go tool pprof   http://localhost:6060/debug/pprof/mutexFetching profile over HTTP from http://localhost:6060/debug/pprof/mutexSaved profile in C:\Users\admin\pprof\pprof.contentions.delay.001.pb.gzType: delayTime: Oct 13, 2020 at 12:31am (CST)Entering interactive mode (type "help" for commands, "o" for options)(pprof)

image.png

image.png