如何在項目中使用異步日志，以及它的實現(xiàn)原理

Spring Boot 項目默認(rèn)使用的日志工具是 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 文件，復(fù)用了 Spring Boot 的一些默認(rèn)的配置，只使用控制臺輸出的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>

參數(shù)說明：
discardingThreshold：默認(rèn)值為-1，當(dāng)queueSize的剩余空間小于該容量的20%的時候，會丟棄TRACE, DEBUG 和 INFO級別的日志，只保留WARN 和 ERROR日志。如果要保證不丟失日志，可以設(shè)置該值為0。
queueSize：異步日志使用 BlackingQueue 緩存日志事件，此參數(shù)表示日志緩存的大小，默認(rèn)值256
maxFlushTime：當(dāng)LoggerContext停止時, AsyncAppender 的stop 方法等待worker完成日志刷新任務(wù)的最大超時時間，默認(rèn)值為1000毫秒
neverBlock：默認(rèn)值為false，表示當(dāng)緩存隊列放不下日志的時候會阻塞住。設(shè)置為true時，表示會丟棄日志，不會阻塞線程。
includeCallerData：是否包含調(diào)用者數(shù)據(jù)，默認(rèn)值為false，默認(rèn)線程名稱和MDC會拷貝。

異步日志的原理：在日志輸出的時候不會直接輸出日志到磁盤，而是將日志存進(jìn)一個 Queue 的隊列里，另外起線程消費(fèi)隊列里的日志。

Spring Boot 默認(rèn)的配置文件在 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方法會調(diào)用put方法。

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

這段代碼說明當(dāng)neverBlack為true時，如果隊列已滿的話，會丟失日志。

然后看下ch.qos.logback.core.AsyncAppenderBase$Worker，這個內(nèi)部類是，異步日志緩存隊列的消費(fèi)者。

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，消費(fèi)者線程使用引用的Appender打印日志。可以看到這個線程其實就是一個while循環(huán)，當(dāng)JVM進(jìn)程接收到停止信號時，消費(fèi)者線程會被打斷，跳出死循環(huán)，接著會取出隊列中剩余日志消費(fèi)掉。這個注意一個參數(shù)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表示的是當(dāng)消費(fèi)者線程接收到打斷信號，多久以后會清理消費(fèi)者線程的內(nèi)存空間。默認(rèn)是1秒，也就是說當(dāng)JVM進(jìn)程收到停止信號，給消費(fèi)者線程處理剩余日志的時間最大為1秒。