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呢?!

posted @ 2019-07-11 15:54 waterystone 阅读(...) 评论(...) 编辑 收藏