前言
? ? ? 隨著業(yè)務(wù)的快速增長(zhǎng)，日志導(dǎo)致的線程 Block 問題愈發(fā)頻繁。比如調(diào)用后端 RPC 服務(wù)超時(shí)，導(dǎo)致調(diào)用方大量線程 Block；再比如，業(yè)務(wù)內(nèi)部輸出異常日志導(dǎo)致服務(wù)大量線程 Block 等，這些問題嚴(yán)重影響著服務(wù)的穩(wěn)定性。
AsyncAppender 導(dǎo)致線程 Block
? ? ? ? 通過監(jiān)控平臺(tái)查看線程監(jiān)控指標(biāo)，從 Blocked 線程堆棧不難看出是跟日志打印相關(guān)，由于是 ERROR 級(jí)別日志，查看具體報(bào)錯(cuò)日志，發(fā)現(xiàn)有兩種業(yè)務(wù)異常。
? ? ? ? 從 Blocked 線程堆棧中可以看出，線程阻塞在類加載流程上，發(fā)現(xiàn)加載類時(shí)確實(shí)會(huì)根據(jù)類名來加 synchronized 同步塊，因此初步猜測(cè)是類加載導(dǎo)致線程 Block。
注意：
1、項(xiàng)目代碼里只是普通地輸出一條 ERROR 日志而已，為何會(huì)觸發(fā)類加載？
2、通常情況下類加載幾乎不會(huì)觸發(fā)線程 Block，不然一個(gè)項(xiàng)目要加載成千上萬個(gè)類，如果因?yàn)榧虞d類就導(dǎo)致 Block，那項(xiàng)目就沒法正常運(yùn)行了。
為什么會(huì)觸發(fā)類加載？
? ? ? 從 Blocked 線程堆棧著手分析，查看堆棧中的 ThrowableProxy 相關(guān)代碼，發(fā)現(xiàn)其構(gòu)造函數(shù)會(huì)遍歷整個(gè)異常堆棧中的所有堆棧元素，最終獲取所有堆棧元素類所在的 JAR 名稱和版本信息。
具體流程如下：
1、首先獲取堆棧元素的類名稱。
2、再通過 loadClass 的方式獲取對(duì)應(yīng)的 Class 對(duì)象。
3、進(jìn)一步獲取該類所在的 JAR 信息，從 CodeSource 中獲取 JAR 名稱，從Package 中獲取 JAR 版本。
? ? ? ? 當(dāng)前問題已在2.11.1版本中修復(fù)，通過讓 get/put 方法使用同一個(gè) key 來修復(fù)緩存的有效性問題，但由于 ThrowableProxy 對(duì)每個(gè) Throwable 都會(huì)創(chuàng)建一個(gè)全新的 Map，而不是使用全局 Map，因此其緩存也僅僅對(duì)單個(gè) Throwable 生效。
? ? ? ? 上述問題從源碼中可以看到，ThrowableProxy#toExtendedStackTrace 方法通過 Map緩存當(dāng)前堆棧元素類對(duì)應(yīng)的 CacheEntry，來避免重復(fù)解析 CacheEntry，但是由于Map 緩存 put 操作使用的 key 來自于 StackTraceElement.toString 方法，而 get操作使用的 key 卻來自于 StackTraceElement.getClassName 方法，即使對(duì)于同一個(gè) StackTraceElement 而言，其 toString 和 getClassName 方法對(duì)應(yīng)的返回結(jié)果也不一樣，所以此 map 形同虛設(shè)。
? ? ? 通常情況下一個(gè)類加載器對(duì)于一個(gè)類只會(huì)加載一次，類加載器內(nèi)部保存有類緩存，無需重復(fù)加載，但目前的現(xiàn)象卻是由于類加載而導(dǎo)致線程大量 Block，因此必然是有些類加載不了，且不斷重復(fù)嘗試加載，那到底是什么類無法加載呢
到底什么類加載不了？(分析業(yè)務(wù)異常的具體堆棧)
兩份堆?；鞠嗨?，且大多數(shù)類都是很普通的類，但是唯一不同的地方在于：
1、sun.reflect.NativeMethodAccessorImpl
2、sun.reflect.GeneratedMethodAccessor261
? ? ? 從字面信息中不難猜測(cè)出這與反射調(diào)用相關(guān)，但問題是這兩份堆棧對(duì)應(yīng)的其實(shí)是同一份業(yè)務(wù)代碼，查閱相關(guān)資料得知，這與 JVM 反射調(diào)用相關(guān).
JVM 對(duì)反射調(diào)用分兩種情況：
1、默認(rèn)使用 native 方法進(jìn)行反射操作。
2、一定條件下會(huì)生成字節(jié)碼進(jìn)行反射操作，即生成 sun.reflect.GeneratedMethodAccessor<N> 類，它是一個(gè)反射調(diào)用方法的包裝類，代理不同的方法，類后綴序號(hào)遞增。
? ? ? 從源碼的 MethodAccessorGenerator#generateName 方法可以看到，字節(jié)碼生成的類名稱規(guī)則是 sun.reflect.GeneratedConstructorAccessor<N>，其中 N 是從 0 開始的遞增數(shù)字，且生成類是由 DelegatingClassLoader 類加載器定義，所以其他類加載器無法加載該類，也就無法生成類緩存數(shù)據(jù)，從而導(dǎo)致每次加載類時(shí)都需要遍歷JarFile，極大地降低了類查找速度，且類加載過程是 synchronized 同步調(diào)用，在高并發(fā)情況下會(huì)更加惡化，從而導(dǎo)致線程 Block。
JVM 反射調(diào)用為什么要做這么做？
? ? ? 這是 JVM 對(duì)反射調(diào)用的一種優(yōu)化手段，在 sun.reflect.ReflectionFactory 的文檔注釋里對(duì)此做了解釋，這是一種“Inflation”機(jī)制，加載字節(jié)碼的調(diào)用方式在第一次調(diào)用時(shí)會(huì)比 Native 調(diào)用的速度要慢 3~4 倍，但是在后續(xù)調(diào)用時(shí)會(huì)比 Native 調(diào)用速度快 20 多倍。為了避免反射調(diào)用影響應(yīng)用的啟動(dòng)速度，所以在反射調(diào)用的前幾次通過 Native 方式調(diào)用，當(dāng)超過一定調(diào)用次數(shù)后使用字節(jié)碼方式調(diào)用，提升反射調(diào)用性能。
普通通地打印一條 ERROR 日志，為何會(huì)導(dǎo)致解析、加載異常堆棧類？
? ? ? ? ? AsyncAppender 在生成 LogEvent 的快照 Log4jLogEvent 時(shí)，會(huì)先對(duì) LogEvent序列化處理統(tǒng)一轉(zhuǎn)換為 LogEventProxy。
此時(shí)不同類型的 LogEvent 的處理情況稍有差異：
● Log4jLogEvent 類 型， 先 執(zhí) 行 Log4jLogEvent#getThrownProxy 方 法，觸發(fā)創(chuàng)建 ThrowableProxy 實(shí)例。
● MutableLogEvent 類型，先創(chuàng)建 LogEventProxy 實(shí)例，在構(gòu)造函數(shù)內(nèi)執(zhí)行 MutableLogEvent#getThrownProxy 方法，觸發(fā)創(chuàng)建 ThrowableProxy實(shí)例。
? ? ? ? 不管 LogEvent 的實(shí)際類型是 MutableLogEvent 還是 Log4jLogEvent，最終都會(huì)觸發(fā)創(chuàng)建 ThrowableProxy 實(shí)例，并在 ThrowableProxy 構(gòu)造函數(shù)內(nèi)觸發(fā)了解析、加載異常堆棧類。
問題小結(jié)
? ? ? ? Log4j2 打印異常日志時(shí)，AsyncAppender 會(huì)先創(chuàng)建日志事件快照，并進(jìn)一步觸發(fā)解析、加載異常堆棧類。JVM 通過生成字節(jié)碼的方式優(yōu)化反射調(diào)用性能，但該動(dòng)態(tài)生成的類無法被 WebAppClassLoader 類加載器加載，因此當(dāng)大量包含反射調(diào)用的異常堆棧被輸出到日志時(shí)，會(huì)頻繁地觸發(fā)類加載，由于類加載過程是 synchronized同步加鎖的，且每次加載都需要讀取文件，速度較慢，從而導(dǎo)致線程 Block。
