golang 内存泄漏分析案例
1. 前言
关于内存泄漏的情形已经在之前文章总结过了,本文将讨论如何发现内存泄漏。
2. 怎么发现内存泄露
在Go中发现内存泄露有2种方法,一个是通用的监控工具,另一个是go pprof:
2.1. 监控工具
定周期对进程的内存占用情况进行采样,数据可视化后,根据内存占用走势(持续上升),很容易发现是否发生内存泄露。
例如:pidstat命令查看进程内存情况:
#!/bin/bash
prog_name="your_programe_name"
prog_mem=$(pidstat -r -u -h -C $prog_name |awk 'NR==4{print $12}')
time=$(date"+%Y-%m-%d %H:%M:%S")
echo$time"\tmemory(Byte)\t"$prog_mem >>~/record/prog_mem.log
2.2. pprof
使用Go提供的pprof工具判断分析是否发生内存泄露。
3.Pprof 性能分析工具
3.1.简介
Pprof是Go的性能工具,在程序运行过程中,可以记录程序的运行信息,可以是CPU使用情况、内存使用情况、goroutine运行情况等,当需要性能调优或者定位Bug时候,这些记录的信息是相当重要。
当然网上有人罗列了一些问题:
- 内存profiling记录的是堆内存分配的情况,以及调用栈信息,并不是进程完整的内存情况,猜测这也是在go pprof中称为heap而不是memory的原因。
- 栈内存的分配是在调用栈结束后会被释放的内存,所以并不在内存profile中。
- 内存profiling是基于抽样的,默认是每1000次堆内存分配,执行1次profile记录。
- 因为内存profiling是基于抽样和它跟踪的是已分配的内存,而不是使用中的内存,(比如有些内存已经分配,看似使用,但实际以及不使用的内存,比如内存泄露的那部分),所以不能使用内存profiling衡量程序总体的内存使用情况。
- 使用内存profiling不能够发现内存泄露。
总结:
- heap能帮助我们发现内存问题,但不一定能发现内存泄露问题,heap记录了内存分配的情况,我们能通过heap观察内存的变化,增长与减少,内存主要被哪些代码占用了,程序存在内存问题,这只能说明内存有使用不合理的地方,但并不能说明这是内存泄露。
- heap在帮助定位内存泄露原因上贡献的力量微乎其微。如第一条所言,能通过heap找到占用内存多的位置,但这个位置通常不一定是内存泄露,就算是内存泄露,也只是内存泄露的结果,并不是真正导致内存泄露的根源。
3.2.pprof使用方式
- runtime/pprof
主要应用于工具型应用。包含脚本、定时任务等。
如:对于只跑一次的程序,例如每天只跑一次的离线预处理程序,调用 pprof 包提供的函数,手动开启性能数据采集
- net/http/pprof
主要应用于服务型应用。包含HTTP服务,GRPC服务等。
如:对于在线服务,对于一个 HTTP Server,访问 pprof 提供的 HTTP 接口,获得性能数据。当然,实际上这里底层也是调用的 runtime/pprof提供的函数,封装成接口对外提供网络访问。
服务器一般采用net/http/pprof,本文以net/http/pprof作为实例
3.3.net/http/pprof使用
使用pprof有多种方式,Go已经现成封装好了1个:net/http/pprof,使用简单的几行命令,就可以开启pprof,记录运行信息,并且提供了Web服务,能够通过浏览器和命令行2种方式获取运行数据。
看个最简单的pprof的例子
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
)
func main() {
// 开启pprof,监听请求
ip := "0.0.0.0:6060"
if err := http.ListenAndServe(ip, nil); err != nil {
fmt.Printf("start pprof failed on %s\n", ip)
}
}
3.3.1.浏览器方式
浏览器打开http://localhost:6060/debug/pprof/
可以看到9类profile信息:
- allocs:程序启动之后内存分配的情况
- block:导致阻塞操作的一些堆栈跟踪信息
- cmdline:当前程序启动的命令行
- goroutine:所有goroutine的信息,下面的full goroutine stack dump是输出所有goroutine的调用栈,是goroutine的debug=2,后面会详细介绍。
- heap:程序在当前堆上内存分配的情况
- mutex:锁的信息
- profile: CPU profile文件。可以在 debug/pprof?seconds=x秒 GET 参数中指定持续时间。获取pprof文件后,使用 go tool pprof x.prof命令分析pprof文件。
- threadcreate:线程信息
- Trace:当前系统的代码执行的链路情况
3.3.2.命令行方式
# 下载allocs profile
go tool pprof http://localhost:6060/debug/pprof/allocs
# 下载block profile
go tool pprof http://localhost:6060/debug/pprof/block# goroutine blocking profile
# 下载goroutine profile
go tool pprof http://localhost:6060/debug/pprof/goroutine # goroutine profile
# 下载heap profile
go tool pprof http://localhost:6060/debug/pprof/heap # heap profile
# 下载mutex profile
go tool pprof http://localhost:6060/debug/pprof/mutex
# 下载cpu profile,默认从当前开始收集30s的cpu使用情况,需要等待30s
go tool pprof http://localhost:6060/debug/pprof/profile # 30-second CPU profile
go tool pprof http://localhost:6060/debug/pprof/profile?seconds=120 # wait 120s
# 下载threadcreate profile
go tool pprof http://localhost:6060/debug/pprof/threadcreate
# 如果需要下载对应的图片,只需要在后面添加png即可,例如获取heap的图片
go tool pprof -png http://localhost:6060/debug/pprof/heap > heap.png
4.Pprof 分析内存增长
4.1.代码实例
展示内存增长和pprof,并不是内存泄漏
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"os"
"time"
)
func main() {
// 开启pprof
go func() {
ip := "0.0.0.0:6060"
if err := http.ListenAndServe(ip, nil); err != nil {
fmt.Printf("start pprof failed on %s\n", ip)
os.Exit(1)
}
}()
tick := time.Tick(time.Second)
var buf []byte
stime := time.Now()
for range tick {
// 1秒1M内存
buf = append(buf, make([]byte, 1024*1024)...)
fmt.Printf("%f\n", time.Now().Sub(stime).Seconds())
}
}
4.2.查看heap内存图片
go tool pprof -png http://localhost:6060/debug/pprof/heap > heap.png
跟top一样,可以跟踪到main函数,哪一行无法知道了
4.2.查看profile CPU图片
go tool pprof -png http://localhost:6060/debug/pprof/profile > profile.png
cpu看不出啥
4.4.直接heap分析当前的内存
可以看到当前的heap主要内存就在27行
可以看到27行内存堆积
4.5.使用base能够对比两个profile文件的差别
就像diff命令一样显示出增加和减少的变化
1).跑一下heap:go tool pprof http://localhost:6060/debug/pprof/heap
可以看到产生了一个文件:/Users/qicycle/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
2).过一伙再跑一下heap:go tool pprof http://localhost:6060/debug/pprof/heap
可以看到又产生了一个文件:/Users/qicycle/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
3).我已经获取到了两个profile文件:
4)使用base把001文件作为基准,然后用002和001对比,先执行top看top的对比,然后执行list main列出main函数的内存对比,结果如下:
go tool pprof -base pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
通过list main.main 可以看到内存就是在27行的地方不停的增长的:
可以确认27行导致内存增长
5.Pprof 分析goroutine泄漏
5.1.代码实例
每1秒创建一个goroutine,每个goroutine分配1M内存,本来内存在goroutine退出以后会自动释放,不存在泄漏的问题,但是由于outCh只有写入没有读取导致channel写入阻塞,整个goroutine也阻塞在37行,进而导致对应分配的内存没有释放,形成内存泄漏
goroutine泄漏导致内存泄漏
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"os"
"time"
)
func main() {
go func() {
ip := "0.0.0.0:6060"
if err := http.ListenAndServe(ip, nil); err != nil {
fmt.Printf("start pprof failed on %s\n", ip)
os.Exit(1)
}
}()
outCh := make(chan int)
stime := time.Now()
// 每1s个goroutine
for {
time.Sleep(1 * time.Second)
go alloc(outCh)
fmt.Printf("last: %dseconds\n", int(time.Now().Sub(stime).Seconds()))
}
}
// alloc分配1M内存,goroutine会阻塞,不释放内存,导致泄漏
func alloc(outCh chan<- int) {
buf := make([]byte, 1024*1024*1)
_ = len(buf)
fmt.Println("alloc make buffer done")
outCh <- 0 // 37行
fmt.Println("alloc finished")
}
5.2. 查看goroutine图片
go tool pprof -png http://localhost:6060/debug/pprof/goroutine > goroutine.png
看出有28个goroutine累积了
5.3.查看heap图片
go tool pprof -png http://localhost:6060/debug/pprof/heap > heap.png
可以看到malloc占用的大量内存
5.4.heap“不能”定位内存泄露
Goroutine直接使用前面的heap就无法分析出内存泄漏的地方了,从前面的图片也能看出来
该goroutine只调用了少数几次,但消耗了大量的内存,说明每个goroutine调用都消耗了不少内存,内存泄露的原因基本就在该协程内部
Goroutine泄露,这是通过heap无法发现的,所以heap在定位内存泄露这件事上,发挥的作用不大。
5.5.使用base能够对比两个goroutine profile文件的差别
就像diff命令一样显示出增加和减少的变化
1)跑一下goroutine:go tool pprof http://localhost:6060/debug/pprof/goroutine
可以看到产生了一个文件:/Users/qicycle/pprof/pprof.goroutine.001.pb.gz
2).过一伙再跑一下goroutine:go tool pprof http://localhost:6060/debug/pprof/goroutine
可以看到又产生了一个文件: /Users/qicycle/pprof/pprof.goroutine.004.pb.gz
3)使用base把001文件作为基准,然后对比,结果如下:
go tool pprof -base pprof.goroutine.001.pb.gz pprof.goroutine.004.pb.gz
可以看到多了247个goroutine
5.6.查看goroutine数量
go tool pprof http://localhost:6060/debug/pprof/goroutine
可以看到goroutine很多,有610个了
显示有610个goroutine被挂起,这不是goroutine泄露这是啥?已经能确定八九成goroutine泄露了。
是什么导致如此多的goroutine被挂起而无法退出?接下来就看怎么定位goroutine泄露。
5.7.定位goroutine泄露的2种方法
Web可视化和命令行查看
5.7.1.Web可视化查看debug=1
http://localhost:6060/debug/pprof/goroutine?debug=1
可以看到有1038个协程师阻塞在37行
原因就是:阻塞的原因是outCh这个写操作无法完成,outCh是无缓冲的通道,并且由于以下代码是死代码,所以goroutine始终没有从outCh读数据,造成outCh阻塞,进而造成无数个alloc2的goroutine阻塞,形成内存泄露:
5.7.2.Web可视化查看debug=2
http://localhost:6060/debug/pprof/goroutine?debug=2
第2种方式和第1种方式是互补的,它可以看到每个goroutine的信息:同时,也可以看到调用栈,看当前执行停到哪了:main_pprof_me.go的37行
5.7.3.命令行traces+list查看
命令行只需要掌握3个命令就好了,上面介绍过了,详细的倒回去看top, list, traces:
- top:显示正运行到某个函数goroutine的数量
- traces:显示所有goroutine的调用栈
- list:列出代码详细的信息。
看traces命令,traces能列出goroutine的调用栈,有1456个goroutine都执行这个调用路径,可以看到main.alloc阻塞挂起了goroutine,使用list列出main.alloc的代码,显示有1549个goroutine阻塞在37行:
至此goroutine泄漏分析完成