HeapDump性能社区

性能工具
登录注册
性能文章>logback配置不当导致频繁类加载>

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

开翻挖掘机
2年前
440312

一、前沿


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

简单描述下问题：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

 

点赞收藏
开翻挖掘机
请先登录，查看1条精彩评论吧
快去登录吧，你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流，共同进步
2
1
Lv3
开翻挖掘机

徽章

推荐阅读

随机一门技术分享之NettyMappedByteBuffer VS FileChannel：从内核层面对比两者的性能差异JDBC PreparedStatement 字段值为null导致TBase带宽飙升的案例分析浅析AbstractQueuedSynchronizer日常Bug排查-集群逐步失去响应为什么要做代码Review？
站内搜索
Linux
SpringBoot
锁
字节码
火焰图
故障排查
java
jvm
gc
linux
内存泄漏
内核

专题推荐

对于刚刚接触 JVM 的同学来说，JVM 就像一个黑盒一样，完全不知道这是一个什么东西。所以对于小白来说，最重要是搞清楚 JVM 到底是干嘛的，以及其常用的知识框架。针对这样的需求，才有了这个专题，从零开始循序渐进地介绍了 JVM，相信是很不错的 JVM 入门教程。
15篇文章36827阅读量
通过阅读 Redis 源码，可以学习和掌握到的计算机系统设计思想，redis 涉及的知识点有很多，本期专题我们由浅入深，简洁的给大家剖析Redis源码。
15篇文章26449阅读量

本月精选性能专题

本月精选线上案例

本月精选原创好文

HeapDump

有性能问题，上HeapDump性能社区

Copyright © 2019-2024 heapdump.cn 版权所有 浙ICP备17054444号

联系我们

HeapDump性能社区

网媒渠道

堆堆酱

扫码加堆堆酱好友

友情链接

PerfMa官网SegmentFault思否TesterHomeXPocket开源社区DCloud 问答社区稀土掘金博客园W3CTech