泽民博客 ☰ Menu

gctrace Go的GC打印出来的信息

环境
本文的go版本是 go1.8 linux/amd64。



启动程序
设置环境变量GODEBUG，然后启动程序。假如程序叫proc，则启动命令为：
GODEBUG=gctrace=1 ./proc



gc信息
gc打印的内容像这样的：
gc 1 @0.045s 22%: 4.6+182+0.38 ms clock, 9.2+0/96/86+0.77 ms cpu, 52->52->52 MB, 53 MB goal, 2 P
gc打印的信息格式大概如下：
gc # @#s #%: #+…+# ms clock, #+…+# ms cpu, #->#-># MB, # MB goal, # P
字段含义如下:



gc #        the GC number, incremented at each GC

@#s         time in seconds since program start

#%          percentage of time spent in GC since program start

#+...+#     wall-clock/CPU times for the phases of the GC

#->#-># MB  heap size at GC start, at GC end, and live heap

# MB goal   goal heap size

# P         number of processors used 参考： http://stackoverflow.com/questions/20551748/decipher-golang-garbage-collection-output <!-- more --> 但单单使用 PProf 有时候不一定足够完整，因为在真实的程序中还包含许多的隐藏动作，例如 Goroutine 在执行时会做哪些操作？执行/阻塞了多长时间？在什么时候阻止？在哪里被阻止的？谁又锁/解锁了它们？GC 是怎么影响到 Goroutine 的执行的？这些东西用 PProf 是很难分析出来的，但如果你又想知道上述的答案的话，你可以用本文的主角 go tool trace 来打开新世界的大门。


但单单使用 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.main、runtime/trace.Start.func1、main.main.func1，那么它都做了些什么事呢，接下来我们可以通过点击具体细项去观察。如下：



goroutine2.jpg
同时也可以看到当前 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
这个跟踪图粗略一看，相信有的小伙伴会比较懵逼，我们可以依据注解一块块查看，如下：



时间线：显示执行的时间单元，根据时间维度的不同可以调整区间，具体可执行 shift + ? 查看帮助手册。
堆：显示执行期间的内存分配和释放情况。
协程：显示在执行期间的每个 Goroutine 运行阶段有多少个协程在运行，其包含 GC 等待（GCWaiting）、可运行（Runnable）、运行中（Running）这三种状态。
OS 线程：显示在执行期间有多少个线程在运行，其包含正在调用 Syscall（InSyscall）、运行中（Running）这两种状态。
虚拟处理器：每个虚拟处理器显示一行，虚拟处理器的数量一般默认为系统内核数。
协程和事件：显示在每个虚拟处理器上有什么 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 组合，此乃排查好搭档，谁用谁清楚，即使他并不万能。



你想知道你的Go程序在做什么吗？ go tool trace可以向你揭示：Go程序运行中的所有的运行时事件。 这种工具是Go生态系统中用于诊断性能问题时（如延迟，并行化和竞争异常）最有用的工具之一。 在我之前的博客文章中，我提到我们在Pusher中使用go tool trace来跟踪为何Go垃圾收集器有很长的停顿时间。 在这篇博文中，我更加深入的介绍go toll trace。



go tool trace 试用
go tool trace可以显示大量的信息，所以从哪里开始是个问题。 我们首先简要介绍使用界面，然后我们将介绍如何查找具体问题。



go tool traceUI是一个Web应用程序。 下面我已经嵌入了一个这个web程序的实例！ 此示例是可视化并行快速排序实现的追踪信息：



请尝试这个例子！有关导航UI的帮助，请单击右上角的“？”。单击屏幕上的任何事件可以在下面获取更多信息。这里有一些你可以从这个追踪中找到的有价值的信息：



这个程序运行多长时间？



有多少goroutines运行872微秒？



该进程何时第一次升级到使用三个OS线程？



什么时候主要调用qSortPar？



是什么导致额外的过程（1,2和3）开始工作？



proc＃2什么时候停止？



太棒了! 我应该怎么在我的程序中使用go tool trace?
您必须调整程序以将运行时事件写入二进制文件。 这涉及从标准库导入runtime/trace，并添加几行样板代码。 这个快速的视频将引导您：



视频



以下是需要复制粘贴的代码：



package main
import (
“os”
“runtime/trace”
)



