39 性能分析利器:深入pprof与trace工具
你好,我是郑建勋。
这节课,我们来学习分析Go程序的利器:pprof和trace。
pprof及其使用方法
先来看pprof。pprof用于对指标或特征的分析(Profiling)。借助pprof,我们能够定位程序中的错误(内存泄漏、race 冲突、协程泄漏),也能对程序进行优化(例如 CPU 利用率不足等问题)。
Go 语言运行时的指标并不对外暴露,而是由标准库 net/http/pprof 和 runtime/pprof 来与外界交互。其中, runtime/pprof需要嵌入到代码进行调用,而net/http/pprof 提供了一种通过 HTTP 获取样本特征数据的便利方式。而要对特征文件进行分析,就得依赖谷歌推出的分析工具pprof了。这个工具在 Go 安装时就存在,可以用go tool pprof执行。
要用 pprof 进行特征分析需要执行两个步骤:收集样本和分析样本。
收集样本有两种方式。一种是引用 net/http/pprof,并在程序中开启 HTTP 服务器,net/http/pprof 会在初始化 init 函数时注册路由。
import _ "net/http/pprof"
if err := http.ListenAndServe(":6060", nil); err != nil {
log.Fatal(err)
}
通过HTTP收集样本是实践中最常见的方式,但它并不总是合适的,例如对于一个测试程序,或是只跑一次的定时任务就是如此。
另一种方式是直接在需要分析的代码处嵌入分析函数,例如下例中我们调用了 runtime/pprof 的StartCPUProfile 函数,这样,在程序调用完 StopCPUProfile 函数之后,就可以指定特征文件保存的位置了。
func main(){
f, err := os.Create(*cpuProfile)
if err := pprof.StartCPUProfile(f); err != nil {
log.Fatal("could not start CPU profile: ", err)
}
defer pprof.StopCPUProfile()
busyLoop()
}
接下来,让我们用第一种方式在项目的main函数中注册pprof。
package main
import (
"github.com/dreamerjackson/crawler/cmd"
_ "net/http/pprof"
)
func main() {
cmd.Execute()
}
pprof库在init函数中默认注册了下面几个路由。
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)
}
接着,我们需要在Master中开启一个默认的HTTP服务器,用它来接收外界的pprof请求。
其实在之前实现GRPC-gateway时,已经为Master和Worker开启了HTTP的服务器。但是当时开启的HTTP服务器并不是Go中默认的HTTP路由器,所以我们不能为pprof复用该端口。
我们在这里开启一个新的HTTP服务器来处理pprof请求,处理方式如下。
// cmd/master.go
MasterCmd.Flags().StringVar(
&PProfListenAddress, "pprof", ":9981", "set GRPC listen address")
func Run() {
// start pprof
go func() {
if err := http.ListenAndServe(PProfListenAddress, nil); err != nil {
panic(err)
}
}()
}
有了用于处理pprof请求的HTTP服务器之后,我们就可以调用相关的HTTP接口,获取性能相关的信息了。pprof的URL为debug/pprof/xxxx形式,最常用的 3 种 pprof 类型包括了堆内存分析(heap)、协程栈分析(goroutine)和 CPU 占用分析(profile)。
- profile用于获取CPU相关信息,调用如下。
- goroutine用于获取协程堆栈信息,调用如下。
- heap用于获取堆内存信息,调用如下。在实践中我们大多使用 heap 来分析内存分配情况。
- cmdline用于打印程序的启动命令,调用如下。
» curl -o cmdline.out <http://localhost:9981/debug/pprof/cmdline>
» cat cmdline.out
./main master --id=2 --http=:8081 --grpc=:9091
另外,block、threadcreate、mutex 这三种类型在实践中很少使用,一般只用于特定的场景分析。
获取到特征文件后,我们就可以开始具体地分析了。
一般我们使用 go tool pprof 来分析。
» go tool pprof heap.out jackson@bogon
Type: inuse_space
Time: Dec 18, 2022 at 1:08am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
此外,我们也可以直接采用下面的形式完成特征文件的收集与分析,通过 HTTP 获取到的特征文件将存储在临时目录中。
pprof堆内存分析
当我们用pprof分析堆内存的特征文件时,默认的分析类型为inuse_space,代表它是分析程序正在使用的内存,文件的最后一行会出现等待进行交互的命令。
交互命令有许多,我们可以通过 help 指令查看,比较常用的包括top、list、tree等。首先来看看使用最多的top指令,top指令能够显示出分配资源最多的函数。
我们现在启动Worker,在只有一个任务(爬取豆瓣图书的信息)的情况下,利用pprof查看堆内存的占用情况。可以看到,当前收集的内存量为5915.93KB。
» go tool pprof heap.out jackson@bogon
Type: inuse_space
Time: Dec 18, 2022 at 1:37am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 5915.93kB, 100% of 5915.93kB total
Showing top 10 nodes out of 92
flat flat% sum% cum cum%
2562.81kB 43.32% 43.32% 2562.81kB 43.32% runtime.allocm
768.26kB 12.99% 56.31% 768.26kB 12.99% go.uber.org/zap/zapcore.newCounters (inline)
536.37kB 9.07% 65.37% 536.37kB 9.07% google.golang.org/protobuf/internal/strs.(*Builder).AppendFullName
512.23kB 8.66% 74.03% 512.23kB 8.66% google.golang.org/protobuf/internal/filedesc.(*Message).unmarshalFull
512.20kB 8.66% 82.69% 512.20kB 8.66% runtime.malg
512.05kB 8.66% 91.35% 512.05kB 8.66% runtime.acquireSudog
512kB 8.65% 100% 512kB 8.65% go-micro.dev/v4/config/reader/json.(*jsonValues).Get
0 0% 100% 768.26kB 12.99% github.com/dreamerjackson/crawler/cmd.Execute
0 0% 100% 768.26kB 12.99% github.com/dreamerjackson/crawler/cmd/worker.Run
0 0% 100% 768.26kB 12.99% github.com/dreamerjackson/crawler/cmd/worker.RunGRPCServer
我们当前收集的内存量为5915.93KB,这些内存来自哪里呢?top可以为我们分析出分配内存最多的函数来自哪里。其中2562.81KB由runtime.allocm函数分配,这是运行时创建线程m的函数。还有768.26kB来自Zap日志库的zapcore.newCounters方法。
top 会列出以 flat 列从大到小排序的序列。不同的场景下flat对应值的含义不同。当类型为heap的inuse_space 模式时,flat对应的值表示当前函数正在使用的内存大小。
cum 列对应的值是一个累积的概念,指当前函数及其调用的一系列函数flat的和。flat本身只包含当前函数的栈帧信息,不包括它的调用函数的栈帧信息,cum字段正好弥补了这一点,flat%和cum%分别表示flat和cum字段占总字段的百分比。
要注意的是,5915.93KB 并不是当前程序的内存大小,它只是样本的大小。在实践过程中,很多人会想当然地犯错。那如果我们想获取当前时刻程序的内存大小要怎么做呢?
在程序中,我们可以使用runtime标准库来获取当前的内存指标,下面是我打印出的程序当前的内存大小。
memStats := new(runtime.MemStats)
runtime.ReadMemStats(memStats)
fmt.Println(memStats.Alloc/1024, "KB")
另外我们也可以用pprof做到这一点,在HTTP请求中添加debug=1参数,我们就可以打印出当前的堆栈信息和内存指标了。
打印结果如下所示。
...
# runtime.MemStats
# Alloc = 3525848
# TotalAlloc = 28212464
# Sys = 21840904
# Lookups = 0
# Mallocs = 36600
# Frees = 26354
# HeapAlloc = 3525848
# HeapSys = 11599872
# HeapIdle = 6160384
# HeapInuse = 5439488
# HeapReleased = 3252224
# HeapObjects = 10246
# Stack = 983040 / 983040
# MSpan = 170680 / 179520
# MCache = 14400 / 15600
# BuckHashSys = 1454473
# GCSys = 5338888
# OtherSys = 2269511
# NextGC = 6464480
# LastGC = 1671360289891484000
# PauseNs = [80190 73495 74791 123637 100272 80321 64056 76872 105588 66730 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
# PauseEnd = [1671360184885772000 1671360188628568000 1671360202091581000 1671360215146797000 1671360226657167000 1671360238789623000 1671360250378171000 1671360265788220000 1671360278228022000 1671360289891484000 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
# NumGC = 10
# NumForcedGC = 0
# GCCPUFraction = 1.9176443581930546e-05
# DebugGC = false
# MaxRSS = 24653824
我们还可以使用top-cum命令,对cum进行排序,查看哪一个函数分配的内存量最多(包含了其子函数的内存分配)。
以runtime.newm函数为例进行说明,通过runtime.newm的flat指标可知,其自身没有分配内存,但是由于runtime.newm调用了runtime.allocm,而runtime.allocm分配了2.50MB,所以 runtime.allocm 的 cum 量也达到了2.50MB。
(pprof) top -cum
Showing nodes accounting for 2.50MB, 43.32% of 5.78MB total
Showing top 10 nodes out of 92
flat flat% sum% cum cum%
2.50MB 43.32% 43.32% 2.50MB 43.32% runtime.allocm
0 0% 43.32% 2.50MB 43.32% runtime.newm
0 0% 43.32% 2.50MB 43.32% runtime.resetspinning
0 0% 43.32% 2.50MB 43.32% runtime.schedule
0 0% 43.32% 2.50MB 43.32% runtime.startm
0 0% 43.32% 2.50MB 43.32% runtime.wakep
0 0% 43.32% 2MB 34.66% runtime.mstart
0 0% 43.32% 2MB 34.66% runtime.mstart0
0 0% 43.32% 2MB 34.66% runtime.mstart1
0 0% 43.32% 1.27MB 22.05% runtime.main
我们还可以使用tree命令查看当前函数的调用链。例如,runtime.allocm分配了2.5M内存,其中512.56KB是runtime.mcall调用的,另外2050.25KB是由runtime.mstart0调用的。(runtime.mstart0是程序启动时调用的函数)。
(pprof) tree
Showing nodes accounting for 5915.93kB, 100% of 5915.93kB total
Showing top 80 nodes out of 92
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
2050.25kB 80.00% | runtime.mstart0
512.56kB 20.00% | runtime.mcall
2562.81kB 43.32% 43.32% 2562.81kB 43.32% | runtime.allocm
----------------------------------------------------------+-------------
768.26kB 100% | go.uber.org/zap/zapcore.NewSamplerWithOptions (inline)
768.26kB 12.99% 56.31% 768.26kB 12.99% | go.uber.org/zap/zapcore.newCounters
更进一步地,我们还可以使用 list runtime.allocm 列出内存分配是在哪里发生的。如下所示,可以看到,runtime.allocm函数位于runtime/proc.go,它的内存分配位于第1743行代码的mp := new(m)。
(pprof) list runtime.allocm
Total: 5.78MB
ROUTINE ======================== runtime.allocm in /usr/local/opt/go/libexec/src/runtime/proc.go
2.50MB 2.50MB (flat, cum) 43.32% of Total
. . 1738: }
. . 1739: sched.freem = newList
. . 1740: unlock(&sched.lock)
. . 1741: }
. . 1742:
2.50MB 2.50MB 1743: mp := new(m)
. . 1744: mp.mstartfn = fn
. . 1745: mcommoninit(mp, id)
. . 1746:
. . 1747: // In case of cgo or Solaris or illumos or Darwin, pthread_create will make us a stack.
. . 1748: // Windows and Plan 9 will layout sched stack on OS stack.
这样一来,当遇到内存问题时,我们就可以非常精准地知道要查看哪一行代码了。
除却默认的分析类型inuse_space,在heap中,还有另外三种类型分别是:alloc_objects、alloc_space和inuse_objects。其中alloc_objects 与inuse_objects 分别代表“已经被分配的对象”和“正在使用的对象”的数量,alloc_space表示内存分配的数量,alloc_objects与alloc_space都没有考虑对象的释放情况。
要切换展示的类型很简单,只需要输入对应的指令即可。例如,输入alloc_objects 后再次输入top 指令,当前 flat 代表的就不再是分配的内存大小,而是分配内存的次数。可以看到,分配内存次数最多的是 go-micro 中的 json.Get 函数。
(pprof) alloc_objects
(pprof) top
Showing nodes accounting for 221497, 93.52% of 236838 total
Dropped 140 nodes (cum <= 1184)
Showing top 10 nodes out of 92
flat flat% sum% cum cum%
65536 27.67% 27.67% 65536 27.67% go-micro.dev/v4/config/reader/json.(*jsonValues).Get
65536 27.67% 55.34% 65536 27.67% google.golang.org/grpc.DialContext
32768 13.84% 69.18% 32768 13.84% reflect.copyVal
16384 6.92% 76.10% 16384 6.92% crypto/sha256.(*digest).Sum
12289 5.19% 81.28% 12289 5.19% reflect.Value.MapRange
8192 3.46% 84.74% 12894 5.44% net/http.(*persistConn).readLoop
6554 2.77% 87.51% 6554 2.77% crypto/x509/pkix.(*Name).FillFromRDNSequence
5461 2.31% 89.82% 5461 2.31% runtime.acquireSudog
4681 1.98% 91.79% 4681 1.98% net/textproto.(*Reader).ReadMIMEHeader
4096 1.73% 93.52% 4096 1.73% crypto/sha256.New
proof 工具还提供了强大的可视化功能,可以生成便于查看的图片或HTML文件。但实现这种功能需要先安装Graphviz(开源的可视化工具)。你可以在官网找到最新的下载方式,安装完成后,在pprof提示符中输入 Web 就可以在浏览器中看到资源分配的可视化结果了。
从图中,我们能够直观地看出当前函数的调用链、内存分配数量和比例,找出程序中内存分配的关键部分,越大的方框代表分配内存的次数更多。
我们来详细解读一下这张图片。
- 节点颜色: 红色代表累计值 cum 为正,并且很大; 绿色代表累计值 cum 为负,并且很大; 灰色代表累计值 cum 可以忽略不计。
- 节点字体大小: 较大的字体代表当前值较大; 较小的字体代表当前值较小。
- 边框颜色:当前值较大且为正数时为红色; 当前值较小且为负数时为绿色;当前值接近 0 时为灰色。
- 箭头大小:箭头越粗代表当前的路径消耗的资源越多, 箭头越细代表当前的路径消耗的资源越小。
- 箭头线型:虚线箭头表示两个节点之间的某些节点已被忽略,为间接调用;实线箭头表示两个节点之间为直接调用。
pprof协程栈分析
除了堆内存分析,协程栈分析使用得也比较多。分析协程栈有两个作用,一是查看协程的数量,判断协程是否泄漏;二是查看当前协程在重点执行哪些函数,判断当前协程是否健康。
下面这个例子,我们查看协程信息会发现,当前收集到了36个协程,程序总的协程数为37个。收集到的协程中,33个协程都位于runtime.gopark中,而runtime.gopark意味着协程陷入到了休眠状态。
» go tool pprof <http://localhost:9981/debug/pprof/goroutine> jackson@bogon
Fetching profile over HTTP from <http://localhost:9981/debug/pprof/goroutine>
Saved profile in /Users/jackson/pprof/pprof.goroutine.015.pb.gz
Type: goroutine
Time: Dec 18, 2022 at 1:26pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 36, 97.30% of 37 total
Showing top 10 nodes out of 96
flat flat% sum% cum cum%
33 89.19% 89.19% 33 89.19% runtime.gopark
1 2.70% 91.89% 1 2.70% runtime.sigNoteSleep
1 2.70% 94.59% 1 2.70% runtime/pprof.runtime_goroutineProfileWithLabels
1 2.70% 97.30% 1 2.70% syscall.syscall6
0 0% 97.30% 2 5.41% bufio.(*Reader).Peek
0 0% 97.30% 1 2.70% bufio.(*Reader).Read
0 0% 97.30% 2 5.41% bufio.(*Reader).fill
0 0% 97.30% 2 5.41% bytes.(*Buffer).ReadFrom
0 0% 97.30% 2 5.41% crypto/tls.(*Conn).Read
0 0% 97.30% 2 5.41% crypto/tls.(*Conn).readFromUntil
我们再执行tree,会看到大多数协程陷入到了网络堵塞和select中。这是符合预期的,因为我们的程序是网络I/O密集型的,当有大量协程在等待服务器返回时,协程会休眠等待网络数据准备就绪。
(pprof) tree
Showing nodes accounting for 33, 89.19% of 37 total
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
22 66.67% | runtime.selectgo
6 18.18% | runtime.netpollblock
4 12.12% | runtime.chanrecv
1 3.03% | time.Sleep
33 89.19% 89.19% 33 89.19% | runtime.gopark
pprof mutex堵塞分析
mutex 主要用于查看锁争用产生的休眠时间,它还可以帮助我们排查由于锁争用导致 CPU 利用率不足的问题。但是这两种特征并不常用,下面我们模拟了频繁的锁争用场景。
var mu sync.Mutex
var items = make(map[int]struct{})
runtime.SetMutexProfileFraction(5)
for i := 0; ; i++ {
go func(i int) {
mu.Lock()
defer mu.Unlock()
items[i] = struct{}{}
}(i)
}
接着我们分析pprof mutex会发现,当前程序陷入到互斥锁的休眠时间总共为2.46s,这个时长大概率是有问题的,需要再结合实际程序判断锁争用是否导致了CPU 利用率不足。
» go tool pprof <http://localhost:9981/debug/pprof/mutex>
Fetching profile over HTTP from <http://localhost:9981/debug/pprof/mutex>
Saved profile in /Users/jackson/pprof/pprof.contentions.delay.010.pb.gz
Type: delay
Time: Dec 18, 2022 at 1:57pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 2.46s, 100% of 2.46s total
flat flat% sum% cum cum%
2.46s 100% 100% 2.46s 100% sync.(*Mutex).Unlock
0 0% 100% 2.46s 100% main.main.func2
pprof CPU占用分析
在实践中,我们还会使用 pprof 来分析 CPU 的占用情况。它可以在不破坏原始程序的情况下估计出函数的执行时间,找出程序的瓶颈。
我们可以执行下面的指令进行 CPU 占用分析。其中,seconds 参数可以指定一共要分析的时间。下面的例子代表我们要花费60s收集CPU信息。
收集到CPU信息后,我们一般会用下面的指令在Web页面里进行分析。
Worker的 CPU信息的可视化图像如下所示。
从图片中我们可以看出耗时最多的函数在哪里。例如,从第一列调用链可以看出,在我们探测的周期内,程序有14.29%的时间是在http.readLoop函数中工作,这个函数是http标准库中读取数据的协程。从整体上可以看出,我们的耗时主要是在网络数据处理上。用户协程的数据处理占用的CPU极少。
除此之外,我们还可以将上面的图像切换为火焰图。火焰图是用于分析CPU特征和性能的利器,因为它的形状和颜色像火焰而得名。火焰图可以快速准确地识别出使用最频繁的代码路径,让我们看到程序的瓶颈所在。
Go 1.11 之后,火焰图已经内置到了pprof 分析工具中,用于分析堆内存与CPU的使用情况。Web 页面的最上方为导航栏,可以查看之前提到的许多 pprof 分析指标,点击导航栏中VIEW 菜单下的Flame Graph 选项,可以切换到火焰图。如下所示,颜色最深的函数为HTTP请求的发送与接收。
我们以CPU 火焰图为例说明一下。
- 最上方的 root 框代表整个程序的开始,其他的框各代表一个函数。
- 火焰图每一层的函数都是平级的,下层函数是它对应的上层函数的子函数。
- 函数调用栈越长,火焰就越高。
- 框越长、颜色越深,代表当前函数占用 CPU 的时间越久。
- 可以单击任何框,查看该函数更详细的信息。
trace及其使用方法
通过 pprof 的分析,我们能够知道一段时间内的CPU 占用、内存分配、协程堆栈信息。这些信息都是一段时间内数据的汇总,但是它并不能让我们了解整个周期内发生的具体事件,例如指定的 Goroutines 何时执行,执行了多长时间,什么时候陷入了堵塞,什么时候解除了堵塞,GC 是怎么影响单个 Goroutine 的执行的,STW 中断花费的时间是否太长等。而这正是 Go1.5 之后推出的trace 工具的强项,它提供了指定时间内程序中各事件的完整信息,具体如下。
- 协程的创建、开始和结束
- 协程的堵塞,系统调用、通道和锁
- 网络 I / O 相关事件
- 系统调用事件
- 垃圾回收相关事件
收集 trace 文件的方式和收集 pprof 特征文件也非常相似,主要有两种,一种是在程序中调用runtime/trace 包的接口。
另一种方式仍然是使用pprof库。net/http/pprof 库中集成了 trace 的接口,下面这个例子,我们获取了 60s 内的trace 事件并存储到了trace.out 文件中。
要对获取的文件进行分析,需要使用 trace 工具。
执行上面的命令会默认打开浏览器,显示出超链接信息。
这几个选项中最复杂、信息最丰富的当数第1 个 View trace 选项。点击它会出现一个交互式的可视化界面,它展示的是整个执行周期内的完整事件。
我们来详细说明一下图中的信息。
- 时间线。显示的是执行的时间,时间单位可以放大或缩小,可以使用键盘快捷键(WASD) 浏览时间轴。
- 堆内存。显示的是执行期间内存的分配情况,对于“查找内存泄漏”及“检查每次运行时 GC 释放的内存”非常有用。
- Goroutines。显示每个时间点正在运行的 Goroutine 的数量及可运行(等待调度)的Goroutine 的数量。如果存在大量可运行的 Goroutine,可能意味着调度器繁忙。
- 操作系统线程。显示的是正在使用的操作系统线程数和被系统调用阻止的线程数。
- GC的情况。
- 网络调用情况。
- 系统调用情况。
- 每个逻辑处理器的运行情况。
点击一个特定的协程,可以在下方信息框中看到许多协程的信息,具体包括下面几点。
- Title:协程的名字。
- Start:协程开始的时间。
- Wall Duration:协程持续时间。
- Start Stack Trace:协程开始时的栈追踪。
- End Stack Trace:协程结束时的栈追踪。
- Event:协程产生的事件信息。
对上面的程序进行分析,我们可以得出下面几点结论。
- 程序每隔2秒钟进行一次网络调用,这是符合预期的,因为我们设置了任务的请求间隔。
- 程序中有12个逻辑处理器P,每一个P中间都可以明显看到大量的间隙,这些间隙代表没有执行任何任务。
- 查看Goroutines,会发现在任一时刻,当前存在的协程都并不多,表明当前程序并无太多需要执行的任务,还未达到系统的瓶颈。
- 观察内存的使用情况,可以看到内存的占用很小,只有不到8MB。但内存的增长表现出了锯齿状。进一步观察,我们发现在60s内,执行了6次GC。点击触发GC的位置,会发现触发GC主要来自于ioutl.ReadAll函数。
接着查看函数堆栈信息,会发现我们在采集引擎中使用了ioutil.ReadAll读取数据。每一次HTTP请求都会新建一个切片,切片使用完毕后就变为了垃圾内存。因此我们可以考虑在此处复用内存,优化内存的分配,减少程序GC的频率。
func (b BrowserFetch) Get(request *spider.Request) ([]byte, error) {
...
bodyReader := bufio.NewReader(resp.Body)
e := DeterminEncoding(bodyReader)
utf8Reader := transform.NewReader(bodyReader, e.NewDecoder())
return ioutil.ReadAll(utf8Reader)
}
trace 工具非常强大,它提供了追踪到的运行时的完整事件和宏观视野。不过 trace 仍然不是万能的,如果想查看协程内部函数占用 CPU 的时间、内存分配等详细信息,还是需要结合 pprof 来实现。
pprof底层原理
这节课的最后,我们再来了解一下pprof的底层原理。pprof 分为采样和分析两个阶段。
采样指一段时间内某种类型的样本数据,pprof 并不会像 trace 一样记录每个事件,因此相对于trace ,pprof收集到的文件要小得多。
以堆内存为例,对堆内存进行采样时,最好的时机就是分配内存的时候。Go分配内存的函数为mallocgc。但是并不是每次调用 mallocgc 分配堆内存信息都会被记录下来,这里有一个指标:MemProfileRate。当多次内存分配的大小累积到该指标以上时,样本才会被pprof记录一次。
if rate := MemProfileRate; rate > 0 {
// Note cache c only valid while m acquired; see #47302
if rate != 1 && size < c.nextSample {
c.nextSample -= size
} else {
profilealloc(mp, x, size)
}
}
记录下来的每个样本都是一个bucket。该 bucket 会存储到全局 mbuckets 链表中,mbuckets 链表中的对象不会被 GC 扫描,因为它加入到了 span 中的special 序列。bucket 中保留的重要数据除了当前分配的内存大小,还包括具体触发了内存分配的函数以及该函数的调用链,这可以借助栈追踪来实现。
堆内存样本收集考虑到了垃圾回收的情况,最大程度地希望当前内存的分配信息表征是当前程序中活着的内存。但是内存分配是实时发生的,垃圾内存的清扫却是懒清扫,这导致了从当前时刻来看内存会存在一些没来得及回收的内存。为了解决这一问题,Go语言做了特殊的处理,如果你想深挖下去,可以查看runtime/mprof.go中的注释。
pprof分析 CPU 占用的能力更令人惊讶。它可以得到在某段时间内每个函数执行的时间,而不必修改原始程序。这是如何实现的呢?
其实,和调度器的抢占类似,这需要借助程序中断的功能为分析和调试提供时机。在类 Unix 操作系统中,这需要调用操作系统库的函数 setitimer 实现。 setitimer 将按照设定好的频率中断当前程序,然后进入操作系统内核处理中断事件,这个过程显然进行了线程的上下文切换。操作系统会从内核态返回用户态,进入之前注册好的信号处理函数,从而为分析提供时机。
当调用 pprof 获取 CPU 样本接口时,程序会将 setitimer 函数的中断频率设置为100Hz,即每秒中断 100 次。这是深思熟虑的选择,因为中断也会花费时间成本,所以中断的频率不可过高。同时,中断的频率也不可过低,否则我们就无法准确地计算出函数花费的时间了。
调用 setitimer 函数时,中断的信号为ITIMER_PROF。当内核态返回到用户态之后,会调用注册好的sighandler 函数,sighandler 函数识别到信号为_SIGPROF 时,执行 sigprof 函数记录CPU样本。
func sighandler(sig uint32, info *siginfo, ctxt unsafe.Pointer, gp *g) {
if sig == _SIGPROF {
sigprof(c.sigpc(), c.sigsp(), c.siglr(), gp, _g_.m)
return
}
...
}
sigprof 的核心功能是记录当前的栈追踪,同时添加CPU的样本数据。CPU 样本会写入叫作data 的 buf 中,每份样本数据都包含该样本的长度、时间戳、hdrsize和栈追踪指针。
pprof 的所有样本数据最后都会经过序列化被转为Protocol Buffers格式并通过 gzip 压缩后写入文件。用户获取该文件后,可以使用 go tool pprof 对样本文件进行解析。go tool pprof 可以将文件解码并还原为Protocol Buffers 格式。
trace底层原理
但是,即便我们使用 net/http/pprof来获取trace信息,底层仍然会调用 runtime/trace库。在 trace 的初始阶段首先需要STW,然后获取协程的快照、状态、栈帧信息,接着设置trace.enable=true 开启GC,最后重新启动所有协程。
trace 提供了强大的内省功能,但这种功能不是没有代价的。Go 语言在运行时源码中每个重要的事件处都加入了判断trace.enabled 是否开启的条件,并编译到了程序中。trace 开启后,会触发 traceEvent 写入事件。
这些关键的事件包括协程的生命周期、协程堵塞、网络 I/O、系统调用、垃圾回收等。根据事件的不同,运行时可以保存和此事件相关的参数和栈追踪数据。每个逻辑处理器 P 都有一个缓存(p.tracebuf),用于存储已经被序列化为字节的事件(Event)。
事件的版本、时间戳、栈ID、协程ID等整数信息使用LEB128 编码,用于有效压缩数字的长度。字符串使用UFT-8 编码。每个逻辑处理器P的缓存都是有限度的。当超过了缓存限度后,逻辑处理器P 中的 tracebuf 会转移到全局链表中。同时,trace 工具会新开一个协程专门读取全局trace 上的信息,此时全局的事件对象已经是序列化之后的字节数组了,直接添加到文件中即可。
当指定的时间到期后,我们需要结束 trace 任务,程序会再次陷入 STW 状态,刷新逻辑处理器P 上的tracebuf 缓存,设置trace.enabled = false,完成整个 trace 收集周期。
完成收集工作并将数据存储到文件后,go tool trace 会解析 trace 文件并开启HTTP服务供浏览器访问,在 Go 源码中可以看到具体的解析过程。trace 的 Web 界面来自trace-viewer 项目,trace-viewer可以从多种事件格式中生成可视化效果。
总结
这节课,我结合我们的爬虫项目介绍了调试Go语言程序的强大工具pprof和trace。除却使用方法,我们还介绍了它们的底层原理,这有助于我们更深入地理解pprof和trace的能力与局限。
pprof 提供了内存大小、CPU 使用时间、协程堆栈信息、堵塞时间等多种维度的样本统计信息。通过查看占用资源的代码路径,我们可以方便地检查出程序遇到的内存泄露、死锁、CPU 利用率过高等问题。在实践中,我们可以放心地将 pprof 以HTTP的形式暴露出来,在不调用HTTP接口的情况下,这种做法对程序的性能几乎没有影响。
而 trace 是以事件为基础的信息追踪工具,它可以反映出一段时间内程序的变化,例如频繁的 GC 和协程调度情况等,方便我们追踪程序的运行状态,分析程序遇到的瓶颈问题。
思考题
学完这节课,给你留一道思考题。
如果我们利用 pprof 分析内存和CPU,找到了内存分配最多和CPU耗时最长的函数,那它们就一定是最大的瓶颈吗?为什么?
欢迎你在留言区与我交流讨论,我们下节课再见。
- Realm 👍(1) 💬(0)
思考题: 单次执行占用很高的cpu和内存的函数,不一定是瓶颈。 调用非常频繁的函数,并且每次需要分配内存或者造成软中断,也可能形成瓶颈。
2023-01-12 - 公共账号 👍(0) 💬(0)
pprof top后为什么会有负数出现
2024-01-06 - 加油 👍(0) 💬(0)
火焰图 : 框越长、颜色越深,代表当前函数占用 CPU 的时间越久。 —————— 这句话有问题哈,框越长,代表当前函数占用CPU的时间越久。但是和颜色无关,火焰图的颜色是随机的暖色调。
2023-05-18 - 徐海浪 👍(0) 💬(0)
内存分配多和CPU耗时长,只能说明这个函数占用的资源多,还需要结合执行次数分析,计算平均每次执行时间和内存分配的情况。
2023-01-17