JVM 知识回顾

由于我们的项目线上使用的是 ParNew 和 CMS ，所以我们先来简单回顾一下相关的基础知识。

ParNew 收集器

ParNew 收集器其实就是 Serial 收集器的多线程版本。除了使用多线程外其余行为均和 Serial 收集器一模一样（参数控制、收集算法、Stop The World、对象分配规则、回收策略等）。

特点：多线程、ParNew 收集器默认开启的收集线程数与 CPU 的数量相同，在 CPU 非常多的环境中，可以使用-XX:ParallelGCThreads参数来限制垃圾收集的线程数。和 Serial 收集器一样存在 Stop The World 问题。

应用场景：ParNew 收集器是许多运行在 Server 模式下的虚拟机中首选的新生代收集器，因为它是除了 Serial 收集器外，唯一一个能与 CMS 收集器配合工作的。

CMS 收集器

CMS牺牲了系统的吞吐量来追求收集速度，适合追求垃圾收集速度的服务器上。

特点：基于标记-清除算法实现。并发收集、低停顿。

应用场景：适用于注重服务的响应速度，希望系统停顿时间最短，给用户带来更好的体验等场景下。如 web 程序、b/s 服务。

CMS收集器的运行过程分为下列4步：

初始标记：标记 GC Roots 能直接找到的对象。速度很快但是仍存在 Stop The World 问题
并发标记：进行GC Roots Tracing 的过程，找出存活对象且与用户线程可并发执行。
重新标记：为了修正并发标记期间因用户程序继续运行而导致标记产生变动的那一部分对象的标记记录。仍然存在 Stop The World 问题。
并发清除：对标记的对象进行清除回收。

JVM 内存模型

这里放张图，大家在回顾下就不做过多介绍了

JVM 常用参数

常见的如下：

Xms64m 初始堆内存 64m.
Xmx128m 最大堆内存 128m.
Xmn32m 年轻代内存 32m.
-XX:+UseParNewGC 新生代使用并行收集器.
-XX:+UseConcMarkSweepGC 老年代使用 cms 收集器.
Xss=256k 线程栈大小.
-XX:+PrintGCDetails 打印 GC 详情.
XX:+HeapDumpOnOutOfMemoryError 发送内存溢出时 dump 内存.
-XX:NewRatio=2新生代和老年代的默认比例为 1:2，也就是说新生代占用 1/3的堆内存，而老年代占用 2/3 的堆内存。可以通过参数 -XX:NewRatio=2 来设置老年代/新生代的比例.

背景描述

上次一个新项目在经历过生产压测后发现一个问题，那就是系统的 cpu 占用率特别高。在达到一定的 QPS 的时候，cpu 占用率高达 80%-90% ,这是意料之外的，所以压测结果也并没有达到预期。因为这个时候系统层面没有任何优化，是直接调用数据库裸奔。所以怀疑可能是因为查询数据和处理数据时间比较长导致请求阻塞。

由于在生产压测，线程快照、内存快照都没有来的及保存就及时恢复生产状态了

在这之后我还单独在本地压测下接口，想要试着复现下 cpu 占用的问题，由于环境差异比较大，并没有发现什么问题。于是就继续进行优化和容灾的建设了。在经历过压测后，又有新的需求接入上线了，导致流量大幅增长。问题就开始暴露出来了。

问题现象

现象一：cpu 飙升

现象二：系统响应耗时增加

现象三：内存使用率下降

排查步骤

发现生产又出现 cpu 飙升的情况，就赶快登录出现问题的机器，通过以下步骤进行排查。

步骤一：登录服务器查找 cpu 占用率高的进程

首先登录到服务器后通过 top 命令，我们可以查看当前 cpu 占用率最高的进程，从图中我们可以看出 pid 324023 的这个进程占用的 cpu 使用率比较高，实际生产可能高达 99%。这个截图是我为了演示模拟的。

步骤二：找到进程中占用 cpu 最多的线程

我们继续从 pid 324023 中找到占用 cpu 最多的线程，可以使用 top -H -p 324023 命令来查看

假设 pid 324089 就是我们找到的 cpu 占用率最高的线程，我就简单粗暴的使用 jstack 命令将线程快照打印出来了，后面使用分析工具进行分析。使用以下命令：

jstack -l 324089 > thread-stack.txt

通过分析工具发现，我擦，啥情况线程都 Blocked 了。我们来看下线程什么情况下会进入 Blocked 状态。

阻塞状态（Blocked）

阻塞状态是线程因为某种原因放弃CPU使用权，暂时停止运行。直到线程进入就绪状态，才有机会转到运行状态。阻塞的情况分三种：

等待阻塞：运行的线程执行wait()方法，JVM会把该线程放入等待池中。
同步阻塞：运行的线程在获取对象的同步锁时，若该同步锁被别的线程占用，则JVM会把该线程放入锁池中。
其他阻塞：运行的线程执行sleep()或join()方法，或者发出了I/O请求时，JVM会把该线程置为阻塞状态。当sleep()状态超时、join()等待线程终止或者超时、或者I/O处理完毕时，线程重新转入就绪状态。

步骤三：查看 JVM 内存情况

