Go heap profile 明明分配了 126MB 却显示 0

CPU profile 看「时间花哪」，内存 profile 看「对象去哪」。我在给一个日志组装函数做 benchmark 时，-benchmem 给出 744 B/op 9 allocs/op。9 次分配，一个请求一次，QPS 上去之后就是每秒几万次分配。但 benchmem 只告诉我「有 9 次」，没告诉我「哪 9 次」。函数体就四行，光靠盯代码很难确定是哪一步在分配。

用 memory profile 跑一遍，list 把行号和字节数直接标出来。但更意外的是另一件事：写了个对照实验，两段代码分配的总字节数一模一样（126MB），其中一段在默认的 heap profile 里显示为 0。

三个基本判断

1. go tool pprof 打开 heap profile 时默认显示的那一栏（inuse_space），只能查内存泄漏，查不了 GC 压力。 大量「分配完就丢」的代码在这个视图里完全隐形，而它恰恰是多数 Go 服务真正的性能问题。
2. -benchmem 和 memory profile 不是同一件事。 前者是精确计数（ReadMemStats 差值），后者是 512KB 一次的抽样估算。两者对不上是正常的，实测差了 17%。
3. allocs/op 比 B/op 更值得优先优化。 分配次数决定 GC 扫描和 malloc 调用频率；字节数只决定单次成本。实测例子中字节降到 1/5.8，耗时降到 1/4.9 主要靠分配次数从 9 降到 1。

heap profile 记了什么

Go 的内存 profile 不是内存快照，是一张「分配点 → 分配量」的表。每个分配点是一个调用栈，每个调用栈挂了四个数字，在 pprof 里对应四个独立视图：

• inuse_space：当前还活着的对象占多少字节，用于查内存泄漏、常驻内存过大
• inuse_objects：当前还活着的对象个数，用于查小对象堆积
• alloc_space：程序启动至今累计分配了多少字节（含已被 GC 回收的），用于查 GC 压力、分配热点
• alloc_objects：累计分配的对象个数，用于查分配次数热点

heap profile 同时跟踪「所有存活对象的分配点」和「程序启动以来所有对象的分配点」，默认视图是 -inuse_space。

两个必须记住的点：

• heap profile 报告的是「最近一次已完成的 GC」时的状态，会故意忽略更近期的分配，避免数据偏向垃圾而不是存活对象。手写 profile 之前要先 runtime.GC()，否则最后那段代码干的事根本不在里面。
• runtime.MemProfile 的文档说明：返回的 profile 可能滞后最多两个 GC 周期。分配是实时发生的，释放要等 GC 清扫，只有给过 GC 一次机会的分配才算数。

容易混淆的一点：pprof.Lookup("heap") 和 pprof.Lookup("allocs") 采的是同一份数据，区别只有默认视图——heap 默认 inuse_space，allocs 默认 alloc_space。go test -memprofile 产出的是 allocs 那种。所以从 benchmark 里采出来的 profile，top 打开默认就是累计分配量；自己 WriteHeapProfile 采的，默认是存活量。

最小 Demo：一行日志的四种拼法

把一条访问日志的若干字段拼成一行文本。go1.23.3 下可直接运行。

package main

import (
    "fmt"
    "strings"
)

var fields = []string{
    "ts=2026-08-30T08:00:00Z", "level=info", "method=GET",
    "path=/api/v1/orders", "status=200", "cost=13ms",
    "trace=8f2c1d9e", "uid=100234", "ua=curl/8.7.1",
}

// buildConcat：字符串累加
func buildConcat(f []string) string {
    s := ""
    for _, x := range f {
        s += x + " "
    }
    return s
}

// buildSprintf：fmt.Sprintf
func buildSprintf(f []string) string {
    s := ""
    for _, x := range f {
        s = fmt.Sprintf("%s%s ", s, x)
    }
    return s
}

// buildBuilder：strings.Builder，没预分配
func buildBuilder(f []string) string {
    var b strings.Builder
    for _, x := range f {
        b.WriteString(x)
        b.WriteByte(' ')
    }
    return b.String()
}

// buildBuilderGrow：strings.Builder + 一次性 Grow
func buildBuilderGrow(f []string) string {
    n := 0
    for _, x := range f {
        n += len(x) + 1
    }
    var b strings.Builder
    b.Grow(n)
    for _, x := range f {
        b.WriteString(x)
        b.WriteByte(' ')
    }
    return b.String()
}

