共计 3471 个字符,预计需要花费 9 分钟才能阅读完成。
大家好,我是煎鱼。
前段时间分享了《Go 程序崩了?煎鱼教你用 PProf 工具来救火!》,但有时候单单应用 pprof 还不肯定足够残缺观查并解决问题,因为在实在的程序中还蕴含许多的暗藏动作,例如:
- Goroutine 在执行时会做哪些操作?
- Goroutine 执行 / 阻塞了多长时间?
- Syscall 在什么时候被阻止?在哪里被阻止的?
- 谁又锁 / 解锁了 Goroutine?
- GC 是怎么影响到 Goroutine 的执行的?
这些货色用 pprof 是很难剖析进去的,但如果你又想晓得上述的答案的话,你能够用本章节的配角 go tool trace
来关上新世界的大门。
一起欢快地开始吸鱼之路。
初步理解
import (
"os"
"runtime/trace"
)
func main() {trace.Start(os.Stderr)
defer trace.Stop()
ch := make(chan string)
go func() {ch <- "Go 语言编程之旅"}()
<-ch
}
生成跟踪文件:
$ go run main.go 2> trace.out
启动可视化界面:
$ go tool trace trace.out
2019/06/22 16:14:52 Parsing trace...
2019/06/22 16:14:52 Splitting trace...
2019/06/22 16:14:52 Opening browser. Trace viewer is listening on http://127.0.0.1:57321
查看可视化界面:
- View trace:查看跟踪
- Goroutine analysis:Goroutine 剖析
- Network blocking profile:网络阻塞详情
- Synchronization blocking profile:同步阻塞详情
- Syscall blocking profile:零碎调用阻塞详情
- Scheduler latency profile:调度提早详情
- User defined tasks:用户自定义工作
- User defined regions:用户自定义区域
- Minimum mutator utilization:最低 Mutator 利用率
调度提早详情
在刚开始查看问题时,除非是很显著的景象,否则不应该一开始就陷入细节。
因而咱们个别先查看“Scheduler latency profile”,咱们能通过 Graph 看到整体的调用开销状况,如下:
演示程序比较简单,因而这里就两块,一个是 trace
自身,另外一个是 channel
的收发。
Goroutine 剖析
第二步看“Goroutine analysis”,咱们能通过这个性能看到整个运行过程中,每个函数块有多少个有 Goroutine 在跑。
察看每个的 Goroutine 的运行开销都破费在哪个阶段。如下:
通过上图咱们能够看到共有 3 个 goroutine,别离是:
runtime.main
。runtime/trace.Start.func1
。main.main.func1
。
它们都做了些什么事呢,咱们能够通过点击具体细项去察看。如下:
同时也能够看到以后 Goroutine 在整个调用耗时中的占比,以及 GC 打扫和 GC 暂停期待的一些开销。
如果你感觉还不够,能够把图表下载下来剖析,相当于把整个 Goroutine 运行时掰开来看了,这块可能很好的帮忙咱们 对 Goroutine 运行阶段做一个的分析,能够得悉到底慢哪,而后再决定下一步的排查方向。
如下:
名称 | 含意 | 耗时 |
---|---|---|
Execution Time | 执行工夫 | 3140ns |
Network Wait Time | 网络等待时间 | 0ns |
Sync Block Time | 同步阻塞工夫 | 0ns |
Blocking Syscall Time | 调用阻塞工夫 | 0ns |
Scheduler Wait Time | 调度等待时间 | 14ns |
GC Sweeping | GC 打扫 | 0ns |
GC Pause | GC 暂停 | 0ns |
查看跟踪
在对以后程序的 Goroutine 运行散布有了初步理解后,咱们再通过“查看跟踪”看看之间的关联性,如下:
这个跟踪图粗略一看,置信有的小伙伴会比拟懵逼,咱们能够根据注解一块块查看,如下:
- 工夫线:显示执行的工夫单元,依据工夫维度的不同能够调整区间,具体可执行
shift
+?
查看帮忙手册。 - 堆:显示执行期间的内存调配和开释状况。
- 协程:显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行,其蕴含 GC 期待(GCWaiting)、可运行(Runnable)、运行中(Running)这三种状态。
- OS 线程:显示在执行期间有多少个线程在运行,其蕴含正在调用 Syscall(InSyscall)、运行中(Running)这两种状态。
- 虚构处理器:每个虚构处理器显示一行,虚构处理器的数量个别默认为零碎内核数。
- 协程和事件:显示在每个虚构处理器上有什么 Goroutine 正在运行,而连线行为代表事件关联。
点击具体的 Goroutine 行为后能够看到其相关联的详细信息,这块很简略,大家实际操作一下就懂了。文字解释如下:
- Start:开始工夫
- Wall Duration:持续时间
- Self Time:执行工夫
- Start Stack Trace:开始时的堆栈信息
- End Stack Trace:完结时的堆栈信息
- Incoming flow:输出流
- Outgoing flow:输入流
- Preceding events:之前的事件
- Following events:之后的事件
- All connected:所有连贯的事件
查看事件
咱们能够通过点击 View Options-Flow events、Following events 等形式,查看咱们利用运行中的事件流状况。如下:
通过剖析图上的事件流,咱们可得悉:
- 这程序从
G1 runtime.main
开始运行。 - 在运行时创立了 2 个 Goroutine:
- 先是创立
G18 runtime/trace.Start.func1
。 - 再是创立
G19 main.main.func1
。
同时咱们能够通过其 Goroutine Name 去理解它的调用类型。如下:
runtime/trace.Start.func1
就是程序中在main.main
调用了runtime/trace.Start
办法。- 紧接着该办法又利用协程创立了一个闭包
func1
去进行调用。
在这里咱们联合结尾的代码去看的话,很显著就是 ch
的输入输出的过程了。
实战演练
凌晨三点,忽然生产环境忽然呈现了问题,机智的你早已埋好 _ "net/http/pprof"
这个神奇的工具。
被告警电话叫醒的你,迷迷糊糊地通过特定的形式执行了如下命令:
$ curl http://127.0.0.1:6060/debug/pprof/trace\?seconds\=20 > trace.out
$ go tool trace trace.out
查看跟踪
你很快的看到了相熟的 List 界面,而后不信邪点开了 View trace 界面,如下:
齐全看懵的你,稳住,对着适合的区域执行快捷键 W
一直地放大工夫线,如下:
通过初步排查,你发现上述绝大部分的 G 居然都和 google.golang.org/grpc.(*Server).Serve.func
无关,关联的一大串也是 Serve
所触发的相干动作。
这时候有教训的你心里曾经有了初步论断,你能够持续追踪 View trace 深刻进去。
不过倡议先鸟瞰全貌,因而咱们再往下看“Network blocking profile”和“Syscall blocking profile”所提供的信息。
网络阻塞详情
零碎调用阻塞详情
通过对以上三项的跟踪剖析,加上这个泄露,这个阻塞的耗时,这个波及的外部办法名,很显著就是哪位又遗记敞开客户端连贯了。
这时候咱们就能够接下进行下一步的排查和批改了。
总结
通过本文咱们习得了 go tool trace
的武林秘籍,它可能跟踪捕捉各种执行中的事件,例如:
- Goroutine 的创立 / 阻塞 / 解除阻塞。
- Syscall 的进入 / 退出 / 阻止,GC 事件。
- Heap 的大小扭转。
- Processor 启动 / 进行等等。
心愿你可能用好 Go 的两大杀器 pprof + trace 组合,此乃排查好搭档,谁用谁分明,即便他并不是相对的万能。
若有任何疑难欢送评论区反馈和交换,最好的关系是相互成就 ,各位的 点赞 就是煎鱼创作的最大能源,感激反对。
文章继续更新,能够微信搜【脑子进煎鱼了】浏览,回复【000】有我筹备的一线大厂面试算法题解和材料。
本文 GitHub github.com/eddycjy/blog 已收录,欢送 Star 催更。