使用logback异步打印日志

一、介绍

对于每一个开发人员来说，在业务代码中添加日志是至关重要的，尤其是后端开发，如果不打印日志，在接口出现bug的时候将无法定位bug；有了日志，即使接口出现bug，也可以通过查询日志很快的定位到bug的位置。

使用springboot开发的朋友使用最多的日志框架想必都是logback了吧，毕竟它是springboot官方推荐的日志框架，与springboot天然整合。再结合第三方工具lombok，当我们需要打印日志时只需要通过log.info("第一条日志");、log.error("日志信息:{}", arg1);简单的代码即可完成打印。

如果接口中出现大量日志，且日志是直接输出到日志文件或通过网络发送到其他服务器呢？这种场景下，将会出现较为耗时的磁盘IO或网络IO，从而导致接口响应时间变长。

有没有办法通过异步的形式将日志打印出来呢？答案是肯定的，logback早就想到这一点了。请往下看。

二、运行环境

• springboot：2.4.3
• logback：1.2.3。logback是springboot自带的默认日志框架

该版本的springboot中自带该版本的logback，因此不必单独引入logback的依赖。

三、演示项目

本项目仅用于logback日志的异步打印，因此较为简单，仅包含一个接口和logback日志配置文件。

1. 接口

@Slf4j
@RestController
@RequestMapping("/student")
public class StudentController {

    @GetMapping("/insert")
    public String insert() {
        log.info("第一条日志");
        log.info("第二条日志");
        log.info("第三条日志");
        log.info("第四条日志");
        log.info("第五条日志");
        return "成功";
    }
}

2. 日志配置文件

logback提供了大量的Appender将日志输出到指定的位置。如ConsoleAppender用于同步地将日志输出到控制台，FileAppender用于同步地将日志输出到指定日志文件，SocketAppender用于同步地将日志通过套接字发送到指定服务器。他们都有一个共同点：同步。

那么如何修改日志配置文件将日志输出改为异步呢？logback提供了一个Appender的异步实现类：AsyncAppender。使用方法也非常简单，同样也是通过在配置文件中添加<appender>标签声明AsyncAppender，然后通过引用属性引用一个同步Appender即可，如下所示

<?xml version="1.0" encoding="utf-8" ?>
<configuration>

    <!-- 日志输出格式 -->
    <property name="log.pattern"
              value="%red(%d{yyyy-MM-dd HH:mm:ss}) %green([%thread]) %highlight(%-5level) %boldMagenta(%logger{36}) - %gray(%msg%n)"/>

    <!-- 同步输出到控制台 -->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${log.pattern}</pattern>
        </encoder>
    </appender>

    <!-- 异步输出 -->
    <appender name="async-console" class="ch.qos.logback.classic.AsyncAppender">
        <!-- 引用同步，将其包装为异步 -->
        <appender-ref ref="console" />
    </appender>

    <!-- 采用异步输出 -->
    <root level="INFO">
        <appender-ref ref="async-console" />
    </root>
    
</configuration>

3. 效果演示

我们使用postman调用接口，得到返回结果，如下图所示

查看控制台打印的日志，如下图所示

可这如何看出该日志打印和接口业务代码为异步的呢？

4. 异步输出验证

我们在AppenderAttachableImpl类的appendLoopOnAppenders()方法上添加断点，且要将该端点设置为多线程模式，如下图所示

此时再次调用接口，得到相同的结果，如下图所示

虽然接口已经正常响应了，但是我们发现代码却进入了断点，从该方法参数可以看出，在将要打印第一条日志时进入断点。如下图所示

且控制台上没有输出任何日志

当我们逐次放开断点使代码继续执行时，日志才逐行打印出来。因此我们可以断定接口业务代码与日志的打印为异步执行。

四、异步输出原理

为什么给同步Appender包装一层AsyncAppender就可以实现异步输出呢？

AsyncAppender内部维护了一个阻塞队列ArrayBlockingQueue，logback将我们打印日志的代码log.info("第一条日志")封装为一个事件Event，每当我们需要打印一行日志时，logback会将该事件放在阻塞队列中，然后再通过多线程的形式从该阻塞队列中获取一个事件执行。

