案例实战：
每天10亿数据的日志清洗系统的OOM问题排查实践！
石杉老师最新出品：《C2C 电商系统微服务架构 120 天实战训练营》，点击了解详情
儒猿架构官网上线，内有石杉老师架构课最新大纲，儒猿云平台详细介绍，敬请浏览
官网：www.ruyuan2020.com（建议PC端访问）
1、案例背景引入
今天的案例背景是一个每天10亿数据量的日志清洗系统，这个系统做的事情其实非常的简单，他主要就是从Kafka中不停的消费各种日志数据，然后对日志的格式进行很多清洗，比如对一些涉及到用户敏感信息的字段（姓名、手机号、身份证号）进行脱敏处理，然后把清洗后的数据交付给其他的系统去使用。
比如推荐系统、广告系统、分析系统都会去使用这些清洗好的数据，我们先看下面的图，大致就知道这个系统的运行情况了。
2、事故发生现场
某天我们也是突然收到线上的报警，发现日志清洗系统发生了OOM的异常！
我们登陆到线上机器查看日志之后，发现还是那么经典的java.lang.OutOfMemoryError: java heap space的问题，又是堆内存溢出。
此时我们当然就会来分析一下问题到底出在哪里了，大家应该还记得我们分析OOM问题的套路
首先先看看异常日志，去定位一下到底是谁导致的这个问题，当时我们在日志里大致看到了类似如下的一些信息：
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分析一下内存快照了。
3、初步分析内存快照
接着我们开始分析生产现场的内存快照，之前我们已经详细讲解了如何通过MAT去分析内存快照，快速定位创建大量对象的代码和方法，其实在日志中我们是可以看到是哪个方法导致的内存溢出，但是我们通过日志不知道到底是哪个方法调用创建了大量的对象。
因此最终无论如何，还是得通过MAT去分析一下，在分析的时候，我们就发现了一个问题，因为有大量的XXClass.process()方法的递归执行，每个XXClass.process()中都创建了大量的char数组！
最后因为XXClass.process()方法又多次递归调用，也就导致了大量的char[]数组耗尽了内存。
先看看下图，在图里我们表示出来了方法递归调用，每次调用都创建大量char[]数组导致的内存溢出问题。
4、功夫在诗外：问题在JVM参数上
基本定位出了问题所在了，但是先别着急直接去代码中检查问题所在，因为我们当时发现了一个比较大的问题。
虽然XXClass.process()方法递归调用了多次，但是实际上我们在MAT中发现递归调用的次数也并不是很多，大概也就是十几次递归调用到最多几十次递归调用而已
而且我们观察了一下，所有递归调用加起来创建的char[]数组对象总和其实也就最多1G而已。
如果是这样的话，其实我们应该先注意一个问题，那就是可能这次OOM的发生不一定是代码就写的有多么的烂，可能就是我们的JVM的内存参数设置的不对，给堆内存分配的空间太小了！
如果要是给JVM堆内存分配更大的空间呢？一切都要尝试一下，所以先别着急，慢慢来。
先看下面的图，在里面我们表示出来了这个内存过小的问题。
5、分析一下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日志详细记录在了一个日志文件里，另外指定了内存溢出的时候要导出内存快照，另外就是堆内存给的是1GB大小，但是要知道这台机器可是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)]
我把GC日志中大量的无关紧要的信息省略掉了，因为跟我们分析关系不大
但是大家可以发现一点，因为Allocation Failure触发的Full GC很多，也就是堆内存无法分配新的对象了，然后触发GC，结果触发的时候肯定是先触发Full GC了，这个关于Full GC触发的原因和时机之前大量的分析过，这里不多说了。
而且你会发现每次Full GC都只能回收掉一点点对象，发现堆内存几乎都是占满了。
另外我们这里没有显示时间，当时日志里显示的是每秒钟都会执行一次Full GC，这个就很可怕了。基本上我们可以明确一点，应该是在系统运行的时候，因为XXClass.process()方法不停递归创建了大量的char[]数组，导致堆内存几乎是塞满的。
我们先看下面的图，表示出了这一点。
然后这就导致了连续一段时间，每秒触发一次Full GC，因为内存都满了，特别是老年代可能几乎都满了，所以可能是每秒钟执行young gc之前，发现老年代可用空间不足，就会提前触发full gc
也可能是young gc过后存活对象太多无法放入Survivor中，都要进入老年代，放不下了，只能进行full gc。
我们看下图，表示出来了每秒钟执行一次full gc的场景。
但是每次full gc只能回收少量对象，直到最后可能某一次full gc回收不掉任何对象了，然后新的对象无法放入堆内存了，此时就会触发OOM内存溢出的异常。
我们看下面的图，表示出来了这个过程。
分析到这里不知道大家有什么感觉？其实很明显一点，就是堆内存肯定是偏小了，这个就导致频繁的full gc。
6、分析一下JVM运行时内存使用模型
接着我们再用jstat分析一下当时JVM运行时的内存模型，当时我们重启了系统，每秒钟打印一次jstat的统计信息，就看到了下面的情况：
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%
说明什么？
说明YGC后存活对象太多，Survivor放不下，直接进老年代了！
接着老年代都占了99%了，直接就触发了一次Full GC，但是也仅仅让老年代从占比99%到87%而已，回收了少量的对象。
上面的那个过程反复循环几次，大家思考一下，年轻代的对象反复进入老年代，不停的触发Full GC，但是还回收不了多少对象，几次循环过后，老年代满了，可能Full GC没回收多少对象，新的对象一大批放不下了，就触发OOM了。
7、优化第一步：增加堆内存大小
所以这个OOM的问题，说白了不能直接说是代码问题，从JVM运行情况以及内存大小来看，就是内存分配不足的问题。
因此这里第一步，直接在4核8G的机器上，给堆内存加大空间，直接给了堆内存5G的内存。
接着运行系统，通过jstat观察，就可以发现，每次Young GC过后存活对象都落入Survivor区域了，不会随便进入老年代，而且因为堆内存很大，基本上运行一段时间不会发生OOM问题了。
8、优化第二步：改写代码
另外就是改写代码，让他不要占用过多的内存。当时代码之所以递归，就是因为在一条日志中，可能会出现很多用户的信息，一条日志也许会合并包含了十几个到几十个用户的信息。
这个时候代码中就是会递归十几次到几十次去处理这个日志，每次递归都会产生大量的char[]数组，是切割了日志用来处理的。
其实这个代码写的完全没有必要，因为对每一条日志，如果发现包含了多个用户的信息，其实就对这一条日志切割出来进行处理就可以了，完全没有必要递归调用，每次调用都切割一次日志，生成大量的char[]数组。
所以把这一步代码优化了之后，一下子发现线上系统的内存使用情况降低了10倍以上。
9、案例总结
今天这个案例，大家会发现，我们先是通过OOM的排查方法去分析，发现主要是内存太小导致的问题
然后用gc日志和jstat分析，明显发现是内存不够用了，最后加大系统内存，并且优化代码就可以了。
End
版权：公众号儒猿技术窝
未经许可不得传播，如有侵权将追究法律责任
儒猿技术窝精品专栏及课程推荐：
1760
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