benchmark 部分（sink 是包级变量，防止编译器优化掉结果）：

package main

import "testing"

var sink string

func BenchmarkConcat(b *testing.B) {
    for i := 0; i < b.N; i++ {
        sink = buildConcat(fields)
    }
}

// BenchmarkSprintf / BenchmarkBuilder / BenchmarkBuilderGrow 同理

跑一下：从「9 次分配」到「第 19 行」

-count=5 的 benchmem 结果，五次数据几乎一致：

goos: darwin  goarch: arm64  cpu: Apple M4  go1.23.3
BenchmarkConcat-10          185.5 ns/op    744 B/op     9 allocs/op
BenchmarkSprintf-10         583.0 ns/op   1016 B/op    26 allocs/op
BenchmarkBuilder-10          80.1 ns/op    360 B/op     4 allocs/op
BenchmarkBuilderGrow-10      37.8 ns/op    128 B/op     1 allocs/op

两个立刻能用的结论：

• fmt.Sprintf 拼字符串是四种里最差的：比 += 还慢 3 倍，分配次数 26 次。每轮都要走格式化解析，还得把 s 和 x 装箱成 any 塞进 []any（go build -gcflags=-m 里能看到 s escapes to heap / x escapes to heap）。
• strings.Builder + Grow 是唯一做到 1 allocs/op 的写法：容量一次到位，中间不扩容。相比 += 快 4.9 倍、字节少 5.8 倍、分配次数少 9 倍。

回到最初的问题：那 9 次分配在哪？采一份 memory profile：

go test -run=^$ -bench=BenchmarkConcat -benchmem \
  -memprofile=mem_concat.prof -count=1

先 top 看总量：

$ go tool pprof -sample_index=alloc_space -top -nodecount=8 mem_concat.prof
Type: alloc_space
Showing nodes accounting for 4.73GB, 100% of 4.73GB total
       flat  flat%   sum%        cum   cum%
     4.73GB   100%   100%     4.73GB   100%  memdemo.buildConcat (inline)
          0     0%   100%     4.73GB   100%  memdemo.BenchmarkConcat

4.73GB 是 580 万次迭代累加的总量，不是常驻内存。这里要看的是「100% 都在 buildConcat」。

然后是最有用的一条命令，list：

$ go tool pprof -sample_index=alloc_space -list=buildConcat mem_concat.prof
Total: 4.73GB
ROUTINE ======================== memdemo.buildConcat in /tmp/memdemo/line.go
     4.73GB     4.73GB (flat, cum)   100% of Total
          .          .     16:func buildConcat(f []string) string {
          .          .     17:   s := ""
          .          .     18:   for _, x := range f {
     4.73GB     4.73GB     19:       s += x + " "
          .          .     20:   }
          .          .     21:   return s
          .          .     22:}

第 19 行，100%。 这一行里藏了两次分配：x + " " 生成一个临时字符串，s + 那个临时串 又生成一个新字符串。9 个字段循环 9 轮，每轮把之前拼好的内容整个复制一遍——典型的 O(n²) 内存行为。

list 的前提是有源码和符号信息。线上用 -ldflags="-s -w" 剥离过的话，list 只能给出空表，这点和 CPU profile 一样。

关键实验：同样 126MB，一个显示 0

两个模式，分配总字节数完全相同（2000 块 × 64KB = 128MB），区别只在分配出来的东西是否还活着。

package main

import (
    "flag"
    "fmt"
    "os"
    "runtime"
    "runtime/pprof"
)

const (
    blockSize = 64 * 1024 // 每块 64KB
    blocks    = 2000      // 2000 块 = 128MB
)

// cache：所有对象被全局变量引用，GC 收不掉
var cache [][]byte

func modeCache() {
    cache = make([][]byte, 0, blocks)
    for i := 0; i < blocks; i++ {
        b := make([]byte, blockSize)
        b[0] = byte(i)
        cache = append(cache, b)
    }
}

// sinkBuf 只为了让分配逃逸到堆上
var sinkBuf []byte

