logback异步日志配置与源码解读

如何在项目中使用异步日志，以及它的实现原理

Spring Boot 项目默认使用的日志工具是 logback，它的配置文件是 org.springframework.boot.logging.logback 包下的 base.xml 文件

<?xml version="1.0" encoding="UTF-8"?>

<!--
Base logback configuration provided for compatibility with Spring Boot 1.1
-->

<included>
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <property name="LOG_FILE" value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}/spring.log}"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />
    <include resource="org/springframework/boot/logging/logback/file-appender.xml" />
    <root level="INFO">
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="FILE" />
    </root>
</included>

配置异步日志，要在 resources 目录下添加 logback-spring.xml 文件，复用了 Spring Boot 的一些默认的配置，只使用控制台输出的Appender 打印日志。

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />
    <appender name="ASYNC_CONSOLE" class="ch.qos.logback.classic.AsyncAppender">
        <discardingThreshold>0</discardingThreshold>
        <queueSize>2048</queueSize>
        <appender-ref ref="CONSOLE" />
    </appender>
    <root level="INFO">
        <appender-ref ref="ASYNC_CONSOLE" />
    </root>
</configuration>

参数说明：
discardingThreshold：默认值为-1，当queueSize的剩余空间小于该容量的20%的时候，会丢弃TRACE, DEBUG 和 INFO级别的日志，只保留WARN 和 ERROR日志。如果要保证不丢失日志，可以设置该值为0。
queueSize：异步日志使用 BlackingQueue 缓存日志事件，此参数表示日志缓存的大小，默认值256
maxFlushTime：当LoggerContext停止时, AsyncAppender 的stop 方法等待worker完成日志刷新任务的最大超时时间，默认值为1000毫秒
neverBlock：默认值为false，表示当缓存队列放不下日志的时候会阻塞住。设置为true时，表示会丢弃日志，不会阻塞线程。
includeCallerData：是否包含调用者数据，默认值为false，默认线程名称和MDC会拷贝。

异步日志的原理：在日志输出的时候不会直接输出日志到磁盘，而是将日志存进一个 Queue 的队列里，另外起线程消费队列里的日志。

Spring Boot 默认的配置文件在 spring-boot.jar 的 logging 目录下，它有以下几个核心概念：

logback配置文件的核心概念

概念
root: 根 logger （所有 logger 都继承它的属性）
logger：定义某个包的日志级别
appender：定义日志输出的方式

同步日志输出时的时序图

异步日志输出的时序图

ch.qos.logback.core.AsyncAppenderBase部分源码解读

protected void append(E eventObject) {
    if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
        return;
    }
    preprocess(eventObject);
    put(eventObject);
}

AsyncAppender继承了AsyncAppenderBase，所以异步的Appender的append方法会调用put方法。

private void put(E eventObject) {
    if (neverBlock) {
        blockingQueue.offer(eventObject);
    } else {
        putUninterruptibly(eventObject);
    }
}

这段代码说明当neverBlack为true时，如果队列已满的话，会丢失日志。

然后看下ch.qos.logback.core.AsyncAppenderBase$Worker，这个内部类是，异步日志缓存队列的消费者。

class Worker extends Thread {

    public void run() {
        AsyncAppenderBase<E> parent = AsyncAppenderBase.this;
        AppenderAttachableImpl<E> aai = parent.aai;

        // loop while the parent is started
        while (parent.isStarted()) {
            try {
                E e = parent.blockingQueue.take();
                aai.appendLoopOnAppenders(e);
            } catch (InterruptedException ie) {
                break;
            }
        }

        addInfo("Worker thread will flush remaining events before exiting. ");

        for (E e : parent.blockingQueue) {
            aai.appendLoopOnAppenders(e);
            parent.blockingQueue.remove(e);
        }

        aai.detachAndStopAllAppenders();
    }
}

AsyncAppenderBase.this获取Worker的外部类对象，从而获取到异步Appender引用的Appender，消费者线程使用引用的Appender打印日志。可以看到这个线程其实就是一个while循环，当JVM进程接收到停止信号时，消费者线程会被打断，跳出死循环，接着会取出队列中剩余日志消费掉。这个注意一个参数maxFlushTime。
ch.qos.logback.core.AsyncAppenderBase#stop

public void stop() {
    if (!isStarted())
        return;

    // mark this appender as stopped so that Worker can also processPriorToRemoval if it is invoking
    // aii.appendLoopOnAppenders
    // and sub-appenders consume the interruption
    super.stop();

    // interrupt the worker thread so that it can terminate. Note that the interruption can be consumed
    // by sub-appenders
    worker.interrupt();

    InterruptUtil interruptUtil = new InterruptUtil(context);

    try {
        interruptUtil.maskInterruptFlag();

        worker.join(maxFlushTime);

        // check to see if the thread ended and if not add a warning message
        if (worker.isAlive()) {
            addWarn("Max queue flush timeout (" + maxFlushTime + " ms) exceeded. Approximately " + blockingQueue.size()
                            + " queued events were possibly discarded.");
        } else {
            addInfo("Queue flush finished successfully within timeout.");
        }

    } catch (InterruptedException e) {
        int remaining = blockingQueue.size();
        addError("Failed to join worker thread. " + remaining + " queued events may be discarded.", e);
    } finally {
        interruptUtil.unmaskInterruptFlag();
    }
}

这段代码说明，maxFlushTime表示的是当消费者线程接收到打断信号，多久以后会清理消费者线程的内存空间。默认是1秒，也就是说当JVM进程收到停止信号，给消费者线程处理剩余日志的时间最大为1秒。