GC日志
取了2条最新的GC日志做对比
第一条是系统刚发布完不就机器重启后，做了一次heap dump，触发了一次Full GC
第二条是系统运行2天后，发生了一次Full GC
可以看出是由于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分析
看看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倒排，第一个就是我们要找的
选中这行，右键 list objects -> with outgoing references
发现这个类的实例有10000+
继续选中第一行，右键 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的对象
通过查看源代码，以下就是我们要找的对象
那么为什么会有那么多ClassLoaderWeavingAdaptor，原因是map里面存放了很多个node，每个node都指向一个。我们具体来看一下这个map里面存放的对象，找到那个map，找到outgoing references，仔细看会发现key都是一个AdaptorKey对象，而这个AdaptorKey在构造方法会传入一个ClassLoader对象，这个ClassLoader目前看起来就是org.drools.dynamic.DynamicProjectClassLoader。而且往下一直检查，发现绝大多数AdaptorKey都是这个DynamicProjectClassLoader
这个类一下子引起了我的注意，是我们用到的drools框架中的自定义ClassLoader，难道又是drools规则太多，导致了很多自定义类加载器？
为了搞清楚这个问题，我想得先搞清楚aspectj这个框架，弄明白这个Aj.java到底是干什么的。 通过反复谷歌百度，还有公司内部confluence搜索，得到了一些启发。
由于公司内部有一套自研的调用链跟踪系统，使用到了aspectj无侵入式埋点，而我们项目的启动参数确实配置了 -javaagent
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仍然线性上升。
优化之前
优化之后
这个时候，才发现自己多么愚蠢，最开头的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的加载
项目中确实用到了Google aviator表达式，发现在对表达式进行编译时，AviatorEvaluator.compile 传参第二个值是false，没有对表达式的编译结果进行缓存，可能导致多次编译，然后引起类的反复加载，每一次都是动态创建一个类，这样就造成了Metaspace内存的泄露。
重新修改代码AviatorEvaluator.compile(expr, true)然后发布，继续观察内存，Metaspace used一直保持200多M，不再线性上升，commited也保持在低位（虽然相对其他项目来说，Metaspace这个使用率也比较高了，但是泄露是没有了，使用率较高可能还是跟规则引擎drools框架的使用有关）
至此，问题解决。虽然大部分时间都没找到核心线索，但借此机会也对MAT工具更熟悉了，对aspectj的框架有了进一步了解。
解决问题，方向很重要，Metaspace泄露，直接观察类的加载和卸载过程！
