Go语言中常见100问题-#98 Not using Go diagnostics tooling

不知道使用分析工具

Go语言提供了一些优秀的分析工具，可以帮助我们定位程序的性能问题。本文关注最关键的两个工具：pprof和trace。pprof和trace都是Go语言自带的性能分析工具，pprof可以采集内存分配、goroutine等信息，使用trace可以分析并发、阻塞事件以及GC情况。

pprof

通过pprof可以深入了解程序的运行情况，帮助我们定位性能和内存泄漏问题，检查数据竞争等。利用pprof主要从以下几个维度了解程序状况。

• CPU:决定程序的时间都花在哪些地方。
• Goroutine: 报告正在运行协程的调用栈信息。
• Heap:报告堆内存分配，监控当前内存使用情况并检查可能的内存泄漏。
• Mutex:报告锁竞争情况，以帮助我们分析代码中的mutex行为，判断程序是否在锁调用上花费了太长时间。
• Block:显示goroutines阻塞等待同步原语的位置。

启用pprof

有多种方法启用pprof，方法之一是使用 net/http/pprof包提供的通过HTTP，示例代码如下：

import (
 "fmt"
 "log"
 "net/http"
 _ "net/http/pprof"
)

func main() {
 http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
  fmt.Fprintf(w, "")
 })
 log.Fatal(http.ListenAndServe(":80", nil))
}

导入 net/http/pprof 包后我们可以通过访问 http://host/debug/pprof URL获取pprof信息。注意，在生产环境中启用pprof也是安全的（https://go.dev/doc/diagnostics#profiling），影响程序性能的信息采集默认是不开启的，例如获取CPU信息。并且pprof也不是持续不断采集信息，而是在特定时间段内采集。

CPU采样分析

CPU性能分析依赖于操作系统和信号，当启动采样时，默认情况下应用程序要求操作系统每隔10ms中断一次业务执行，该过程是通过SIGPROF信号实现的，当我们的应用程序接收到SIGPROF信号量时，会挂起正在运行逻辑，转移执行分析器逻辑代码，进行数据收集。例如当前的goroutine活动，并整理成我们可以查看的统计信息。分析器逻辑执行完后又回头执行业务逻辑，直到下一个SIGPROF信号.

访问 /debug/pprof/profile URL可以获取CPU采样信息。默认采样时间为30秒，在30秒内每间隔10毫秒进行一次采样统计。这两个时间值也是可以自定义的，假如我们想采用时间为15秒，可以像这样设置， /debug/pprof/profile?seconds=15, 我们也可以设置间隔时间小于10毫秒，通常来说间隔值10毫秒已足够了。间隔时间设置的越小意味着采用频率提高，高频采样会对程序的性能有影响，在生产环境中要特别注意这点。30秒到期后会得到一个CPU采样文件。

我们也可以在进行性能测试时启动CPU采样，通过 -cpuprofile 参数启动，具体如下：

go test -bench=. -cpuprofile profile.out

上述命令中profile.out即为生成的采集结果文件，通过 /debug/pprof/profile得到的文件也是一样的。

得到CPU文件后，通过 go tool 在浏览器中查看结果。

go tool pprof -http=:8080 <file>

下图展示的是一个真实应用程序CPU采样结果，图中框越大，说明它占用的时间越大。

观察每个框图可以看到更详细的信息，例如 docode 框图，FetchResponse的docode方法花费了0.06秒，在这0.06秒中，RecordBatch.decode用了0.02秒，makemap用了0.01秒。

我们还可以从不同的展示方式查看性能信息，例如 TOP、Graph 等。TOP展示对函数执行时间进行了排序，Graph(火焰图)以可视化形式展示执行时间层次结构。此外，还可以通过命令行模式深入分析数据。

通过上面函数占用树状图，可以了解到该应用以下几点需要关注：

• runtime.mallogc调用很多，意味着过多的小堆内存分配，应该尽量减少。
• 在通道操作或互斥锁上的时间较多，表明存在过多的争用，会降低程序性能。
• 在syscall.Read和syscall.Write上花费太多的时间，意味着程序在内核模式下花费较多时间，运用缓存区可能会改善这种状况。

注意：我们可以给不同的函数打上标签，然后使用 pprof.Labels查看CPU运行时间情况，这在某些场景非常有用，例如公共函数被多个客户端调用，可以区分跟踪各个客户端花费的时间。

堆内存采样分析

进行堆采样我们可以分析程序堆内存使用情况, 同CPU采样我们可以调整堆采样率，但是注意粒度不能调整的太小，因为粒度太小进行采样时要统计信息很多，这会对程序性能造成影响。默认情况下，在堆上每分配512KB内存会进行一次采样。

通过访问 /debug/pprof/heap 地址可以获取到原始的堆数据信息，但是这种数据不利于我们阅读。因此，常规操作是访问 /debug/pprof/heap/?debug=0, 获取到堆采样文件后使用 go tool 在浏览器中可视化查看。

