性能文章>logback配置不当导致频繁类加载>

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

201401

一、前沿


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

简单描述下问题: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`,但这个配置是干什么,我还不知道,直接官网查了下【[**官方学习地址**](https://logback.qos.ch/manual/configuration.html)】:

官网明确说明了,该参数是在栈信息的基础上,额外增加了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;【应用意外退出可能导致日志少量丢失】

---

原文地址:https://segmentfault.com/a/1190000041891376

 

点赞收藏
开翻挖掘机
请先登录,感受更多精彩内容
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

【全网首发】(大表小技巧)有时候 2 小时的 SQL 操作,可能只要 1 分钟

【全网首发】(大表小技巧)有时候 2 小时的 SQL 操作,可能只要 1 分钟

一次java内存top res高排查记录

一次java内存top res高排查记录

JAVA中计算两个日期时间的差值竟然也有这么多门道

JAVA中计算两个日期时间的差值竟然也有这么多门道

干货!Java代码优化必知的30个小技巧!

干货!Java代码优化必知的30个小技巧!

Java 异步调用原理与实战

Java 异步调用原理与实战

没有二十年功力,写不出Thread.sleep(0)这一行“看似无用”的代码!

没有二十年功力,写不出Thread.sleep(0)这一行“看似无用”的代码!

1
0