// churn：高频分配后立刻丢弃，总字节数和 modeCache 一样，但没人引用
func modeChurn() {
    for i := 0; i < blocks; i++ {
        b := make([]byte, blockSize)
        b[0] = byte(i)
        sinkBuf = b // 只保留最后一块
    }
    fmt.Fprintln(os.Stderr, "churn last block:", len(sinkBuf))
}

func main() {
    mode := flag.String("mode", "churn", "cache | churn")
    out := flag.String("out", "mem.prof", "heap profile 输出路径")
    flag.Parse()

    switch *mode {
    case "cache":
        modeCache()
    case "churn":
        modeChurn()
    default:
        fmt.Fprintln(os.Stderr, "unknown mode")
        os.Exit(1)
    }

    f, err := os.Create(*out)
    if err != nil {
        panic(err)
    }
    defer f.Close()

    // 必须先 GC。heap profile 报的是最近一次已完成的 GC 时的状态
    runtime.GC()
    if err := pprof.Lookup("heap").WriteTo(f, 0); err != nil {
        panic(err)
    }

    var ms runtime.MemStats
    runtime.ReadMemStats(&ms)
    fmt.Printf("mode=%s TotalAlloc=%dMB HeapAlloc=%dMB NumGC=%d\n",
        *mode, ms.TotalAlloc>>20, ms.HeapAlloc>>20, ms.NumGC)
}

sinkBuf 是第一版漏写的坑：第一次跑出来 TotalAlloc=1MB，profile 里两个视图全是 0。逃逸分析发现 b 没离开函数，直接放栈上了，压根没进堆。这说明内存优化很多时候是在跟逃逸分析打配合，-gcflags=-m 该常备。

两个模式的运行时统计：

$ ./memdemo -mode=churn -out=churn.prof
mode=churn  TotalAlloc=126MB  HeapAlloc=1MB    NumGC=46

$ ./memdemo -mode=cache -out=cache.prof
mode=cache  TotalAlloc=126MB  HeapAlloc=126MB  NumGC=7

四个 profile 视图的对照：

churn 模式实打实分配了 126MB、触发了 46 次 GC，而 go tool pprof 默认打开的 inuse_space 给出的答案是 0。抓了 profile 一看「啥都没有，内存挺干净」，就直接错过了真正的问题。

churn 的 GC 次数是 cache 的 6.5 倍。原因不难理解：Go 默认 GOGC=100，堆增长到上次存活量的两倍就触发 GC。churn 的存活堆一直只有 1MB 左右，GC 触发阈值也一直很小，126MB 的分配量被切成 46 次 GC。cache 的堆一路往上涨，阈值跟着涨，反而只 GC 了 7 次。

「堆小」不等于「GC 轻松」。 一个稳定在 50MB、但每秒分配 2GB 的服务，GC 比一个占 4GB、几乎不分配的服务累得多。

操作习惯：拿到 heap profile，先看 alloc_space 和 alloc_objects，再看 inuse_*。前者回答「谁在给 GC 加班」，后者回答「谁把内存吃住不放」。前者靠复用（sync.Pool、预分配、Builder）和减少逃逸，后者靠淘汰策略和及时释放引用。

512KB 抽样：为什么 9 变成了 10.5

TotalAlloc 是 126MB，profile 的 alloc_space 是 138.29MB，多了 10%。

memory profile 是抽样的。runtime.MemProfileRate 默认值 512 * 1024，官方定义是「平均每分配 512KB 采一次样」。采到之后 pprof 按采样率反推总量，所以看到的 alloc_space 是估算值。

在 alloc_objects 上误差更明显。默认采样率下：

alloc_objects = 61,475,422   迭代次数 = 5,846,364 → 平均 10.5 objects/op

-benchmem 给的是 9 allocs/op，差了 17%。

-benchmem 对。它用 runtime.ReadMemStats 的前后差值，精确计数；profile 是抽样估算。

把采样率调成 1（每次分配都记）：

go test -run=^$ -bench=BenchmarkConcat -benchmem \
  -memprofile=mem_exact.prof -memprofilerate=1 -benchtime=200000x

结果：

alloc_objects = 1,800,009   迭代次数 = 200,000 → 9.000045 objects/op

和 benchmem 完全吻合。代价也很直接：

