GC日志
取了2條最新的GC日志做對比
第一條是系統(tǒng)剛發(fā)布完不就機(jī)器重啟后，做了一次heap dump，觸發(fā)了一次Full GC
第二條是系統(tǒng)運(yùn)行2天后，發(fā)生了一次Full GC
可以看出是由于Metadata GC Threshold引起的，而且耗時(shí)居然有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默認(rèn)的內(nèi)存泄露分析報(bào)告
Problem Suspect1
KieContainerFactory類里面，ConcurrentHashMap$Node[]這個(gè)類的實(shí)例出現(xiàn)了非常多次，內(nèi)存占比達(dá)到了15.22%
查看代碼，KieContainerFactory內(nèi)部確實(shí)有一個(gè)ConcurrentHashMap屬性，map里面的對象是在Spring init的時(shí)候初始化進(jìn)去的，我們這個(gè)域是執(zhí)行規(guī)則引擎drools的服務(wù)，KieContainer的創(chuàng)建邏輯很重，所以需要預(yù)熱放到內(nèi)存中，規(guī)則執(zhí)行的時(shí)候直接創(chuàng)建KieSession，然后執(zhí)行。查看了一下，系統(tǒng)正常運(yùn)行的規(guī)則有幾千個(gè)，所以看起來這個(gè)內(nèi)存占用是正常的業(yè)務(wù)需要。
Problem Suspect2
ClassLoaderWeavingAdaptor類出現(xiàn)了9200+個(gè)實(shí)例，而且這些實(shí)例都是被 java.util.HashMap$Node[]這個(gè)類的實(shí)例引用指向，總共內(nèi)存占用達(dá)到了60%，非常可怕。
這個(gè)看起來是aspectj框架的類，里面存的到底是啥呢，我們慢慢分析
首先，打開Histogram視圖，按照Retained Heap倒排，第一個(gè)就是我們要找的
選中這行，右鍵 list objects -> with outgoing references
發(fā)現(xiàn)這個(gè)類的實(shí)例有10000+
繼續(xù)選中第一行，右鍵 list objects -> with incoming references
發(fā)現(xiàn)是 org.aspectj.weaver.loadtime.Aj#WeaverContainer 這個(gè)類里面，有一個(gè)名稱為 weavingAdaptors，類型為 java.utils.Collections.synchronizedMap的屬性，而這個(gè)map的key是org.aspectj.weaver.loadtime.AjExplicitlyInitializedClassLoaderWeavingAdaptor，而ExplicitlyInitializedClassLoaderWeavingAdaptor這個(gè)內(nèi)部類里面又有一個(gè)weavingAdaptor的對象
通過查看源代碼，以下就是我們要找的對象
那么為什么會有那么多ClassLoaderWeavingAdaptor，原因是map里面存放了很多個(gè)node，每個(gè)node都指向一個(gè)。我們具體來看一下這個(gè)map里面存放的對象，找到那個(gè)map，找到outgoing references，仔細(xì)看會發(fā)現(xiàn)key都是一個(gè)AdaptorKey對象，而這個(gè)AdaptorKey在構(gòu)造方法會傳入一個(gè)ClassLoader對象，這個(gè)ClassLoader目前看起來就是org.drools.dynamic.DynamicProjectClassLoader。而且往下一直檢查，發(fā)現(xiàn)絕大多數(shù)AdaptorKey都是這個(gè)DynamicProjectClassLoader
這個(gè)類一下子引起了我的注意，是我們用到的drools框架中的自定義ClassLoader，難道又是drools規(guī)則太多，導(dǎo)致了很多自定義類加載器？
為了搞清楚這個(gè)問題，我想得先搞清楚aspectj這個(gè)框架，弄明白這個(gè)Aj.java到底是干什么的。 通過反復(fù)谷歌百度，還有公司內(nèi)部confluence搜索，得到了一些啟發(fā)。
由于公司內(nèi)部有一套自研的調(diào)用鏈跟蹤系統(tǒng)，使用到了aspectj無侵入式埋點(diǎn)，而我們項(xiàng)目的啟動參數(shù)確實(shí)配置了 -javaagent
aspectj在做類的織入之前，會調(diào)用org.aspectj.weaver.loadtime.Aj#preProcess方法，方法內(nèi)部會進(jìn)行WeaverContainer（即weavingAdaptors）的初始化，在創(chuàng)建weavingAdaptor之前會有一個(gè)是否跳過的判斷，這個(gè)loadersToSkip 實(shí)際上讀取了系統(tǒng)屬性配置。
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;
}
}
//------------------------- !!!關(guān)鍵代碼在這里，get的時(shí)候如果沒有則創(chuàng)建
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();
}
}
那么，現(xiàn)在weavingAdaptors里有很多Map.Node的原因找到了，是因?yàn)橛泻芏郉ynamicProjectClassLoader，每個(gè)加載器在加載類的時(shí)候 ，都會被Aj.preClass攔截，都會生產(chǎn)一個(gè)ClassLoaderWeavingAdaptor對象。（至于為什么會有這么多類加載器，本機(jī)調(diào)試發(fā)現(xiàn)是由于每個(gè)KieContainer創(chuàng)建的時(shí)候都有單獨(dú)的類加載器，而且不止這一個(gè)，具體原因不贅述）
因?yàn)樯a(chǎn)必須使用aspectj實(shí)現(xiàn)全鏈路跟蹤，那么我們就要針對這個(gè)自定義類加載器做優(yōu)化，所以我們就需要指定跳過
-Daj.weaving.loadersToSkip=org.drools.core.rule.JavaDialectRuntimeData$PackageClassLoader,org.drools.dynamic.DynamicProjectClassLoader
看到這里，或許你跟我一樣，以為解決了，終于可以松一口氣了。還好我沉得住氣，先修改配置，再觀察一下，才能跟領(lǐng)導(dǎo)匯報(bào)結(jié)果。
沒想到，改完重啟后，Heap Usage確實(shí)降下來了，但是Metaspace Usage仍然線性上升。
優(yōu)化之前
優(yōu)化之后
這個(gè)時(shí)候，才發(fā)現(xiàn)自己多么愚蠢，最開頭的GC日志已經(jīng)明確顯示是Metaspace GC Threshold，而我找了半天問題，解決的根本不是Metaspace的問題。埋頭繼續(xù)......
找到一些參考資料：
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啟動參數(shù)，觀察類的加載和卸載
-XX:+TraceClassLoading -XX:+TraceClassUnloading
持續(xù)調(diào)用接口，發(fā)現(xiàn)有特別多com.googlecode.aviator.Expression的加載
項(xiàng)目中確實(shí)用到了Google aviator表達(dá)式，發(fā)現(xiàn)在對表達(dá)式進(jìn)行編譯時(shí)，AviatorEvaluator.compile 傳參第二個(gè)值是false，沒有對表達(dá)式的編譯結(jié)果進(jìn)行緩存，可能導(dǎo)致多次編譯，然后引起類的反復(fù)加載，每一次都是動態(tài)創(chuàng)建一個(gè)類，這樣就造成了Metaspace內(nèi)存的泄露。
重新修改代碼AviatorEvaluator.compile(expr, true)然后發(fā)布，繼續(xù)觀察內(nèi)存，Metaspace used一直保持200多M，不再線性上升，commited也保持在低位（雖然相對其他項(xiàng)目來說，Metaspace這個(gè)使用率也比較高了，但是泄露是沒有了，使用率較高可能還是跟規(guī)則引擎drools框架的使用有關(guān)）
至此，問題解決。雖然大部分時(shí)間都沒找到核心線索，但借此機(jī)會也對MAT工具更熟悉了，對aspectj的框架有了進(jìn)一步了解。
解決問題，方向很重要，Metaspace泄露，直接觀察類的加載和卸載過程！
