采用logback打印日志遇到的问题总结

最近在项目问题排查过程中发现，日志显示的程序执行时间 远大于 程序中计算的耗时，程序示例如下：

private static final Logger LOGGER = LoggerFactory.getLogger(Test.class);

    public static void main(String[] args) throws InterruptedException {
        LOGGER.info("start");
        long start = System.currentTimeMillis();
        LOGGER.info("spend: {}", System.currentTimeMillis() - start);
    }

发现日志的时间差 和 spend的值差距过大。 经过问题排查和debug logback源代码，怀疑是由于 写日志时的锁竞争 和 磁盘IO，导致了写日志时耗时较长。

问题排查过程

一、导入项目依赖 

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.7</version>
        </dependency>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-core</artifactId>
            <version>1.1.7</version>
        </dependency>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-access</artifactId>
            <version>1.1.7</version>
        </dependency>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.1.7</version>
        </dependency>

 

二、导入logback配置文件，这里INFO日志使用的Appender是 RollingFileAppender

<!-- Logback configuration. See http://logback.qos.ch/manual/index.html -->
<configuration scan="true" scanPeriod="10 seconds">
    <include resource="org/springframework/boot/logging/logback/base.xml" />

    <appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <File>info.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>info-%d{yyyyMMdd}.log.%i</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>2</maxHistory>
        </rollingPolicy>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} -%msg%n
            </Pattern>
        </layout>
    </appender>

    <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
        </filter>
        <File>error.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>error-%d{yyyyMMdd}.log.%i
            </fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>2</maxHistory>
        </rollingPolicy>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} -%msg%n
            </Pattern>
        </layout>
    </appender>
    
    <appender name="TRACE_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <filter class="ch.qos.logback.classic.filter.LevelFilter"> 
            <level>TRACE</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <File>trace.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>trace-%d{yyyyMMdd}.log.%i
            </fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>2</maxHistory>
        </rollingPolicy>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} -%msg%n
            </Pattern>
        </layout>
    </appender>
    
    <!-- hibernate日志输入 -->
    <!-- <logger name="org.hibernate.type.descriptor.sql.BasicBinder"
        level="TRACE" />
    <logger name="org.hibernate.type.descriptor.sql.BasicExtractor"
        level="TRACE" />
    <logger name="org.hibernate.SQL" level="INFO" />
    <logger name="org.hibernate.engine.QueryParameters" level="INFO" />
    <logger name="org.hibernate.engine.query.HQLQueryPlan" level="INFO" /> -->

    <root level="INFO">
        <appender-ref ref="INFO_FILE" ></appender-ref>
        <appender-ref ref="ERROR_FILE" />
        <appender-ref ref="TRACE_FILE" />
    </root>
    
</configuration>

三、编写测试代码

public class Test {
    private static final Logger LOGGER = LoggerFactory.getLogger(Test.class);

    public static void main(String[] args) throws InterruptedException {
        LOGGER.info("start");
    }
}

四、调试代码

经过调试代码，发现最终写日志的时候，调用的是各个Appender的 doAppend 方法

当代码调用到这里的时候，会去获得锁

写日志的时候，会直接同步写到日志文件

 

在这里产生磁盘IO，写日志的线程有可能会被CPU换出。

五、问题及答案

1.打日志时，日志的时间是调用LOGGER.info的时间还是日志写到磁盘的时间？

是调用LOGGER.info的时间，是格式化的LoggingEvent的timeStamp字段。

2.打日志是同步写到磁盘的还是异步写到磁盘的？

如果使用的是RollingFileAppender，则是同步写到磁盘的。如果需要异步写到磁盘，需要配置其它的Appender。