大量类加载器创建导致诡异 FullGC

现象

最近接手了一个同事的项目，某一天接口的响应耗时突然增加了很多，由几十ms 增加到了几十秒。

首先查看机器上的日志，有调用第三方接口超时，查询数据库超时。立马查看第三方接口监控和数据库监控，一切正常。可能由于 GC 停顿造成统计的超时，这个时候我们通过 jstat -gcutil pid 查看 gc 情况。数据如下：

S0 S1 E O M CCS YGC YGCT FGC FGCT GCT

0.00 0.00 3.88 12.86 76.39 45.62 211 8.574 892 626.192 634.767

0.00 0.00 4.10 12.86 76.39 45.62 211 8.574 893 626.192 634.767

0.00 0.00 0.00 12.88 76.39 45.62 211 8.574 894 626.915 635.489

0.00 0.00 0.11 12.88 76.39 45.62 211 8.574 896 627.678 636.253

0.00 0.00 0.00 12.87 76.39 45.62 211 8.574 897 628.926 637.500

0.00 0.00 0.00 12.87 76.39 45.62 211 8.574 899 630.381 638.956

0.00 0.00 1.92 12.87 76.39 45.62 211 8.574 901 631.155 639.729

0.00 0.00 0.00 12.87 76.39 45.62 211 8.574 902 632.379 640.954

0.00 0.00 2.14 12.87 76.39 45.62 211 8.574 903 633.094 641.668

0.00 0.00 0.00 12.88 76.39 45.62 211 8.574 904 633.859 642.433

这里我们可以看到年轻代(E) 使用率很小，老年代(O)使用率 12% 也不多，M(Metaspace) 使用率 76.39% 也没占满，Yong GC 没有变化，Full GC 一直在进行，每次耗时800多ms。结合前面 E、O 和 M 使用率都没有变化，说明内存一直回收不掉。

JVM 内存大小相关配置如下：

-Xms3g -Xmx3g -Xmn1g -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m

接下来我们看下 GC 日志：

2020-08-13T23:11:00.352+0800: 214929.371: [GC (CMS Initial Mark) 276144K(3040896K), 0.0405942 secs]

2020-08-13T23:11:00.886+0800: 214929.905: [Full GC (Metadata GC Threshold) 290482K->275966K(3040896K), 0.7939954 secs]

2020-08-13T23:11:01.693+0800: 214930.712: [Full GC (Last ditch collection) 275966K->275964K(3040896K), 0.8086755 secs]

2020-08-13T23:11:02.520+0800: 214931.539: [Full GC (Metadata GC Threshold) 295199K->273816K(3040896K), 0.8332017 secs]

2020-08-13T23:11:03.366+0800: 214932.385: [Full GC (Last ditch collection) 273816K->273799K(3040896K), 0.7748226 secs]

GC 日志中有 Metadata GC Threshold ，结合前面 Metaspace 使用率最高我们猜测可能是 Metaspace 溢出了，然后我们在日志中 grep OutOfMemory 关键字，有如下报错：

java.lang.OutOfMemoryError: Metaspace

至此可以确认是 Metaspace 出问题了，但是为什么 jstat 输出的使用率只有 76.39% 呢？大家如果经常使用 jstat 看一下正常的程序就会很多正常情况 Metaspace 都占用 90% 以上。

Metaspace

Metaspace 元数据空间，专门用来存储类的元数据，它是 JDK8 中用来替代 Perm 的特殊数据结构。

Metaspace 空间被分配在本地内存中(非堆上)，默认不限制内存使用，可以使用 MaxMetaspaceSize 指定最大值。MetaspaceSize 指定最小值，默认 21 M。通过 mmap 来从操作系统申请内存，申请的内存会分成一个一个 Metachunk，以 Metachunk 为单位将内存分配给类加载器，每个 Metachunk 对应唯一一个类加载器，一个类加载器可以有多个 Metachunk 。

可以用 java -XX:+PrintFlagsFinal -version 来查看 JVM 的默认参数值

在 Java 虚拟机中，每个类加载器都有一个 ClassLoaderData 的数据结构，ClassloaderData 内部有管理内存的 Metaspace，Metaspace 在 initialize 的时候会调用 get_initialization_chunk 分配第一块 Metachunk，类加载器在类的时候是以 Metablock 为单位来使用 Metachunk。