下图是堆采样展示，可以看到 MetadataResponse.decode调用分配了1536KB的堆内存（占整个堆内存的6.32%）。但是，该函数逻辑直接分配的内存为0，继续看它调用的函数，TopicMetadata.decode分配了512KB，剩下的1024KB被调用的其它函数分配。

这种以函数调用栈的形式展示了堆内存分配情况，框图越大表明分配的内存越多，可以快速锁定哪些地方分配的内存较多。此外，我们还可以从其它维度了解内存分配情况：

• alloc_objects:分配的对象总数目
• alloc_space:分配的内存总量
• inuse_objects:已分配未释放的对象数量
• inuse_space:已分配未释放的内存量

堆采样还可以帮助我们定位内存泄露问题，对于基于GC的语言，排查内存泄露的一般操作步骤如下：

1. 触发GC回收掉不再使用的内存
2. 获取堆采样信息
3. 等待几秒钟或几分钟
4. 再触发一次GC
5. 再获取一次堆采样信息
6. 比较2和5中的采样信息

在进行堆采样之前进行GC操作是为了排除干扰，如果我们没有首先进行GC，采样到的峰值数据不能判断它是一个内存泄漏还是将在下一次GC时会被回收。

使用pprof，可以在进行堆采样前同时执行GC。对应到Go语言中，具体操作流程如下：

1. 访问 /debug/pprof/heap?gc=1(触发GC并进行采样)
2. 等待几秒钟或几分钟
3. 再次访问 /debug/pprof/heap?gc=1
4. 使用 go tool 比较两个堆配置文件

go tool pprof -http=:8080 -diff_base <file2> <file1>

下图展示的是两个堆文件差异值，可以看到 newTopicProducer方法占用的堆内存减少了513KB， 而 updateMetadata方法占用的堆内存增加了512KB。这种缓慢增加一般是正常的，可能的原因是在进行第二次堆采样时处于服务调用过程中。我们可以重复上述流程，或者两次采样中间等待更长的时间，重点关注那些特定对象占用的内存大小稳定增长的情况，这里很有可能存在内存泄漏问题。

NOTE:另一个分析堆文件的维度是allocs, 它记录了堆内存分配情况。堆采样显示堆内存的当前状态，如果我们想了解从程序启动到现在内存分配，可以用本小节介绍的堆采样。因为栈上分配开销很低，所以内存分配采样关注的是堆内存。

goroutine剖析

goroutine剖析文件记录了当前应用程序中所有goroutine的堆栈信息。我们可以访问 /debug/pprof/goroutine/?debug=0获取goroutine信息文件。使用 go tool 将goroutine信息可视化，如下图所示。

从图中可以看到每个函数创建了多少个goroutine，例如 withRecover创建了296个正在运行的goroutine(占整个goroutine数量的63%)，其中29个与responseFeeder调用相关。可以利用这些数据分析goroutine泄露问题。

block剖析

block剖析文件记录了阻塞在同步原语上的goroutine, 这些同步原语主要是以下方面：

• 向无缓冲区的通道发送数据或从无缓冲区的通道接收数据
• 向已经满了的缓冲区发送数据
• 从已经空了的缓冲区读取数据
• 锁竞争
• 网络或文件系统等待

block剖析文件也记录了goroutine阻塞等待的时间，可以访问 /debug/pprof/block获取block文件。block剖析对于我们分析程序性能是否受到阻塞调用影响非常有用。

block剖析功能默认是不启用的，可以调用 runtime.SetBlockProfileRate 启用。该函数接收一个int类型的rate参数。该参数含义是，只要发现了一个阻塞事件的持续时间达到了多少个纳秒，就对其进行采样。如果这个参数值小于等于0，则完全停止对阻塞信息采样。block采样一旦启用后，就开始进行采样，即使我们没有调用/debug/pprof/block. 注意参数rate设置过小，采样的频率会增加，对程序性能有影响。

NOTE: dump完整的goroutine栈信息。如果怀疑程序可能存在死锁或有goroutine处于阻塞状态，可以访问 /debug/pprof/goroutine/?debug=2获取完整的goroutine函数栈信息。下面是dump内容一部分，可以看到sarama goroutine阻塞在读取通道上已达1420分钟。

goroutine 2494290 [chan receive, 1420 minutes]:
github.com/Shopify/sarama.(*syncProducer).SendMessages(0xc00071a090,
{0xc0009bb800, 0xfb, 0xfb})
    /app/vendor/github.com/Shopify/sarama/sync_producer.go:117 +0x149

mutex剖析

最后一种与阻塞有关因素是锁问题。如果我们怀疑程序大量时间花费在等待mutex上，可以访问 /debug/pprof/mutex获取剖析文件。默认情况不会启动mutex剖析，通过 runtime.SetMutexProfileFraction启动。上面的 block剖析也会记录锁阻塞信息，那这里的mutex与它有啥不同呢？mutex是在解锁(unlock)时才会记录一次阻塞行为，而block是在开始执行lock调用时记录。

关于性能剖析的注意点：

