logback log.info耗时异常，RollingFileAppender+TimeBasedRollingPolicy配置踩坑

小林子你真猛！

已于 2024-07-09 09:29:34 修改

阅读量1.6k

点赞数 30

分类专栏：源码文章标签： logback java

于 2024-07-03 11:36:45 首次发布

本文链接：https://blog.youkuaiyun.com/weixin_41653901/article/details/139527143

版权

我喜欢把核心内容放开头

此次log.info耗时异常升高，是由于日志量过大（5G甚至以上），并且使用同步阻塞的RollingFileAppender+TimeBasedRollingPolicy，再加上appender-file（即日志打印路径）与rollingPolicy-fileNamePattern的路径不一致，导致日志滚动耗时增加，并且log.info一直等待日志文件滚动，造成了超时异常。解决方式很简单：

修改logback.xml里logger配置，准确定义日志打印的包甚至类，控制日志量
使用异步非阻塞的Appender，例如：AsyncAppender
注意appender-file（即日志打印路径）与rollingPolicy-fileNamePattern中的路径是否一致，这次的异常可能与两个路径不同导致，因为底层在滚动旧日志时使用java.io.File#renameTo，这个方法（linux环境下）在路径不同时会移动文件再重命名，耗时明显增长，尤其在容器环境中两个路径挂载在不同的硬盘上更会拉长时间。

背景

公司使用xxl-job框架实现的分布式任务调度。
在这里插入图片描述

xxl-job主要分两块，一个管理端，若干执行器。管理端将任务派发给执行器执行，调度方式是管理端通过http请求执行器的接口实现调度。

现象

自从一次上线后管理端每天00:00的任务会调度失败，且过了00:00之后调度就恢复了。
在这里插入图片描述
调度失败的日志显示是因为接口超时：

源码解析

logback配置文件加载

配置文件加载与本次的异常无关，只是之前没研究过logback相关的源码，所以这次从头看了一下。

小伙伴们应该都知道logback会默认从工程目录中寻找logback.xml配置，并根据配置加载logger等组件。但是什么时候开始加载logback.xml，logback又是如何配置appender与rollingPolicy的呢？
我将断点打在start:65, TimeBasedRollingPolicy (ch.qos.logback.core.rolling) ，沿着堆栈向上查看。
slf4j作为门面框架通过LoggerFactory.getLogger第一次被调用时初始化整个日志框架。
初始化默认日志上下文：
在这里插入图片描述
默认为logback.
然后ContextInitializer会在本地找logback配置文件：

这里可以看到logback.xml的加载由Classloader.getResource获取:

这里引入另一个踩过的坑，如果您使用start.sh等通过java命令启动的项目，需要小心classpath中jar包的顺序，务必将您自己的项目jar放在classpath最前面，否则可能出现由其他jar包中的logback.xml配置日志打印，出现驴唇不对马嘴的日志打印效果。

找到logback.xml之后开始加载配置文件，装配组件：
在这里插入图片描述

logback选择SAXParser流式处理，xml会被读取成startevent-bodyevent-endevent这样的结构：

随后根据这些event进行解析

    public void play(List<SaxEvent> aSaxEventList) {
   
        eventList = aSaxEventList;
        SaxEvent se;
        for (currentIndex = 0; currentIndex < eventList.size(); currentIndex++) {
   
            se = eventList.get(currentIndex);

            if (se instanceof StartEvent) {
   
                interpreter.startElement((StartEvent) se);
                // invoke fireInPlay after startElement processing
                interpreter.getInterpretationContext().fireInPlay(se);
            }
            if (se instanceof BodyEvent) {
   
                // invoke fireInPlay before characters processing
                interpreter.getInterpretationContext().fireInPlay(se);
                interpreter.characters((BodyEvent) se);
            }
            if (se instanceof EndEvent) {
   
                // invoke fireInPlay before endElement processing
                interpreter.getInterpretationContext().fireInPlay(se);
                interpreter.endElement((EndEvent) se);
            }

        }
    }

例如logger的appender、level参数和logger根据name形成的树状结构都是在StartEvent进行设置的。
而appender的file、filter、encoder、rollingPolicy参数都是在bodyevent进行设置的：

    public void body(InterpretationContext ec, String body) {
   

        String finalBody = ec.subst(body);
        // get the action data object pushed in isApplicable() method call
        IADataForBasicProperty actionData = (IADataForBasicProperty) actionDataStack.peek();
        switch (actionData.aggregationType) {
   
        case AS_BASIC_PROPERTY:
        	//这里的setproperty通过反射调用参数对应的setter方法，将参数传递进去
            actionData.parentBean.setProperty(actionData.propertyName, finalBody);
            break;
        case AS_BASIC_PROPERTY_COLLECTION:
            actionData.parentBean.