协程栈分析
除 堆内存分析,协程栈分析也使用较多。 分析协程栈有两方面作用:
- 查看协程数量,看协程是否泄露
- 查看当前大量的协程在执行哪些函数,判断当前协程是否健康
引入net/http/pprof,然后启一个goroutine来监听端口
package main import ( "log" "net/http" _ "net/http/pprof" "time" ) func main() { go func() { log.Println(http.ListenAndServe(":6060", nil)) }() a := make(chan int) for { time.Sleep(time.Second) go func() { <-a }() } }
运行以上代码,同时 go tool pprof http://localhost:6060/debug/pprof/goroutine
当前协程有33个,大部分都在runtime.gopark函数中(gopark是协程休眠函数)
通过tree查看函数调用链,发现协程阻塞,是调用runtime.chanrecv函数以表明通道正在等待接收导致
同样可以使用web命令,在浏览器查看调用关系:
也可以使用 go tool pprof --http :9091 pprof.goroutine.001.pb.gz
,可视化查看各种信息
base基准分析
除了查看协程栈帧数据,goroutine profile 还可用来排查协程泄露。
通过对比协程的总数,可以大概评估出程序是否陷入泄露状态。
pprof提供了强大的工具,用来对比前后特征文件的区别。
下面使用-base
标志,后面跟两个基准特征文件:
同样支持web指令
mutex堵塞分析
和block类似,mutex主要用于查看锁争用导致的休眠时间。有助于排查锁争用导致的CPU利用率不足问题(不经常使用)
package main import ( "log" "net/http" _ "net/http/pprof" "runtime" "sync" ) func main() { go func() { log.Println(http.ListenAndServe(":6060", nil)) }() var mu sync.Mutex var items = make(map[int]struct{}) runtime.SetMutexProfileFraction(5) for i := 0; i < 1000000*1000000; i++ { go func(i int) { mu.Lock() defer mu.Unlock() items[i] = struct{}{} }(i) } }
运行以上代码,同时 go tool pprof http://localhost:6060/debug/pprof/mutex
同样支持web指令
CPU分析
获取程序在30s内占用CPU的情况:curl http://IP:port/debug/pprof/profile?seconds=30 -o profile_cui.out
或 go tool pprof http://localhost:6060/debug/pprof/profile?second=30
火焰图分析
参见上面内容
trace
在pprof分析中,可以知道一段时间CPU占用、内存分配、协程堆栈信息。这些消息都是一段时间内数据的汇总,但并没有提供整个周期内发生的事件,如 指定的goroutine何时执行、执行了多长时间、什么时刻陷入了阻塞、什么时刻解除了阻塞、GC如何影响单个goroutine的执行、STW中断花费的时间是否太长等。
Go 1.5之后推出了trace工具,提供了指定时间内程序发生的事件的完整信息,包括:
- 协程的创建、开始和结束
- 协程的阻塞
---
系统调用、通道、锁 - 网络I/O相关事件
- 系统调用事件
- 垃圾回收相关事件
(源码在runtime/trace.go)
收集trace文件的方式和收集pprof特征文件差不多,都有两种方式
详细使用方式可参考 煎鱼-Golang 大杀器之跟踪剖析 trace
收集:
curl http://IP:port/debug/pprof/trace?seconds=30 -o trace_cui.out
分析:
go tool trace trace_cui.out
之后会自动打开浏览器:
View trace
其中最复杂,信息最丰富的是第一个 View trace 选项,显示整个执行周期的完整事件
<br>
1.时间线:可使用如下快捷键浏览时间轴
w
快捷键可以放大图像s
快捷键可以缩小图像a
快捷键可以左移图像d
快捷键可以右移图像
2.Goroutines:显示每个时间点正在运行的goroutine数量,及可运行(等待调度)的goroutine数量。存在大量可运行的goroutine,可能表明调度器繁忙。
3.堆: 显示执行期间的内存分配情况,对于查找内存泄露及检查每次runtime GC释放的内存很有用处。
4.操作系统线程: 显示正在使用的操作系统线程及被系统调用阻塞的线程数
5.显示每个逻辑处理器
6.显示协程和事件,表明协程何时开始,何时结束,以及结束的原因
w
放大,选中某一位置:
- Title: 协程的名字
- Start: 协程开始的事件
- Wall Duration: 协程持续时间
- Start Stack Trace: 协程开始时的栈追踪
- End Stack Trace: 协程结束时的栈追踪
- Event(s): 协程产生的事件信息
Goroutine analysis选项
点击一处进入详情,可看到每个goroutine的id,以及执行时间,网络等待时间,因同步而锁定的时间,因系统调用锁定的时间,调度等待时间,GC清扫时间,GC暂停时间
之后的四处profile选项
都是一个调用关系及时间图
- Network blocking profile选项: 用调用关系图展示网络阻塞的情况
- Synchronization blocking profile 选项: 同步阻塞耗时情况,使用调用关系图来展示
- Syscall blocking profile选项: 系统调用阻塞耗时情况,使用调用关系图来展示
- Scheduler latency profile 选项: 调度器延迟耗时情况,使用调用关系图来展示
User-defined tasks、User-defined regions
用户自定义 trace 的 tasks/用户自定义 trace 的 region
Go 1.11 版本中引入的特性,trace 可以添加我们自定义的内容,用来快速跟踪想要看到的代码块的耗时点
Minimum mutator utilization
用一个曲线图来展示 GC 对程序的影响情况,可以用来分析和判断是否要对 GC 做优化
大约1.2ms后,程序才获得到 cpu 使用(在这之前GC 做了 STW) 。
如果曲线随着时间增加依然不高,说明 GC 负担比较重,占用更多系统资源,这个时候需对 GC 做优化
曲线图右侧的几个选项:
- System:整个系统的利用率
- Per-goroutine:每一个协程的利用率
- STW:Stop the word,表示所有协程同时暂停,在做 GC 的时,是会 STW
- Background workers:GC 的协程,会消耗 25% 的利用率,在 GC 的时候,会以后台方式执行
- Mark assist:GC 要减慢内存分配速度时,会分配 goroutine 来做标记
- Sweep:回收在 GC 之间未使用的内存
- Show percentiles:除了最基本数据外,还显示 mutator 利用率的百分比
trace 使用场景
分析延迟问题
如某个接口预期200ms执行完,但却用了2s。
当程序中重要的协程长时间无法运行,可能带来延迟问题。协程长时间无法得到执行,可能因为系统调用被阻塞,通道/互斥锁上被阻塞,协程运行时代码(如GC)阻塞。这些都可以通过trace来查看。
诊断不良并行性
如预期使用全部CPU,使用trace后发现,只有一个CPU在跑~
关于trace,还可参考 go trace 剖析 go1.14 异步抢占式调度
更多参考:
Tony Bai - 通过实例理解Go Execution Tracer
其他第三方profiling工具:
鸟窝-调试利器:dump goroutine 的 stacktrace
文中部分工具已经out...
Go官方博客:
(这里认为Profiling和Tracing是同级。我这里把Profiling看成是Tracing的上一级)
部分译文:
原创分享 Go 高性能系列教程:读懂 pprof 生成的报告
更多可参考:
golang pprof 的使用调试 cpu,heap,gc,逃逸