探索 Go Trace 包

概述

本文基于 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 是垃圾回收器中的两个 “Stop the World” 阶段。在这两个阶段，goroutines 被停止。
• GC (空闲) 是在没有工作要做时标记内存的 goroutine。
• MARK ASSIST 是在分配期间帮助标记内存的 goroutines。
• GXX runtime.bgsweep 是垃圾回收器完成后的内存扫描阶段。
• GXX runtime.gcBgMarkWorker 是帮助标记内存的专用后台 goroutines。

然而，有些追踪事件并不容易理解。让我们回顾一下，以便更好地理解：

• 当处理器与线程关联时，将调用 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 ），允许在生产环境中进行连续的分析，同时又对应用程序保持较小的开销。

译自：https://medium.com/a-journey-with-go/go-discovery-of-the-trace-package-e5a821743c3c