viakiba

Golang-Trace-转

2022/09/26 Golang

本文由 简悦 SimpRead 转码， 原文地址 mp.weixin.qq.com

本篇文章简要介绍了 go 语言执行跟踪程序 (Trace)，从功能和性能上阐述了它的优势。翻译原文可通过“阅读原文” 访问。 

回顾上篇文章：一次 inode 耗尽实例分析

前言

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

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

  • 创建，启动和终止 goroutines

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

  • 网络 I/O

  • Syscalls

  • 垃圾回收

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

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

Trace 概览

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

package mainimport (        "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 做到这一点。

package mainimport (        "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 execution tracer (design doc)

Using the go tracer to speed fractal rendering

Go tool trace

Your pprof is showing

小米运维

和我们一起成为更酷的运维工程师

Search

    Table of Contents