一次JVM内存问题致使的线上事故

背景

公司线上有个tomcat服务，里面合并部署了大概8个微服务，之因此没有像其余微服务那样单独部署，其目的是为了节约服务器资源，何况这8个服务是属于边缘服务，并发不高，就算宕机也不会影响核心业务。

由于并发不高，因此线上一共部署了2个tomcat进行负载均衡。

这个tomcat刚上生产线，运行挺平稳。大概过了大概1天后，运维同事反映2个tomcat节点均挂了。没法接受新的请求了。CPU飙升到100%。

排查过程一

接手这个问题后。首先大体看了下当时的JVM监控。

CPU的确居高不下

FULL GC从大概这个小时的22分开始，就开始频繁的进行FULL GC，一分钟最高能进行10次FULL GC

minor GC每分钟居然接近60次，至关于每秒钟都有minor GC

从老年代的使用状况也反应了这一点

随机对线上应用分析了线程的cpu占用状况，用top -H -p pid命令

能够看到前面4条线程，都占用了大量的CPU资源。随即进行了jstack，把线程栈信息拉下来，用前面4条线程的ID转换16进制后进行搜索。发现并无找到相应的线程。因此判断为不是应用线程致使的。

第一个结论

经过对当时JVM的的监控状况，能够发现。这个小时的22分以前，系统 一直保持着一个比较稳定的运行状态，堆的使用率不高，可是22分以后，年轻代大量的minor gc后，老年代在几分钟以内被快速的填满。致使了FULL GC。同时FULL GC不停的发生，致使了大量的STW，CPU被FULL GC线程占据，出现CPU飙高，应用线程因为STW再加上CPU太高，大量线程被阻塞。同时新的请求又不停的进来，最终tomcat的线程池被占满，再也没法响应新的请求了。这个雪球终于仍是滚大了。

分析完了案发现场。要解决的问题变成了：

是什么缘由致使老年代被快速的填满？

拉了下当时的JVM参数

-Djava.awt.headless=true -Dfile.encoding=UTF-8 -server -Xms2048m -Xmx4096m -Xmn2048m -Xss512k -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:+DisableExx plicitGC -XX:MaxTenuringThreshold=5 -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCMSCompactAtFullCollection
-XX:+PrintGCDetails -Xloggc:/data/logs/gc.log

总共4个G的堆，年轻代单独给了2个G，按照比率算，JVM内存各个区的分配状况以下：

因此开始怀疑是JVM参数设置的有问题致使的老年代被快速的占满。

可是其实这参数已是以前优化后的结果了，eden区设置的挺大，大部分咱们的方法产生的对象都是朝生夕死的对象，应该大部分都在年轻代会清理了。存活的对象才会进入survivor区。到达年龄或者触发了进入老年代的条件后才会进入老年代。基本上老年代里的对象大部分应该是一直存活的对象。好比static修饰的对象啊，一直被引用的 缓存啊，spring容器中的bean等等。

我看了下垃圾回收进入老年代的触发条件后（关注公众号后回复“JVM”获取JVM内存分配和回收机制的资料），发现这个场景应该是属于大对象直接进老年代的这种，也就是说年轻代进行minor GC后，存活的对象足够大，不足以在survivor区域放下了，就直接进入老年代了。

可是一次minor GC应该超过90%的对象都是无引用对象，只有少部分的对象才是存活的。并且这些个服务的并发一直不高，为何一次minor GC后有那么大量的数据会存活呢。

随即看了下当时的jmap -histo 命令产生的文件

发现String这个这个对象的示例居然有9000多w个，占用堆超过2G。这确定有问题。可是tomcat里有8个应用 ，不可能经过分析代码来定位到。仍是要从JVM入手来反推。

第二次结论

程序并发不高，可是在几分钟以内，在eden区产生了大量的对象，而且这些对象没法被minor GC回收 ，因为太大，触发了大对象直接进老年代机制，老年代会迅速填满，致使FULL GC，和后面CPU的飙升，从而致使tomcat的宕机。

基本判断是，JVM参数应该没有问题，极可能问题出在应用自己不断产生没法被回收的对象上面。可是我暂时定位不到具体的代码位置。

排查过程二

次日，又看了下当时的JVM监控，发现有这么一个监控数据当时漏看了

这是FULL GC以后，老年代的使用率。能够看到。FULL GC后，老年代依然占据80%多的空间。full gc就根本清理不掉老年代的对象。这说明，老年代里的这些对象都是被程序引用着的。因此清理不掉。可是平稳的时候，老年代一直维持着大概300M的堆。从这个小时的22分开始，以后就狂飙到接近2G。这确定不正常。更加印证了我前面一个观点。这是由于应用程序产生的没法回收的对象致使的。

可是当时我并无dump下来jvm的堆。因此只能等再次重现问题。

终于，在晚上9点多，这个问题又重现了，熟悉的配方，熟悉的味道。

直接jmap -dump，通过漫长的等待，产生了4.2G的一个堆快照文件dump.hprof，通过压缩，获得一个466M的tar.gz文件

而后download到本地，解压。

运行堆分析工具JProfile，装载这个dump.hprof文件。

而后查看堆当时的全部类占比大小的信息

发现致使堆溢出，就是这个String对象，和以前Jmap得出的结果同样，超过了2个G，而且没法被回收

随即看大对象视图，发现这些个String对象都是被java.util.ArrayList引用着的，也就是有一个ArrayList里，引用了超过2G的对象

而后查看引用的关系图，往上溯源，源头终于显形：

这个ArrayList是被一个线程栈引用着，而这个线程栈信息里面，能够直接定位到相应的服务，相应的类。具体服务是Media这个微服务。

看来已经要逼近真相了！

第三次结论

本次大量频繁的FULL GC是由于应用程序产生了大量没法被回收的数据，最终进入老年代，最终把老年代撑满了致使的。具体的定位经过JVM的dump文件已经分析出，指向了Media这个服务的ImageCombineUtils.getComputedLines这个方法，是什么会产生尚不知道，须要具体分析代码。

最后

得知了具体的代码位置， 直接进去看。通过小伙伴提醒，发现这个代码有一个问题。

这段代码为一个拆词方法，具体代码就不贴了，里面有一个循环，每一次循环会往一个ArrayList里加一个String对象，在循环的某一个阶段，会重置循环计数器i，在普通的参数下并无问题。可是某些特定的条件下。就会不停的重置循环计数器i，致使一个死循环。

如下是模拟出来的结果，能够看到，才运行了一会，这个ArrayList就产生了322w个对象，且大部分Stirng对象都是空值。

至此，水落石出。

最终结论

由于Media这个微服务的程序在某一些特殊场景下的一段程序致使了死循环，产生了一个超大的ArrayList。致使了年轻代的快速被填满，而后触发了大对象直接进老年代的机制，直接往老年代里面放。老年代被放满以后。触发FULL GC。可是这些ArrayList被GC ROOT根引用着，没法回收。致使回收不掉。老年代依旧满的，随机立刻又触发FULL GC。同时由于老年代没法被回收，致使minor GC也无法清理，不停的进行minor GC。大量GC致使STW和CPU飙升，致使应用线程卡顿，阻塞，直至最后整个服务没法接受请求。

联系做者

搜索公众号:jishuyuanren

关注公众号后回复“JVM”获取JVM内存分配和回收机制的资料