泽民博客 ☰ Menu

go tool trace

该工具是Go 1.5版本加入的，通过度量go语言特定事件的运行时，例如：



创建，启动和终止goroutines



阻塞/非阻塞goroutines(syscalls, channels, locks)



网络 I/O



Syscalls



垃圾回收



以上事件的所有数据会被跟踪器收集，而且不会做任何类型的聚合和抽样。这在一些复杂的应用程序中，通过 go tool trace 命令对其进行分析后可能会产生一个较大的文件。

在引入执行trace程序之前，已经有了pprof内存和CPU分析器，那么为什么它还会被添加到官方的工具链中呢？虽然CPU分析器做了一件很好的工作，告诉你什么函数占用了最多的CPU时间，但它并不能帮助你确定是什么阻止了goroutine运行，或者在可用的OS线程上如何调度goroutines。这正是跟踪器真正起作用的地方。trace设计文档很好地解释了跟踪程序背后的动机以及它是如何被设计和工作的。



让我们从一个简单的“Hello，world”示例开始。在本例中，我们使用runtime/trace包将trace数据写入标准错误输出。



package main



import (

“os”
“runtime/trace”
)



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

defer trace.Stop()

// create new channel of type int
ch := make(chan int)



// start new anonymous goroutine

go func() {        

    // send 42 to channel

    ch <- 42

}()    

// read from channel

<-ch }


这个例子创建了一个无缓冲的channel，初始化一个goroutine，并发送数字42到channel。运行主goroutine时是阻塞的，它会等待另一个goroutines发送一个int数值给channel。



用 go run main.go 2> trace.out 运行这段代码会发送trace数据到trace.out，之后可以用 go tool trace trace.out 读取trace。（该程序是个web app，默认启动127.0.0.1地址的一个随机端口，如果需要修改host可以加参数解决，例如 go tool trace –http=’:8080’ trace.out，译者加）



Tips: go 1.8之前，你同时需要可执行二进制文件和trace数据来分析trace；用go 1.8之后的版本编译的程序，trace数据已经包含了go tool trace命令所有的信息。



运行该命令后，在浏览器窗口打开该地址，它会提供一些选项。每一个都会打开trace的不同视图，涵盖了程序执行的不同信息。



1 View trace



最复杂、最强大和交互式的可视化显示了整个程序执行的时间轴。这个视图显示了在每个虚拟处理器上运行着什么，以及什么是被阻塞等待运行的。稍后我们将在这篇文章中深入探讨这个视图。注意它只能在chrome上显示。



2 Goroutine analysis



显示了在整个执行过程中，每种类型的goroutines是如何创建的。在选择一种类型之后就可以看到关于这种类型的goroutine的信息。例如，在试图从mutex获取锁、从网络读取、运行等等每个goroutine被阻塞的时间。



3 Network/Sync/Syscall blocking profile



这些图表显示了goroutines在这些资源上所花费的时间。它们非常接近pprof上的内存/cpu分析。这是分析锁竞争的最佳选择。



4 Scheduler latency profiler



为调度器级别的信息提供计时功能，显示调度在哪里最耗费时间。



View Trace



点击“View Trace”链接，你会看到一个界面，里面充满了关于整个程序执行的信息。
Tips: 右上角的”?”按钮可以获取快捷方式列表，以帮助跟踪trace。
下面的图片突出了最重要的部分，图片下面是对每个部分的说明描述：



1 Timeline



显示执行的时间，根据跟踪定位的不同，时间单位可能会发生变化。你可以通过使用键盘快捷键（WASD键，就像视频游戏一样）来导航时间轴。



2 Heap



在执行期间显示内存分配，这对于发现内存泄漏非常有用，并检查垃圾回收在每次运行时能够释放多少内存。



3 Goroutines



在每个时间点显示有多少goroutines在运行，有多少是可运行的（等待被调度的）。大量可运行的goroutines可能显示调度竞争，例如，当程序创建过多的goroutines，会导致调度程序繁忙。