//classLoaderData.hpp

class ClassLoaderData : public CHeapObj<mtClass> {

...

Metaspace * _metaspace; // Meta-space where meta-data defined by the

// classes in the class loader are allocated.

Mutex* _metaspace_lock; // Locks the metaspace for allocations and setup.

...

}

// metaspace.hpp

class Metaspace : public CHeapObj<mtClass> {

...

private:

void initialize(Mutex* lock, MetaspaceType type);

Metachunk* get_initialization_chunk(MetadataType mdtype,

size_t chunk_word_size,

size_t chunk_bunch);

...

}

// metachunk.hpp

class Metachunk : public Metabase<Metachunk>

class Metablock : public Metabase<Metablock>

// Metablock 和 Metachunk 的父类

template <class T>

class Metabase VALUE_OBJ_CLASS_SPEC {

size_t _word_size;

T* _next;

T* _prev;

...

}

下图所示是每个类加载器分配内存结构。

接下来我们讲下什么时候会触发 FullGC，有个参数 MinMetaspaceFreeRatio(默认40) ，当满足如下条件就会进行 GC，如果当前需要申请的内存比剩余可以 commit 的空间还要大，如果还没有达到 MaxMetaspaceSize 的话，会触发扩容。

剩余可以 commit 的空间大小 < (commited 大小 * MinMetaspaceFreeRatio)

上面说到 commited 的内存，这里还有几个概念：used、capacity、reserved，如下图所示

used: chunk 中已经使用的 block 内存，这些 block 中都加载了类的数据。
capacity：在使用的 chunk 内存。
commited：所有分配的 chunk 内存，这里包含空闲可以再次被利用的。
reserved：是可以使用的内存大小。

如下所示，是打印出来的内存信息，最后一行是开启压缩指针(64位压缩为32位)后，Metaspace 中专门存放 kclass 的信息。

Heap

par new generation total 30720K, used 1519K [0x00000007f8600000, 0x00000007fa750000, 0x00000007fa750000)

eden space 27328K, 5% used [0x00000007f8600000, 0x00000007f877bcc8, 0x00000007fa0b0000)

from space 3392K, 0% used [0x00000007fa400000, 0x00000007fa400000, 0x00000007fa750000)

to space 3392K, 0% used [0x00000007fa0b0000, 0x00000007fa0b0000, 0x00000007fa400000)

concurrent mark-sweep generation total 68288K, used 21614K [0x00000007fa750000, 0x00000007fea00000, 0x00000007fea00000)

Metaspace used 23505K, capacity 30704K, committed 30720K, reserved 1073152K

class space used 3341K, capacity 7550K, committed 7552K, reserved 1048576K

基础知识讲完了，现在我们回到开头，我们通过 jstat 打印出的 M 是怎么计算的呢？这里使用率并不是我们理解的整个 Metaspace 内存的使用率。

M = used / commited

所以 Metaspace 内存溢出了，使用率也才 76%，有两种可能：

这次分配的内存达到了 61M( 256M*24% ) 以上？
给类加载器分配的 chunk 使用率很低？

第一种显然不太可能，一个类不可能需要这么大的内存。第二种有种情况，当创建很多类加载器，而每个类加载器又加载了很少的类。

上面我们说了剩余空闲内存小于metaspaceGC的阈值就会执行FullGC，但是我们开头说有些正常场景我们通过 jstat 打印的使用率都达到了 90% 多都没有触发 FullGC，这是为什么呢？欢迎留言分享你的答案

排查程序

首先，我们看下 Metaspace 加载的到底是哪些类

jcmd pid GC.class_stats |awk '{print $13}'| sort | uniq -c |sort -r| head

通过 jcmd 查看加载的类，然后统计数量，我们看到，Script1 被加载了两万多次，按 JVM 类加载的双亲委派方式，一个类最多被加载一次，这里出现了多次，可能是不同的类加载器加载的。

27348 Script1

2 ClassName

1 sun.util.spi.CalendarProvider

1 sun.util.resources.en.TimeZoneNames_en

1 sun.util.resources.en.CurrencyNames_en_US

1 sun.util.resources.en.CalendarData_en

1 sun.util.resources.TimeZoneNamesBundle

1 sun.util.resources.TimeZoneNames

1 sun.util.resources.ParallelListResourceBundle$KeySet

