Trade-offs

Although asynchronous logging can give significant performance benefits, there are situations where you may want to choose synchronous logging. This section describes some of the trade-offs of asynchronous logging.

Benefits

• Higher peak throughput. With an asynchronous logger your application can log messages at 6 - 68 times the rate of a synchronous logger.

  This is especially interesting for applications that occasionally need to log bursts of messages. Async logging can help prevent or dampen latency spikes by shortening the wait time until the next message can be logged. If the queue size is configured large enough to handle the burst, asynchronous logging will help prevent your application from falling behind (as much) during a sudden increase of activity.

• Lower logging response time latency. Response time latency is the time it takes for a call to Logger.log to return under a given workload. Asynchronous Loggers have consistently lower latency than synchronous loggers or even queue-based asynchronous appenders.

• Error handling. If a problem happens during the logging process and an exception is thrown, it is less easy for an asynchronous logger or appender to signal this problem to the application. This can partly be alleviated by configuring an ExceptionHandler, but this may still not cover all cases. For this reason, if logging is part of your business logic, for example if you are using Log4j as an audit logging framework, we would recommend to synchronously log those audit messages. (Note that you can still combine them and use asynchronous logging for debug/trace logging in addition to synchronous logging for the audit trail.)
• In some rare cases, care must be taken with mutable messages. Most of the time you don't need to worry about this. Log4 will ensure that log messages like logger.debug("My object is {}", myObject) will use the state of the myObject parameter at the time of the call to logger.debug(). The log message will not change even if myObject is modified later. It is safe to asynchronously log mutable objects because most Message implementations built-in to Log4j take a snapshot of the parameters. There are some exceptions however: MapMessage and StructuredDataMessage are mutable by design: fields can be added to these messages after the message object was created. These messages should not be modified after they are logged with asynchronous loggers or asynchronous appenders; you may or may not see the modifications in the resulting log output. Similarly, custom Message implementations should be designed with asynchronous use in mind, and either take a snapshot of their parameters at construction time, or document their thread-safety characteristics.
• If your application is running in an environment where CPU resources are scarce, like a machine with one CPU with a single core, starting another thread is not likely to give better performance.
• If the sustained rate at which your application is logging messages is faster than the maximum sustained throughput of the underlying appender, the queue will fill up and the application will end up logging at the speed of the slowest appender. If this happens, consider selecting a faster appender, or logging less. If neither of these is an option, you may get better throughput and fewer latency spikes by logging synchronously.

Making All Loggers Asynchronous

Log4j-2.9 and higher require disruptor-3.3.4.jar or higher on the classpath. Prior to Log4j-2.9, disruptor-3.0.0.jar or higher was required.

This is simplest to configure and gives the best performance. To make all loggers asynchronous, add the disruptor jar to the classpath and set the system property log4j2.contextSelector to org.apache.logging.log4j.core.async.AsyncLoggerContextSelector.

By default, location is not passed to the I/O thread by asynchronous loggers. If one of your layouts or custom filters needs location information, you need to set "includeLocation=true" in the configuration of all relevant loggers, including the root logger.

A configuration that does not require location might look like:

<?xml version="1.0" encoding="UTF-8"?>

<!-- Don't forget to set system property
-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
     to make all loggers asynchronous. -->

<Configuration status="WARN">
  <Appenders>
    <!-- Async Loggers will auto-flush in batches, so switch off 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>

When AsyncLoggerContextSelector is used to make all loggers asynchronous, make sure to use normal <root> and <logger> elements in the configuration. The AsyncLoggerContextSelector will ensure that all loggers are asynchronous, using a mechanism that is different from what happens when you configure <asyncRoot> or <asyncLogger>. The latter elements are intended for mixing async with sync loggers. If you use both mechanisms together you will end up with two background threads, where your application passes the log message to thread A, which passes the message to thread B, which then finally logs the message to disk. This works, but there will be an unnecessary step in the middle.

There are a few system properties you can use to control aspects of the asynchronous logging subsystem. Some of these can be used to tune logging performance.

The below properties can also be specified by creating a file named log4j2.component.properties and including this file in the classpath of the application.

Note that system properties were renamed into a more consistent style in Log4j 2.10.0. All old property names are still supported which are documented here.

There are also a few system properties that can be used to maintain application throughput even when the underlying appender cannot keep up with the logging rate and the queue is filling up. See the details for system properties log4j2.asyncQueueFullPolicy and log4j2.discardThreshold.