4 OS Threads



显示有多少OS线程正在被使用，有多少个被syscalls阻塞。



5 Virtual Processors



每个虚拟处理器显示一行。虚拟处理器的数量由GOMAXPROCS环境变量控制（默认为内核数）。



6 Goroutines and events



显示在每个虚拟处理器上有什么goroutine在运行。连接goroutines的连线代表事件。在示例图片中，我们可以看到goroutine “G1.runtime.main”衍生出了两个不同的goroutines:G6和G5（前者是负责收集trace数据的goroutine，后者是我们使用“go”关键字启动的那个）。每个处理器的第二行可能显示额外的事件，比如syscalls和运行时事件。这还包括goroutine代表运行时所做的一些工作（例如辅助垃圾回收）。下图显示了当选择一个goroutine时得到的信息。



该信息包含：



它的“名称”(Title)



何时开始(Start)



持续时间(Wall Duration)



开始时的栈trace



结束时的栈trace



该goroutine产生的事件


我们可以看到，这个goroutine创造了两个事件：



trace goroutine和在channel上发送42的goroutine。



通过点击一个特定的事件（点击图中的一条连线或者在点击goroutine后选择事件），我们可以看到：



事件开始时的栈信息



事件持续时长



事件包含的goroutine



你可以点击这些goroutines来定位跟踪到它们的trace数据。



阻塞概况



从trace中获得的另一个特殊视图是网络/同步/syscall阻塞概况。阻塞概况显示了一个类似于pprof的内存/cpu概况中的图形视图。不同之处在于，这些概况显示每个goroutine在一个特定资源上花费的阻塞时间，而不是显示每个函数分配了多少内存。
下图告诉我们示例代码的“同步阻塞概况”



这告诉我们，我们的主goroutine从一个channel接收花费了12.08微秒。当太多的goroutines在竞争着获取一个资源的锁时，这种类型的图是找到锁竞争的很好的方法。



收集trace



有三种收集trace的方法：



1 使用 runtime/trace包



这个需要调用trace.Start和trace.Stop，已经在我们的示例程序中讲过。



2 使用 -trace=测试标志



用来收集关于被测试代码的trace时比较有用。



3 使用 debug/pprof/tracehandler



这是用来收集运行中的web应用的trace的最好的方法。



跟踪一个web应用



想要从一个运行的web应用收集trace, 你需要添加 /debug/pprof/trace handler。下面的代码示例展示了如何通过简单地导入 net/http/pprof 包为 http.DefaultServerMux 做到这一点。



package main



import (

“net/http”
_
“net/http/pprof”
)



func main() {
http.Handle(“/hello”, http.HandlerFunc(helloHandler))



http.ListenAndServe("localhost:8181", http.DefaultServeMux) }


func helloHandler(w http.ResponseWriter, r *http.Request) {
w.Write([]byte(“hello world!”))
}



为了收集trace，我们需要向endpoint发出请求，例如，
curl localhost:8181/debug/pprof/trace?seconds=10 > trace.out
此请求将阻塞10秒钟，trace数据将写入文件trace.out。像这样生成的trace可以像我们以前那样查看：
go tool trace trace.out



Tips: 请注意，将pprof handlers暴露给Internet是不建议的。推荐的做法是在不同的只绑定到loopback接口的http.Server暴露这些endpoint。这篇博客（https://mmcloughlin.com/posts/your-pprof-is-showing）讨论该风险，并有代码示例解释如何正确地暴露pprof handler。



在收集trace之前，让我们首先通过wrk来给我们的服务加一些负载：
$ wrk -c 100 -t 10 -d 60s http://localhost:8181/hello



