本文基于 Go 1.13
Go 为我们提供了一个工具,可以在运行时进行跟踪,并获得程序执行的详细视图。这个工具可以通过在测试中使用标记 -trace 来启用,可以通过 pprof 来进行实时跟踪,也可以通过 trace 包 在代码中的任何位置启用。这个工具可以更加强大,因为您可以自定义 traces 来增强它。让我们回顾一下它是如何工作的。
流程
该工具的流程非常简单。每个事件,如内存分配;垃圾回收器的所有阶段;goroutines 在运行、暂停等情况下会被 Go 标准库静态记录,并格式化后显示。然而,在录制开始之前,Go 首先“stops the world”,并对当前的 goroutines 及其状态进行快照。
这将在之后能让 Go 正确地构建每个 goroutine 的生命周期。流程如下:
然后,将收集的事件推送到缓冲区,当达到最大容量时,该缓冲区随后将刷新到完整缓冲区列表。这是此流程的图:
跟踪器现在需要一种将这些跟踪转储到输出的方法。为此,当追踪开始时,Go 会产生一个专用于此的 goroutine。如果可用,该 goroutine 将转储数据,并将把 goroutine 停放到下一个。这是它的一个表示:
现在流程非常清晰,所以让我们回顾一下记录的跟踪事件。
追踪
生成跟踪后,就可以通过运行命令 go tool trace my-output.out 来实现可视化。让我们以一些跟踪事件为例:
大多数都很简单。与垃圾回收器相关的跟踪位于蓝色跟踪 GC 下:
快速回顾:
STW
GC (空闲)
MARK ASSIST
GXX runtime.bgsweep
GXX runtime.gcBgMarkWorker
然而,有些追踪事件并不容易理解。让我们回顾一下,以便更好地理解:
当处理器与线程关联时,将调用 proc start 。当启动新线程或从 syscall 恢复时,就会发生这种情况。当线程与当前处理器解除关联时,将调用 proc stop 。当线程在 syscall 中被阻塞或线程退出时,就会发生这种情况。当 goroutine 进行系统调用时,将调用自考 syscall :当 goroutine 从 syscall 解除阻止时,将调用 unblock – 在这种情况下,标签 ( sysexit ) 将从被阻塞的通道显示:
跟踪可以增强,因为 Go 允许您定义和可视化自己的跟踪以及标准库中的跟踪。
用户自定义追踪
我们可以定义的跟踪有两个级别:
在任务的顶层,有开始和结束。在区域的子级别上。
下面是一个简单的例子:
func main() {
ctx, task :=trace.NewTask(context.Background(), "main start")
var wg sync.WaitGroup
wg.Add(2)
go func() {
defer wg.Done()
r :=trace.StartRegion(ctx, "reading file")
defer r.End()
ioutil.ReadFile(`n1.txt`)
}()
go func() {
defer wg.Done()
r :=trace.StartRegion(ctx, "writing file")
defer r.End()
ioutil.WriteFile(`n2.txt`, []byte(`42`), 0644)
}()
wg.Wait()
defer task.End()
}
这些新的跟踪可以通过菜单用户自定义直接从工具中可视化:
还可以任意将一些日志记录到任务中:
ctx, task :=trace.NewTask(context.Background(), "main start")
trace.Log(ctx, "category", "I/O file")
trace.Log(ctx, "goroutine", "2")
这些日志将在设置任务的 goroutine 下找到:
还可以通过派生父任务的上下文等将任务嵌入到其他任务中。
但是,由于 pprof 的存在,在生产中实时跟踪所有这些事件可能会在收集它们时略微降低性能。
性能影响
一个简单的基准测试可以帮助理解跟踪的影响。其中一个将带标志 -trace 运行,另一个则不带。下面是 ioutil.ReadFile() 函数的基准测试结果,该函数生成了很多事件:
name time/op
ReadFiles-8 48.1μs ± 0%
name time/op
ReadFiles-8 63.5μs ± 0% // with tracing
在这种情况下,影响约为 ~35%,并且可能因应用程序而异。但是有一些工具(如 StackDriver ),允许在生产环境中进行连续的分析,同时又对应用程序保持较小的开销。