乐趣区

关于php:Go-工程师必学Go-大杀器之跟踪剖析-trace

大家好,我是煎鱼。

‍‍‍‍‍‍‍‍‍前段时间分享了《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 运行散布有了初步理解后,咱们再通过“查看跟踪”看看之间的关联性,如下:

这个跟踪图粗略一看,置信有的小伙伴会比拟懵逼,咱们能够根据注解一块块查看,如下:

  1. 工夫线:显示执行的工夫单元,依据工夫维度的不同能够调整区间,具体可执行 shift + ? 查看帮忙手册。
  2. 堆:显示执行期间的内存调配和开释状况。
  3. 协程:显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行,其蕴含 GC 期待(GCWaiting)、可运行(Runnable)、运行中(Running)这三种状态。
  4. OS 线程:显示在执行期间有多少个线程在运行,其蕴含正在调用 Syscall(InSyscall)、运行中(Running)这两种状态。
  5. 虚构处理器:每个虚构处理器显示一行,虚构处理器的数量个别默认为零碎内核数。
  6. 协程和事件:显示在每个虚构处理器上有什么 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 催更。

退出移动版