通过 jmap -heap 324089 命令查看内存的使用情况，突发发现 Eden 、S0、S1 都没有使用……

带着这个疑问，我们进行下一步排查。

步骤四：查看日志、内存快照

gc 日志

通过步骤三发现是不是内存分配出现了问题，于是就赶快去看 gc 日志，我到线上的服务把 gc 日志和 heap dump 都下载到本地，方便进行分析。

通过分析工具我们看下内存的分配，发现 Meta Space 已经分配了 1.13g 的内存了，这个值已经远远超出设置的最大值了，系统中设置 -XX:MaxMetaspaceSize=160m。

从 JDK8 开始，JVM 将原来存放 klass 元数据的永久代 Perm 换成了本地元空间 Metaspace，Perm 时期会为klass元数据分配一块内存，如果设置不够用就会抛出 OOM，Metaspace 的出现希望能解决这个问题，Metaspace 确实可以最大限度来使用堆外的内存，但是挺遗憾，还是有一些参数会导致 Metaspace 抛出 OOM。

通过这个图发现 Full GC 一直在持续，几乎没有间断，这就说明为啥前边看内存时新生代没有内存分配了，因为这里一直在 Full GC 导致工作线程一直在暂停，无法运行。所以请求就开始阻塞响应时间超时、cpu就开始飙升、内存就开始下降，正好应对了前边说到的 3 个现象。

接下来在看 GC 的原因，这里给出了3个原因：

Last ditch collection

当JVM无法为应该存储在元空间中的东西分配内存时，它首先运行GC。它将导致“元数据GC阈值”GC。如果这个GC不能释放空间，那么尝试扩展元空间。如果仍然无法创建空闲空间，则GC将以“Last ditch collection”为由触发。如果仍然没有足够的空闲空间，则抛出OutOfMemoryError。
Metadata GC Threshold

这种类型的GC事件在以下两种情况下触发:
1. 配置的元空间大小小于实际需求
2. 存在类加载器泄漏 (非常不可能，但有可能)
Concurrent Mode Failure

CMS收集器使用一个或多个垃圾收集器线程，这些线程与应用程序线程同时运行，目标是在旧代变得满之前完成对它的收集。CMS收集器在应用程序线程仍然运行的情况下执行大部分跟踪和清理工作，因此应用程序线程只能看到短暂的暂停。但是，如果CMS收集器无法在老一代填满之前完成回收不可达对象，或者如果分配不能满足于老一代中的可用空闲空间块，那么应用程序将暂停并完成收集。不能同时完成收集被称为并发模式失败，这表明需要调整CMS收集器参数。并发模式失败通常触发Full GC。

通过上边的内存分配综合来分析元空间分配了 1.13g ，在加上 GC 原因 Metadata GC Threshold，所以可以看出本次的 GC 就是因为元空间分配的问题引起的。

内存快照

通过 gc 日志的分析，可以看出我们的 gc 是通过元空间引起的，gc原因中提到过 Metadata GC Threshold 发生的情况，其中有一个是类加载泄露。我们把从服务器下载下来的 heap dump 文件通过 IBM HeapAnalyzer 来分析下。

通过内存快照分析，发现了个不一样的Classloader：AviatorClassLoader ，看到这里想起来了，由于项目中有些动态规则的执行，所以使用开源框架 aviatorscript 。于是就去查找项目代码，找到编译执行规则的地方，发现是使用不当，造成每次调用规则都会产生大量的匿名类。

AviatorScript 是一门高性能、轻量级寄宿于 JVM （包括 Android 平台）之上的脚本语言。

复现demo

/**
 * @author lixiaoshuang
 */
@RestController
@RequestMapping("rule")
public class RuleDemo {
    
    @GetMapping
    public void executor() {
        
        String expression = "a + b + c";
        
        Map<String, Object> params = new HashMap<>();
        params.put("a", 1);
        params.put("b", 2);
        params.put("c", 3);
        
        long result = (long) AviatorEvaluator.execute(expression, params, true);
        
        System.out.println("result : " + result);
    }
}

这个规则的含义是通过输入3个参数 a、b、c，计算三个参数的和。我们通过AviatorEvaluator#execute(java.lang.String, java.util.Map<java.lang.String,java.lang.Object>, boolean) 方法执行表达式，这个方法内部是不会缓存编译结果的。在追踪源码中可以看到,如果没有缓存，每次调用都会生成一个匿名 AviatorClassLoader 类返回。

public AviatorClassLoader getAviatorClassLoader(final boolean cached) {
    if (cached) {
      return this.aviatorClassLoader;
    } else {
      return new AviatorClassLoader(this.getClass().getClassLoader());
    }
  }

也就是说每个请求调用规则的时候都是先编译在执行，并且会创建大量的匿名 AviatorClassLoader，所以才会导致 Metaspace 的占用内存一直扩大，最终导致频繁 Full GC。到此这个 Full GC 的问题终于查明白了。

本文只是简单叙述了下排查问题的过程，其中有大量的基础知识和过程并没有详细说明，也不是一篇文章能够明白的，如果有一些错误还望大家见谅和指正

欢迎大家一起来交流

Email: 644968328@qq.com

WeChat: lx6688s

GitHub: github.com/li-xiao-shu…

生产 Full GC 排查过程