Logback的AsyncAppender與RollingFileAppender流程解析

近期工做中涉及到文件記錄、文件翻轉等操做，思考有沒有成熟的代碼以便參考.
所以，第一時間就聯想到Logback的AsyncAppender以及RollingFileAppender.

• AsyncAppender:經過隊列儲存日誌事件，啓動Worker線程讀取日誌事件並寫入關聯的Appender中；
• RollingFileAppender:當日志文件知足設定的翻滾條件時，對文件進行翻滾操做.

PS: AsyncAppender能夠與RollingFileAppender結合使用，提高日誌事件寫入效率.

1 AsyncAppender

public class AsyncAppender extends AsyncAppenderBase<ILoggingEvent> {

    // 省略部分功能
    boolean includeCallerData = false;

    protected boolean isDiscardable(ILoggingEvent event) {
        Level level = event.getLevel();
        return level.toInt() <= Level.INFO_INT;
    }

    protected void preprocess(ILoggingEvent eventObject) {
        eventObject.prepareForDeferredProcessing();
        if (includeCallerData)
            eventObject.getCallerData();
    }
}

(1)isDiscardable:肯定日誌事件是否能夠丟棄(當緩衝隊列達到上限時，出於性能考慮須要丟棄諸如TRACE、DEBUG級別日誌)；
(2)preprocess:預處理日誌事件（包括格式化msg，線程名稱，MDC中存儲的數據），若是includeCallerData爲true，則須要經過日誌事件的堆棧信息，獲取日誌所在的文件，行號等信息；

由於AsyncAppender的絕大部分功能由AsyncAppenderBase中實現，所以接下來主要講解AsyncAppenderBase的功能點.

public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {

    BlockingQueue<E> blockingQueue;

    public static final int DEFAULT_QUEUE_SIZE = 256;
    int queueSize = DEFAULT_QUEUE_SIZE;

    int appenderCount = 0;

    static final int UNDEFINED = -1;
    int discardingThreshold = UNDEFINED;
    boolean neverBlock = false;

    Worker worker = new Worker();

    public static final int DEFAULT_MAX_FLUSH_TIME = 1000;
    int maxFlushTime = DEFAULT_MAX_FLUSH_TIME;
}

以上是AsyncAppenderBase的主要屬性：

• blockingQueue:阻塞隊列，存儲日誌事件，等待被各Appender消費；
• queueSize：隊列大小，若是沒有設置，則默認爲256；
• discardingThreshold：日誌事件的丟棄閾值，當隊列中的事件數量超過閾值後，則會丟棄諸如TRACE/DEBUG級別日誌；
• worker：消費者線程(單消費者足夠了)；
• maxFlushTime：程序結束時，worker線程的退出時間(從而保證儘可能將隊列中的日誌事件寫至文件中).

1.1 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;
                }
            }

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

            aai.detachAndStopAllAppenders();
        }
    }

Worker線程比較簡單，其主要功能就是判斷Appeneder是否處於運行狀態(parent.isStarted()):

• 運行：讀取阻塞隊列中的數據，經過AppenderAttachableImpl分發至各Appender中;
  
• 不運行：循環讀取緩衝隊列中的殘餘數據，經過AppenderAttachableImpl分發至各Appender中，最後關閉關聯的Appender.

1.2 啓動appender

@Override
    public void start() {

        // 省略部分校驗代碼
        blockingQueue = new ArrayBlockingQueue<E>(queueSize);

        if (discardingThreshold == UNDEFINED)
            discardingThreshold = queueSize / 5;
        worker.setDaemon(true);
        worker.setName("AsyncAppender-Worker-" + getName());
        super.start();
        worker.start();
    }

主要步驟：

(1) 根據設置的隊列大小，建立緩衝隊列大小；

(2) 若是未設置discardingThreshold，則設置discardingThreshold閾值爲緩衝隊列大小的4/5(1-1/5);

(3) 設置worker線程爲守護線程，設置線程名稱；

(4) 啓動Appender，啓動worker線程讀取數據(須要確保Appender在worker線程前啓動).

1.3 關閉appender

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

        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();
        }
    }

