Skip to content

Latest commit

 

History

History
260 lines (167 loc) · 16 KB

12-8-Not-using-Go-diagnostics-tooling.md

File metadata and controls

260 lines (167 loc) · 16 KB

12.8 pprof 诊断工具

Go 提供了一些出色的诊断工具来帮助我们深入了解应用程序的执行情况。本节将重点介绍最重要的：分析和执行跟踪器。这两种工具都非常重要，以至于它们应该成为任何对优化感兴趣的 Go 开发人员的核心工具集的一部分。

让我们首先深入研究 profiling。

12.8.1 Profiling

分析是提供对应用程序执行的洞察力的活动。它使我们能够解决性能问题、检测争用、定位内存泄漏等等。这些见解可以通过几个配置文件收集：

  • CPU：确定应用程序将时间花在哪里
  • Goroutines：报告正在进行的 goroutines 的堆栈跟踪
  • 堆：报告堆内存分配以监控当前内存使用情况并检查可能的内存泄漏
  • Mutex：报告锁竞争以查看我们代码中使用的互斥锁的行为以及应用 程序是否在锁定调用上花费了太多时间
  • 块：显示 goroutine 阻塞等待同步原语的位置

分析是通过使用称为分析器的工具进行检测来实现的；在 Go 中：pprof。首先，让我们了解如何以及何时启用 pprof；然后，我们将深入研究最关键的配置文件类型。

启用 pprof

启用 pprof 有多种方法。例如，我们可以使用 net/http/pprof 包通过 HTTP 提供分析数据：

package main

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 会导致副作用，使我们能够通过 host/debug/pprof 访问 pprof URL。 请注意，启用 pprof 是安全的，即使在生产环境中也是如此。 影响性能的配置文件（例如 CPU 分析）默认情况下不启用，也不会连续运行：它们仅在特定时间段内激活。

现在我们已经了解了如何公开 pprof 端点，让我们深入研究最常见的配置文件。

CPU 分析

CPU 分析器依赖于操作系统和信号。事实上，当被激活时，应用程序将默认通过 SIGPROF 信号要求操作系统每 10 毫秒中断一次。当应用程序收到 SIGPROF 时，它将暂停当前活动并将执行转移到分析器。探查器将抓取和收集数据，例如当前的 goroutines 活动和我们可以检索的汇总执行统计信息。然后，它停止，并继续执行直到下一个 SIGPROF。

我们可以访问 /debug/pprof/profile 端点来激活 CPU 分析。默认情况下，访问此端点将执行 30 秒的 CPU 分析。这意味着在 30 秒内，我们的应用程序将每十毫秒中断一次。请注意，我们可以更改这两个默认值。我们可以使用 second 参数（例如，/debug/pprof/profile?seconds=15）将分析持续多长时间传递给端点。同时，我们还可以改变中断率，甚至在十毫秒以下。然而，在大多数情况下，十毫秒应该足够了，在减小这个值（意味着增加速率）时，我们应该小心不要损害性能。30 秒后，我们将下载 CPU 分析器的结果。

Note 此命令将生成可以通过 /debug/pprof/profile 下载的相同类型的文件。

我们还可以使用 ‑cpuprofile 标志启用 CPU 分析器，例如，在运行基准测试时：

$ go test -bench=. -cpuprofile profile.out

从这个文件中，我们可以使用 go tool 导航到结果:

$ go tool pprof -http=:8080 <file>

此命令将打开一个显示调用图的 Web UI。以下是从一个应用程序中获取的示例，以了解它的整体外观：

盒子越红，越是热路径。然后我们可以导航到这个图表并获得执行洞察力。例如：

在这里，这张图告诉我们，在 30 秒内，decode 方法（*FetchResponse 接收器）花费了 0.06 秒。在这 0.06 秒中，0.02 秒用于 RecordBatch.decode，0.01秒用于 makemap（创建 map）。

我们还可以通过不同的 Web UI 访问此类信息申述。例如，top 视图按执行时间对函数进行排序，而 Flame graph 则可视化执行时间层次结构。UI 甚至可以逐行显示源代码的昂贵部分。

Note 我们还可以通过命令行获取分析数据。但是，我们将在本节中只关注 Web UI。

多亏了这些数据，我们还可以大致了解应用程序的行为方式：

  • 如果我们观察到对 runtime.mallogc 的调用过多，则可能意味着我们可以尝试最小化过多的小堆分配。
  • 如果我们观察到在通道操作或互斥锁上花费了太多时间，则可能是过度争用损害了应用程序的性能。
  • 如果我们观察到 syscall.Read 或 syscall.Write 花费的时间过多，则应用程序会在内核模式下花费大量时间。也许，改进的途径是研究 I/O 缓冲。

这是我们可以从 CPU 分析器中获得的那种洞察力。它为了解最热门的代码路径和识别瓶颈带来了很多价值。但是，请注意，它不会超过配置为 CPU 分析器以固定速度（默认为 10 毫秒）执行时配置的速率。为了获得更细粒度的见解，我们应该使用跟踪，我们将在以后的部分中深入研究。

