Golang中Alloc和HeapAlloc与pprof存在明显差异

Question

我有一个Go程序，用于在内存中计算大型相关矩阵。为此，我设置了三个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

我想知道如何找出程序为什么会分配17GB内存，当峰值内存使用量似乎只有~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()
}

- Gronnesby

---

运行时不一定能够仅分配最小所需内存。您如何确定峰值使用情况？在程序运行时，gctrace输出显示堆所需的内容是什么？ - JimB

可能与最近解决的问题[30333]（https://github.com/golang/go/issues/30333）有关：“...内存的暂时性峰值导致Go运行时增加堆大小，但需要很长时间（大约几分钟）才能将不需要的内存返回给系统...”。 - Mark

@JimB，我不介意运行时分配比所需更多的内存，但额外的约14 GB似乎有点过度了。我已经使用pprof.WriteHeapProfile()来跟踪内存使用情况，但正如您所看到的那样，它并没有提供太多帮助。这让我相信我要么没有正确使用它，要么误解了它的能力。 - Gronnesby

@Gronnesby：这就是为什么我提到了 gctrace，它将显示与垃圾收集器目标相关的堆分配情况。另外确保您正在使用 go1.12.5。 - JimB

Go语言的性能分析工具是采样分析器，因此它不是绝对的度量标准，而是用于相互比较。你可以增加MemProfileRate参数的值，看看是否有助于缩小问题范围。你还可以为各个组件编写基准测试，并使用-benchmem参数查看内存分配情况。 - JimB

将MemProfileRate=1设置似乎有效。现在，在以前被省略的pprof配置文件中列出了其他附加函数。 - Gronnesby

Answer 1

如JimB在评论中提到的，Go语言的性能分析工具是一种采样分析器，只会在特定时间间隔采集内存使用情况。在我的情况下，采样率不够高，无法检测出大量内存使用的函数（例如JSON序列化）。

通过设置环境变量来增加分析器的采样频率： $ export GODEBUG=memprofilerate=1 这将更新runtime.MemProfileRate，并且现在每个已分配的块都包括在分析结果里。

- Gronnesby

Answer 2

一个可能的解决方案（就像在我的情况下一样）是二进制文件是使用-race编译的，这启用了竞争条件检查。

这个开销是巨大的，如果使用htop或类似的工具进行检查，它会看起来像一个大规模的内存泄漏，但不会显示在任何pprof输出中。

- Brian Leishman