func main() {
f, err := os.Create(“trace.out”)
if err != nil {
panic(err)
}
defer f.Close()



err = trace.Start(f)

 if err != nil {

 	panic(err)

}	

defer trace.Stop()  

// Your program here } 这将使您的程序以二进制格式在文件trace.out中写入事件数据。 然后可以运行go tool trace trace.out。 这将解析跟踪文件，并使用可视化程序打开浏览器。 该命令还将启动服务器，并使用跟踪数据来响应可视化操作。 在浏览器中加载初始页面后，单击“View trace”。 这将加载跟踪查看器，如上面嵌入的那样。


使用go tool trace能解决什么问题?
我们来看一个如何使用这个工具跟踪典型问题的例子。



诊断延迟问题
当完成关键任务的goroutine被阻止运行时，可能会引起延迟问题。 可能的原因有很多：做系统调用时被阻塞; 被共享内存阻塞（通道/互斥等）; 被runtime系统（例如GC）阻塞，甚至可能调度程序不像您想要的那样频繁地运行关键goroutine。



所有这些都可以使用go tool trace来识别。 您可以通过查看PROCs时间线来跟踪问题，并发现一段时间内goroutine被长时间阻塞。 一旦你确定了这段时间，应该给出一个关于根本原因的线索。



作为延迟问题的一个例子，让我们看看上一篇博文中长时间的GC暂停：



红色的事件代表了唯一的程序goroutine正在运行。 在所有四个线程上并行运行的goroutines是垃圾收集器的MARK阶段。 这个MARK阶段阻止了主要的goroutine。 你能出到阻止runtime.main goroutine的时间长短吗？



在Go团队宣布GC暂停时间少于100微秒后,我很快就调查了这个延迟问题。 我看到的漫长的停顿时间，go tool trace的结果看起来很奇怪，特别是可以看到它们(暂停)是在收集器的并发阶段发生的。 我在go-nuts 邮件列表中提到了这个问题，似乎与这个问题有关，现在已经在Go 1.8中修复了。 我的基准测试又出现了另一个GC暂停问题，这在写本文时依然会出现。 如果没有go tool trace这一工具，我是无法完成调查工作的。



诊断并行问题
假设您已经编写了一个程序，您希望使用所有的CPU，但运行速度比预期的要慢。 这可能是因为您的程序不像您所期望的那样并行运行。 这可能是由于在很多关键路径上串行运行太多，而很多代码原本是可以异步（并行）运行的。



假设我们有一个pub/sub消息总线，我们希望在单个goroutine中运行，以便它可以安全地修改没有加互斥锁的用户map。 请求处理程序将消息写入消息总线队列。 总线从队列中读取消息，在map中查找订阅者，并将消息写入其套接字。 让我们看看单个消息的go tool trace中的内容：



最初的绿色事件是http处理程序读取发布的消息并将其写入消息总线事件队列。 之后，消息总线以单个线程运行 - 第二个绿色事件 - 将消息写给订阅者。



红线显示消息写入订户的套接字的位置。 写入所有订阅者的过程需要多长时间？



问题是四分之一的线程正在闲置。 有没有办法利用它们？ 答案是肯定的 我们不需要同步写入每个用户; 写入可以在单独的goroutine中同时运行。 让我们看看如果我们作出这个变化，会发生什么：



正如你所看到的，写给订阅者消息的过程正在许多goroutines的上同步进行。



但它是否更快？



有趣的是，鉴于我们使用4X的CPU，加速是适合的。 这是因为并行运行代码有更多的开销：启动和停止goroutines; 共享内存以及单独的缓存。 加速的理论上限使得我们无法实现4倍延迟降低：阿姆达尔定律。



实际上，并行运行代码往往效率较低; 特别是在goroutine是非常短暂的，或者他们之间有很多的竞争的情况下。 这是使用此工具的另一个原因：尝试这两种方法，并检查哪种工作最适合您的用例。



什么时候go tool trace不合适？
当然，go tool trace不能解决一切问题。 如果您想跟踪运行缓慢的函数，或者找到大部分CPU时间花费在哪里，这个工具就是不合适的。 为此，您应该使用go tool pprof，它可以显示在每个函数中花费的CPU时间的百分比。 go tool trace更适合于找出程序在一段时间内正在做什么，而不是总体上的开销。 此外，还有“view trace”链接提供的其他可视化功能，这些对于诊断争用问题特别有用。 了解您的程序在理论上的表现（使用老式Big-O分析）也是无可替代的。



结论
希望这篇文章可以让您了解如何使用go tool trace诊断问题。 即使您没有解决具体问题，可视化您的程序是检查程序运行时特性的好方法。 我在这篇文章中使用的例子很简单，但更复杂的程序中的症状应该与此惊人的相似。



附录
这个博客文章给了你一个使用go tool trace的介绍，但你可能希望更深入地深入了解该工具。 目前正在进行的官方go tool trace文档相当稀少。 有一个Google文档更详细。 除此之外，我发现参考源代码是很有用，可以找出go tool trace如何工作：



go tool trace 源代码



二进制跟踪解析器的源代码



trace 源代码



go tool trace的Web界面来自Catapult项目的跟踪查看器。 该查看器可以从许多跟踪格式生成可视化。 go工具跟踪使用基于JSON的跟踪事件格式。



https://making.pusher.com/go-tool-trace/


Category golang