Log4j2异步日志背后的数字
引言
在程序开发过程中，几乎任何一个应用程序都会通过打印日志来记录跟踪程序运行情况，打印日志信息不仅可以让我们详细的了解程序内部的运行情况，更能在排查问题是提供详细的异常信息，为我们解决问题提供重要的线索。
最近在梳理项目运行情况时发现有个应用每天的日志量较大，在高峰时打印日志较为密集，发现配置日志打印使用的是Apache log4j2同步方式，那果断换成log4j2异步方式啊。但是都说异步方式打印日志性能好，强大且高效，具体性能可以提升多少，和同步方式相比差距有多大，为何大家更偏爱异步日志，今天通过数据对比，揭秘一下真实的原因。
log4j2的三种打印日志方式
Apache log4j2有三种打印日志方式，分别是同步方式、AsyncAppender异步及AsyncLogger异步方式，接下来分别针对这三种方式的用法进行简单的介绍。
1、Sync同步方式
同步记录日志是指当输出日志时，必须等待日志输出语句执行完毕后，才能执行后面的业务逻辑语句。
在输出日志时，会将日志信息转换为日志事件LogEvent对象，然后将LogEvent对象传入对应的Appender中，由对应的Appender调用appender()方法将日志信息写入文件。
下面的代码是在LogConfig类中的log()方法中，创建LogEvent对象，调用processLogEvent()方法将LogEvent对象传入对应的Appender中。
publicvoid log(final String loggerName, final String fqcn, final Marker marker, final Level level, final Message data, final Throwable t) { List<Property> props = null; if (!propertiesRequireLookup) { props = properties; } else { // 省略部分代码 } final LogEvent logEvent = logEventFactoryinstanceof LocationAwareLogEventFactory ? ((LocationAwareLogEventFactory) logEventFactory).createEvent(loggerName, marker, fqcn, requiresLocation() ? StackLocatorUtil.calcLocation(fqcn) : null, level, data, props, t) : logEventFactory.createEvent(loggerName, marker, fqcn, level, data, props, t); try { log(logEvent, LoggerConfigPredicate.ALL); } finally { ReusableLogEventFactory.release(logEvent); } } protectedvoid log(final LogEvent event, final LoggerConfigPredicate predicate) { if (!isFiltered(event)) { processLogEvent(event, predicate); } } privatevoid processLogEvent(final LogEvent event, final LoggerConfigPredicate predicate) { event.setIncludeLocation(isIncludeLocation()); if (predicate.allow(this)) { callAppenders(event); } logParent(event, predicate); } protectedvoid callAppenders(final LogEvent event) { final AppenderControl[] controls = appenders.get(); //noinspection ForLoopReplaceableByForEach for (inti = 0; i < controls.length; i++) { controls[i].callAppender(event); } } |
在抽象类AbstractOutputStreamAppender中的appender()方法，最后调用directEncodeEvent()将日志信息写入文件。
/** * Actual writing occurs here. * <p> * Most subclasses of <code>AbstractOutputStreamAppender</code> will need to override this method. * </p> * * @param event The LogEvent. */ @Override publicvoid append(final LogEvent event) { try { tryAppend(event); } catch (final AppenderLoggingException ex) { error("Unable to write to stream " + manager.getName() + " for appender " + getName(), event, ex); throwex; } }
privatevoid tryAppend(final LogEvent event) { if (Constants.ENABLE_DIRECT_ENCODERS) { directEncodeEvent(event); } else { writeByteArrayToManager(event); } }
protectedvoid directEncodeEvent(final LogEvent event) { getLayout().encode(event, manager); if (this.immediateFlush || event.isEndOfBatch()) { manager.flush(); } } |
log4j2.xml配置如下：
<Configuration status="ERROR"> <Appenders> <RollingFile name="LOG-ACCESS" fileName="logs/access.log" immediateFlush="true"> <PatternLayout pattern="[%-5p %l %t %d{yyyy-MM-dd HH:mm:ss,SSS}] %m%n" /> </RollingFile> </Appenders>
<Loggers> <logger name="com.log.test" level="INFO" additivity="false"> <AppenderRef ref="LOG-ACCESS" /> </logger> </Loggers> </Configuration> |
2、AsyncAppender 异步方式
Appender官方文档上给出的定义是“Appenders are responsible for delivering LogEvents to their destination.”，它的作用是将日志事件传递到指定目标。Log4j2提供了多种Appender，其中AsyncAppender是一种能将日志事件异步写入文件的Appender。
AsyncAppender在官方文档上的介绍如下：
The AsyncAppender accepts references to other Appenders and causes LogEvents to be written to them on a separate Thread. Note that exceptions while writing to those Appenders will be hidden from the application. The AsyncAppender should be configured after the appenders it references to allow it to shut down properly. By default, AsyncAppender uses java.util.concurrent.ArrayBlockingQueue which does not require any external libraries. Note that multi-threaded applications should exercise care when using this appender as such: the blocking queue is susceptible to lock contention. |
简单来说，AsyncAppender的异步打印做了两件事，先把日志事件放到ArrayBlockingQueue队列，然后单独的线程读取队列中的日志事件将其传递给其他引用的Appender，由这些Appender将日志写入文件。
查看AsyncAppender源码，可以看到他的成员变量中有一个ArrayBlockingQueue队列，队列默认大小为1024，一个单独的线程类AsyncThread，还有它引用的Appender数组。
publicfinalclass AsyncAppender extends AbstractAppender { privatestaticfinalintDEFAULT_QUEUE_SIZE = 1024; privatefinal BlockingQueue<LogEvent> queue; privatefinal AppenderRef[] appenderRefs; private AsyncThread thread; // 省略其他成员变量及成员方法相关代码 } |
首先来看AsyncAppender是如何将日志事件存入队列的，下面是AsyncAppender类中的append(LogEvent logEvent)方法，可以看到在appender方法中调用了私有方法transfer(LogEvent memento)，将日志事件存入在队列中。
@Override publicvoid append(final LogEvent logEvent) { if (!isStarted()) { thrownew IllegalStateException("AsyncAppender " + getName() + " is not active"); } final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation); InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage()); if (!transfer(memento)) { // 省略队列阻塞等待相关处理 } else { error("Appender " + getName() + " is unable to write primary appenders. queue is full"); logToErrorAppenderIfNecessary(false, memento); } } }
privateboolean transfer(final LogEvent memento) { returnqueueinstanceof TransferQueue ? ((TransferQueue<LogEvent>) queue).tryTransfer(memento) : queue.offer(memento); } |
然后再看看AsyncThread是如何获取队列中的LogEvent的，并将日志事件传递给其他引用的Appender。
@Override publicvoid append(final LogEvent logEvent) { if (!isStarted()) { thrownew IllegalStateException("AsyncAppender " + getName() + " is not active"); } final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation); InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage()); if (!transfer(memento)) { // 省略队列阻塞等待相关处理 } else { error("Appender " + getName() + " is unable to write primary appenders. queue is full"); logToErrorAppenderIfNecessary(false, memento); } } }
privateboolean transfer(final LogEvent memento) { returnqueueinstanceof TransferQueue ? ((TransferQueue<LogEvent>) queue).tryTransfer(memento) : queue.offer(memento); } |
在AsyncThread的run()方法中，循环阻塞获取队列中的LogEvent，获取日志事件后，在callAppenders(LogEvent event)方法中，将日志事件传递到它引用的Appender，调用对应Appender的appender(LogEvent event)方法，这样就完成了异步将日志事件写入文件。
AsyncAppender异步打印日志方式是在配置文件中添加<Async>标签，在<logger>标签中，引用该appender。
log4j2.xml配置如下：
@Override publicvoid append(final LogEvent logEvent) { if (!isStarted()) { thrownew IllegalStateException("AsyncAppender " + getName() + " is not active"); } final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation); InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage()); if (!transfer(memento)) { // 省略队列阻塞等待相关处理 } else { error("Appender " + getName() + " is unable to write primary appenders. queue is full"); logToErrorAppenderIfNecessary(false, memento); } } }
privateboolean transfer(final LogEvent memento) { returnqueueinstanceof TransferQueue ? ((TransferQueue<LogEvent>) queue).tryTransfer(memento) : queue.offer(memento); } |
3、AsyncLogger 异步方式
AsyncLogger的异步记录器是Log4j2的一个新特性，可以通过在单独的线程中执行I/O操作来提高应用程序的性能。其内部使用了disruptor框架，其底层数据结构为无锁环形队列，每次日志信息保存在队列中，另一个线程将队列中日志写入文件。
AsyncLogger异步记录器官方文档上描述如下：
Asynchronous logging can improve your application's performance by executing the I/O operations in a separate thread. Log4j 2 makes a number of improvements in this area. Asynchronous Loggers are a new addition in Log4j 2. Their aim is to return from the call to Logger.log to the application as soon as possible. LMAX Disruptor technology. Asynchronous Loggers internally use the Disruptor, a lock-free inter-thread communication library, instead of queues, resulting in higher throughput and lower latency. |
通过描述可以看出，AsyncLogger主要是通过使用LMAX disruptor框架代替队列，从而提高吞吐量，降低延迟。那么，disruptor框架到底是个什么呢，disruptor文档上的介绍如下：
The best way to understand what the Disruptor is, is to compare it to something well understood and quite similar in purpose. In the case of the Disruptor this would be Java's BlockingQueue. Like a queue the purpose of the Disruptor is to move data (e.g. messages or events) between threads within the same process. However there are some key features that the Disruptor provides that distinguish it from a queue. They are:
|
根据介绍可以看出disruptor框架是个高性能线程间消息传递库，支持发送多播事件，基本上是无锁状态，会为事件提前分配内存空间。
disruptor框架的底层结构是环形缓冲区RingBuffer，当日志到达后，AsyncLogger的logMessage()方法会将日志信息转换为RingBufferLogEventTranslator对象，然后调用public()方法将translator对象放入RingBuffer中。
privatefinal TranslatorType threadLocalTranslatorType = new TranslatorType() { @Override void log(String fqcn, Level level, Marker marker, Message message, Throwable thrown) { logWithThreadLocalTranslator(fqcn, level, marker, message, thrown); } }; @Override publicvoid logMessage(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) { getTranslatorType().log(fqcn, level, marker, message, thrown); }
privatevoid logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) { // Implementation note: this method is tuned for performance. MODIFY WITH CARE! final RingBufferLogEventTranslator translator = getCachedTranslator(); initTranslator(translator, fqcn, level, marker, message, thrown); initTranslatorThreadValues(translator); publish(translator); } privatevoid publish(final RingBufferLogEventTranslator translator) { if (!loggerDisruptor.tryPublish(translator)) { handleRingBufferFull(translator); } } |
disruptor的单线程批量处理BatchEventProcessor会从RingBuffer中读取存入的事件，回调EventHandler的onEvent()方法。在RingBufferLogEventHandler的onEvent()方法中，将日志信息写入文件。
@Override publicvoid onEvent(final RingBufferLogEvent event, finallongsequence, finalbooleanendOfBatch) throws Exception { try { event.execute(endOfBatch); } finally { event.clear(); // notify the BatchEventProcessor that the sequence has progressed. // Without this callback the sequence would not be progressed // until the batch has completely finished. notifyCallback(sequence); } } // RingBufferLogEvent的execute()方法 /** * Event processor that reads the event from the ringbuffer can call this method. * * @param endOfBatch flag to indicate if this is the last event in a batch from the RingBuffer */ publicvoid execute(finalbooleanendOfBatch) { this.endOfBatch = endOfBatch; asyncLogger.actualAsyncLog(this); } |
AsyncLogger依赖disruptor框架，因此需要在classpath路径下需要额外添加disruptor的jar包。AsyncLogger有两种方式全异步方式和混合同步异步方式。
（1）全异步方式，需要设置系统属性，指定log4j2.contextSelector值为org.apache.logging.log4j.core.async.AsyncLoggerContextSelector，配置文件中使用<Logger>或<Root>标签
（2）混合同步异步方式无需设置系统属性log4j2.contextSelector，在配置文件中使用<AsyncLogger>或<AsyncRoot>标签代替<Logger>或<Root>标签。
混合同步异步方式log4j2.xml配置如下：
<Configuration status="ERROR"> <Appenders> <RollingFile name="LOG-ACCESS" fileName="logs/access.log" immediateFlush="true"> <PatternLayout pattern="[%-5p %l %t %d{yyyy-MM-dd HH:mm:ss,SSS}] %m%n" /> </RollingFile> </Appenders>
<Loggers> <AsyncLogger name=" com.log.test" level="INFO" additivity="false"> <AppenderRef ref="LOG-ACCESS"/> </AsyncLogger> </Loggers> </Configuration> |
现在我们大致知道了这三种日志打印方式的用法了，但是几个问题仍然需要解答：
1、三种日志打印方式对系统性能上差距有多大。
2、同步方式和异步方式在内存使用方面有什么差别。
3、两种异步方式底层队列实现方式不同，究竟哪个性能更好。
接下来我们就要通过测试数据来寻找答案。
实测数据对比
为了更好的比较Log4j2的三种方式记录日志信息对系统性能带来的差别，进行了压力测试，以此来根据测试结果针对不同的应用场景，在保证日志记录详尽的前提下，选择性能最优的日志记录方式。
本次测试使用2核CPU，内存大小4G，50G硬盘的服务器，通过调用http接口，在接口内打印108字节大小的日志，压测过程中，get方式请求接口，tomcat最大线程数设置为10个，并发用户数400个，每次持续时间为6分钟，记录CPU使用率、内存使用率、磁盘写速度、磁盘写次数、接口TPS、接口响应时间等指标。使用各组件的版本信息如下：
JDK：1.8
Spring Boot : 2.1.3.RELEASE
Log4j2 ：2.13.1
Disruptor：3.4.2
1、单个Appender
压测过程中，初始CPU差别不大，400个并发用户数使机器CPU使用率达到100%。
在内存使用情况上，同步方式和AsyncAppender方式差别不大，而AsyncLogger方式的内存使用率略高于另外两种2%。
单个Appender的情况下，两种异步方式的线程数比同步方式多1个，可以看出，异步的方式会创建出新的线程来写入日志。
AsyncAppender的磁盘使用情况和接口每秒调用量都优于AsyncLogger，两种异步记录日志方式的接口每秒调用量是同步记录日志方式的两倍左右，可以看出异步记录日志方式的系统性能明显优于同步记录日志方式。
2、3个Appender
从CPU和内存的使用情况来看，在CPU利用率100%时，AsyncLogger方式的内存使用率依然略高于另外两种方式，和单个Appender的情况差不多，可以看出，AsyncLogger在内存使用上与Appender的个数并无关系。
3个Appender的时候，AsyncAppender的线程数比单个Appender增加了2个，可以看出，每个AsyncAppender 都会创建出一个线程处理日志输出；而 AsyncLogger的线程数和单个Appender的线程数相同，说明AsyncLogger方式共用1个线程来处理日志输出。
由于每新增一个Appender，AsyncAppender就会为其创建一个线程，由于线程数越多，ArrayBlockingQueue阻塞队列受锁争用的影响，线程上下文切换的开销就越大，相比之下，AsyncAppender在Appender越多的情况下优势会慢慢减弱。当有3个Appender时，从磁盘使用情况和接口每秒调用量两个指标来看，AsyncLogger的表现都优于AsyncAppender。
3、6个Appender
结合前面几个图，可以看出，当有6个Appender的时候，AsyncAppender的线程数比单个Appender增加了5个，使用AsyncLogger的系统性能和使用AsyncAppender的系统性能有了明显的优势，也就是说当Appender越多时，AsyncLogger的性能优势在三种日志记录方式中表现的越明显。
4、immediateFlush
在阅读官方文档过程中，发现异步记录日志章节中，文档上特别标注了immediateFlush参数，这个参数是配置每次写入日志时是否立即写入磁盘，于是又添加了一组对比实验，测试这个参数对性能带来的影响。官方文档上对这个参数的介绍如下：
When set to true - the default, each write will be followed by a flush. This will guarantee the data is written to disk but could impact performance. Flushing after every write is only useful when using this appender with synchronous loggers. Asynchronous loggers and appenders will automatically flush at the end of a batch of events, even if immediateFlush is set to false. This also guarantees the data is written to disk but is more efficient. |
默认情况下，该值为true，当值为false时，会在buffer满或异步队列为空的时候刷新写入磁盘。
下图比较的是在3个Appender的情况下AsyncLogger配置immediateFlush值为true和值为false的性能对比。
不难看出当immediateFlush参数配置为false时，关闭立即刷新后，磁盘使用情况和接口每秒调用量只是略高于立即刷新，两者的差距并不是很大，在使用过程中，可以根据自身实际需求选择。
小结
1、在线程使用方面，log4j2的同步方式使用和业务逻辑相同的线程处理日志输出；AsyncAppender内部使用ArrayBlockingQueue队列，对于每一个AsyncAppender都会创建一个线程处理日志输出；AsyncLogger内部使用了disruptor框架，其底层数据结构为无锁环形队列，使用一个单独线程处理日志输出。
2、在日志内容较多，打印日志频繁的情况下，两种异步日志记录方式会优于同步方式。
3、如果系统并非频繁打印日志，只是在异常情况或极端情况下打印几条日志信息，根据实际生产经验，同步和两种异步方式之间体现不出差距，可以选择使用同步方式记录日志信息。