Golang 大杀器之跟踪剖析 trace

标签: golang php 后端 | 发表时间:2019-07-12 19:40 | 作者:煎鱼
出处:https://segmentfault.com/blogs

image

在 Go 中有许许多多的分析工具,在之前我有写过一篇 《Golang 大杀器之性能剖析 PProf》 来介绍 PProf,如果有小伙伴感兴趣可以去我博客看看。

但单单使用 PProf 有时候不一定足够完整,因为在真实的程序中还包含许多的隐藏动作,例如 Goroutine 在执行时会做哪些操作?执行/阻塞了多长时间?在什么时候阻止?在哪里被阻止的?谁又锁/解锁了它们?GC 是怎么影响到 Goroutine 的执行的?这些东西用 PProf 是很难分析出来的,但如果你又想知道上述的答案的话,你可以用本文的主角 go tool trace 来打开新世界的大门。目录如下:

image

初步了解

  import (
    "os"
    "runtime/trace"
)

func main() {
    trace.Start(os.Stderr)
    defer trace.Stop()

    ch := make(chan string)
    go func() {
        ch <- "EDDYCJY"
    }()

    <-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

查看可视化界面:

image

  • 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

在刚开始查看问题时,除非是很明显的现象,否则不应该一开始就陷入细节,因此我们一般先查看 “Scheduler latency profile”,我们能通过 Graph 看到整体的调用开销情况,如下:

image

演示程序比较简单,因此这里就两块,一个是 trace 本身,另外一个是 channel 的收发。

Goroutine analysis

第二步看 “Goroutine analysis”,我们能通过这个功能看到整个运行过程中,每个函数块有多少个有 Goroutine 在跑,并且观察每个的 Goroutine 的运行开销都花费在哪个阶段。如下:

image

通过上图我们可以看到共有 3 个 goroutine,分别是 runtime.mainruntime/trace.Start.func1main.main.func1,那么它都做了些什么事呢,接下来我们可以通过点击具体细项去观察。如下:

image

同时也可以看到当前 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

View trace

在对当前程序的 Goroutine 运行分布有了初步了解后,我们再通过 “查看跟踪” 看看之间的关联性,如下:

image

这个跟踪图粗略一看,相信有的小伙伴会比较懵逼,我们可以依据注解一块块查看,如下:

  1. 时间线:显示执行的时间单元,根据时间维度的不同可以调整区间,具体可执行 shift + ? 查看帮助手册。
  2. 堆:显示执行期间的内存分配和释放情况。
  3. 协程:显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行,其包含 GC 等待(GCWaiting)、可运行(Runnable)、运行中(Running)这三种状态。
  4. OS 线程:显示在执行期间有多少个线程在运行,其包含正在调用 Syscall(InSyscall)、运行中(Running)这两种状态。
  5. 虚拟处理器:每个虚拟处理器显示一行,虚拟处理器的数量一般默认为系统内核数。
  6. 协程和事件:显示在每个虚拟处理器上有什么 Goroutine 正在运行,而连线行为代表事件关联。

image

点击具体的 Goroutine 行为后可以看到其相关联的详细信息,这块很简单,大家实际操作一下就懂了。文字解释如下:

  • Start:开始时间
  • Wall Duration:持续时间
  • Self Time:执行时间
  • Start Stack Trace:开始时的堆栈信息
  • End Stack Trace:结束时的堆栈信息
  • Incoming flow:输入流
  • Outgoing flow:输出流
  • Preceding events:之前的事件
  • Following events:之后的事件
  • All connected:所有连接的事件

View Events

我们可以通过点击 View Options-Flow events、Following events 等方式,查看我们应用运行中的事件流情况。如下:

image

通过分析图上的事件流,我们可得知这程序从 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 去进行调用。

image

在这里我们结合开头的代码去看的话,很明显就是 ch 的输入输出的过程了。

结合实战

今天生产环境突然出现了问题,机智的你早已埋好 _ "net/http/pprof" 这个神奇的工具,你麻利的执行了如下命令:

  • curl http://127.0.0.1:6060/debug/pprof/trace?seconds=20 > trace.out
  • go tool trace trace.out

View trace

你很快的看到了熟悉的 List 界面,然后不信邪点开了 View trace 界面,如下:

image

完全看懵的你,稳住,对着合适的区域执行快捷键 W 不断地放大时间线,如下:

image

经过初步排查,你发现上述绝大部分的 G 竟然都和 google.golang.org/grpc.(*Server).Serve.func 有关,关联的一大串也是 Serve 所触发的相关动作。

image

这时候有经验的你心里已经有了初步结论,你可以继续追踪 View trace 深入进去,不过我建议先鸟瞰全貌,因此我们再往下看 “Network blocking profile” 和 “Syscall blocking profile” 所提供的信息,如下:

Network blocking profile

image

Syscall blocking profile

image

通过对以上三项的跟踪分析,加上这个泄露,这个阻塞的耗时,这个涉及的内部方法名,很明显就是哪位又忘记关闭客户端连接了,赶紧改改改。

总结

通过本文我们习得了 go tool trace 的武林秘籍,它能够跟踪捕获各种执行中的事件,例如 Goroutine 的创建/阻塞/解除阻塞,Syscall 的进入/退出/阻止,GC 事件,Heap 的大小改变,Processor 启动/停止等等。

希望你能够用好 Go 的两大杀器 pprof + trace 组合,此乃排查好搭档,谁用谁清楚,即使他并不万能。

参考

image

相关 [golang 跟踪 trace] 推荐:

Golang 大杀器之跟踪剖析 trace

- - SegmentFault 最新的文章
在 Go 中有许许多多的分析工具,在之前我有写过一篇 《Golang 大杀器之性能剖析 PProf》 来介绍 PProf,如果有小伙伴感兴趣可以去我博客看看. 但单单使用 PProf 有时候不一定足够完整,因为在真实的程序中还包含许多的隐藏动作,例如 Goroutine 在执行时会做哪些操作. GC 是怎么影响到 Goroutine 的执行的.

微服务全链路跟踪:jaeger集成istio,并兼容uber-trace-id与b3 - lipeng的个人空间 - OSCHINA

- -
微服务全链路跟踪:grpc集成zipkin. 微服务全链路跟踪:grpc集成jaeger. 微服务全链路跟踪:springcloud集成jaeger. 微服务全链路跟踪:jaeger集成istio,并兼容uber-trace-id与b3. 微服务全链路跟踪:jaeger集成hystrix. 公司有自己的一套基于k8s的paas系统,并且集成了istio,这里主要是想讲解下springcloud服务如何集成istio.

oracle 打开trace,并分析trace

- - CSDN博客数据库推荐文章
2、跟踪session事件. 作者:huzia 发表于2014-4-22 17:33:55 原文链接. 阅读:71 评论:0 查看评论.

Golang测试技术

- - Tony Bai
本篇文章内容来源于 Golang核心开发组成员 Andrew Gerrand在Google I/O 2014的一次主题分享“ Testing Techniques”,即介绍使用Golang开发 时会使用到的测试技术(主要针对. 单元测试),包括基本技术、高级技术(并发测试、 mock/fake、竞争条件测试、并发测试、内/外部测 试、vet工具等)等,感觉总结的很全面,这里整理记录下来,希望能给大家带来帮助.

Oracle Trace文件的生成及查看

- - 数据库 - ITeye博客
1.Trace file简介: Trace file(追踪文件)是以trc为后续的文本文件,它记录了各种sql操作及所消耗的时间等,根据trace文件我们就可以了解哪些sql导致了系统的性能瓶颈,进而采取恰当的方式调优. 2.怎么生成trace file: 1. 首先用sqlplus登陆Oracle.

golang的杀手级应用:docker

- - _不是我干的 _
docker 是 golang 的第一个杀手级应用,发展迅猛, 现在各大云计算平台几乎全都支持 docker 实例,包括 谷歌,亚马逊,阿里云等. golang 本身已经让我惊喜万分,而 docker 更是极大的激发了我对虚拟化的想象. IT 业发展至今,软件和硬件始终是无法分割的两个物体. 就拿最近几年红红火火的智能机时代来说, 很久之前的诺基亚智能机, 软件和硬件相辅相成, 连进入主界面都需要按一个特定的按钮才能进入.

基于Golang的微服务——Micro实践

- - IT瘾-tuicool
开始开发前需要先配置好Go的开发环境,可以看我写的 基于Golang的微服务——上手篇. 在 GOPATH目录下的src目录下创建我们的实战项目目录 tech,切换到这个目录. go get github.com/micro/go-micro //用于开发的微服务的RPC框架,是micro架构的基础 go get github.com/micro/protoc-gen-micro // 用于生成Protobuf的代码 go get github.com/micro/micro // 工具集安装,会自动将 micro加入环境变量 复制代码.

Oracle EBS SQL Trace日志收集的方法

- - CSDN博客推荐文章
Raw Trace的收集方法. 打开Trace,Help > Diagnostics > Trace > Trace > Trace with Binds and Waits. Trace项代表的意思. 3.关闭Trace,Help > Diagnostics > Trace > Trace > No Trace.

pystack--python stack trace--让python打印线程栈信息

- - BlogJava-首页技术区
类似java中的jstack功能. https://pypi.python.org/pypi/pdbx/0.3.0 下载, 或者直接通过easyinstall安装. python scripts中, import pdbx; pdbx.enable_pystack(); 开启pystack功能. kill -30 pid , 就可以打印stack信息了. .

[原]Java应用日志如何与Jaeger的trace关联

- - 程序员欣宸的博客
这里分类和汇总了欣宸的全部原创(含配套源码): https://github.com/zq2599/blog_demos. 经过 《Jaeger开发入门(java版)》的实战,相信您已经能将自己的应用接入Jaeger,并用来跟踪定位问题了,本文将介绍Jaeger一个小巧而强大的辅助功能,用少量改动大幅度提升定位问题的便利性:将业务日志与Jaeger的trace关联.