Note 我们还可以为不同的功能附加标签。例如，想象一个从不同客户端调用的通用函数。如果我们想跟踪为这两个客户花费的时间，我们可以使用 pprof.Labels。

堆分析

堆分析允许获取有关当前堆使用情况的统计信息。与 CPU 分析一样，堆分析也是基于样本的。我们可以改变这个速率，但我们应该小心不要太细化，因为我们越是降低速率，堆分析将花费更多的精力来收集数据。默认情况下，对于每 512 KB 的堆分配，样本在一个分配处进行分析。

如果我们到达 /debug/pprof/heap/，我们将获得难以阅读的原始数据。但是，我们可以使用 debug/pprof/heap/?debug=0 然后使用 go tool（相同的命令）打开它以使用 Web UI 导航到数据。例如：

在这里，我们可以观察堆图的示例。调用 MetadataResponse.decode 方法会导致分配 1536 KB 的堆数据（占总堆的 6.32%）。但是，这 1536 KB 中的 0 是由该函数直接分配的。因此，我们必须深入研究第二个调用。现在，我们可以注意到 TopicMetadata.decode 方法自己从 1536 KB 中分配了 512 KB。其余的 1024 KB 是通过另一种方法分配的。

这就是我们如何导航调用链以了解应用程序的哪个部分负责大多数堆分配。我们还可以深入研究不同的样本类型：

  • alloc_objects：分配的对象总数
  • alloc_space：分配的内存总数
  • inuse_objects：已分配但尚未释放的对象数量
  • inuse_space：已分配但尚未释放的内存量

对堆分析非常有帮助的另一部分是跟踪内存泄漏。使用基于 GC 的语言，通常的过程如下：

  • 触发 GC
  • 下载堆数据
  • 等待几秒/分钟
  • 触发另一个GC
  • 下载另一个堆数据
  • 对比

在下载数据之前强制 GC 是一种防止错误假设的方法。例如，如果我们看到保留对象的峰值，但没有先运行 GC，我们无法确定它是泄漏还是下一次 GC 将收集的对象。

使用 pprof，我们可以下载堆配置文件并同时强制进行 GC。因此，Go 中的过程如下：

  • 转到 /debug/pprof/heap?gc=1（触发 GC 并下载堆配置文件）
  • 等待几秒/分钟
  • 再次转到 /debug/pprof/heap?gc=1
  • 使用 go tool 比较两个堆配置文件：
$ go tool pprof -http=:8080 -diff_base <file2> <file1>

以下是我们可以访问的数据类型：

例如，我们可以注意到 newTopicProducer 方法（左上角）持有的堆内存量减少了（‑513 KB）。相比之下，updateMetadata（右下）持有的数量增加了（+512 KB）。缓慢增加是正常的。实际上，例如，第二个堆配置文件可以在服务调用的中间计算。但是，我们可以重复这个过程或等待更多时间；重要的部分是跟踪特定对象分配的稳定增长。

Note 还有另一个与堆相关的分析：allocs 报告分配。堆分析显示堆内存的当前状态。如果我们想了解自应用程序启动以来过去的内存分配情况，我们可以使用分配分析。请注意，正如所讨论的，因为堆栈分配很便宜，所以它们不是这个只关注堆的分析的一部分。

Goroutines 分析

goroutine 配置文件报告应用程序中所有当前 goroutine 的堆栈跟踪。我们可以使用 debug/pprof/goroutine/?debug=0 下载一个文件，然后再次使用 go tool。然后，这是我们可以获得的信息类型：

我们可以看到应用程序的当前状态以及每个函数创建了多少个 goroutine。在这里，withRecover 创建了 296 个正在进行的 goroutine（63%），其中 29 个与对 responseFeeder 的调用有关。

如果我们怀疑 goroutine 泄漏，这种信息也是有益的。我们可以深入研究 goroutine 分析器数据，以了解系统的哪个部分是可疑的。

块分析

块配置文件报告正在进行的 goroutine 阻塞等待同步原语的位置。这包括：

  • 在无缓冲通道上发送或接收
  • 发送到完整频道
  • 从空通道接收
  • 互斥争用
  • 网络或文件系统等待

它还将记录一个 goroutine 等待的时间，如果可以通过 debug/pprof/block 访问，这个配置文件会非常有用。我们怀疑阻塞调用会损害性能。

请注意，块配置文件默认情况下未启用，我们必须调用 runtime.SetBlockProfileRate 来启用它。此函数控制报告的 goroutine 阻塞事件的分数。一旦启用，分析器将继续在后台收集数据，即使我们不调用 debug/pprof/block 端点。如果我们想设置一个高速率而不损害性能，我们要小心。

互斥体分析

最后一种配置文件类型与阻塞有关，但仅与互斥锁有关。如果我们怀疑我们的应用程序花费大量时间等待锁定互斥体，从而损害执行，我们可以使用互斥体分析。它可以通过 debug/pprof/mutex 访问。

