前段时间,公司的老系统频繁的出现超时,各方都不胜其扰,不过由于公司性质问题,线上运维和开发是分属不同的人负责,所以我也就没有办法及时的登录服务器排查问题,这还是有点儿让我这个互联网出身的码农有些难受。
书归正题,当时的现象是zookeeper告警创建节点失败,但是由于老系统代码质量的原因,异常堆栈被吞掉了,无分发根据异常堆栈信息判断具体的失败原因,无奈只能加日志上线再观察,在排查日志的过程中发现,几乎是在同一时间段内,系统会出现大量超时,同时还回有GC overhead limit exceeded异常,对于这种异常的含义,可以参考:GC overhead limit exceeded原因分析及解决方案 - 知乎
大概意思就是说,JVM花费了98%的时间进行垃圾回收,而只得到2%可用的内存,频繁的进行内存回收(最起码已经进行了5次连续的垃圾回收),JVM就会曝出java.lang.OutOfMemoryError: GC overhead limit exceeded错误。
很明显,应该是多次FullGC但是却释放不掉内存,所以排查的重心转移到了内存泄漏方向,顺便说一下,如果自己可以操作线上机器,其实第一时间就可以用jstat -gc去看是不是短时间内FullGC次数一直在增加。
接下来跟运维同学说让他在下次出现超时的时候,用jmap把堆内存的映射dump下来给我(登不上线上机器的痛),拿到文件后用工具打开分析,正常来讲,与OOM排查方法类似,可以看哪一类对象占用过高的内存,然后直接根据引用找到相关方法就可以找到问题根源了,但是还是因为老代码质量不高的原因,入参出参很多都是用Map<String, Object>传递,导致从直观上看,占用内存最多的是字符和字符串,没有很好的排查切入点,这大概也是为啥各大公司规范中都不建议甚至不允许使用Map传参的原因之一。
在排查陷入山重水复的境地的时候,有一个问题引起了我的注意,堆内存映射文件显示,内存使用量是400多M,通常默认触发FullGC的阈值没记错的话应该是80%,也就是说,线上该服务的JVM参数配置的最大堆内存应该只有512M,跟运维同学要了启动脚本后,发现JVM参数设置的和我猜测的一样,于是调整参数,重新上线,运行到目前,问题还没有复发。
因为公司无法登录外网的原因,排查过程中很多截图无法在这里贴出,只能等后续有时间再模拟。