一文搞懂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日志了。