记一次隐藏很深的 JVM 线上惨案的分析、排查、解决

1、本文背景

本文会给大家讲解一个比较特殊的JVM优化案例，这个优化案例本身是因为新手工程师对JVM优化可能了解了一个半吊子，然后不知道从哪里找来了一个非常特殊的JVM参数错误的设置了一下，就导致线上系统频繁的出现Full GC的问题。

但是我们后续大量的优化案例其实都是各种各样奇形怪状的场景，因为正是各种奇怪场景才能让大家逐步积累出来较为丰富的JVM优化实战经验

了解的场景越多，自己未来在处理JVM性能问题的时候才能更是得心应手。

2、问题的产生

这个场景的发生大致如下过程：某天团队里一个新手工程师大概是心血来潮，觉得自己网上看到了某个JVM参数，以为学会了绝世武功秘籍，于是就在当天上线一个系统的时候，自作主张设置了一个JVM参数

这个参数是什么呢?

不用急，跟着看下面的案例分析即可，现在只要知道他设置了一个奇怪的参数，接着事故就发生了。

因为一般中大型公司都是接入类似Zabbix、OpenFalcon或者公司自研的一些监控系统的，监控系统一般都做的很好，可以让你的系统直接接入进去，然后在上面可以看到每台机器的CPU、磁盘、内存、网络的一些负载。

而且可以看到你的JVM的内存使用波动折线图，还有你的JVM GC发生的频率折线图。包括如果你自己上报某个业务指标，也可以在监控系统里看到。

而且一般都会针对线上运行的机器和系统设置一些报警，比如说，你可以设置如果10分钟内发现一个系统的JVM发生了超过3次Full GC，就必须发送报警给你，可以发送给你的短信、邮箱或者是钉钉之类的IM工具。

类似这样的监控系统不在我们的专栏范畴内，建议大家自己可以去查阅资料，其实基于我们讲解的命令行工具，比如jstat，你可以通过linux上的一些命令，让jstat自动对jvm进行监控，把监控结果可以输出到机器的某个文件里去。

然后第二天你就可以去查阅那个文件，也可以看到那台机器的jvm的一些gc统计。

所以说，没有可视化工具，用最简单的命令行工具，其实同样可以起到类似的效果。

所以那天那个工程师设置了一个JVM参数之后，直接导致线上频繁接到JVM的Full GC的报警，大家就很奇怪了，于是就开始排查那个系统了。

3、查看GC日志

之前已经给大家讲解过如何在启动系统的时候让他输出GC日志，所以一旦发现报警，直接登录到线上机器，然后就看到对应的GC日志了。

此时我们看到在GC日志中有大量的Full GC的记录。

那么是为什么导致的Full GC呢?

在日志里，看到了一个“Metadata GC Threshold”的字样，类似于如下日志：

【Full GC(Metadata GC Threshold)xxxxx, xxxxx】

从这里就知道，这频繁的Full GC，实际上是JDK 1.8以后的Metadata元数据区导致的，也就是类似我们之前说的永久代。

这个Metadata区域一般是放一些加载到JVM里去的类的。

所以此时就很奇怪了，为什么会因为Metadata区域频繁的被塞满，进而触发Full GC?而且Full GC大家都知道，会带动CMS回收老年代，还会回收Metadata区域本身。

我们先看看下图：

4、查看Metaspace内存占用情况

接着我们当然是想看一看Metaspace区域的内存占用情况了，简单点你可以通过jstat来观察，如果有监控系统，他会给你展示出来一个Metaspace内存区域占用的波动曲线图，类似下面这种。

看起来Metaspace区域的内存呈现一个波动的状态，他总是会先不断增加，达到一个顶点之后，就会把Metaspace区域给占满，然后自然就会触发一次Full GC，Full GC会带着Metaspace区域的垃圾回收，所以接下来Metaspace区域的内存占用又变得很小了。

5、一个综合性的分析思路

看到这里，相信大家肯定有一点感觉了，这个很明显是系统在运行过程中，不停的有新的类产生被加载到Metaspace区域里去，然后不停的把Metaspace区域占满，接着触发一次Full GC回收掉Metaspace区域中的部分类。

然后这个过程反复的不断的循环，进而造成Metaspace区域反复被占满，然后反复导致Full GC的发生，如下图所示。

6、到底是什么类不停的被加载?

接着我们就有点奇怪了，到底是什么类不停的被加载到JVM的Metaspace区域里去?

这个时候就需要在JVM启动参数中加入如下两个参数了：

“-XX:TraceClassLoading -XX:TraceClassUnloading” 

这两个参数，顾名思义，就是追踪类加载和类卸载的情况，他会通过日志打印出来JVM中加载了哪些类，卸载了哪些类。

加入这两个参数之后，我们就可以看到在Tomcat的catalina.out日志文件中，输出了一堆日志，里面显示类似如下的内容：

【Loaded sun.reflect.GeneratedSerializationConstructorAccessor from __JVM_Defined_Class】

明显可以看到，JVM在运行期间不停的加载了大量的所谓“GeneratedSerializationConstructorAccessor”类到了Metaspace区域里去

如下图所示

相信就是因为JVM运行期间不停的加载这种奇怪的类，然后不停的把Metaspace区域占满，才会引发不停的执行Full GC的。

这是一个非常实用的技巧，各位同学一定要掌握，频繁Full GC不光是老年代触发的，有时候也会因为Metaspace区域的类太多而触发。

到此为止，已经慢慢接近真相了。

7、为什么会频繁加载奇怪的类?

（编辑：衡阳站长网）

【声明】本站内容均来自网络，其相关言论仅代表作者个人观点，不代表本站立场。若无意侵犯到您的权利，请及时与联系站长删除相关内容!