Go程序性能分析：pprof从入门到生产问题定位

前言

写Go两年多，pprof一直是"知道但没深入用过"的状态。直到三个月前，一个服务内存从2G慢慢涨到8G，然后OOM被杀，周而复始。常规手段都试了，就是找不到泄漏点。

被逼无奈，花了两天时间把pprof彻底搞明白。那次排查下来，我才发现这工具的威力——不只是找内存泄漏，CPU热点、阻塞分析、协程泄漏，全都能搞定。

这篇文章把我踩的坑和总结的经验分享出来，希望能帮到同样在用Go的朋友。

pprof是什么

pprof是Go自带的性能分析工具，可以采集运行中程序的各种profile数据：

• CPU Profile：CPU时间花在哪些函数上
• Heap Profile：内存分配情况，谁在消耗内存
• Goroutine Profile：协程状态，有没有泄漏
• Block Profile：阻塞分析，哪里在等锁
• Mutex Profile：锁竞争分析

两种使用方式：

1. runtime/pprof：程序内部调用，适合工具类程序
2. net/http/pprof：HTTP接口暴露，适合长期运行的服务

生产环境基本都用HTTP方式，随时可以拉取profile数据。

快速接入

往服务里加几行代码就行：

packagemainimport("net/http"_"net/http/pprof"// 匿名导入，自动注册路由)funcmain(){// 单独起一个端口给pprof，别和业务混在一起gofunc(){http.ListenAndServe(":6060",nil)}()// 业务代码...}

如果用了gin或者echo这类框架，需要手动注册：

// Gin框架import"github.com/gin-contrib/pprof"funcmain(){r:=gin.Default()pprof.Register(r)// 注册pprof路由r.Run(":8080")}

启动后访问http://localhost:6060/debug/pprof/就能看到profile列表。

实战一：CPU热点分析

前段时间接手一个服务，QPS上不去，CPU先到100%了。用pprof定位：

# 采集30秒CPU profilego tool pprof http://localhost:6060/debug/pprof/profile?seconds=30

进入交互式界面后：

(pprof) top 20 Showing nodes accounting for 28.5s, 89.2% of 31.95s total flat flat% sum% cum cum% 12.30s 38.50% 38.50% 12.30s 38.50% encoding/json.(*decodeState).scanWhile 5.20s 16.27% 54.77% 5.20s 16.27% runtime.memmove 3.10s 9.70% 64.47% 15.40s 48.20% encoding/json.(*decodeState).object 2.80s 8.76% 73.23% 2.80s 8.76% runtime.mallocgc

38.5%的时间在json.scanWhile？这个函数是标准库JSON解析的核心函数。继续看调用链：

(pprof) list scanWhile

发现是一个接口每次请求都在解析一个2MB的配置文件。这配置明明可以启动时加载一次的。

改完之后CPU直接降了40%，QPS翻倍。

火焰图更直观

命令行看不直观，生成火焰图：

# 采集profile并用web打开go tool pprof -http=:8080 http://localhost:6060/debug/pprof/profile?seconds=30

浏览器自动打开，点VIEW -> Flame Graph，宽度就是时间占比，一眼就能看出哪个函数是大头。

实战二：内存泄漏排查

这是我被坑最惨的一次。服务内存持续增长，几个小时就OOM。

先看当前内存分配情况：

go tool pprof http://localhost:6060/debug/pprof/heap

(pprof) top Showing nodes accounting for 2.1GB, 95.2% of 2.2GB total flat flat% sum% cum cum% 1.50GB 68.18% 68.18% 1.50GB 68.18% bytes.makeSlice 0.35GB 15.91% 84.09% 0.35GB 15.91% github.com/xxx/cache.(*LRU).Add 0.25GB 11.36% 95.45% 0.25GB 11.36% bufio.NewReaderSize

1.5G在bytes.makeSlice，但这只是分配的位置，不是根因。用-alloc_space看累计分配：

go tool pprof -alloc_space http://localhost:6060/debug/pprof/heap

(pprof) top flat flat% sum% cum cum% 150GB 45.2% 45.2% 150GB 45.2% bytes.makeSlice 89GB 26.8% 72.0% 89GB 26.8% github.com/xxx/cache.(*LRU).Add

150GB累计分配？程序才跑了几小时。看调用链：

(pprof) tree bytes.makeSlice

顺着调用链往上找，发现是一个HTTP客户端没有关闭Response Body：

// 问题代码resp,err:=http.Get(url)iferr!=nil{returnerr}// 没有 resp.Body.Close()，连接不会被复用，buffer一直累积data,_:=ioutil.ReadAll(resp.Body)

经典错误。加上defer close之后，内存稳定在500MB。

对比两次heap快照

更精准的方法是对比两个时间点的heap：

# 第一次采集curlhttp://localhost:6060/debug/pprof/heap>heap1.out# 等一段时间，第二次采集curlhttp://localhost:6060/debug/pprof/heap>heap2.out# 对比差异go tool pprof -base heap1.out heap2.out

这样能看到这段时间内净增加的内存分配，排除启动时的正常分配干扰。

实战三：协程泄漏

有一次服务响应越来越慢，CPU内存都正常，但协程数从几百涨到了几万。

go tool pprof http://localhost:6060/debug/pprof/goroutine

(pprof) top Showing nodes accounting for 32156, 99.8% of 32210 total flat flat% sum% cum cum% 32100 99.66% 99.66% 32100 99.66% runtime.gopark 56 0.17% 99.83% 56 0.17% runtime.netpollblock

3万多协程在gopark（等待状态），看具体在等什么：

(pprof) traces runtime.gopark

找到了：

32100 runtime.gopark runtime.chanrecv1 github.com/xxx/worker.(*Pool).dispatch

原来是worker pool里的协程在等channel，但生产者已经退出了，没人发消息，这些协程就永远等下去。

问题代码：

func(p*Pool)Start(){fori:=0;i<p.size;i++{gofunc(){fortask:=rangep.taskChan{// 如果channel没close，这里永远阻塞task.Run()}}()}}

Pool退出时没close channel，修复：

func(p*Pool)Stop(){close(p.taskChan)// 关闭channel，所有worker协程会退出}

实战四：锁竞争分析

有个服务QPS死活上不去，CPU只用了30%。怀疑是锁竞争。

需要先开启mutex profiling（默认关闭）：

runtime.SetMutexProfileFraction(1)// 采样率，1表示全采集

然后采集：

go tool pprof http://localhost:6060/debug/pprof/mutex

(pprof) top flat flat% sum% cum cum% 5.2s 78.5% 78.5% 5.2s 78.5% sync.(*RWMutex).Lock 1.1s 16.6% 95.1% 1.1s 16.6% sync.(*Mutex).Lock

78%的时间在等RWMutex，定位到代码：

varcache sync.Map// 本来用的sync.Mapvarmu sync.RWMutexvardatamap[string]interface{}// 被改成了这样，读也要抢锁funcGet(keystring)interface{}{mu.RLock()defermu.RUnlock()returndata[key]}

之前用sync.Map没问题，有人重构的时候改成了普通map+RWMutex，高并发下读锁也成了瓶颈。改回sync.Map，QPS立马上去了。

生产环境注意事项

1. 安全隔离

pprof端口别暴露到公网，内网也要加认证：

import"net/http/pprof"funcmain(){mux:=http.NewServeMux()// 加个简单的认证mux.HandleFunc("/debug/pprof/",func(w http.ResponseWriter,r*http.Request){ifr.Header.Get("X-Pprof-Token")!="your-secret-token"{http.Error(w,"Forbidden",403)return}pprof.Index(w,r)})gohttp.ListenAndServe(":6060",mux)}

2. 采集开销

• Heap profile：几乎无开销，随便采
• CPU profile：有开销，别采太久，30秒足够
• Mutex/Block profile：需要设置采样率，别设成1，用100或1000

3. 批量排查

多个实例排查时，我一般用星空组网把测试环境和线上机器串起来，本地直接访问任意实例的pprof端口，不用一台台跳。

4. 常用命令速查

# CPU分析go tool pprof http://host:port/debug/pprof/profile?seconds=30# 内存分析（当前在用）go tool pprof http://host:port/debug/pprof/heap# 内存分析（累计分配）go tool pprof -alloc_space http://host:port/debug/pprof/heap# 协程分析go tool pprof http://host:port/debug/pprof/goroutine# 阻塞分析go tool pprof http://host:port/debug/pprof/block# 锁分析go tool pprof http://host:port/debug/pprof/mutex# 直接打开web界面go tool pprof -http=:8080[profile文件或URL]

交互命令：

• top：显示资源占用最高的函数
• list 函数名：显示函数源码和每行的资源占用
• tree：显示调用树
• web：生成SVG在浏览器打开
• traces：显示调用栈

搭配其他工具

配合trace分析延迟

pprof是采样的，看不到具体的请求延迟分布。这时候用trace：

import"runtime/trace"f,_:=os.Create("trace.out")trace.Start(f)defertrace.Stop()

go tool trace trace.out

能看到每个协程的时间线，GC暂停时间，调度延迟等。

配合benchmark

写benchmark时自动采集profile：

gotest-bench=. -cpuprofile=cpu.out -memprofile=mem.out go tool pprof cpu.out

总结

pprof用熟了，Go程序的性能问题基本都能定位到：

1. CPU高：采CPU profile，找热点函数
2. 内存涨：采heap profile，对比两次快照找增量
3. 响应慢：先看协程数，再看锁竞争
4. 协程泄漏：看goroutine profile，找阻塞点

这工具是Go的标配，开销小、信息全，没理由不用。每个Go服务都应该把pprof端口开着，出问题时能第一时间采集现场。

建议新项目直接把pprof加进去，别等出了问题再临时加——那时候可能已经OOM重启了，现场都没了。