深入浅出Go语言trace

发表于 |

你有没有考虑过，你的goroutines是如何被go的runtime系统调度的？是否尝试理解过为什么在程序中增加了并发，但并没有给它带来更好的性能？go执行跟踪程序可以帮助回答这些疑问，还有其他和其有关性能的问题，例如延迟、竞争和较低的并行效率。

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

  1. 创建，启动和终止goroutines
  2. 阻塞/非阻塞goroutines(syscalls, channels, locks)
  3. 网络 I/O
  4. Syscalls
  5. 垃圾回收

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

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

Trace概览

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
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=<file>测试标志
    用来收集关于被测试代码的trace时比较有用
  3. 使用debug/pprof/trace handler
    这是用来收集运行中的web应用的trace的最好的方法

跟踪一个web应用

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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
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。这篇[博客](http://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命令完成的。当该工具解析文件的整个内容时，这将花费比我们之前的示例花费的时间更长。当它完成时，页面看起来略有不同：

1
2
3
4
5
6
7
8
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 博客文章)。

参考

  1. Go execution tracer (design doc)
  2. Using the go tracer to speed fractal rendering
  3. Go tool trace
  4. Your pprof is showing

原文链接