Log4j2分析与实践-异步Logger

  异步日志可以通过在单独的线程中执行I/O操作来提高应用系统的性能,Log4j2在这个领域做了大量改善。
(1)异步Logger是Log4j2中新增的功能,目的是尽快向调用方返回结果。你可以选择将所有Loggers设置为异步的,也可以选择同步和异步混合的方式。将所有Logger都设置为异步的可以获得最好的性能,而混合的Logger会给你更好的灵活性。
(2)LMAX Disruptor技术。异步Logger内部使用的是Disruptor,一个无锁的线程间通信库,而不是采用的队列。如此一来,异步Logger就有更高的吞吐量和更低的延迟。

(3)异步Appenders作为异步Logger功能的一部分,在一个批次的最后(即当队列为空时),将日志冲刷进磁盘的功能也得到了增强。这个实现的效果跟设置 "immediateFlush=true"是一样的,但是更加高效,因为它不用在每次日志事件到达时都去进行一次磁盘I/O。(异步Appender内部使用的是ArrayBlockingQueue,所以不需要disruptor的jar包)。


优劣权衡

  尽管异步日志可以带来重大的性能提升,但是有些场景也许需要选择同步日志。本节就异步日志的优劣进行讨论!
优点
(1)更高的吞吐量。异步Logger的吞吐量可以达到同步Logger的6至68倍。特别是在高峰时大量日志请求涌入,如果队列配置得足够大,使用异步日志可以快速向请求方返回结果,从而避免了系统不能正常响应日志请求。
(2)更低的延迟。异步Logger比同步Logger(甚至基于队列的异步Appender)有着更低的延迟。
缺点
(1)对错误的处理。如果在日志记录的过程中出现了错误,或者有异常抛出,异步Logger很难将出现的问题告知给应用系统。也许可以配置一个ExceptionHandler来缓解这个问题,但是也不能覆盖所有的情况。因此,如果日志记录是你业务逻辑的一部分,比如你将Log4j作为一个审计用的日志框架,建议使用同步方式记录日志。
(2)在一些极少的情况下,需要注意一下可变消息。大部分情况你不必关心这个问题。Log4j2会确保logger.debug("My object is {}", myObject)日志消息会使用myObject参数的值来替换{}占位符。即使之后myObject发生了变化,日志消息也不会发生变化。使用异步日志记录可变对象参数时安全的,因为Log4j2中Message的实现对可变参数维持了一个快照。也有例外,MapMessage和StructuredDataMessage就是被设计为可变的,在Message对象被创建后,还可以向其添加字段。这些消息在被异步Logger或者异步Appender处理之后不该被修改,但是你也许会在输出中看到被修改了。类似的,自定义的Message实现应该基于异步情况进行设计,可以在构建的时候对参数维持一份快照,并给予其线程安全的特性。


(3)若你的应用运行在CPU资源匮乏的环境下,比如单核CPU,另外启动一个线程也不太可能会有更好的性能。
(4)如果日志请求的速率大于Appender处理的速率,队列很快就会被占满了,此时应用的日志记录速度将会决定于最慢的一个Appender。如果这种情况发生了,可以选择一个更快的Appender,或者少发起一些日志请求。若都不行,也许使用同步日志会有更好的吞吐量。


将所有Logger都设置为异步的

    需要disruptor-3.0.0.jar或者更高版本的jar包。未来的Log4j2将会需要disruptor-3.3.3.jar或者更高。
    这是最简单的配置方式,却能获得最佳的性能。将所有Logger都设置为异步的,需要将disruptor.jar放到classpath,并且将系统属性Log4jContextSelector设置为org.apache.logging.log4j.core.async.AsyncLoggerContextSelector。可以在classpath下新建一个配置文件log4j2.component.properties,然后在里面添加一个Log4jContextSelector配置。
    默认情况下,location位置信息是不会传递给异步Logger的I/O线程的。如果有Layout或者Filter需要位置信息,则要在所有相关Logger的配置中添加"includeLocation=true",包括根Logger。


<?xml version="1.0" encoding="UTF-8"?>
<!-- 别忘了设置系统属性-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -->
<Configuration status="WARN">
  <Appenders>
    <!-- 异步Logger会在批量处理时自动冲刷,所以关闭immediateFlush -->
    <RandomAccessFile name="RandomAccessFile" fileName="async.log" immediateFlush="false" append="false">
      <PatternLayout>
        <Pattern>%d %p %c{1.} [%t] %m %ex%n</Pattern>
      </PatternLayout>
    </RandomAccessFile>
  </Appenders>
  <Loggers>
    <Root level="info" includeLocation="false">
      <AppenderRef ref="RandomAccessFile"/>
    </Root>
  </Loggers>
