Golang Alloc 和 HeapAlloc vs pprof 差异较大答案

【问题标题】：Golang Alloc and HeapAlloc vs pprof large discrepanciesGolang Alloc 和 HeapAlloc vs pprof 差异较大
【发布时间】：2019-10-02 16:09:15
【问题描述】：

我有一个计算内存中大型相关矩阵的 Go 程序。为此，我设置了一个由 3 个 goroutine 组成的管道，其中第一个读取文件，第二个计算相关矩阵，最后一个将结果存储到磁盘。

问题是，当我运行程序时，Go 运行时分配 ~17GB 的内存，而矩阵只占用 ~2-3GB。使用runtime.ReadMemStats 表明程序正在使用~17GB（并使用htop 验证），但pprof 仅报告约~2.3GB。

如果我在通过管道运行一个文件后查看内存统计信息：

var mem runtime.MemStats
runtime.ReadMemStats(&mem)
fmt.Printf("Total alloc: %d GB\n", mem.Alloc/1000/1000/1000)

这显示了程序的总分配：

Total alloc: 17 GB

但是，如果我运行 go tool pprof mem.prof，我会得到以下结果：

(pprof) top5
Showing nodes accounting for 2.21GB, 100% of 2.21GB total
Showing top 5 nodes out of 9
      flat  flat%   sum%        cum   cum%
    1.20GB 54.07% 54.07%     1.20GB 54.07%  dataset.(*Dataset).CalcCorrelationMatrix
    1.02GB 45.93%   100%     1.02GB 45.93%  bytes.makeSlice
         0     0%   100%     1.02GB 45.93%  bytes.(*Buffer).WriteByte
         0     0%   100%     1.02GB 45.93%  bytes.(*Buffer).grow
         0     0%   100%     1.02GB 45.93%  encoding/json.Indent

所以我想知道如何才能找出程序分配 17 GB 的原因，而峰值内存使用量似乎只有 ~2.5GB？有没有办法使用 pprof 跟踪整个程序的内存使用情况？

编辑

我再次使用 GODEBUG=gctrace=1 运行程序并得到以下跟踪：

gc 1 @0.017s 0%: 0.005+0.55+0.003 ms clock, 0.022+0/0.47/0.11+0.012 ms cpu, 1227->1227->1226 MB, 1228 MB goal, 4 P
gc 2 @14.849s 0%: 0.003+1.7+0.004 ms clock, 0.015+0/1.6/0.11+0.018 ms cpu, 1227->1227->1227 MB, 2452 MB goal, 4 P
gc 3 @16.850s 0%: 0.006+60+0.003 ms clock, 0.027+0/0.46/59+0.015 ms cpu, 1876->1876->1712 MB, 2455 MB goal, 4 P
gc 4 @22.861s 0%: 0.005+238+0.003 ms clock, 0.021+0/0.46/237+0.015 ms cpu, 3657->3657->3171 MB, 3658 MB goal, 4 P
gc 5 @30.716s 0%: 0.005+476+0.004 ms clock, 0.022+0/0.44/476+0.017 ms cpu, 5764->5764->5116 MB, 6342 MB goal, 4 P
gc 6 @46.023s 0%: 0.005+949+0.004 ms clock, 0.020+0/0.47/949+0.017 ms cpu, 10302->10302->9005 MB, 10303 MB goal, 4 P
gc 7 @64.878s 0%: 0.006+382+0.004 ms clock, 0.024+0/0.46/382+0.019 ms cpu, 16548->16548->7728 MB, 18011 MB goal, 4 P
gc 8 @89.774s 0%: 0.86+2805+0.006 ms clock, 3.4+0/24/2784+0.025 ms cpu, 20208->20208->17088 MB, 20209 MB goal, 4 P

所以很明显堆在整个程序中稳步增长，但我无法确定在哪里。在调用内存密集型函数后，我使用pprof.WriteHeapProfile 分析了内存使用情况：

func memoryProfile(profpath string) {

    if _, err := os.Stat(profpath); os.IsNotExist(err) {
        os.Mkdir(profpath, os.ModePerm)
    }

    f, err := os.Create(path.Join(profpath, "mem.mprof"))
    fmt.Printf("Creating memory profile in %s", "data/profile/mem.mprof\n")
    if err != nil {
        panic(err)
    }

    if err := pprof.WriteHeapProfile(f); err != nil {
        panic(err)
    }
    f.Close()
}

【问题讨论】：

运行时不一定只能分配所需的最低内存。您如何确定峰值使用量？程序运行时，堆所需的 gctrace 输出显示什么？
可能与最近解决的问题 30333 相关：“...内存中的临时峰值导致 Go 运行时增加堆，但这需要很长时间（大约几分钟）将不需要的内存返回给系统……”。
@JimB 我很满意运行时分配的内存超出了需要，但额外增加了约 14 GB 似乎有点过多。我使用pprof.WriteHeapProfile() 来跟踪内存使用情况，但正如您所见，它不是很有帮助。这让我相信我要么没有正确使用它，要么误解了它的功能。
@Gronnesby：这就是我提到gctrace 的原因，它将显示与垃圾收集器目标相关的堆分配。还要确保您使用的是 go1.12.5。
go profile 是一个采样分析器，所以它不是一个绝对的度量，你用来比较事物之间的相对关系。您可以增加MemProfileRate，看看这是否有助于缩小范围。您还可以为各个组件编写基准测试，并使用-benchmem 查看分配发生的位置。

标签： go memory profiling

【解决方案1】：

正如JimB 在 cmets 中所提到的，go 配置文件是一个采样分析器，并以特定间隔对内存使用情况进行采样。在我的例子中，采样的频率不足以捕获使用大量内存的函数（JSON 编组）。

通过设置环境变量提高profiler的采样率

$ export GODEBUG=memprofilerate=1

将更新runtime.MemProfileRate并且配置文件现在包括每个分配的块。

【讨论】：

【解决方案2】：

一个可能的解决方案（就我而言）是使用-race 编译二进制文件，这样可以检查竞争条件。

这样做的开销是巨大的，如果使用htop 或类似的东西进行检查，看起来就像是大量内存泄漏，但不会显示在任何 pprof 输出中

【讨论】：