log4j输出到控制台的性能问题

一、背景

最近几个业务遇到服务假死的情况，通过排查，我们发现是因为业务在线上使用了日志框架的ConsoleAppender所致。

请尊重作者劳动成果，转载请标明原文链接：https://www.cnblogs.com/waterystone/p/11170540.html

二、排查过程

2.1 被block线程的堆栈

我们跟进后通过jsack把线程的堆栈打出来，发现大量线程被同一把monitor锁block住了（at org.apache.logging.log4j.core.layout.TextEncoderHelper.copyDataToDestination），其中一个完整的线程堆栈如下：

 通过堆栈我们可以看到，线程执行到TextEncoderHelper.copyDataToDestination()时，需要获取一把OutputStreamManager对象的锁，但这个锁被其他线程锁住了。源码如下（注：OutputStreamManager是ByteBufferDestination的子类）：

 

2.2 获取锁的线程的堆栈

那么这把锁被哪个线程锁住了呢？这个线程又在干什么呢？进一步排查，获取该锁的线程堆栈如下：

 我们发现，业务线程在使用ConsoleAppender打印日志时，需要同步获取到OutputStreamManager对象的monitor锁，然后同步调用PrintStream.write() → BufferedOutputStream.write() → FileOutputStream.write() ，接着flush()，等写到Console成功后，才会释放锁，而其他需要获取该锁的业务线程在此期间只能阻塞等待。其调用时序如下：

 

2.3 console日志性能分析

从前两步我们看到，在打印console日志时，需要先获取到OutputStreamManager对象的monitor锁，然后同步调用PrintStream.write() → BufferedOutputStream.write() → FileOutputStream.write() ，接着flush()，等写到Console成功后，才会释放锁。这期间其他打印console日志的线程都要被该monitor锁block住。

那么我们就有理由怀疑同步块中调用这些write()操作效率太低，从而导致大量其他业务线程被block住。通过官网查证，打印console日志，效率还真不是一般的低！！！如下所示：

三、AsyncLogger

从以上分析我们可以看到，业务通过同步Logger使用ConsoleAppender时会阻塞业务线程。其实通过同步Logger使用RollingRandomAccessFileAppender也会阻塞业务线程，只不过其同步块的处理效率更高些而已。那么有没有其他更高效的解决方案呢？有！AsyncLogger！！！

log4j2框架通过引入高性能环形消息队列框架Disruptor，将打印日志操作异步化，解除对业务线程的同步阻塞，极大加快业务线程的响应时间。

详细信息参考官网：https://logging.apache.org/log4j/2.x/manual/async.html。

其工作时序如下：

从上图可以看出，业务线程在使用AsyncLogger打印日志时，将日志消息放到disruptor的环形队列后即返回，这里也不会涉及到锁的同步竞争，极大加快了业务线程的响应时间。Disruptor会有一个专门的线程池来负责监听环形队列的消息事件，并将其落地。

 

AsyncLogger具有超强的性能，官方数据如下：

 

3.1 如何接入

AsyncLogger这么好用，如何接入呢？

1）在log4j2框架下，额外引入disruptor。

<dependency>
    <groupId>com.lmax</groupId>
    <artifactId>disruptor</artifactId>
    <version>3.4.2</version>
</dependency>

 

2）log4j2.xml配置成如下方式：

<Loggers>
    <!-- 将spring日志设置成info -->
    <AsyncLogger name="org.springframework" level="ERROR" includeLocation="true" />
 
    <asyncRoot level="INFO" includeLocation="true">
        <AppenderRef ref="INFO" />
        <AppenderRef ref="WARN" />
        <AppenderRef ref="ERROR" />
    </asyncRoot>
</Loggers>

 

四、总结

• 线上业务，严禁使用ConsoleAppender；
• 线上业务，强烈推荐AsyncLogger；
• 线上业务，可以使用同步Logger，但不推荐。以性能较高的RollingRandomAccessFileAppender为例，其在打印日志时同样也需要获取RollingRandomAccessFileManager对象的monitor锁，只不过该同步块中的处理效率较高，不像OutputStreamManager锁块那么低效而已。

看到这里，你还有什么理由使用ConsoleAppender呢？？？还有什么理由不使用AsyncLogger呢？！