君子不立危墙之下-记一次服务内存泄漏的排查和解决
1.事发背景
某天早上看到告警群云主机机器可用率大幅度下跌😨
与运维取得联系，得到机器出现大批量卡待重启的信息。由过往的经验得知，这种卡待重启的情况只有云主机房间结束后没有收到关闭房间推送导致，属于偶现事件，但是此前已经对此情况做了多次推送的兜底策略，按理推送丢失的情况应该有所减少，为什么出现同一时间大批量的推送丢失呢？
因为在业务逻辑方面都有日志跟踪，故可以基本排除是代码逻辑引起的原因，然后这种突发的情况平台的错误日志趋势都没明显的上升，既然在应用层已经保证逻辑和推送都没问题，那就往基础服务方面考虑。
开始看推送服务的代码（也是个陈年老代码了😶），发现有个推送的错误日志打了warn级别
此时更加怀疑根源是推送的问题了，极有可能是出现大量的错误由于日志的级别没有告警导致被忽略了
然后登录日志系统查询，果不其然，在这个时间范围出现大量的报错，登上推送服务机器看具体错误日志发现大量"no adapter proxy selected"报错
在日志层面发现l去调用推送服务job的时候，服务发现找不到job，找不到服务要么服务发现有问题，要么就是服务挂了，后续结合Tars发布系统的记录发现，这个时间job服务因为没有上报心跳被视为僵尸进程被kill掉重启了，而且在重启之后的时间在也没有推送失败的日志
那么这个问题就很明显了，在于job服务本身的问题了，但是还不清楚是什么原因导致job服务出现问题，因为已经没有现场了，按照以往的经验无非就是cpu、内存、磁盘等等问题导致的。
于是上去机器监控面板找下线索，发现这个时间点job服务的机器内存打满了，然后又发现没有出现服务器内存告警是因为这台机器被划分到了非重要告警组，导致收不到告警信息。结合这个内存的趋势可以发现，这是个明显的内存泄漏问题。
2.关于内存泄漏
内存泄漏是指程序在申请内存后，未能及时释放不再使用的内存空间，导致这部分内存无法被再次使用，随着时间的推移，程序占用的内存不断增长，最终导致系统资源耗尽或程序崩溃。
像golang、java本身已经支持自动gc机制，相比对需要手动gc的c++来说，极大减轻了开发人员的负担了，对于golang来说比较常见的有两种：
1.全局变量泄漏： 大map，大slice等不断追加元素，没有进行合理的内存淘汰策略（如LRU），导致堆内存不断积压变大。
2.goroutine泄漏： 由于死循环、channel阻塞等导致协程没有结束，从而导致栈内存没有释放。
3.性能优化大杀器pprof
pprof是golang内置的性能分析工具，在进行性能问题分析(入内存泄露，goroutine泄露,cpu资源占用较高等分析)时使用，其可成为我们进行golang开发时，调试应用性能的常用工具。
pprof主要模块介绍：
CPU profile： 当前程序的CPU使用情况，pprof按照一定频率去采集应用程序在CPU和寄存器上面的数据
Memory Profile（Heap Profile）： 当前程序的内存使用情况，可查看heap和alloc的情况。
Block Profiling： 程序当前goroutines不在运行状态的情况，可以用来分析和查找死锁等性能瓶颈。
Goroutine Profiling： 程序当前goroutines的使用情况，查看所有goroutine，产看调用关系，可发现未释放的go协程。
4.排查过程
确定是job服务的内存泄漏的问题之后，就开始关注job服务本身的代码问题了，因为线上用的推送服务是用的开源的框架Goim（github.com/Terry-Mao/g…），在想开源出来的框架不会有这种致命问题吧？
于是开始对比开源版本和本地版本，发现一个比较头疼的问题是，本地是Goim版本是非常老的而且是还是用Vendor管理的，开源仓库都已经找不到这版本的代码了，其中还有不少前面的同学改过源码的痕迹，虽然大体上流程相似，但是有很多细节实现跟开源版本有差异，所以这里为了找到问题代码，只能自己去排查了，于是给job服务开启了pprof监听：
go http.ListenAndServe("localhost:49511", nil)
服务开启监听运行一段时间之后，服务器内存在逐渐上涨，涨的越多，那么pprof抓取的数据就更加明显了
登上服务器使用pprof 30s采样抓取heap数据，把源文件下载到本地进行分析（pprof的采集文件不仅可以用命令行交互进行分析还可以借助用一些可视化工具比如graphviz 去分析）：
wget http://localhost:49511/debug/pprof/heap?seconds=30 -O heap_20241114
采用命令行交互的方式去分析
go tool pprof heap_2024111510
根据报告显示，在增量采样的30s内，方法goim/job/handler.(*RoomBucket).Get产生了最多的内存，达到了2468.70kB
再使用list命令跟踪到代码层面 （跟踪代码的功能需要把采集的源文件放到项目目录下才能使用） ：
list Get
这里显示这个生成room信息的占用的内存达到2.41MB，但是这也不能说明这里是造成内存泄漏的根本原因呀，因为即使这里产生了内存，只是代表了采集的这30s内产生了这么多内存，也有可能在之后的时间会产生GC回收掉。
排查到这里，就不能用定时增量采样的形式去抓取数据了，要排查内存泄漏，最直观的方法是不是直接找到当前整个进程占用内存最大的那块，然后分析为什么会占用这么大，这个才是正确思路。于是继续用pprof工具直接获取当前全量的内存占用情况
wget http://localhost:49511/debug/pprof/heap -O heap_2024111514_all
分析如下：
可以看到当前占用内存最多的为 common/libs/bytes.NewWriterSize 这块代码，竟然占了460.06MB 占总内的83.93% 之多，这里肯定是有猫腻了。
接着对这块代码进行list分析和代码分析
可以看到NewWriterSize方法里面生成了一个Writer对象指针，这个对象里面嵌套了一个8k左右的切片，按理这个方法结束了这个对象就GC掉了，但是这里返回用的是指针，实际上产生了一个内存逃逸，逃逸到堆上了，而pushproc方法的栈又引用了这个堆地址，pushproc方法结束了buf会被会回收掉，这个Writer对象也会被回收，那么这里没有被回收掉的原因只是pushproc方法没有结束！那么一个方法没有结束，主流程业务为什么能正常运行？再结合代码可可以看到pushproc这个方法是异步执行的，所以不会卡主流程。
好排查到这里，问题的方向从单纯的内存泄漏变成协程泄漏了。接下来为了看协程都阻塞在哪儿导致没有结束，继续使用pprof采集goroutine的情况进行分析：
wget http://localhost:49511/debug/pprof/goroutine -O goroutine_2024111516_all
通过traces和list命令分析得到，有6w多个协程在这个channel的读取阻塞住了：
分析整个pushproc方法的实现：
// pushproc merge proto and push msgs in batch.
func (r *Room) pushproc(timer *itime.Timer, batch int, sigTime time.Duration) {
var (
n int
last time.Time
p *impb.Proto
td *itime.TimerData
buf = bytes.NewWriterSize(int(impb.MaxBodySize))
)
log.Debug(fmt.Sprintf("start room: %d goroutine", r.id))
td = timer.Add(sigTime, func() {
select {
case r.proto <- roomReadyProto:
default:
}
})
for {
if p = <-r.proto; p == nil { //业务不会触发
break // exit
} else if p != roomReadyProto {
// merge buffer ignore error, always nil
p.WriteTo(buf)
if n++; n == 1 {
last = time.Now()
timer.Set(td, sigTime)
continue
} else if n < batch {
if sigTime > time.Now().Sub(last) {
continue
}
}
} else {
if n == 0 {
continue
}
}
broadcastRoomBytes(r.id, buf.Buffer())
n = 0
// TODO use reset buffer
// after push to room channel, renew a buffer, let old buffer gc
buf = bytes.NewWriterSize(buf.Size())
}
timer.Del(td)
log.Debug(fmt.Sprintf("room: %d goroutine exit", r.id))
}
分析pushproc方法代码比较容易发现，这里是进行了一个高并发推送的合并优化，当同一个房间产生了推送后不断把推送合并到buf中，当推送数量达到一批或者合并等待结束就进行一次推送然后清空buf，然后在for循环里面一直监听推送的到来，但是这个for循环里面唯一的break是不会触发的，导致相当于产生了死循环，另外这块代码可能是年代比较久远当时golang还没有推出timer包，所以写了一个自定义实现。
针对这种合并的思路对代码进行改造，保证房间没有推送一段时间之后时候及时释放掉这个监听的协程，除了优化逻辑之外，更新了timer包的使用， 修改后的代码如下：
// sigTime 时间设置过短推送可能会丢失
func (r *Room) pushproc(timer *itime.Timer, batch int, sigTime time.Duration) {
var (
n int
last time.Time
p *impb.Proto
buf = bytes.NewWriterSize(int(impb.MaxBodySize))
)
log.Info(fmt.Sprintf("[pushproc msg] start roomId:%d goroutine, batch:%v, sigTime:%+v",
r.id, batch, sigTime))
newTimer := time.AfterFunc(sigTime, func() {
select {
case r.proto <- roomReadyProto:
log.Debug(fmt.Sprintf("[pushproc msg] roomReadyProto product,roomId:%d", r.id))
default:
}
})
defer newTimer.Stop()
for {
if p = <-r.proto; p == nil { // 正常逻辑不会触发
break // exit
} else if p != roomReadyProto { // 收到其他业务数据推送
// merge buffer ignore error, always nil
log.Debug(fmt.Sprintf("[pushproc msg] receive other push roomId:%d", r.id))
p.WriteTo(buf)
if n++; n == 1 {
last = time.Now()
newTimer.Reset(sigTime)
continue
} else if n < batch {
if sigTime > time.Since(last) {
continue
}
}
} else { // 收到发送批量信号
if n == 0 { // buf没有数据时，又收到兜底推送，此时可以结束监听
log.Debug(fmt.Sprintf("[pushproc msg] end break roomId:%d", r.id))
break
}
}
// 真正发送的地方
log.Debug(fmt.Sprintf("[pushproc msg] broadcastRoomBytes roomId:%d", r.id))
broadcastRoomBytes(r.id, buf.Buffer())
n = 0
// after push to room channel, renew a buffer, let old buffer gc
// 还有另外一个作用就是清除之前已经发送过的推送数据
buf = bytes.NewWriterSize(buf.Size())
// 最后刷新设置一个最新定时10s之后触发销毁这个协程，兜底
newTimer.Reset(10 * time.Second)
}
roomBucket.DeleteRoom(r.id)
log.Info(fmt.Sprintf("[pushproc msg] roomId:%d ,goroutine exit", r.id))
}
代码修复完之后，线上效果是非常明显的，这个隐藏了5年的BUG终于解决了
5.问题总结
1.错误日志级别设置错误
由于推送服务的错误日志只设置为warn最终出现大量错误的时候没有触发告警，导致没有第一时间发现是推送的问题，因此日常开发中要重视日志的规范。
2.服务器告警级别设置错误
由于此部署服务的服务器被划分到了非重要告警组，导致自动屏蔽了内存100%的致命告警，服务器告警是线上稳定性的”心电图“，需要再次确认配置。
3.服务没有开启pprof监听端口
当服务引起cpu、内存飙升之后，如果没有开启pprof端口，问题出现后需要重新发版去监听采集数据的时候， 线场已经丢失了，如果是由于代码边界问题引起的话，那么这个现场复现就很难了，所以每一个线上服务尽量开启pprof端口。
4.协程没有及时释放
在进行并发编程的时候，需要明确如channel读写、锁的加锁解锁、循环的退出。根据墨菲定律：“任何可能出错的事情最终都会出错”， 所以尽量避免边界模糊的代码逻辑，还需重视单元测试。
5.pprof的heap不能定位goroutine泄漏
本例中用pprof采集heap的数据是很难直观看出goroutine泄漏，最直观的方法是采集goroutine的数据，再通过top、traces、list等命令去逐步分析，这样才可以看到当前运行的goroutine数量和阻塞的地方
6.思考
在遇到线上问题的时候，心态不要慌，要根据现象找原因，多维度多工具去结合排查，抽丝剥茧找到问题根源，问题往往出现在我们不熟悉的领域，经过探索的过程才能有所收获， “当你感觉到痛苦的时候，说明你正在成长”