通过 jcmd 查看，需要在启动是加上参数：-XX:+UnlockDiagnosticVMOptions

然后我们再看下 JVM 类加载器的数据

jmap -clstats pid

这里 classes 是加载类的数量，从输出中可以看到有大量 GroovyClassLoader 类加载器。

class_loader classes bytes parent_loader alive? type

0x000000077bc27bc0 1 1394 0x000000077bc64418 dead groovy/lang/GroovyClassLoader$InnerLoader@0x00000007f0dcf828

0x000000077d9e7d98 0 0 0x0000000770800000 dead groovy/lang/GroovyClassLoader@0x00000007f0af9890

0x00000007805e8050 0 0 0x0000000770800000 dead groovy/lang/GroovyClassLoader@0x00000007f0af9890

0x000000077df07de0 0 0 0x0000000770800000 dead groovy/lang/GroovyClassLoader@0x00000007f0af9890

0x0000000780028010 1 1394 0x000000078005a6c8 dead groovy/lang/GroovyClassLoader$InnerLoader@0x00000007f0dcf828

0x0000000776467650 1 1394 0x000000077646b190 dead groovy/lang/GroovyClassLoader$InnerLoader@0x00000007f0dcf828

0x000000077a167a00 1 1394 0x000000077a16b380 dead groovy/lang/GroovyClassLoader$InnerLoader@0x00000007f0dcf828

通过统计，每个 GroovyClassLoader$InnerLoader 都只加载一个类，然后他的数量一共有 27348，跟上面的 Script1 类数量刚好对的上，说明就是这个类加载器加载的。

接下来怎么定位哪里生产的类加载器加载的类呢？

首先看 groovy 是哪里引入的，然后本地调试，加上JVM 参数：-XX:+UnlockDiagnosticVMOptions，加载类的时候控制台就会打印，就可以一步一步定位到哪里加载的。

我们项目中用 sharding 做的分表，sharding 引入的 groovy 版本如下

<groupId>io.shardingsphere</groupId>

<artifactId>sharding-jdbc-spring-boot-starter</artifactId>

</dependency>

<groupId>org.codehaus.groovy</groupId>

<artifactId>groovy</artifactId>

</dependency>

最终定位到出现问题的代码如下，当你配置分表的表达式后，每次执行查询操作，都会创建一个 GroovyShell 来执行配置的表达式。在 GroovyShell 中，每次都会生成一个类加载器，来加载类 Script1，加载完后又无法被 GC 掉，导致内存泄露。

public InlineShardingStrategy(final InlineShardingStrategyConfiguration inlineShardingStrategyConfig) {

Preconditions.checkNotNull(inlineShardingStrategyConfig.getShardingColumn(), "Sharding column cannot be null.");

Preconditions.checkNotNull(inlineShardingStrategyConfig.getAlgorithmExpression(), "Sharding algorithm expression cannot be null.");

shardingColumn = inlineShardingStrategyConfig.getShardingColumn();

String algorithmExpression = InlineExpressionParser.handlePlaceHolder(inlineShardingStrategyConfig.getAlgorithmExpression().trim());

closure = (Closure) new GroovyShell().evaluate(Joiner.on("").join("{it -> \"", algorithmExpression, "\"}"));

}

这里升级 sharding 新版本即可，新版本中 GroovyShell 是static 的。

public final class InlineExpressionParser {

...

private static final GroovyShell SHELL = new GroovyShell();

...

}

这里还有个疑问，类加载器加载用完了并且状态是 dead 为什么不回收掉呢？

本地复现

复现的代码很简单，引入上述 groovy 版本，在运行时加上 JVM 参数

// -Xmx100M -Xms100M -verbose:class -XX:+PrintGCDetails -XX:MaxMetaspaceSize=30M -XX:MetaspaceSize=30M -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+UnlockDiagnosticVMOptions -XX:+HeapDumpOnOutOfMemoryError

public static void main(String[] args) {

for (int i = 0; i < 4000; i++) {

new GroovyShell().parse("");

}

接下来主要讲下，怎么用 mat 来排查这个类加载为什么没有被回收。用 mat 加载上示例程序 dump 出来的堆，选择 Histogram ，然后在正则中输入 GroovyClassLoader ，Objects 是表示创建对象数量，这里有 3255 个，说明上面的 for 循环执行了 3255 次之后 Metaspace 就溢出了。