一文搞懂Java日志級别，重複記錄、丢日志問題（中）

2.3 AsyncAppender

使用Logback的AsyncAppender，即可實作異步日志記錄。

AsyncAppender類似裝飾模式，在不改變類原有基本功能情況下，為其增添新功能。這便可把AsyncAppender附加在其他Appender，将其變為異步。

定義一個異步Appender ASYNCFILE，包裝之前的同步檔案日志記錄的FileAppender， 即可實作異步記錄日志到檔案

記錄1000次日志和10000次日志的調用耗時，分别是537ms和1019ms

• 異步日志真的如此高性能？并不，因為它并沒有記錄下所有日志。

3 AsyncAppender異步日志的天坑

• 記錄異步日志撐爆記憶體
• 記錄異步日志出現日志丢失
• 記錄異步日志出現阻塞。

3.1 案例

模拟個慢日志記錄場景：

首先，自定義一個繼承自ConsoleAppender的MySlowAppender，作為記錄到控制台的輸出器，寫入日志時睡1s。

配置檔案中使用AsyncAppender，将MySlowAppender包裝為異步日志記錄

測試代碼

耗時很短但出現日志丢失：要記錄1000條日志，最終控制台隻能搜尋到215條日志，而且日志行号變問号。

• 原因分析

  AsyncAppender提供了一些配置參數，而目前沒用對。

源碼解析

• includeCallerData

  預設false：方法行号、方法名等資訊不顯示

• queueSize

控制阻塞隊列大小，使用的ArrayBlockingQueue阻塞隊列，預設容量256：記憶體中最多儲存256條日志

• discardingThreshold

  丢棄日志的門檻值，為防止隊列滿後發生阻塞。預設

  隊列剩餘容量 ＜ 隊列長度的20%

  ，就會丢棄TRACE、DEBUG和INFO級日志
• neverBlock控制隊列滿時，加入的資料是否直接丢棄，不會阻塞等待，預設是false

• • 隊列滿時：offer不阻塞，而put會阻塞
  • neverBlock為true時，使用offer

public class AsyncAppender extends AsyncAppenderBase<ILoggingEvent> {
    // 是否收集調用方資料
    boolean includeCallerData = false;
    protected boolean isDiscardable(ILoggingEvent event) {
        Level level = event.getLevel();
        // 丢棄 ≤ INFO級日志
        return level.toInt() <= Level.INFO_INT;
    }
    protected void preprocess(ILoggingEvent eventObject) {
        eventObject.prepareForDeferredProcessing();
        if (includeCallerData)
            eventObject.getCallerData();
    }
}
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;
    static final int UNDEFINED = -1;
    int discardingThreshold = UNDEFINED;
    // 當隊列滿時：加入資料時是否直接丢棄，不會阻塞等待
    boolean neverBlock = false;

    @Override
    public void start() {
        ...
        blockingQueue = new ArrayBlockingQueue<E>(queueSize);
        if (discardingThreshold == UNDEFINED)
        //預設丢棄門檻值是隊列剩餘量低于隊列長度的20%，參見isQueueBelowDiscardingThreshold方法
            discardingThreshold = queueSize / 5;
        ...
    }

    @Override
    protected void append(E eventObject) {
        if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) { //判斷是否可以丢資料
            return;
        }
        preprocess(eventObject);
        put(eventObject);
    }

    private boolean isQueueBelowDiscardingThreshold() {
        return (blockingQueue.remainingCapacity() < discardingThreshold);
    }

    private void put(E eventObject) {
        if (neverBlock) { //根據neverBlock決定使用不阻塞的offer還是阻塞的put方法
            blockingQueue.offer(eventObject);
        } else {
            putUninterruptibly(eventObject);
        }
    }
    //以阻塞方式添加資料到隊列
    private void putUninterruptibly(E eventObject) {
        boolean interrupted = false;
        try {
            while (true) {
                try {
                    blockingQueue.put(eventObject);
                    break;
                } catch (InterruptedException e) {
                    interrupted = true;
                }
            }
        } finally {
            if (interrupted) {
                Thread.currentThread().interrupt();
            }
        }
    }
}        

預設隊列大小256，達到80%後開始丢棄<=INFO級日志後，即可了解日志中為什麼隻有兩百多條INFO日志了。