请注意，此配置文件的工作方式与阻塞配置文件的工作方式类似。默认情况下它是禁用的，我们必须使用 runtime.SetMutexProfileFraction 来启用它，它控制报告的互斥锁争用事件的比例。

关于分析的一些附加说明：

  • 我们没有提到 threadcreate 配置文件，因为它自 2013 年以来就被破坏了
  • 确保一次只启用一个分析器；例如，不能同时进行 CPU 和堆分析。否则，可能会导致错误的观察。
  • pprof 是可扩展的，我们可以使用 pprof.Profile 创建自己的自定义配置文件。

总结分析，我们已经看到了最重要的配置文件，我们可以启用这些配置文件来帮助我们了解应用程序的执行方式以及可能的优化途径。通常，建议启用 pprof，即使在生产中也是如此，因为它在大多数情况 下提供了出色的平衡。某些配置文件（例如 CPU 配置文件）会导致性能下降，但仅限于启用期间。

现在让我们深入研究执行跟踪器。

12.8.2 执行跟踪器

执行跟踪器是一种捕获各种运行时事件的工具，使它们可用于使用 go tool 进行可视化。跟踪器有助于：

  • 了解一些运行时事件，例如 GC 是如何执行的
  • 了解 goroutines 是如何执行的
  • 识别并行性较差的执行

让我们用 并发并不总是更快 中给出的示例来尝试一下。我们讨论了合并排序算法的两个并行版本。第一个版本的问题是糟糕的并行化导致创建了太多的 goroutine。让我们看看跟踪器如何帮助我们验证这个语句。

让我们首先在第一个版本上编写基准测试并使用 ‑trace 标志执行它以启用执行跟踪器：

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

Note 我们还可以使用 debug/pprof/trace?debug=0 pprof 端点下载远程跟踪文件。

此命令创建一个 trace.out 文件，我们现在可以使用 go tool 打开该文件：

$ go tool trace trace.out
2021/11/26 21:36:03 Parsing trace...
2021/11/26 21:36:31 Splitting trace...
2021/11/26 21:37:00 Opening browser. Trace viewer is listening on
    http://127.0.0.1:54518

它会打开 Web 浏览器，现在我们可以单击 View trace 以获取特定时间范围内的所有跟踪：

此处，该数字表示大约 150 毫秒。我们可以观察到多个有用的指标，例如 goroutine 数量或堆大小。堆大小稳定增长，直到触发 GC 为止。我们还可以观察每个 CPU 内核的 Go 应用程序的活动。timeframe 从用户级代码开始，然后执行 stop-the-world，占用四个 CPU 内核大约 40 毫秒。

关于并发，我们可以观察到这个版本利用了机器上所有可用的 CPU 内核。但是，让我们放大一毫秒的一部分：

每个 bar 对应于一个 goroutine 执行。有太多的小酒吧看起来不正确。这意味着并行化很差的执行；我们可以进一步放大以了解这些 goroutine 是如何编排的：

在这里，我们可以观察到大约 50% 的 CPU 时间没有花在执行应用程序代码上。空格表示 Go 运行时启动和编排新 goroutine 所花费的时间。现在让我们与第二个并行实现进行比较，它快了一个数量级，并再次放大到一毫秒的时间范围：

我们可以观察到每个 goroutine 需要更多的时间来执行，并且空白的数量已经显着减少。因此，这意味着 CPU 在执行应用程序代码时比第一个版本占用更多。因此，每毫秒的 CPU 时间都得到了更有效的利用，从而解释了基准测试的差异。

请注意，跟踪的粒度是每个 goroutine，而不是像 CPU 分析那样的每个函数。但是，可以使用 runtime/trace 包定义用户级任务以获取每个函数或函数组的见解。

例如，想象一个计算斐波那契数的函数，然后使用 atomic 将其写入全局变量；我们可以定义两个不同的任务：

var v int64
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，我们还可以获得关于这两个任务如何执行的更精确的信息。在前面的跟踪 UI 中，我们可以观察每个 goroutine 的每个任务的边界。同时，在 User-defined tasks 中，我们可以遵循持续时间分布：

在这里，我们可以注意到，在大多数情况下，fibonacci 任务的执行时间不到 15 微秒，而存储任务的执行时间不到 6309 纳秒。

我们在上一节中已经讨论过我们可以从 CPU 分析中获得什么样的信息。但是我们可以从用户级跟踪中获得的数据的主要区别是什么？

  • CPU 分析
    • 基于样本
    • 每个功能
    • 不低于采样率（默认为 10 毫秒）
  • 用户级跟踪：
    • 不基于样本
    • 每个 goroutine 执行（除非我们使用 runtime/trace 包）
    • 时间执行不受任何速率的约束

总之，执行跟踪器是了解应用程序如何执行的强大工具。正如我们在归并排序示例中看到的那样，我们可以识别出并行性较差的执行。但是，除非我们手动使用 runtime/trace 与 CPU 配置文件相比，否则它的粒度仍然是每个 goroutine。在优化应用程序时，我们可以同时使用分析和执行跟踪器来充分利用标准 Go 诊断工具。

下一节将讨论 GC 的工作原理以及如何对其进行调优。