亿级流量的数据清洗系统OOM排查实战 _数据清洗

每天亿级数据量的日志清洗系统，从Kafka不停消费各种日志数据，然后对日志格式进行各种清洗，如对敏感信息字段（姓名、手机号、身份证号）进行脱敏，再把清洗后数据给其它系统，如推荐系统、广告系统、分析系统都会去使用这些清洗好的数据。
OOM 现场某天我们也是突然收到线上的报警，发现日志清洗系统发生OOM 。第一时间登录到线上机器，查看日志，经典日志
JAVA.lang.OutOfMemoryError: java heap space堆内存溢出。套路应该很熟了。
先看异常日志，定位啥导致的问题，日志里看到了：
java.lang.OutOfMemoryError: java heap space xx.xx.xx.log.clean.XXClass.process() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.process() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.process() xx.xx.xx.log.clean.XXClass.xx() xx.xx.xx.log.clean.XXClass.xx()似乎同样的一个方法（XXClass.process()）反复出现，最终导致堆内存溢出。
再仔细分析日志，代码出现大量递归操作，正是这大量递归，导致堆内存溢出。接着自然就是MAT分析内存快照。
初步分析内存快照虽然日志能看到哪个方法导致内存溢出，但不知道到底哪个方法调用创建的大量对象。因此还得用MAT分析。
因大量XXClass.process()递归执行，每个XXClass.process()中都创建了大量char数组，最后因XXClass.process()又多次递归调用，也就导致大量的char[]数组耗尽内存：

文章插图

JVM参数问题？基本定位出问题了，但先别急直接去代码检查问题，因为发现了比较大问题。
虽然XXClass.process()递归调用多次，但实际上我们在MAT中发现递归调用的次数也不多，最多几十次。所有递归调用加起来创建的char[]数组对象总和其实也最多1G 。
可能这次OOM发生不一定是代码写的烂，可能就是JVM 内存参数不对，给堆内存分配太少。
分析GC日志要知道堆内存是不是设小了，就得分析JVM运行时的内存使用模型。
现在宕机了，唯一能看到的，就是当时在JVM启动参数中加入的自动记录的GC日志。
从GC日志中，可见JVM启动时的完整参数设置：

 -Xmx1024m -Xms1024m -XX:+PrintGCDetails -XX:+PrintGC() -XX:+HeapDumpOnOutOfMemoryError -Xloggc:/opt/logs/gc.log-XX:HeapDumpPath=/opt/logs/dump

这里主要是把gc日志详细记录在了一个日志文件，另外指定OOM时要导出内存快照，堆内存1G，但这台机器可是4核8G！
记录下来的gc.log日志：

 [Full GC (Allocation Failure) 866M->654M(1024M)] [Full GC (Allocation Failure) 843M->633M(1024M)][Full GC (Allocation Failure) 855M->621M(1024M)][Full GC (Allocation Failure) 878M->612M(1024M)]

因Allocation Failure触发的Full GC很多，即堆内存无法创建新对象，然后触发GC，结果触发时肯定先触发Full GC了。发现每次Full GC都只回收一点点对象，堆内存几乎都占满的。
日志显示的是每s都会执行一次Full GC，这就绝了。应该是在系统运行时，因为XXClass.process()不停递归创建大量char[]数组，导致堆内存几乎满。
然后导致连续一段时间，每s触发一次Full GC，因为内存都满了，特别是Old可能几乎都满了，所以可能每s执行YGC前，发现Old可用空间不足，就会提前触发Full GC 。

文章插图

也可能YGC后，存活对象太多无法放入Survivor，而都要进入Old，也放不下了，只能Full GC 。但每次full gc只能回收少量对象，直到最后可能某次full gc回收不掉任何对象了，然后新的对象无法放入堆内存了，就触发OOM了：

文章插图

明显就是堆内存偏小了，导致频繁full gc 。
分析一下JVM运行时内存使用模型接着jstat分析当时JVM运行时的内存模型，当时重启系统，每s打印一次：
S0 S1 E O YGC FGC0 100 57 69 36 00 100 57 69 36 00 100 65 69 37 00 100 0 99 37 00 100 0 87 37 1我就给出部分信息大家就可以看出来问题所在了，刚开始都是Eden在涨，接着YGC从36到37，发生了一次YGC，Old直接从69%到99% 。
why？YGC后存活对象太多，Survivor放不下，直接进了Old！接着Old都占99%了，直接触发一次Full GC，但也仅让Old从99%到87%，只回收少量对象。
该过程反复循环了几次，年轻代对象反复进入老年代，不停触发Full GC，但是还回收不了多少对象，几次循环过后，老年代满了，可能Full GC没回收多少对象，新的对象一大批放不下了，就触发OOM了。