每日10亿数据的日志分析系统OOM

背景

一个每日10亿数据的日志清洗系统，主要工作就是从消息队列中消费各种各样的日志，然后对日志进行清洗，例如：用户敏感信息(姓名、手机号、身份证)进行脱敏处理,然后把清理完的数据交付给其他系统使用。
我们项目中，推荐系统、营销系统，大数据分析系统，都会使用清洗好的数据。

现场

收到线上的报警，发现日志清洗系统发生了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分析内存快照。

分析

1. 通过MAT去分析的时候，我们就发现了一个问题，因为有大量的XXClass.process()方法的递归执行，每个XXClass.process()中都创建了大量的char数组！导致大量的char[] 数组，耗尽了内存。
2. 此时，我们发现了一个问题，递归的次数不是很多，也就十几次到几十次递归。我们也观察了一下，所有创建的char[]，占用的内存也就1G，这就有一个问题了，这次oom不全是代码的问题，可能是我们的jvm参数设置的不对，分配的堆内存空间太小了。
3. 因为我们要分析是不是堆内存设置的太小了，就要分析jvm运行时的内存使用模型，只能去看jvm启动参数中加入的自动记录GC日志，在日志中，我们发现JVM启动时的核心参数：
   -Xmx1024m -Xms1024m -XX:+PrintGCDetails -XX:+PrintGC() -XX:+HeapDumpOnOutOfMemoryError -
   Xloggc:/opt/logs/gc.log -XX:HeapDumpPath=/opt/logs/dump
   。
4. 观察日志可以发现，jvm参数里指定了gc的日志路径，以及内存溢出时要导出的内存快照地址，还有给堆分配的内存-Xmx1024m -Xms1024m，这台机器是4 core 8G的，只分配1G内存太小了
5. 接下来详细看下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一次，很可怕。导致一直full gc的原因有两个，一个是老年代内存满了，每秒钟执行young gc之前，会发现老年代可用空间不够，就会提前触发full gc；另外一个可能是young gc之后，存活的对象无法放入到survivor区，都要进入老年代，放不下，就会触发full gc；
6. 我们重启了系统，利用jstat分析了一下当时jvm运行时的内存模型，发现如下情况：
   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

jstat解析
YGC 从36 -> 37 表示发生一次young gc，但是我们发现old区从69 -> 99 ，表示young gc之后，survivor区放不下，直接进入lod区，紧接着发生了一次FGC，但是发现old区并没有回收掉多少内存，几次循环之后，内存就堆满了，直接触发oom。

优化

1. 增加堆内存大小
   给堆内存加大空间，直接给了堆内存5G的内存。
2. 改代码
   改写代码，让他不要占用过多的内存。当时代码之所以递归，就是因为在一条日志中，可能会出现很多用户的信息，一条日志也许会合并包含了十几个到几十个用户的信息。
   这个时候代码中就是会递归十几次到几十次去处理这个日志，每次递归都会产生大量的char[]数组，是切割了日志用来处理的。
   其实这个代码写的完全没有必要，因为对每一条日志，如果发现包含了多个用户的信息，其实就对这一条日志切割出来进行处理就可以
   了，完全没有必要递归调用，每次调用都切割一次日志，生成大量的char[]数组。
   所以把这一步代码优化了之后，一下子发现线上系统的内存使用情况降低了10倍以上。

总结

今天这个案例，大家会发现，我们先是通过OOM的排查方法去分析，发现主要是内存太小导致的问题。然后用gc日志和jstat分析，明显发现是内存不够用了，最后加大系统内存，并且优化代码就可以了。