</Configuration>
    当设置AsyncLoggerContextSelector使得所有Logger变为异步的之后,请在配置中使用普通的<root>和<logger>标签,因为AsyncLoggerContextSelector会根据普通的Logger标签来确保所有的logger均为异步的,若混合使用<asyncRoot>或者<asyncLogger>就会导致后台有两个线程,应用会将日志消息传递给线程A,然后再传递给线程B,最后才将日志写入磁盘,中间经历了不必要的步骤。
    还有一些系统属性可以用来控制异步日志,这些属性均可以添加到log4j2.component.properties文件中。
(1)AsyncLogger.ExceptionHandler,用于处理日志记录过程中的异常,它的值为处理类的名字全称,这个类需要实现com.lmax.disruptor.ExceptionHandler接口。若没有指定,默认异常处理器会将异常堆栈信息打印到默认输出流中。
(2)AsyncLogger.RingBufferSize,默认为256 * 1024。异步日志系统使用的RingBuffer的大小。要使得这个值足够大,最小值为128。RingBuffer将会在首次使用时预分配,并且运行期间不再变化。若日志的请求速度比对应Appender处理速度要快,而队列花了很长时间才变满,那么性能表现就会取决于AsyncQueueFullPolicy。
(3)AsyncLogger.WaitStrategy,默认为Timeout。合法的值为Block、Timeout或者Yield。Block会使用一个锁和条件变量,使得I/O线程会等待日志事件,可以用在在吞吐量和低延迟没有CPU资源重要的情况。Timeout是Block的变体,会周期性地从锁定条件下唤醒。在I/O线程等待日志事件时,Sleep策略会首先自旋,然后调用Thread.yield(),再等待操作系统和JVM所允许的最小时间。Sleep是性能和CPU资源的组合方案。Yield会在首轮自旋后使用Thread.yield()来等待日志事件.Yield是性能和CPU资源的组合方案,但是会比Sleep使用更多的CPU资源。
AsyncLogger.ThreadNameStrategy,默认为CACHED。合法的值为CACHED或者UNCACHED。默认情况下,AsyncLogger会在ThreadLocal中缓存线程的名称,以此来提高性能。若应用中需要在运行时修改线程名字,要指定UNCACHED选项。
(4)log4j.Clock,默认为SystemClock。合法的值为SystemClock或者CachedClock。org.apache.logging.log4j.core.util.Clock接口的实现,用于在所有Logger都是异步时对日志事件生成时间戳。默认情况下,每次日志事件均会调用System.currentTimeMillis。CacheClock是企图对低延迟的系统进行的优化,即时间戳由一个时钟生成,这个时钟会在后台一个线程中每隔1毫秒更新一个内部事件,或者每隔1024个时间更新一次。CachedClock 也许减少了一些延迟,但损失了时间戳的精度。在WEB应用中不推荐使用CachedClock。你也可以自定义一个实现了Clock接口的类。
     Log4j2分析与实践-Appenders中提到的log4j2.AsyncQueueFullPolicy和log4j2.DiscardThreshold也可以在日志请求速率快与处理速率时发挥作用。


混合使用同步和异步Logger

    需要disruptor-3.0.0.jar或者更高版本的jar包。未来的Log4j2将会需要disruptor-3.3.3.jar或者更高。不要设置Log4jContextSelector参数。
同步和异步Logger可以共存,虽然会有一点性能损失(与将所有Logger都设置为异步的相比而言)。使用<asyncRoot>或者<asyncLogger>就可以将Logger指定为异步的。
    默认情况下,location位置信息是不会传递给异步Logger的I/O线程的。如果有Layout或者Filter需要位置信息,则要在所有相关Logger的配置中添加"includeLocation=true",包括根Logger。


<?xml version="1.0" encoding="UTF-8"?>
<!-- 使用<asyncLogger>或者<asyncRoot>的时候不要设置Log4jContextSelector -->
<Configuration status="WARN">
  <Appenders>
    <!-- 异步Logger会在批量处理时自动冲刷,所以关闭immediateFlush -->
    <RandomAccessFile name="RandomAccessFile" fileName="asyncWithLocation.log"
              immediateFlush="false" append="false">
      <PatternLayout>
        <Pattern>%d %p %class{1.} [%t] %location %m %ex%n</Pattern>
      </PatternLayout>
    </RandomAccessFile>
  </Appenders>
  <Loggers>
    <!-- PatternLayout用到了位置信息, 所以需要设置includeLocation -->
    <AsyncLogger name="com.foo.Bar" level="trace" includeLocation="true">
      <AppenderRef ref="RandomAccessFile"/>
    </AsyncLogger>
    <Root level="info" includeLocation="true">
      <AppenderRef ref="RandomAccessFile"/>
    </Root>
  </Loggers>
</Configuration>
    同时,混合同步和异步模式也有系统属性可以设置,包含AsyncLoggerConfig.ExceptionHandler、AsyncLoggerConfig.RingBufferSize和AsyncLoggerConfig.WaitStrategy,设置方法与前文所述类似。