主要步驟:

(1) super.stop():關閉Appender,worker線程執行退出邏輯；

(2) worker.interrupt()：給worker線程設置中斷標誌(worker中未檢測中斷標誌，所以保持繼續運行狀態)，設置的意義是讓當前appender關聯的sub-appender消費，從而安全的關閉sub-appender;

(3) interruptUtil.maskInterruptFlag():清除當前線程的interrupt狀態；

(4) worker.join(maxFlushTime):等待worker線程退出，結束其生命週期；

(5) 判斷worker線程是否存活，若是存活說明阻塞隊列中仍存有部分日誌事件未被寫入文件等載體中,記錄消息；

(6) interruptUtil.unmaskInterruptFlag():恢復worker線程的interrupt狀態.

劃重點:

上述代碼中，對worker線程的中斷標誌進行了若干次操做：

(1) interrupt:中斷worker關聯的sub-appender；

(2) interruptUtil.maskInterruptFlag: 取消中斷標誌（在線程標誌爲true的狀態下，join操做會當即返回），所以爲了確保join操做有效，須要清除worker線程的interrupt標誌；

(3) interruptUtil.unmaskInterruptFlag：結束操做，恢復worker線程的interrupt標誌.

1.4 添加日誌事件

日誌事件的添加，實質是就是往阻塞隊列中插入日誌事件.
根據阻塞隊列接口，分兩種插入方式：

(1) offer：非阻塞插入，插入失敗不進行處理(存在丟日誌可能性)；

(2) put：阻塞插入(插入失敗後會循環進行再次插入操做).

2 RollingFileAppender

public class RollingFileAppender<E> extends FileAppender<E> {
    File currentlyActiveFile;
    TriggeringPolicy<E> triggeringPolicy;
    RollingPolicy rollingPolicy;
}

主要屬性：

• currentlyActiveFile:當前日誌寫入文件；
• triggeringPolicy：日誌文件觸發策略(觸發條件包括：單個日誌文件大小，文件中日誌文件整體積，翻轉時刻等條件)；
• rollingPolicy：翻轉策略(主要肯定日誌文件翻轉文件名，存儲路徑等信息).

須要注意，若是沒有日誌事件寫入，那麼即便日誌文件達到時間或者大小的觸發條件，也不會建立相應的新日誌文件.

2.1 添加日誌事件

protected void subAppend(E event) {
        synchronized (triggeringPolicy) {
            if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {
                rollover();
            }
        }
        super.subAppend(event);
    }

主要步驟:

(1) 判斷當前文件是否達到觸發條件，若是是則翻轉文件(使用synchronized加鎖以保證同一時間段，只有一個線程進行文件的翻轉操做)；

(2) 調用基類的subAppend方法，將日誌文件寫入BufferedOutputStream中.

翻轉文件：

public void rollover() {
        lock.lock();
        try {
            this.closeOutputStream();
            attemptRollover();
            attemptOpenFile();
        } finally {
            lock.unlock();
        }
    }

由以上代碼可知，翻轉文件涉及到如下幾個操做：

(1) 關閉當前BufferedOutputStream；

(2) attemptRollover: 進行文件翻轉（重命名已寫入文件名，根據需求壓縮日誌文件，根據日誌文件夾總大小以及日期刪除文件等）；

(3) attemptOpenFile:根據翻轉條件，肯定新日誌文件名稱，並建立對應的日誌文件供後續寫入.

2.2 SizeAndTimeBasedRollingPolicy

工做中，常常使用的文件翻轉工具類爲SizeAndTimeBasedRollingPolicy(實現了RollingPolicy以及TriggeringPolicy接口)，顧名思義，其根據時間和文件大小肯定日誌文件的翻轉觸發條件.

2.2.1 日誌觸發

須要注意，觸發器實際定義於SizeAndTimeBasedFNATP類中.

