作者: bryan31
原链接:https://www.v2ex.com/t/701513

背景

公司线上有个 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 飙升，导致利用线程卡顿，阻塞，直至最初整个服务无奈承受申请。

关注公众号:java宝典