Mixing Synchronous and Asynchronous Loggers

Log4j-2.9 and higher require disruptor-3.3.4.jar or higher on the classpath. Prior to Log4j-2.9, disruptor-3.0.0.jar or higher was required. There is no need to set system property "Log4jContextSelector" to any value.

Synchronous and asynchronous loggers can be combined in configuration. This gives you more flexibility at the cost of a slight loss in performance (compared to making all loggers asynchronous). Use the <asyncRoot> or <asyncLogger> configuration elements to specify the loggers that need to be asynchronous. A configuration can contain only one root logger (either a <root> or an <asyncRoot> element), but otherwise async and non-async loggers may be combined. For example, a configuration file containing <asyncLogger> elements can also contain <root> and <logger> elements for the synchronous loggers.

By default, location is not passed to the I/O thread by asynchronous loggers. If one of your layouts or custom filters needs location information, you need to set "includeLocation=true" in the configuration of all relevant loggers, including the root logger.

A configuration that mixes asynchronous loggers might look like:

<?xml version="1.0" encoding="UTF-8"?>

<!-- No need to set system property "log4j2.contextSelector" to any value
     when using <asyncLogger> or <asyncRoot>. -->

<Configuration status="WARN">
  <Appenders>
    <!-- Async Loggers will auto-flush in batches, so switch off 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>
    <!-- pattern layout actually uses location, so we need to include it -->
    <AsyncLogger name="com.foo.Bar" level="trace" includeLocation="true">
      <AppenderRef ref="RandomAccessFile"/>
    </AsyncLogger>
    <Root level="info" includeLocation="true">
      <AppenderRef ref="RandomAccessFile"/>
    </Root>
  </Loggers>
</Configuration>

There are a few system properties you can use to control aspects of the asynchronous logging subsystem. Some of these can be used to tune logging performance.

The below properties can also be specified by creating a file named log4j2.component.properties and including this file in the classpath of the application.

Note that system properties were renamed into a more consistent style in Log4j 2.10. All old property names are still supported which are documented here.

There are also a few system properties that can be used to maintain application throughput even when the underlying appender cannot keep up with the logging rate and the queue is filling up. See the details for system properties log4j2.asyncQueueFullPolicy and log4j2.discardThreshold.

Location, location, location...

If one of the layouts is configured with a location-related attribute like HTML locationInfo, or one of the patterns %C or $class, %F or %file, %l or %location, %L or %line, %M or %method, Log4j will take a snapshot of the stack, and walk the stack trace to find the location information.

This is an expensive operation: 1.3 - 5 times slower for synchronous loggers. Synchronous loggers wait as long as possible before they take this stack snapshot. If no location is required, the snapshot will never be taken.

However, asynchronous loggers need to make this decision before passing the log message to another thread; the location information will be lost after that point. The performance impact of taking a stack trace snapshot is even higher for asynchronous loggers: logging with location is 30-100 times slower than without location. For this reason, asynchronous loggers and asynchronous appenders do not include location information by default.

You can override the default behaviour in your logger or asynchronous appender configuration by specifying includeLocation="true".

Asynchronous Logging Performance

The throughput performance results below were derived from running the PerfTest, MTPerfTest and PerfTestDriver classes which can be found in the Log4j 2 unit test source directory. For throughput tests, the methodology used was:

• First, warm up the JVM by logging 200,000 log messages of 500 characters.
• Repeat the warm-up 10 times, then wait 10 seconds for the I/O thread to catch up and buffers to drain.
• Measure how long it takes to execute 256 * 1024 / threadCount calls to Logger.log and express the result in messages per second.
• Repeat the test 5 times and average the results.

The results below were obtained with log4j-2.0-beta5, disruptor-3.0.0.beta3, log4j-1.2.17 and logback-1.0.10.

Under The Hood

Asynchronous Loggers are implemented using the LMAX Disruptor inter-thread messaging library. From the LMAX web site:

... using queues to pass data between stages of the system was introducing latency, so we focused on optimising this area. The Disruptor is the result of our research and testing. We found that cache misses at the CPU-level, and locks requiring kernel arbitration are both extremely costly, so we created a framework which has "mechanical sympathy" for the hardware it's running on, and that's lock-free.

LMAX Disruptor internal performance comparisons with java.util.concurrent.ArrayBlockingQueue can be found here.