这将使用10个线程的100个连接在60秒内发出请求。当wrk正在运行时，我们可以使用 curl localhost:8181/debug/pprof/trace?seconds=5 > trace.out 来收集5s的trace数据。这会产生一个5MB的文件（如果我们能够在我的4核CPU机器上生成更多的负载，它就可以快速增长）。同样，打开trace是由go tool trace命令完成的。当该工具解析文件的整个内容时，这将花费比我们之前的示例花费的时间更长。当它完成时，页面看起来略有不同：



View trace (0s-2.546634537s)
View trace (2.546634537s-5.00392737s)



Goroutine analysis
Network blocking profile
Synchronization blocking profile
Syscall blocking profile
Scheduler latency profile



为了保证浏览器渲染呈现所有内容，该工具将trace分为两个连续的部分。更复杂的应用或更长的trace可能需要工具将其分割成更多的部分。点击“View trace(2.546634537-5.00392737)”我们可以看到有很多事情正在发生：



这个特殊的屏幕截图显示了一个GC运行情况，它从1169ms-1170ms开始，在1174ms之后结束。在这段时间里，一个OS线程（PROC 1）运行一个用于GC的goroutine，而其他goroutines则在一些GC阶段中提供辅助（这些步骤显示在goroutine的连线中，并被叫做MARK ASSIST)。在截图的最后，我们可以看到大部分分配的内存都被GC释放了。 另一个特别有用的信息是在“Runnable”状态下的goroutines的数量（在选定的时间内是13）：如果这个数字随着时间的推移变得很大，这就意味着我们需要更多的cpu来处理负载。



结论



trace程序是调试并发问题的强大工具。例如，竞争和逻辑冲突。但它并不能解决所有的问题：它并不是用来跟踪哪块代码花费最多CPU时间或分配的最佳工具。
go tool pprof 更适用于这些用例。当你想要了解一个耗时程序的行为，并且想知道当每个goroutine不运行时它在做什么，这个工具就会很好地发挥作用。收集trace可能会有一些开销，并且会生成大量的数据用来检查。不幸的是，官方文档是缺失的，因此需要进行一些试验来尝试和理解trace程序所显示的内容。这也是对官方文档和整个社区作出贡献的机会（e.g 博客文章)。



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



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



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



红色的事件代表了唯一的程序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 不合适？
当然， 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 的跟踪事件格式。



什么时候go tool trace不合适？
当然，go tool trace不能解决一切问题。 如果您想跟踪运行缓慢的函数，或者找到大部分CPU时间花费在哪里，这个工具就是不合适的。 为此，您应该使用go tool pprof，它可以显示在每个函数中花费的CPU时间的百分比。 go tool trace更适合于找出程序在一段时间内正在做什么，而不是总体上的开销。 此外，还有“view trace”链接提供的其他可视化功能，这些对于诊断争用问题特别有用。 了解您的程序在理论上的表现（使用老式Big-O分析）也是无可替代的。
使用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是非常短暂的，或者他们之间有很多的竞争的情况下。 这是使用此工具的另一个原因：尝试这两种方法，并检查哪种工作最适合您的用例。



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



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



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



这个程序运行多长时间？



有多少goroutines运行872微秒？



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



什么时候主要调用qSortPar？



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



proc＃2什么时候停止？



go tool trace trace.out(具体路径)



http trace



)增加如下代码



//导入包
import (
“net/http”
_ “net/http/pprof”
)



//增加如下代码
go func() {
fmt.Println(http.ListenAndServe(“:5567”, nil))
}()
2）执行curl 127.0.0.1:5567/debug/pprof/trace?seconds=10 > trace.data，获取到trace.data数据



3) 执行 go tool trace -http=’:8888’ your_app_bin trace.data。会跳转到浏览器查看trace到数据.



$ go tool trace trace.out
2019/08/25 15:35:28 Parsing trace…
failed to parse trace: unsupported trace file version 1.9 (update Go toolchain) 1009



编译版本和运行go tool trace 版本不匹配



https://github.com/divan/gotrace



Category golang