默认采样率：       BenchmarkConcat-10    182.6 ns/op
memprofilerate=1： BenchmarkConcat-10   5722 ns/op   ← 慢了 31 倍

这个开销在本机调试时无所谓，生产环境开就是自杀。官方文档提醒：分析工具假定采样率在程序生命周期内恒定，要改就在 main 开头改一次，别中途来回调。

实际用法：定位「哪个函数在分配」用默认采样率就够了；只有需要精确核对分配次数、排查特别稀疏的小对象分配时，才在本地临时开 -memprofilerate=1。

生产环境怎么做

• 服务里用 net/http/pprof，别自己写文件。 import _ "net/http/pprof" 之后，go tool pprof http://host:port/debug/pprof/heap 直接远程抓，不改业务代码、不重启。想要 profile 前先触发一次 GC，加参数 /debug/pprof/heap?gc=1。
• pprof 端口不能暴露公网。 调用栈、内存布局、goroutine 全在里面。单独 mux、绑内网、加鉴权，或只允许跳板机访问。
• 查内存增长用两份 profile 做差，不要只看一份。 go tool pprof -base old.prof new.prof 才能看出「这半小时里新长出来的是什么」。排查缓慢泄漏最有效的招。
• /debug/pprof/heap?seconds=30 直接给一份 delta profile。 官方文档写明 seconds=N 对 allocs / block / goroutine / heap / mutex / threadcreate 生效，返回增量。省掉自己抓两份再 -base 的步骤，排查「正在涨」的内存很顺手。
• inuse_space 一直涨但找不到大对象时，看 inuse_objects。 大量小对象（没关的 time.Timer、堆积的 map key）总字节不显眼但个数惊人，同时拖高 GC 扫描时间。
• 别把 sync.Pool 当万能解药。 它适合「同一类对象高频创建销毁、生命周期短且明确」的场景。乱用会让对象活得比预期长，inuse_space 反而涨，还会引入「拿到的对象带着上次的脏数据」这类难查的 bug。上手前先用 alloc_objects 确认这真是个分配热点。
• 配合 GODEBUG=gctrace=1 一起看。 profile 告诉你「谁在分配」，gctrace 告诉你「GC 到底累不累、STW 多长」。churn 例子里光看 profile 的 inuse 什么也发现不了，但 gctrace 里 46 次 GC 一目了然。

常见错误

// 错误 1：写 heap profile 之前不 GC
pprof.WriteHeapProfile(f)   // ✗ 报告的是上一次 GC 时的状态

// 正确：先拿到最新统计
runtime.GC()
pprof.WriteHeapProfile(f)

• 错误 2：以为 alloc_space 是「当前内存占用」。 它是程序启动至今的累计分配，跑够久就是几十 GB，跟常驻内存没关系。
• 错误 3：拿抽样估算的 alloc_objects 去跟 benchmem 的 allocs/op 对账。 默认 512KB 采样，对不上是正常的。
• 错误 4：在生产环境常开 memprofilerate=1。 实测慢 31 倍。

两个不算错误但很浪费时间的事：

• 只看 top 不用 list。top 告诉你是哪个函数，list 才告诉你是哪一行。函数一长，光知道函数名基本等于没定位。
• 忘了 defer f.Close()，或 profile 没写完程序就退了，最后拿到残缺文件，pprof 解析报错还以为是工具问题。

理解

Go 的内存问题粗分成两类，对应两套不同的动作：

• 常驻内存过高 / 缓慢泄漏 → 看 inuse_space / inuse_objects，用 -base 做差分，找「谁在把引用攥着不放」。典型元凶：无淘汰的全局 map、忘了关的资源、goroutine 泄漏顺带拖住栈上引用的对象。
• GC 占用 CPU 过高 / 延迟抖动 → 看 alloc_space / alloc_objects，找「谁在疯狂产生垃圾」。典型元凶是一行 += 或顺手一个 fmt.Sprintf。

这两类问题在默认视图里的表现天差地别——第二类甚至能显示成 0。默认值是给「查泄漏」场景准备的，但日常遇到「分配太多」的频率远高于「泄漏」。优化优先级：先减分配次数，再减分配字节。前者用 alloc_objects 定位，后者用 alloc_space 定位。多数情况下，次数降下来字节数也会跟着降——因为每次分配通常带着固定开销和扩容冗余。