@Override
    public boolean isTriggeringEvent(File activeFile, final E event) {

        long time = getCurrentTime();

        // first check for roll-over based on time
        if (time >= nextCheck) {
            Date dateInElapsedPeriod = dateInCurrentPeriod;
            elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convertMultipleArguments(dateInElapsedPeriod, currentPeriodsCounter);
            currentPeriodsCounter = 0;
            setDateInCurrentPeriod(time);
            computeNextCheck();
            return true;
        }

        // next check for roll-over based on size
        if (invocationGate.isTooSoon(time)) {
            return false;
        }

        if (activeFile.length() >= maxFileSize.getSize()) {
            elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convertMultipleArguments(dateInCurrentPeriod, currentPeriodsCounter);
            currentPeriodsCounter++;
            return true;
        }
        return false;
    }

主要步驟:

(1) 獲取當前時間點，並與nextCheck進行比較(日誌出發時間點)；

(2) 若是當前時間點大於nextCheck，則計算獲得新的日誌文件名前綴,賦值至elapsedPeriodsFileName；清空currentPeriodsCounter(記錄時間段內的日誌文件總數)；計算下一個觸發時間點後退出函數；

(3) 若當前時間點小於nextCheck，則進行文件大小的校驗(經過isTooSoon判斷函數觸發是否過於頻繁，若是時，則退出等待之後校驗)；

(4) 比較當前日誌文件和設置的最大文件大小比較，若是當前文件大小達到閾值，則計算新的日誌文件名前綴，currentPeriodsCounter進行+1操做.

2.2.2 日誌翻轉

public void rollover() throws RolloverFailure {

        // when rollover is called the elapsed period's file has
        // been already closed. This is a working assumption of this method.

        String elapsedPeriodsFileName = timeBasedFileNamingAndTriggeringPolicy.getElapsedPeriodsFileName();
        String elapsedPeriodStem = FileFilterUtil.afterLastSlash(elapsedPeriodsFileName);

        if (compressionMode == CompressionMode.NONE) {
            if (getParentsRawFileProperty() != null) {
                renameUtil.rename(getParentsRawFileProperty(), elapsedPeriodsFileName);
            } // else { nothing to do if CompressionMode == NONE and parentsRawFileProperty == null }
        } else {
            if (getParentsRawFileProperty() == null) {
                compressionFuture = compressor.asyncCompress(elapsedPeriodsFileName, elapsedPeriodsFileName, elapsedPeriodStem);
            } else {
                compressionFuture = renameRawAndAsyncCompress(elapsedPeriodsFileName, elapsedPeriodStem);
            }
        }

        if (archiveRemover != null) {
            Date now = new Date(timeBasedFileNamingAndTriggeringPolicy.getCurrentTime());
            this.cleanUpFuture = archiveRemover.cleanAsynchronously(now);
        }
    }

主要步驟：

(1) 獲取isTriggeringEvent函數設置的elapsedPeriodsFileName文件名稱;

(2) 若是不須要對日誌文件進行壓縮操做，則嘗試將當前日誌文件的名稱重命名爲elapsedPeriodsFileName；

(3) 若是須要對日誌文件進行壓縮，則嘗試將日誌文件進行異步壓縮操做(須要注意，涉及到日誌文件重命名操做);

(4) 設置archiveRemover，將當前時間點傳入archiveRemover，經過其刪除過時文件，或刪除早期文件以保證文件夾大小在合理範圍.

劃重點:

(1) getParentsRawFileProperty: 配置文件中能夠設置活動日誌文件名稱(簡稱rawFileName)，當日志文件達到觸發條件時，將日誌文件內容轉移至翻轉文件中，從新建立日誌文件並命名爲rawFileName；

(2) renameUtil.rename：日誌文件轉移時，會判斷當前日誌文件和翻轉文件是否在同一塊volume上，若是是則重命名文件便可，若是不是則複製當前文件內容至翻轉文件中;

(3) 以上Future任務均是提交至Logback的線程池中執行，以保證日誌記錄的穩定性，避免成爲應用的性能負擔.

總結

經過以上篇幅可知，對於日誌文件的翻轉和寫入，Logback均進行了細緻和合理的設計，保證了日誌組件的高可用性和性能. 在編寫應用程序，涉及IO操做時，不妨參考Logback的代碼編寫.