记一次JVM Full GC (Metadata GC Threshold)调优经历

记一次JVM Full GC (Metadata GC Threshold)调优经历

一、背景：

线上服务器内存使用超过90%，分析上面部署的各个服务的GC日志，发现有一个服务的JVM内存分配过大，使用率较低，有调优的空间，可以在不迁移服务或者不升级服务器配置的情况下，降低服务器内存占用。

JVM推荐配置原则：

  1. 应用程序运行时，计算老年代存活对象的占用空间大小X。程序整个堆大小（Xmx和Xms）设置为X的3 ~ 4倍；永久代PermSize和MaxPermSize设置为X的1.2 ~ 1.5倍。年轻代Xmn的设置为X的1 ~ 1.5倍。老年代内存大小设置为X的2 ~ 3倍。
  2. JDK官方建议年轻代占整个堆大小空间的3/8左右。
  3. 完成一次Full GC后，应该释放出70%的堆空间（30%的空间仍然占用）。

观察线上

Full GC日志1

发现2G的堆内存，Full GC之后的活跃对象才占用60M。按照推荐设置JVM内存只需要给几百M就好了。所以决定改成1G，既能够降低服务器内存占用，也预留了足够的业务增长空间。

在这个过程中，发现如下几个问题：

  1. GC日志没有时间显示，看起来很不方便
  2. GC日志没有滚动，时间久了，日志文件较大
  3. GC日志中存在大量Full GC (Metadata GC Threshold)

显然第三个问题最为严重。我们知道，元数据区主要是用来存储类的元数据的。一般来讲，类加载完成之后，大小应该是比较稳定的，不会有太大变动。所以可以判断，这么频繁的Full GC (Metadata GC Threshold)，肯定是哪里出问题了。

但是我们一步一步来解决问题，而且GC日志不够详细也影响我们定位问题。

二、优化GC日志打印

首先复习一下JVM的GC日志打印的启动参数。详见官方介绍

  • -verbose:gc

同-XX:+PrintGC

  • -XX:+PrintGC

最简单的 GC 参数 会打印 GC 前后堆空间使用情况以及 GC 花费的时间

  • -XX:+PrintGCDetails

打印GC的详细信息，会打印 youngGC FullGC前后堆【新生代，老年代，永久区】的使用情况以及 GC 时用户态 CPU 耗时及系统 CPU 耗时及 GC 实际经历的时间

  • -XX:+PrintGCTimeStamps

打印CG发生的时间戳，从应用启动开始累计的时间戳

  • -XX:+PrintGCDateStamps

打印GC发生的时刻，所处日期时间信息

  • -Xloggc:gc.log

指定GC log的位置，以文件输出

  • -XX:+PrintHeapAtGC

每一次GC前和GC后，都打印堆信息。

所以通过增加-XX:+PrintGCDateStamps解决我的第一个问题。

其次，JVM滚动记录GC日志参数如下：

  • -XX:UseGCLogFileRotation

打开或关闭GC日志滚动记录功能，要求必须设置 -Xloggc参数。

  • -XX:NumberOfGCLogFiles

设置滚动日志文件的个数，必须大于等于1。日志文件命名策略是，.0, .1, ..., .n-1，其中n是该参数的值。

  • -XX:GCLogFileSize

设置滚动日志文件的大小，必须大于8k。当前写日志文件大小超过该参数值时，日志将写入下一个文件。

不过需要注意的是，如果设置滚动，最好保留足够多的滚动日志，以免异常时的GC日志被冲掉。

三、Full GC排查

3.1 现象

最后，我们来解决Full GC (Metadata GC Threshold)的问题。

以下是系统重新启动之后，从GC日志中grep出的Full GC日志。

Full GC日志2

可以观察到如下几个现象：

  • 前几次Full GC, 元数据区的空间并没有释放。
  • 元数据区Full GC前的占用空间会逐渐增大至趋于一个比较稳定的值
  • Full GC过于频繁，几乎没30秒一次Full GC，这太夸张。
3.2 相关知识及分析

抱着这些疑问，我们学习一下metadata的启动参数配置项：

  • -XX:MetaspaceSize

这个参数是初始化的Metaspace大小，该值越大触发Metaspace GC的时机就越晚。随着GC的到来，虚拟机会根据实际情况调控Metaspace的大小，可能增加上线也可能降低。在默认情况下，这个值大小根据不同的平台在12M到20M浮动。使用java -XX:+PrintFlagsInitial命令查看本机的初始化参数，-XX:Metaspacesize为21810376B（大约20.8M）。

  • -XX:MaxMetaspaceSize
    这个参数用于限制Metaspace增长的上限，防止因为某些情况导致Metaspace无限的使用本地内存，影响到其他程序。在本机上该参数的默认值为4294967295B（大约4096MB）。

  • -XX:MinMetaspaceFreeRatio
    当进行过Metaspace GC之后，会计算当前Metaspace的空闲空间比，如果空闲比小于这个参数，那么虚拟机将增长Metaspace的大小。在本机该参数的默认值为40，也就是40%。设置该参数可以控制Metaspace的增长的速度，太小的值会导致Metaspace增长的缓慢，Metaspace的使用逐渐趋于饱和，可能会影响之后类的加载。而太大的值会导致Metaspace增长的过快，浪费内存。

  • -XX:MaxMetasaceFreeRatio
    当进行过Metaspace GC之后， 会计算当前Metaspace的空闲空间比，如果空闲比大于这个参数，那么虚拟机会释放Metaspace的部分空间。在本机该参数的默认值为70，也就是70%。

  • -XX:MaxMetaspaceExpansion
    Metaspace增长时的最大幅度。在本机上该参数的默认值为5452592B（大约为5MB）。

  • -XX:MinMetaspaceExpansion
    Metaspace增长时的最小幅度。在本机上该参数的默认值为340784B（大约330KB为）。

