一次Full GC [Metadata GC Threshold

GC日志

取了2条最新的GC日志做对比
第一条是系统刚发布完不就机器重启后，做了一次heap dump，触发了一次Full GC
第二条是系统运行2天后，发生了一次Full GC

image.png

可以看出是由于Metadata GC Threshold引起的，而且耗时居然有10s，非常恐怖

2022-05-14T13:10:37.806+0800: 178995.554: 
[Full GC (Metadata GC Threshold) 2022-05-14T13:10:37.807+0800: 178995.554: 
[CMS: 2198976K->2012812K(5242880K), 9.7080398 secs] 2627723K->2012812K(6186624K), 
[Metaspace: 575152K->575152K(1906688K)], 10.1689786 secs] 
[Times: user=8.84 sys=1.32, real=10.17 secs] 

Heap dump下载

MAT分析

image.png

看看MAT默认的内存泄露分析报告

Problem Suspect1

KieContainerFactory类里面，ConcurrentHashMap$Node[]这个类的实例出现了非常多次，内存占比达到了15.22%

查看代码，KieContainerFactory内部确实有一个ConcurrentHashMap属性，map里面的对象是在Spring init的时候初始化进去的，我们这个域是执行规则引擎drools的服务，KieContainer的创建逻辑很重，所以需要预热放到内存中，规则执行的时候直接创建KieSession，然后执行。查看了一下，系统正常运行的规则有几千个，所以看起来这个内存占用是正常的业务需要。

Problem Suspect2

ClassLoaderWeavingAdaptor类出现了9200+个实例，而且这些实例都是被 java.util.HashMap$Node[]这个类的实例引用指向，总共内存占用达到了60%，非常可怕。

这个看起来是aspectj框架的类，里面存的到底是啥呢，我们慢慢分析

首先，打开Histogram视图，按照Retained Heap倒排，第一个就是我们要找的

image.png

选中这行，右键 list objects -> with outgoing references
发现这个类的实例有10000+

image.png

继续选中第一行，右键 list objects -> with incoming references

发现是 org.aspectj.weaver.loadtime.Aj#WeaverContainer 这个类里面，有一个名称为 weavingAdaptors，类型为 java.utils.Collections.synchronizedMap的属性，而这个map的key是org.aspectj.weaver.loadtime.AjExplicitlyInitializedClassLoaderWeavingAdaptor，而ExplicitlyInitializedClassLoaderWeavingAdaptor这个内部类里面又有一个weavingAdaptor的对象

image.png

通过查看源代码，以下就是我们要找的对象

image.png image.png

那么为什么会有那么多ClassLoaderWeavingAdaptor，原因是map里面存放了很多个node，每个node都指向一个。我们具体来看一下这个map里面存放的对象，找到那个map，找到outgoing references，仔细看会发现key都是一个AdaptorKey对象，而这个AdaptorKey在构造方法会传入一个ClassLoader对象，这个ClassLoader目前看起来就是org.drools.dynamic.DynamicProjectClassLoader。而且往下一直检查，发现绝大多数AdaptorKey都是这个DynamicProjectClassLoader

image.png

这个类一下子引起了我的注意，是我们用到的drools框架中的自定义ClassLoader，难道又是drools规则太多，导致了很多自定义类加载器？

为了搞清楚这个问题，我想得先搞清楚aspectj这个框架，弄明白这个Aj.java到底是干什么的。 通过反复谷歌百度，还有公司内部confluence搜索，得到了一些启发。

由于公司内部有一套自研的调用链跟踪系统，使用到了aspectj无侵入式埋点，而我们项目的启动参数确实配置了 -javaagent

image.png

aspectj在做类的织入之前，会调用org.aspectj.weaver.loadtime.Aj#preProcess方法，方法内部会进行WeaverContainer（即weavingAdaptors）的初始化，在创建weavingAdaptor之前会有一个是否跳过的判断，这个loadersToSkip 实际上读取了系统属性配置。

public static List<String> loadersToSkip = null;

    static {
        // pr271840 - touch the types early and outside the locks
        new ExplicitlyInitializedClassLoaderWeavingAdaptor(new ClassLoaderWeavingAdaptor());
        try {
            String loadersToSkipProperty = System.getProperty("aj.weaving.loadersToSkip","");
            StringTokenizer st = new StringTokenizer(loadersToSkipProperty, ",");
            if (loadersToSkipProperty != null && loadersToSkip == null) {
                if (st.hasMoreTokens()) {
//                  System.out.println("aj.weaving.loadersToSkip is set. Skipping loaders: '"+loadersToSkipProperty+"'");
                    loadersToSkip = new ArrayList<String>();
                }
                while (st.hasMoreTokens()) {
                    String nextLoader = st.nextToken();
                    loadersToSkip.add(nextLoader);
                }
            }
        } catch (Exception e) {
            // Likely security issue related to property access...
        }
    }

public byte[] preProcess(String className, byte[] bytes, ClassLoader loader, ProtectionDomain protectionDomain) {
        if (loader == null || className == null || 
            loader.getClass().getName().equals(deleLoader) || loader.getClass().getName().equals(deleLoader2)) {
            // skip boot loader, null classes (hibernate), or those from a reflection loader
            return bytes;
        }
        // ----------------------- !!! 这里可以自定义跳过的类加载器
        if (loadersToSkip != null) {
            // Check whether to reject it
            if (loadersToSkip.contains(loader.getClass().getName())) {
//              System.out.println("debug: no weaver created for loader '"+loader.getClass().getName()+"'");
                return bytes;
            }
        }

        if (trace.isTraceEnabled())
            trace.enter("preProcess", this, new Object[] { className, bytes, loader });
        if (trace.isTraceEnabled())
            trace.event("preProcess", this, new Object[] { loader.getParent(), Thread.currentThread().getContextClassLoader() });

        try {
            synchronized (loader) {

                if (SimpleCacheFactory.isEnabled()) {
                    byte[] cacheBytes= laCache.getAndInitialize(className, bytes,loader,protectionDomain);
                    if (cacheBytes!=null){
                            return cacheBytes;
                    }
                }

//------------------------- !!!关键代码在这里，get的时候如果没有则创建
                WeavingAdaptor weavingAdaptor = WeaverContainer.getWeaver(loader, weavingContext);
                if (weavingAdaptor == null) {
                    if (trace.isTraceEnabled())
                        trace.exit("preProcess");
                    return bytes;
                }
                try {
                    weavingAdaptor.setActiveProtectionDomain(protectionDomain);
                    byte[] newBytes = weavingAdaptor.weaveClass(className, bytes, false);
                    Dump.dumpOnExit(weavingAdaptor.getMessageHolder(), true);
                    if (trace.isTraceEnabled())
                        trace.exit("preProcess", newBytes);
                    if (SimpleCacheFactory.isEnabled()) {
                        laCache.put(className, bytes, newBytes);
                    }
                    return newBytes;
                } finally {
                    weavingAdaptor.setActiveProtectionDomain(null);
                }
            }

            /* Don't like to do this but JVMTI swallows all exceptions */
        } catch (Throwable th) {
            trace.error(className, th);
            Dump.dumpWithException(th);
            // FIXME AV wondering if we should have the option to fail (throw runtime exception) here
            // would make sense at least in test f.e. see TestHelper.handleMessage()
            if (trace.isTraceEnabled())
                trace.exit("preProcess", th);
            return bytes;
        } finally {
            CompilationAndWeavingContext.resetForThread();
        }
    }

那么，现在weavingAdaptors里有很多Map.Node的原因找到了，是因为有很多DynamicProjectClassLoader，每个加载器在加载类的时候 ，都会被Aj.preClass拦截，都会生产一个ClassLoaderWeavingAdaptor对象。（至于为什么会有这么多类加载器，本机调试发现是由于每个KieContainer创建的时候都有单独的类加载器，而且不止这一个，具体原因不赘述）
因为生产必须使用aspectj实现全链路跟踪，那么我们就要针对这个自定义类加载器做优化，所以我们就需要指定跳过

-Daj.weaving.loadersToSkip=org.drools.core.rule.JavaDialectRuntimeData$PackageClassLoader,org.drools.dynamic.DynamicProjectClassLoader

看到这里，或许你跟我一样，以为解决了，终于可以松一口气了。还好我沉得住气，先修改配置，再观察一下，才能跟领导汇报结果。
没想到，改完重启后，Heap Usage确实降下来了，但是Metaspace Usage仍然线性上升。

优化之前

image.png

优化之后

image.png

这个时候，才发现自己多么愚蠢，最开头的GC日志已经明确显示是Metaspace GC Threshold，而我找了半天问题，解决的根本不是Metaspace的问题。埋头继续......

找到一些参考资料：
https://mp.weixin.qq.com/s/qgpMMR8-493-Y9uwWiMdRg
https://mp.weixin.qq.com/s/N7YKNGHL3g6oEXKUcTDlZg
http://lovestblog.cn/blog/2016/10/29/metaspace/

然后，通过配置jvm启动参数，观察类的加载和卸载
-XX:+TraceClassLoading -XX:+TraceClassUnloading

持续调用接口，发现有特别多com.googlecode.aviator.Expression的加载

image.png

项目中确实用到了Google aviator表达式，发现在对表达式进行编译时，AviatorEvaluator.compile 传参第二个值是false，没有对表达式的编译结果进行缓存，可能导致多次编译，然后引起类的反复加载，每一次都是动态创建一个类，这样就造成了Metaspace内存的泄露。

image.png

重新修改代码AviatorEvaluator.compile(expr, true)然后发布，继续观察内存，Metaspace used一直保持200多M，不再线性上升，commited也保持在低位（虽然相对其他项目来说，Metaspace这个使用率也比较高了，但是泄露是没有了，使用率较高可能还是跟规则引擎drools框架的使用有关）

image.png

至此，问题解决。虽然大部分时间都没找到核心线索，但借此机会也对MAT工具更熟悉了，对aspectj的框架有了进一步了解。
解决问题，方向很重要，Metaspace泄露，直接观察类的加载和卸载过程！