java内存溢出的排查记录

问题

     背景：服务异常，交易无法发到服务器，经排查发现大量SYN_RECV，重启服务后交易正常。有大量CLOSE_WAIT、SYN_RECV连接，交易日志无增量输出，每次重启后不久服务又出现无法访问现象，反复重启3次后，截止发邮件时生产上仍有CLOSE_WAIT,CLOSE_WAIT、SYN_RECV许多连接为F5地址，怀疑可能由F5引起大量非正常连接，进而导致交易无法正常使用。console.log中出现java.lang.OutOfMemoryError

问题排查及分析

1. 收集相关信息。确认异常，明确现象： 
   1. 大量close_wait：根据TCP三次握手建立通讯可以知道，这个一般是在服务端出现的。排除恶意攻击的情况，只会在客户端断开链接之后服务端未及时关闭链接时出现；具体流程见相关文章
   2. 内存溢出：java.lang.OutOfMemoryError: Java heap space ；该异常为内存不足，一般是程序问题导致的。
   3. 在JVM参数中新增下列参数，在JVM虚拟机发生内存溢出异常时，自动产生DUMP文件

   4. #当应用抛出 OutOfMemoryError 时自动生成dump文件 -XX:+HeapDumpOnOutOfMemoryError #dump文件输出路径 -XX:HeapDumpPath=/home/sunefrs/sunefrs.dump

   5. 从dump文件上看，Log4j占用了大量内存.其回根收节点见下图
      
2. 分析当前可能引起异常现象的可能原因：
   1. 生产日志量很大，大部分为图片比对交易，交易报文一般在几百K到1、2M不等，暂未发现超大报文的情况。
   2. 有大量F5调用异常。
   3. dump文件显示：有大量内存被log4j占用了。很可能是因为日志打印问题。
3. 确认可能原因是否成立：
   1. F5正常。不太可能是F5造成的
   2. 日志量很大，从dump文件分析有极大可能是由于log4j打印日志造成的
4. 复现生产问题步骤：
   1. 使用jmeter进行压测。使用大报文模拟交易。
   2. 打开java visualVm 监控内存使用情况
   3. 打开console.log监控控制台日志
   4. 使用netstat命令监控close_wait情况【此处不放截图，仅说结论】：
      1. 60并发压测:屏蔽日志打印，垃圾回收正常，交易未出现问题
      2. 60并发压测:不屏蔽日志打印，垃圾无法及时回收，交易OOM，并出现大量close_wait【之前测试没出现是因为设置了Keep-Alive参数
5. 问题原因分析：
   1. 从业务日志上看，交易报文比较大，在日志打印的时候会把字段打印出来如下：日志量将会是8倍，如果是2M图片，会写16M以上日志【这里取值有点问题，正常生成是会写8倍日志的】【补充说明：实际上还有16进制的日志打印也会有2次，比原图片还大的多图片未写出来】
   2. 再看log4j配置文件：日志是异步打印的。当交易量较大的时候。日志打印量会超级大，假设每次报文图片大小为2M,有每分钟20个请求，每分钟就会有320M以上的日志量。且目前生产log4j配置为两处输出，因此日志量*2也就是640M以上，加上其他交易的日志，日志量会非常大。
      【测试环境写磁盘速度大约为87.2MB/sec，考虑到还有日志压缩和其他系统的读写，程序写日志不会把写磁盘速度用满。因此会有大量日志停留在内存中。因此会造成内存溢出。内存溢出后程序直接卡死，不能正常处理交易且无法恢复】
      
6. 验证分析：
   1. 单线程且间隔较大时间调用交易：交易正常内存正常回收
   2. 高并发调用交易：程序快速内存溢出
   3. 关闭日志：高并发内存快速释放，交易正常 

总结

         内存溢出原因为：日志打印量过大，占用了过多磁盘资源，写日志的速度跟不上新增待写日志速度导致。

         查内存溢出最重要的就是要找到是什么类占用了内存，为什么不能正常释放。明确了这两点。内存溢出问题就不难解决。

解决方案

1. 推荐方案：使用log4j过滤器，屏蔽图片字段相关打印。移除多余的日志打
2. 可选方案：分多个jvm处理类似大报文的交易，把这个jvm的log4j文件直接屏蔽日志。
3. 可选方案：修改底层代码，调整日志打印方式。

参考文章

1. TCP状态变更流程：https://www.cnblogs.com/qingergege/p/6603488.html