那么我们可以得到结论：

  • 前几次Full GC，是因为默认的-XX:MetaspaceSize 设置的太小而导致的。我们可以根据自己的应用情况适当调大。
  • 后面逐渐增大并动态稳定的原因是-XX:MinMetaspaceFreeRatio和-XX:MaxMetasaceFreeRatio这两个参数在起作用。空闲比 = GC释放内存/GC前的大小，GC释放得太多，就缩小MetaSpaceSize，释放得太少，就扩大MetaSpaceSize。

同时，复习一下元数据区GC的相关知识：

Metaspace中的类需要满足什么条件才能够被当成垃圾被卸载回收？

条件还是比较严苛的，需同时满足如下三个条件的类才会被卸载：

  1. 该类所有的实例都已经被回收；
  2. 加载该类的ClassLoader已经被回收；
  3. 该类对应的java.lang.Class对象没有任何地方被引用。

从GC日志我们可以看到，Metaspace已使用内存在Full GC后明显变小（219105K -> 92087K），说明Metaspace经过Full GC后，确实卸载了很多类。

从这点来看，我们有理由怀疑系统可能在频繁地生成大量”一次性“的类，导致Metaspace所占用空间不断增长，增长到GC阈值后触发Full GC。

那么这些被回收的类是什么呢？为了弄清楚这点，我增加了如下两个JVM启动参数来观察类的加载、卸载信息：

-XX:TraceClassLoading -XX:TraceClassUnloading

加了这两个参数后，系统跑了一段时间，从GC日志中发现大量如下的日志：

GC日志中的类加载记录

将Aviator与Full GC做一个关联搜索，果然遇到这个问题的，不止我一个。

同时也在作者的github上找到相关的issue.

3.3 源码解析

查看代码我们可以看到Aviator提供了两个调用接口：

public static Object execute(String expression, Map<String, Object> env, boolean cached) {
	return getInstance().execute(expression, env, cached);
}
public static Object execute(String expression, Map<String, Object> env) {
	return execute(expression, env, false);
}

深入源码：

public Expression compile(final String expression, final boolean cached) {
        if (expression != null && expression.trim().length() != 0) {
            if (cached) {
                FutureTask<Expression> task = (FutureTask)this.cacheExpressions.get(expression);
                if (task != null) {
                    return this.getCompiledExpression(expression, task);
                } else {
                    task = new FutureTask(new Callable<Expression>() {
                        public Expression call() throws Exception {
                            return AviatorEvaluatorInstance.this.innerCompile(expression, cached);
                        }
                    });
                    FutureTask<Expression> existedTask = (FutureTask)this.cacheExpressions.putIfAbsent(expression, task);
                    if (existedTask == null) {
                        existedTask = task;
                        task.run();
                    }

                    return this.getCompiledExpression(expression, existedTask);
                }
            } else {
                return this.innerCompile(expression, cached);
            }
        } else {
            throw new CompileExpressionErrorException("Blank expression");
        }
    }

可以发现核心方法是innerCompile方法。继续深入找到cached参数最底层的使用：

public AviatorClassLoader getAviatorClassLoader(boolean cached) {
        return cached ? this.aviatorClassLoader : new AviatorClassLoader(Thread.currentThread().getContextClassLoader());
    }

综上，我们发现

  • cached参数为true时，会优先从缓存中获取编译好的表达式对象。同时使用编译表达式使用的类加载器也是同一个。
  • 而cached为false时，每次执行表达式都会去编译表达式，且每次编译使用的是一个全新的类加载器。这是导致元数据区加载太多"一次性"类的元凶。

四、问题解决

最终，在调用参数中，将cached设置为true，成功解决Full GC (Metadata GC Threshold)问题。

成功解决该问题，内存使用率由原先的90%多下降到80%左右这样一个比较健康的水平，能够给业务增长留有空间。

服务器内存使用图表

观察GC日志，也没有Full GC (Metadata GC Threshold)的日志了。

通过这次调优过程，学习巩固了一些 JVM GC相关的启动参数，并对Metadata元数据区的内存管理有了更加详细的认识。

posted @ 2021-06-09 19:35  Ellen艾伦  阅读(5402)  评论(0)  编辑  收藏  举报