• 本文没有提及 threadcreate 剖析，因为从2013年开始存在问题不能使用了（https://github.com/golang/go/issues/6104）。
• 一次只能进行一种类型剖析，不要同时启动CPU和堆采样分析，这会影响结果。
• pprof是可以扩展的，我们可以使用pprof.Profile创建自定义剖析功能。

执行跟踪

trace工具也是golang支持的go tool工具之一，它能够帮助我们跟踪程序的执行情况。有助于：

• 了解运行时事件，例如GC执行
• 了解goroutine执行
• 识别并行执行不佳的情况

结合Go语言中常见100问题-#56 Concurrency isn’t always faster进行说明，该文章讨论了两个不同版本都是通过并行实现的归并算法。第一个版本通过并行实现的归并排序性能很差，比串行实现都慢，原因是创建了太多的goroutine。下面通过执行跟踪来证实原因。

运行第一个版本基准测试，执行时携带 -trace参数来启动跟踪，并将执行跟踪信息保存在trace.out文件中。

go test -bench=BenchmarkParallelMergesortV1 -v -trace=trace.out

当然我们也可以通过HTTP方式访问 /debug/pprof/trace?debug=0 获取执行跟踪文件。

生成trace.out文件后，用go tool查看它。

go tool trace trace.out                         
2024/02/02 08:35:03 Parsing trace...
2024/02/02 08:35:25 Splitting trace...
2024/02/02 08:35:57 Opening browser. Trace viewer is listening on http://127.0.0.1:61913

执行上述命令后，会启动web服务，在浏览器中可以看到如下view trace信息。

点击某个View trace文件可以查看特定时间段内的跟踪信息，例如点击 View trace(0s-148.306916ms)，得到如下页面。

可以看到在接近150毫秒（0s-148.306916ms）内，展示了多种维度数据。比如 goroutine数量和堆内存大小。堆内存大小稳定增长，直到触发GC。此外，我们还可以观察每个CPU内核的Go程序活动。

如下图所示，timeframe从用户级代码开始，然后 stop the world 执行GC, 占用四个CPU内核大约40毫秒时间。

选取上图中1毫秒时间段进行放大，得到效果如下图所示，图中每个条形块对应一次goroutine执行，可以看到有密密麻麻的条形块，这意味着并行执行的效果不佳。

进一步缩小上图中的时间刻度，方便查看这些goroutine是如何编排的。放大后的效果如下，图中空白表示Go运行时启动和编排新的goroutine占用的时间，整体来看大约有50%的CPU时间没有用于执行应用代码。

同理对第二种并行实现生成trace.out文件，在Go语言中常见100问题-#56 Concurrency isn’t always faster当时测得第二版本比第一个版本快一个数量级。

go test -bench=BenchmarkParallelMergesortV2 -v -trace=trace.out

下图是第二个版本选取1毫秒时间段放大后的效果图。相比第一个版本，条形块数量明显减少，并且空白数量也已显著减少。CPU用在执行应用代码上的时间要比第一个版本多很多，每一毫秒CPU时间得到了更好的利用。这也进一步证实了两个版本性能有很大差异原因。

NOTE:执行跟踪的粒度是协程，不像CPU剖析那样定位到每个函数。但是我们可以定义用户级别任务，利用 runtime/trace 包提供的功能，获得按函数或函数组维度跟踪能力。下面举例说明

假设一个计算斐波拉契函数，然后使用atomic将计算结果保存到一个全局变量中。我们可以定义两种不同的任务：

ctx, fibTask := trace.NewTask(context.Background(), "fibonacci")
trace.WithRegion(ctx, "main", func() {
v = fibonacci(10)
})
fibTask.End()
ctx, fibStore := trace.NewTask(ctx, "store")
trace.WithRegion(ctx, "main", func() {
atomic.StoreInt64(&result, v)
})
fibStore.End()

使用go tool可以获取这两个任务执行时更精确时间信息。在前面的执行跟踪效果图中可以看到每个goroutine中每个任务的界限，在用户自定义任务中，展示的是持续时间分布情况。

通过上图可以看到，在大多数情况下，fibonacci任务执行时间不到15微秒，而store任务的执行时间不到6309纳秒。

用户自定义执行跟踪可以获取到各种性能信息，上一节的CPU采样分析也可以获取各种性能信息，它们有啥区别呢？

• CPU采样分析：
  1. 基于采样
  2. 以函数为粒度
  3. 按设置频率进行采样（默认值为10毫秒）
• 用户自定义执行跟踪：
  1. 不基于采样
  2. 粒度是goroutine执行（除非使用runtime/trace包）
  3. 执行时间不受频率限制

总结：执行跟踪是了解程序如何运行的有力工具，前面通过归并排序实例分析第二个版本比第一个版本性能优异原因。注意执行跟踪与CPU采样两种性能分析的差异点，CPU采样分析的颗粒度是函数，可以直观定位问题到函数级别，而执行跟踪分析的颗粒度是goroutine，除非使用runtime/trace包。在优化应用程序时，可以联合使用性能剖析pprof和执行跟踪两种手段，更好挖掘程序存在的问题。