056-日志清洗系统的OOM问题排查实践

135次阅读
没有评论

共计 4376 个字符,预计需要花费 11 分钟才能阅读完成。

案例实战:每天10亿数据的日志清洗系统的OOM问题排查实践!

1、案例背景引入

今天的案例背景是一个每天10亿数据量的日志清洗系统,这个系统做的事情其实非常的简单,他主要就是从Kafka中不停的消费各种日志数据,然后对日志的格式进行很多清洗,比如对一些涉及到用户敏感信息的字段(姓名、手机号、身份证号)进行脱敏处理,然后把清洗后的数据交付给其他的系统去使用。

比如推荐系统、广告系统、分析系统都会去使用这些清洗好的数据,我们先看下面的图,大致就知道这个系统的运行情况了。

056-日志清洗系统的OOM问题排查实践

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[]数组导致的内存溢出问题。

056-日志清洗系统的OOM问题排查实践

4、功夫在诗外:问题在JVM参数上

基本定位出了问题所在了,但是先别着急直接去代码中检查问题所在,因为我们当时发现了一个比较大的问题。

虽然XXClass.process()方法递归调用了多次,但是实际上我们在MAT中发现递归调用的次数也并不是很多,大概也就是十几次递归调用到最多几十次递归调用而已

而且我们观察了一下,所有递归调用加起来创建的char[]数组对象总和其实也就最多1G而已。

如果是这样的话,其实我们应该先注意一个问题,那就是可能这次OOM的发生不一定是代码就写的有多么的烂,可能就是我们的JVM的内存参数设置的不对,给堆内存分配的空间太小了!

如果要是给JVM堆内存分配更大的空间呢?一切都要尝试一下,所以先别着急,慢慢来。

先看下面的图,在里面我们表示出来了这个内存过小的问题。

056-日志清洗系统的OOM问题排查实践

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[]数组,导致堆内存几乎是塞满的。

我们先看下面的图,表示出了这一点。

056-日志清洗系统的OOM问题排查实践

然后这就导致了连续一段时间,每秒触发一次Full GC,因为内存都满了,特别是老年代可能几乎都满了,所以可能是每秒钟执行young gc之前,发现老年代可用空间不足,就会提前触发full gc

也可能是young gc过后存活对象太多无法放入Survivor中,都要进入老年代,放不下了,只能进行full gc。

我们看下图,表示出来了每秒钟执行一次full gc的场景。

056-日志清洗系统的OOM问题排查实践

但是每次full gc只能回收少量对象,直到最后可能某一次full gc回收不掉任何对象了,然后新的对象无法放入堆内存了,此时就会触发OOM内存溢出的异常。

我们看下面的图,表示出来了这个过程。

056-日志清洗系统的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分析,明显发现是内存不够用了,最后加大系统内存,并且优化代码就可以了。


正文完
 
yangleduo
版权声明:本站原创文章,由 yangleduo 2023-05-17发表,共计4376字。
转载说明:除特殊说明外本站文章皆由CC-4.0协议发布,转载请注明出处。