每天亿级数据量的日志清洗系统，从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 FGC
 
 0 100 57 69 36 0
 
 0 100 57 69 36 0
 
 0 100 65 69 37 0
 
 0 100 0 99 37 0
 
 0 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了。

优化第一步：加大堆内存

所以这OOM，不能一口说是代码问题，从JVM运行情况及内存大小来看，其实是内存分配不足问题。

第一步，直接在4核8G的机器上，加大堆内存，直接给堆5G。

接着运行系统，jstat发现，每次YGC过后存活对象都落入Survivor区域了，不会随便进入老年代，而且因为堆内存很大，基本上运行一段时间不会发生OOM问题了。

优化第二步：改写代码

让他不要占用过多内存。代码之所以递归，是因为在一条日志中，可能出现很多用户的信息，一条日志也许会合并包含了十几个到几十个用户的信息。

这时代码中就是会递归处理日志，每次递归都会产生大量char[]数组，是切割了日志用来处理的。

这代码写的完全没必要，因为对每一条日志，若发现包含多个用户的信息，就对这一条日志切割出来进行处理，没必要递归调用，每次调用都切割一次日志，生成大量char[]数组。

该步代码优化后，线上系统的内存使用情况降低10倍以上。

总结

先通过OOM的排查方法去分析，发现主要是内存太小导致的问题然后用gc日志和jstat分析，明显发现是内存不够用了，最后加大系统内存，并优化代码即可。