logback配置不當導致頻繁類載入

開翻挖掘機發表於2022-05-25

一、前沿

  這個問題也是在客戶的應用系統中遇到的。實話撂了，就喜歡給客戶看問題，忒別漲姿勢！！

  簡單描述下問題：logback在列印error資訊的時候瘋狂類載入，同時還拋ClassNotFound的error。方法呼叫棧如下：

image.png

二、stackoverflow的相似問題

  本著儘快解決問題的原則，先搜下是否有現成的答案。在stackoverflow上發現了個十分相似的問題《java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy?》，該國外網友提供的執行緒線是這樣的：

<Sep 9, 2015 9:27:13 AM UTC> <Warning> <Common> <BEA-000632> <Resource Pool "JDBC Data Source-0" shutting down, ignoring 3 resources still in use by applications..>
Exception in thread "Thread-12" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
        at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:125)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:468)
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:424)
        at ch.qos.logback.classic.Logger.log(Logger.java:824)
        at org.apache.commons.logging.impl.SLF4JLocationAwareLog.error(SLF4JLocationAwareLog.java:225)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.completeTransactionAfterThrowing(TransactionAspectSupport.java:415)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:114)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.cache.interceptor.CacheInterceptor$1.invoke(CacheInterceptor.java:58)
        at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:213)
        at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:66)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
        ................
        at java.lang.Thread.run(Thread.java:701)
Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy
        at weblogic.utils.classloaders.GenericClassLoader.findLocalClass(GenericClassLoader.java:297)
        at weblogic.utils.classloaders.GenericClassLoader.findClass(GenericClassLoader.java:270)
        at weblogic.utils.classloaders.ChangeAwareClassLoader.findClass(ChangeAwareClassLoader.java:64)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:323)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:268)
        at weblogic.utils.classloaders.GenericClassLoader.loadClass(GenericClassLoader.java:179)
        at weblogic.utils.classloaders.ChangeAwareClassLoader.loadClass(ChangeAwareClassLoader.java:52)
        ... 18 more
Exception in thread "Thread-18" java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/ThrowableProxy
        at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:125)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:468)
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:424)
        at ch.qos.logback.classic.Logger.log(Logger.java:824)
        at org.apache.commons.logging.impl.SLF4JLocationAwareLog.error(SLF4JLocationAwareLog.java:225)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.completeTransactionAfterThrowing(TransactionAspectSupport.java:415)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:114)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.cache.interceptor.CacheInterceptor$1.invoke(CacheInterceptor.java:58)
        at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:213)
        at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:66)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
        .......................
        at java.lang.Thread.run(Thread.java:701)
Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy
        at weblogic.utils.classloaders.GenericClassLoader.findLocalClass(GenericClassLoader.java:297)
        at weblogic.utils.classloaders.GenericClassLoader.findClass(GenericClassLoader.java:270)
        at weblogic.utils.classloaders.ChangeAwareClassLoader.findClass(ChangeAwareClassLoader.java:64)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:323)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:268)
        at weblogic.utils.classloaders.GenericClassLoader.loadClass(GenericClassLoader.java:179)
        at weblogic.utils.classloaders.ChangeAwareClassLoader.loadClass(ChangeAwareClassLoader.java:52)
    ... 18 more

乍一看，好像和我遇到的問題差不多啊，甚至一度以為也是因為打包或者logback的版本導致的問題。靜下心來再看看自己的方法呼叫棧，發現和上面外國友人的問題根本不是一回事【心急吃不了熱豆腐啊】。ClassNotFound拋的地方不一致，外國友人的應用在初始化LoggingEvent物件的時候就報錯了，而我這邊LoggingEvent是正常初始化的。最終還是打算自己翻原始碼，徹底搞清楚這個問題。

三、原始碼的答案

  為了快速定位問題，直接跟的方法呼叫棧遛一下logback的關鍵方法，很快找到了症點了，答案就在LoggingEvent的構造方法中，如下圖：

image.png

只有lc.isPackagingDataEnabled()為true，才會呼叫calculatePackagingData()方法，那isPackagingDataEnabled()的返回值是什麼呢？跟下去，發現該方法的返回的值，是LoggerContext的一個成員屬性，預設是false，那肯定是哪裡改了預設配置：

image.png

簡單暴力的方法，直接全域性搜尋下packagingDataEnabled在哪裡被引用到了，發現有個setPackagingDataEnabled()方法是專門設值的，再看setPackagingDataEnabled()在哪裡被引用了。很幸運，只有一個地方呼叫了這個方法：ch.qos.logback.classic.joran.action.ConfigurationAction#begin，部分原始碼如下：

LoggerContext lc = (LoggerContext) context;
// 這裡很容聯想到，是在配置檔案配置新的值
boolean packagingData = OptionHelper.toBoolean(ic.subst(attributes.getValue(PACKAGING_DATA_ATTR)), LoggerContext.DEFAULT_PACKAGING_DATA);
lc.setPackagingDataEnabled(packagingData);

只要看下PACKAGING_DATA_ATTR這個值是什麼就知道是通過配置檔案的哪個引數影響了packagingDataEnabled的預設值。

image.png

現在知道了肯定是在配置檔案配置了packagingDataEnabled為true，但這個配置是幹什麼，我還不知道，直接官網查了下：
image.png

官網明確說明了，該引數是在棧資訊的基礎上，額外增加了jar包的名稱和版本資訊。而且還明確說明了，該配置引數雖然有用，但是十分昂貴【每個類都會觸發類載入操作】。

四、ClassNotFound的根源

  至此，我們知道了在logback.xml中配置了packagingData="true"，導致執行packagingData相關的方法。而logback在列印error資訊的時候一般會輸出執行緒棧資訊，導致每行棧資訊都會觸發類載入，但是ClassNotFound是咋回事？

  這邊其實我立馬聯想到了AOP。首先，客戶的日誌輸出操作都是寫在一個切面類中，而在Spring中，被切方法所在的類，Spring都會重新建立一個代理類Bean。不管是通過JDK動態代理還是CGLIB動態代理建立的代理類Bean在本地磁碟都是沒有對應的class檔案的，因此在類載入過程中，肯定是找不到這些類檔案的，也就會丟擲ClassNotFound的錯誤。

  為了驗證這個猜想，我在本地嘗試了在Pointcut指向的類中列印日誌，並輸出stack資訊：

image.png

通過本地壓測，成功還原了客戶系統的問題，本地stack資訊如下：

image.png

五、結尾

  隔了很久，終於遇到了一個稍微有意思的問題，興高采烈地記錄下。重在分析思路吧，當然針對logback還是提下：

  1. packagingData="true"不要隨意配置，效能很差很差；
  2. 儘量用非同步日誌；
  3. 注意日誌格式配置：%F - java原始檔名；%L - java原始碼行數；%C - java類名；%M-java方法名，這些都會導致輸出執行緒棧資訊，很耗費CPU資源；
  4. 日誌壓縮，注意壓縮頻率【磁碟空間充足就不要壓縮了】

相關文章