logback配置不当导致频繁类加载

一、前沿

  这个问题也是在客户的应用系统中遇到的。实话撂了，就喜欢给客户看问题，忒别涨姿势！！

  简单描述下问题：logback在打印error信息的时候疯狂类加载，同时还抛ClassNotFound的error。方法调用栈如下：

二、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的构造方法中，如下图：

只有lc.isPackagingDataEnabled()为true，才会调用calculatePackagingData()方法，那isPackagingDataEnabled()的返回值是什么呢？跟下去，发现该方法的返回的值，是LoggerContext的一个成员属性，默认是false，那肯定是哪里改了默认配置：

简单暴力的方法，直接全局搜索下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的默认值。

现在知道了肯定是在配置文件配置了packagingDataEnabled为true，但这个配置是干什么，我还不知道，直接官网查了下【官方学习地址】：

官网明确说明了，该参数是在栈信息的基础上，额外增加了jar包的名称和版本信息。而且还明确说明了，该配置参数虽然有用，但是十分昂贵【每个类都会触发类加载操作】。

四、ClassNotFound的根源

  至此，我们知道了在logback.xml中配置了packagingData="true"，导致执行packagingData相关的方法。而logback在打印error信息的时候一般会输出线程栈信息，导致每行栈信息都会触发类加载，但是ClassNotFound是咋回事？

  这边其实我立马联想到了AOP。首先，客户的日志输出操作都是写在一个切面类中，而在Spring中，被切方法所在的类，Spring都会重新创建一个代理类Bean。不管是通过JDK动态代理还是CGLIB动态代理创建的代理类Bean在本地磁盘都是没有对应的class文件的，因此在类加载过程中，肯定是找不到这些类文件的，也就会抛出ClassNotFound的错误。

  为了验证这个猜想，我在本地尝试了在Pointcut指向的类中打印日志，并输出stack信息：

通过本地压测，成功还原了客户系统的问题，本地stack信息如下：

五、结尾

  隔了很久，终于遇到了一个稍微有意思的问题，兴高采烈地记录下。重在分析思路吧，当然针对logback还是提下：

1. packagingData="true"不要随意配置，性能很差很差；
2. 尽量用异步日志；
3. 注意日志格式配置：%F - java源文件名；%L - java源码行数；%C - java类名；%M-java方法名，这些都会导致输出线程栈信息，很耗费CPU资源；
4. 日志压缩，注意压缩频率【磁盘空间充足就不要压缩了】
5. immediateFlush默认为true，如果想要更高的日志吞吐量，设置为false；【应用意外退出可能导致日志少量丢失】

---