Go 高性能系列教程之四：执行跟踪器

不同于pprof的采样分析检测，执行跟踪器是基于运行时环境，且能够知道 Go 程序在特定的时刻正在做什么。但是原理是什么呢？

01

—

什么是执行跟踪器，我们为什么需要它？

要解释什么是执行跟踪器，它又为什么如此重要。最简单的方式就是通过使用 pprof 的代码片段，用 go tool pprof 执行一段性能表现不佳的代码，看看有哪些方面是该工具覆盖不到的。

我们看下这段代码，代码地址位于https://github.com/campoy/mandelbrot

go build && ./mandelbrot

如果我们编译并运行该程序，将产生如下的图片：

1.1 这个程序运行了多长时间

这段程序花了多长时间生成这个 1024*1024 像素图片呢？

最简单的方式就是使用使用 time 命令：

$ time ./mandelbrot

注意：不要使用 time go run mandebrot.go,否则你将要包含编译该程序的时间。

1.2 这个程序做了什么？

那么，这个程序花了 5.104 秒（注意不同的机器运行输出时间可能不同,相同机器多次运行的时间也可能不同）的时间生成了一张曼德勃罗图片并输出了它。

这是运行时间比较快的吗？我们还能让它运行的再快点吗？回答这个问题的一个方式就是使用 Go 内建的 pprof 工具来生成profiling。

02

—

生成&分析profiling

2.1 用 runtime/pprof 包生成profiling文件

为了表现方便，我们直接将 cpuprofile 的输出到 os.Stdout 中

import "runtime/pprof"

func main() {
    pprof.StartCPUProfile(os.Stdout)    
    defer pprof.StopCPUProfile()
}

通过增加函数开头的这部分代码，该程序运行时将把 cpu 的监测数据写入到 os.Stdout 中。

go run mandelbrot.go > cpu.pprof

注意：我们可以直接使用 go run 命令运行，因为 cpu 的监控分析文件只包含 mandelbrot.go 的执行时间，并不会包含编译时间。

2.2 分析profiling文件

现在我们已经得到了监控文件，我们可以使用 go tool pprof 工具来分析了。

% go tool pprof -http=:8080 cpu.pprof

执行后，我们看到整个程序运行了 6.58 秒（和之前的 5.104 秒相比增加了一些固定的 profiling 开销）。我们也看到 pprof 采集数据花费了 5.09 秒，因为 pprof 是基于数据采样的，依赖于操作系统的 SIGPROF 计时器。

我们可以用 pprof 中的 top 命令来对跟踪信息进行排序：

$ go tool pprof cpu.pprof

我们看到 mandelbrot.fillPixel 函数花费的 CPU 时间是最多的。

在堆栈上发现 mandelbrot.paint 函数并不奇怪，这是程序内部的函数。它是按像素输出的。但是，是什么导致 paint 函数花这么长时间呢？我们可以用 cummulative flag（累加时间）进一步检查：

(pprof) top --cum

以上输出显示实际上是 mandelbrot.fillPixed 函数做了大部分的工作（根据累加耗时排序后，除系统自带的函数外，mandelbrot.fillPixel 函数的累计值是最多的)。

03

—

Tracing VS Profiling

希望这个例子已经说明了pprof分析的局限性。pprof分析只能告诉我们一个整体的概况：fillPixel 正在做所有的工作。但我们看不到 fillPixel 为什么慢，哪里最耗时。

现在，我们来介绍执行跟踪器：它从另一个不同的角度来分析该程序。

3.1 使用执行跟踪器

import "github.com/pkg/profile"

func main() {
    defer profile.Start(profile.TraceProfile, profile.ProfilePath(".")).Stop()
}

当我们执行这个程序时，我们在当前目录会得到一个 trace.out 文件。

$ time ./main

跟 pprof 一样，在 go 命令行中有一个工具可以分析这个文件：go tool trace

$ go tool trace trace.out

如下图是执行结果：

go tool trace 和 go tool pprof 有点不同。执行跟踪器复用了很多 chrome 浏览器内置的可视化基础组件，所以 go tool trace 扮演了一个服务器，将原始的跟踪信息转换成了 chrome 浏览器可以渲染的数据。

3.2 分析跟踪数据

我们首先点击 “view trace” 连接进入对应的页面，如下图。

从跟踪信息中我们看到该程序只用了一个 CPU，如图红框中，代表一个有 4 个虚拟处理器，但只有红框中的 1 个在使用。

func seqFillImg(m *img) {
    for i, row := range m.m {
        for j := range row {
            fillPixel(m, i, j)
        }
    }
}

