记一次内存泄漏的解决
内存泄漏
内存泄漏(Memory Leak)是指程序中已动态分配的堆内存由于某种原因程序未释放或无法释放,造成系统内存的浪费,导致程序运行速度减慢甚至内存溢出,系统崩溃等严重后果。
在Go语言服务中,内存泄漏的大多数原因是goroutine泄露。
问题发现
在巡检过程中忽然发现某个服务模块服务的内存疯涨,刚刚部署时候很小,过了两个月左右达到了惊人的200倍左右,继续增长下去的结果就是内存溢出导致该服务的pod重启(该服务使用k8s的deploy部署)。需要排查一下泄露问题出在哪里,于是在本地自己模拟了一套逻辑相似的环境(自测用的,模拟了一个简单场景)。
pprof工具
pprof 是一个强大的性能分析工具,可以捕捉到多维度的运行状态的数据,便于排查程序的堆栈信息,goroutine分布等。
排查过程
1、程序中添加pprof工具
首先在程序添加监听端口,如下:
然后导入pprof包:
2、启动程序
访问本地端口6060(主要关注goroutine数量)
3、使用goTest发起请求
这里模拟了20个并发量,一次请求。
4、使用pprof查看样本数据
可以看到在请求结束之后,goroutine数量依然存在,并没有被回收。
猜测原因:大量goroutine滞留导致栈空间没有被释放(影响较小),goroutine没有被释放,goroutine指向的heap一系列对象没有被回收掉,heap越用越多,持续申请内存造成内存持续异常增长,也就是内存泄漏。
点击goroutine查看详细信息:
可以看到有四种类型的goroutine栈居高不下,grpc的出现率很高,猜测是在发起请求时创建的grpc连接没有释放掉。
gRpc的源码不必追溯,也没有完整的调用栈信息,作为一个rpc库,已经封装了关闭请求流的方法。应该关注引用的它库的位置,看看是否在应用层有暴露出来的关闭流的方法。
选择从该处向上追溯,首先定位到该处的源码:
每次的请求在该处都会阻塞住,是否需要在该处上游有一个释放信号,将该context构造的goroutine树释放掉。
一路向上追溯源码(不详述),看到一个在应用层结构体实现了close方法,点到close方法,可以看到该方法可以释放连接与缓存。于是在应用层找到合适的位置调用了close方法。
再次发起模拟请求,查看pprof工具:
可以看到协程数量恢复如初,业务正常没受影响,初步猜测是该处的原因。接下来各种业务验证不详述...
5、并发测试进程memory
继续单元测试。
创建20个协程,每个协程100个请求,中间休眠一秒(为了防止速度太快脚本无法记录)。
监控脚本一览:
#!/bin/bash
read -p "输入进程的id:" processId
while [ 1 ]
do
#每隔五秒读一次进程内存,看结束之后内存情况
ProcessMem=`cat /proc/$processId/status |grep VmRSS|awk '{print $2,$3}'`
DateTime=` date "+%H:%M:%S"`
echo $DateTime "| 进程内存:"$ProcessMem >> noclose-process-mem.txt
sleep 5s
done
6、测试结果
不关闭流:
内存情况(脚本统计):16M -> 822M,相当大
贴出来一部分脚本统计数据:
09:33:11 | 进程内存:16580 kB
09:33:16 | 进程内存:16580 kB
09:33:21 | 进程内存:16580 kB
09:33:26 | 进程内存:16580 kB
09:33:31 | 进程内存:16580 kB #发起请求,内存开始暴涨
09:33:36 | 进程内存:44324 kB
09:33:41 | 进程内存:74400 kB
09:33:46 | 进程内存:98708 kB
09:33:51 | 进程内存:122612 kB
09:33:56 | 进程内存:147912 kB
.....
10:05:57 | 进程内存:822224 kB #请求结束慢慢恢复稳定
10:06:12 | 进程内存:822488 kB
10:06:17 | 进程内存:822488 kB
......
10:06:47 | 进程内存:822488 kB
10:06:52 | 进程内存:822488 kB
10:06:57 | 进程内存:822488 kB#之后内存并没有缩小
查看一下goroutine:
关闭流:
内存统计:16M -> 44M(优化了80%左右,请求时间也缩短)
每次请求关闭流:
09:25:44 | 进程内存:16496 kB#初始内存----往下表示发起请求,内存开始增长
09:25:49 | 进程内存:35948 kB
09:25:54 | 进程内存:41320 kB
09:25:59 | 进程内存:41776 kB
......
09:29:24 | 进程内存:43976 kB#逐渐趋于稳定
09:29:29 | 进程内存:43976 kB
09:29:34 | 进程内存:43976 kB
09:29:39 | 进程内存:44180 kB#已经稳定在44M
09:29:44 | 进程内存:44180 kB
7、再次定位
定位到问题,虽然上述方法可以解决内存泄露的问题,但是并没有选择这种方式,因为和最初的设计模式相悖,最初针对这块设计模式是单例模式。
之后又是抓耳挠腮的读代码,调试,终于发现问题所在.......
查看一波自己写的该部分代码:
/*源代码不能泄露,这是本地自己编写的代码,大概逻辑类似*/
func GetClient(userName string) *Client{
//先在缓存读,读不到就new,存map
key := userName
//从map中获取,该map是sync.map,并发安全
value, ok := Map.Load(key)
if ok{
fmt.Println("读syncmap")
return value.(*Client)
}
client := newClient(userName)
Map.Store(key,client)
return client
}
发现客户端作为单例对象,不是线程安全的,没有并发控制机制,当初始遇到并发请求时候,就会创建大量的客户端,请求结束无法释放,导致程序中大量无感的客户端占用内存。
最终解决方法:既然不是线程安全,加个锁。
/*本地模拟的代码*/
func GetClient(userName string) *Client{
//加锁保证线程安全
lock.Lock()
defer lock.UnLock()
key := userName
value, ok := Map.Load(key)
if ok{
fmt.Println("读syncmap")
return value.(*Client)
}
client := newClient(userName)
Map.Store(key,client)
return client
}
果断修改调试.....
等待一天后......
goroutine数虽然有所减少还是让人抓狂,陷入自我怀疑
猜测问题是不是出在map里面,开始一波针对性的检查。
终于又发现问题:
首先,map在清理的时候没有释放掉里面的连接(在第一种方案时候就定位到了)。
map清理的定期时间是可配的,读取配置文件出错没有异常处理,使用了默认值(默认值很小)。
完成问题定位,最终修改完成,调试,内存虽然有增长,但是要优化了很多。
问题解决
这次问题的解决并不是一帆风顺,这个泄露问题是好多点综合作用的结果,期间还有很多繁琐的点,要复现某个泄露的点真的很让人头大,pprof显示的所有泄露的点调用栈都在引用的库源码里,和网上的定位文章一点不一样,算是在摸索着前进。最终主要的优化方式就是上述两种方式。选择了后者,最初设计是不能乱改的嘛,不过正因为这次问题出现,对Golang有了更深层的了解。
也得到一点经验教训:
一定要在测试机上仔细检查,业务验证同时要关注服务的内存与CPU。
goroutine泄露的点主要发生在channel的阻塞上。
对于Golang错误处理留个心眼,万一在没有察觉的地方出错了呢?
推荐阅读