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日志了。