这个并不奇怪，默认情况下，mandelbrot.go 依次为每一行中的每个像素顺序调用 fillPixel 函数，如上代码。

一旦图片被渲染，执行跟踪器将切换到写入.png 文件。这会在堆内存上产生碎片垃圾，所以在这一点上跟踪信息发生了变化，我们看到了经典的垃圾回收模式。

trace 分析提供了微秒级别的时序图。这是我们用 pprof 工具所不能获取到的。

在我们继续之前，我们先讨论下关于 go tool trace 工具的一些用法

• 该工具使用 Chrome 浏览器内置的 javascript 调试器。trace profile 只能在 Chrome 浏览下工作，在 Firefox，Safari，IE 下是不能正常运行的。
• 因为是 Google 的产品，所以它支持使用快捷键。例如用 WASD 导航，用 ？ 获取列表
• 查看跟踪图会消耗很多的内存。说实话，4Gb 不会觉得多，8GB 可能是最小值，越多越好。

3.3 使用更多的 CPU

从上面我们知道，跟踪的程序是顺序执行的，而且并没有利用到多核 CPU 的优势。

曼德勃罗图的生成是可以并发执行的。每个像素都相互独立，他们可以并行的计算。所以，让我们试试用多个 cpu 执行。

2021/06/27 23:31:17 profile: trace enabled, trace.out

而且这个执行时间基本和单核 cpu 是一样的。但是 user time 却多了点，这是有道理了，因为我们使用了所有的 CPU，但 real 时间（wall time）大致相同。

让我们再来看看 trace。正如你看到的，这次 trace 产生了更多的数据：

• 看起来很多工作正在完成，但是如果您放大再放大，就会发现每个协程运行的时间很多，之间会有空隙。这是由于程序调度而产生的。
• 我们使用了 4 个 CPU 核心同时工作，因为每个 fillPixel 是执行了一个相对较小的工作量，所以我们会花费大量的调度时间。

3.4 批量处理

每个像素使用一个 goroutine 粒度太细了。相反，让我们试试用一个 goroutine 来处理一行像素：

$ time ./main -mode row

这看起来是一个非常好的改进，我们几乎节省了一半的运行时间。让我们来看看跟踪信息。

正如你所看到的，trace 现在比之前更小更容易查看了。我们可以看到整个 trace，这是个不错的改进。

• 在程序刚开始的地方，我们看到协程的数量在 1000 个左右，这比上面每个像素使用一个协程的程序产生的 1 << 20 个协程是一个很大的改进。
• 放大跟踪图，我们可以看到每个 onePerRowFillImg 运行的时间会更长，同时协程的生成工作提前完成，所以调度器可以有效的处理剩余的可运行的协程。

3.5 使用 workers 模式

mandelbrot.go 支持另一种模式，让我们试试。

$ time ./main -mode workers

那么，运行时间比之前的更多了。让我们来跟踪并看看能否找到发生了什么。

查看 trace，你会看到只有 1 个生产者和 1 个消费者在来回切换，因为在我们的程序中只有 1 个生产者和 1 个消费者。那让我们增加下 workers 的数量：

$ time ./main -mode workers 4

花费的时间更多了。更多的 real 时间，更多的 cpu 时间。让我们继续 trace 看看发生了什么。

这个跟踪是比较混乱的。现在有很多的可用 workers，但好像是所有时间都花在了他们竞争工作上。

这是因为使用了无缓冲 channel。一个无缓冲 channel 直到有接受者接收信息的时候才会发送消息。

• 直到有个一个消费 worker 准备好接收信息时，生产者才能发送消息到通道
• 消费者 worker 直到生产者准备好发送数据的时候才会接收，所以他们之间是在相互等待各自完成工作。
• 发送者没有特权，它不能优先于已经运行的消费者 worker

我们在这里看到的是无缓冲 channel 带来的大量延迟。在调度器里有很多开启、暂停，本质上是相互等待时产生的加锁和互斥，这就是我们看到的 sys 时间耗时多的原因。

4. 更多资源

• Rhys Hiltner, Go’s execution tracer (dotGo 2016)
• Rhys Hiltner, An Introduction to "go tool trace" (GopherCon 2017)
• Dave Cheney, Seven ways to profile Go programs (GolangUK 2016)
• Dave Cheney, High performance Go workshop
• Ivan Daniluk, Visualizing Concurrency in Go (GopherCon 2016)
• Kavya Joshi, Understanding Channels (GopherCon 2017)
• Francesc Campoy, Using the Go execution tracer

参考链接 https://dave.cheney.net/high-performance-go-workshop/gophercon-2019.html