阻塞队列可以保证日志的输出是有序的，多线程保证日志的输出是异步的。

五、其他参数配置

AsyncAppender能实现异步输出日志的关键因素是阻塞队列和多线程，既然说到阻塞队列，那么必然少不了相关的参数。

参数	类型	说明
queueSize	int	阻塞队列的最大容量，默认为256。
discardingThreshold	int	默认地，当阻塞队列剩余容量达到20%时，logback将丢弃trace, debug和info三个级别的日志，而只输出warn和error级别的日志。如果需要全部输出，则将该值设置为0。
includeCallerData	boolean	如果为true，logback对日志封装的事件中将包含更多调用者和父线程的信息，将降低性能。默认为false。
maxFlushTime	int	当服务停止时，logback将会等待一段时间，在这段时间内将正在输出的日志完成。
neverBlock	boolean	当阻塞队列已满时，如果为true，logback将丢失日志时间。默认为false。

配置文件如下所示

<?xml version="1.0" encoding="utf-8" ?>
<configuration>

    <!-- 日志输出格式 -->
    <property name="log.pattern"
              value="%red(%d{yyyy-MM-dd HH:mm:ss}) %green([%thread]) %highlight(%-5level) %boldMagenta(%logger{36}) - %gray(%msg%n)"/>

    <!-- 同步输出到控制台 -->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${log.pattern}</pattern>
        </encoder>
    </appender>

    <!-- 异步输出 -->
    <appender name="async-console" class="ch.qos.logback.classic.AsyncAppender">
        <!-- 阻塞队列的参数配置 -->
        <queueSize>256</queueSize>
        <discardingThreshold>20</discardingThreshold>
        <includeCallerData>false</includeCallerData>
        <maxFlushTime>1000</maxFlushTime>
        <neverBlock>false</neverBlock>
        
        <!-- 引用同步，将其包装为异步 -->
        <appender-ref ref="console" />
    </appender>

    <!-- 采用异步输出 -->
    <root level="INFO">
        <appender-ref ref="async-console" />
    </root>
    
</configuration>

六、源码分析

在logback中，任何日志的输出去都是通过start()方法完成的，接下来我们以ConsoleAppender同步输出 和 AsyncAppender异步输出为例，从源码层面分析。

1. 同步输出

进入ConsoleAppender源码，查看其start()方法。

可以看到其中第一行代码中通过target.getStream()获取输出目标的流，而target属性的声明如下所示，从该声明中我们看到通过target.getStream()获取输出目标的流就是System.out.print()了。这下我们就明白ConsoleAppender是如何将日志输出到控制台了。

再进入setOutputStream()方法查看其具体实现，从中可以看到是通过lock.lock() 和 lock.unlock()来保证其同步执行的，其中lock所是一个非公平的可重入同步锁，这是多线程中同步锁AQS体系的概念，这里不详细展开，我们只需要知道通过该锁实现同步即可。

2. 异步输出

进入AsyncAppender源码，查看其start()方法，该方法定义在其父类AsyncAppenderBase中。

在该方法中我们看到第102行代码使用queueSize参数声明一个指定容量的阻塞队列，默认的discardingThreshold参数为阻塞队列容量的1/5，即20%，然后就是对worker属性进行设置，然后调用其start()方法。worker实际上是Thread类的子类Worker对象，调用其start()方法就是通过一个新线程调用该对象的run()方法。

从该方法中我们发现，无论是直接调用take()方法获取阻塞队列中的元素，还是通过遍历阻塞队列获取其中的元素，都会调用appendLoopOnAppenders()方法，而该方法就是logback真正输出日志的方法，也是我们在验证其异步输出是打断点的地方。

七、总结

• logback通过AyncAppender实现日志的异步输出。
• AyncAppender异步输出的原理是通过阻塞队列和多线程实现的。

纸上得来终觉浅，绝知此事要躬行。

————————我是万万岁，我们下期再见————————