Asynchronous loggers

Asynchronous logging is a technique that improves application logging performance by executing all I/O operations in a separate thread.

Log4j offers out-of-the-box two different asynchronous logging solutions:

Asynchronous appender

An asynchronous appender is a classical queue-based asynchronous appender which is available since Log4j 1.

See Asynchronous appender for more details.

Asynchronous loggers

Asynchronous loggers have been a new feature since Log4j 2. They are based on LMAX Disruptor, a lock-free inter-thread communication library, instead of queues, resulting in higher throughput and lower latency.

The rest of this chapter is dedicated to this new component.

Logging performance depends significantly on the architecture of your application and the way you use logging. The solutions offered by this chapter should be evaluated using benchmarks against your application. If benchmarks and profiling don’t show a statistically significant difference between asynchronous and synchronous logging solutions, the latter is recommended since it is the simplest.

Trade-offs

There are certain trade-offs associated with asynchronous logging:

Benefits

Higher peak throughput

Applications that occasionally need to log bursts of messages, can take advantage of asynchronous logging. It can prevent or dampen latency spikes by shortening the wait time until the next message can be logged. If the queue size is large enough to handle the burst, asynchronous logging will prevent your application from falling behind during a sudden increase of activity.

Lower logging latency

Logger method calls return faster, since most of the work is done on the I/O thread.

Drawbacks

Lower sustainable throughput

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.

Error handling

If a problem happens during the logging process and an exception is thrown, it is less easy for an asynchronous setting to signal this problem to the application. This can partly be alleviated by configuring an exception handler, but this may still not cover all cases.

If logging is part of your business logic, e.g. you are using Log4j as an audit logging framework, we would recommend to synchronously log those audit messages.

See mixed synchronous/asynchronous loggers on how to log some messages synchronously.
Stateful messages

Most Message implementations take a snapshot of the formatted message on the calling thread (cf. log4j2.formatMsgAsync). The log message will not change even if the arguments of the logging call are modified later.

There are some exceptions to this rule. MapMessage and StructuredDataMessage for example 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.

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 (see AsynchronouslyFormattable).

Computational overhead

If your application is running in an environment where CPU resources are scarce, like a VM with a single vCPU, starting another thread is not likely to give better performance.

Installation

In order to use async loggers, you need to add LMAX Disruptor to you application’s dependencies, by adding the following dependency to your build tool:

  • Maven

  • Gradle

<dependency>
  <groupId>com.lmax</groupId>
  <artifactId>disruptor</artifactId>
  <version>4.0.0</version>
  <scope>runtime</scope>
</dependency>
runtimeOnly 'com.lmax:disruptor:4.0.0'

Configuration

There are two ways asynchronous loggers can be used in Log4j. You can:

Under the hood, these methods use different Log4j plugins but also share a set of common configuration properties.

Making all loggers asynchronous

This is the simplest to configure and gives the best performance: to make all logger asynchronous, all you need to set the log4j2.contextSelector property to one of the asynchronous logger context selectors:

org.apache.logging.log4j.core.async.BasicAsyncLoggerContextSelector

This will create a single logger context and disruptor for all the classes in the JVM,

org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

This will create a different logger context and disruptor for each classloader in the JVM.

When using an asynchronous logger context, you should only use the Root and Logger elements (cf. Logger configuration).

If you use AsyncRoot and AsyncLogger configuration elements, two asynchronous barriers will be created instead of one, impairing performance.

Tuning a fully asynchronous configuration

Since Disruptor is initialized at the same time as the logger context and before any Log4j configuration file is loaded, tuning async loggers is only possible through configuration properties.

Beyond the common configuration properties, the following additional elements are configurable:

log4j2.asyncLoggerExceptionHandler

Env. variable

LOG4J_ASYNC_LOGGER_EXCEPTION_HANDLER

Type

Class<? extends ExceptionHandler<? super RingBufferLogEvent>>

Default value

AsyncLoggerDefaultExceptionHandler

Fully qualified name of a class that implements the ExceptionHandler interface, which will be notified when an exception occurs while logging messages. The class needs to have a public zero-argument constructor.

The default exception handler will print a message and stack trace to the standard error output stream.

log4j2.asyncLoggerRingBufferSize

Env. variable

LOG4J_ASYNC_LOGGER_RING_BUFFER_SIZE

Type

int

Default value

256 × 1024

(GC-free mode: 4 × 1024)

Size (number of slots) in the RingBuffer used by the asynchronous logging subsystem. Make this value large enough to deal with bursts of activity. The minimum size is 128. The RingBuffer will be pre-allocated at first use and will never grow or shrink during the life of the system.

When the application is logging faster than the underlying appender can keep up with for a long enough time to fill up the queue, the behaviour is determined by the AsyncQueueFullPolicy.

log4j2.asyncLoggerWaitStrategy

Env. variable

LOG4J_ASYNC_LOGGER_WAIT_STRATEGY

Type

predefined constant

Default value

Timeout

Specifies the WaitStrategy used by the LMAX Disruptor.

The value needs to be one of the predefined constants:

Block

a strategy that uses a lock and condition variable for the I/O thread waiting for log events. Block can be used when throughput and low-latency are not as important as CPU resource. Recommended for resource constrained/virtualized environments. This wait strategy is not garbage free.

Timeout

a variation of the Block strategy that will periodically wake up from the lock condition await() call. This ensures that if a notification is missed somehow the consumer thread is not stuck but will recover with a small latency delay, see log4j2.asyncLoggerTimeout. This wait strategy is garbage free.

Sleep

a strategy that initially spins, then uses a Thread.yield(), and eventually parks for the minimum number of nanos the OS and JVM will allow while the I/O thread is waiting for log events (see log4j2.asyncLoggerRetries and log4j2.asyncLoggerSleepTimeNs). Sleep is a good compromise between performance and CPU resource. This strategy has very low impact on the application thread, in exchange for some additional latency for actually getting the message logged. This wait strategy is garbage free.

Yield

is a strategy that will use 100% CPU, but will give up the CPU if other threads require CPU resources. This wait strategy is garbage free.

log4j2.asyncLoggerTimeout

Env. variable

LOG4J_ASYNC_LOGGER_TIMEOUT

Type

int

Default value

10

Timeout in milliseconds of Timeout wait strategy (see log4j2.asyncLoggerWaitStrategy).

log4j2.asyncLoggerSleepTimeNs

Env. variable

LOG4J_ASYNC_LOGGER_SLEEP_TIME_NS

Type

long

Default value

100

Sleep time in nanoseconds of Sleep wait strategy (see log4j2.asyncLoggerWaitStrategy).

log4j2.asyncLoggerRetries

Env. variable

LOG4J_ASYNC_LOGGER_RETRIES

Type

int

Default value

200

Total number of spin cycles and Thread.yield() cycles of Sleep (see log4j2.asyncLoggerWaitStrategy).

log4j2.asyncLoggerSynchronizeEnqueueWhenQueueFull

Env. variable

LOG4J_ASYNC_LOGGER_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL

Type

boolean

Default value

true

Synchronizes access to the Disruptor ring buffer for blocking enqueue operations when the queue is full. Users encountered excessive CPU utilization with Disruptor v3.4.2 when the application was logging more than the underlying appender could keep up with and the ring buffer became full, especially when the number of application threads vastly outnumbered the number of cores. CPU utilization is significantly reduced by restricting access to the enqueue operation. Setting this value to false may lead to very high CPU utilization when the async logging queue is full.

log4j2.asyncLoggerThreadNameStrategy

Env. variable

LOG4J_ASYNC_LOGGER_HREAD_NAME_STRATEGY

Type

ThreadNameCachingStrategy (enumeration)

Default value

UNCACHED for JRE 8u102 or later,

CACHED otherwise

Specifies the ThreadNameCachingStrategy to use to cache the result of Thread#getName().

This setting allows to cache the result of Thread.getName() calls and has two values:

CACHED

stores the name of the current thread in a ThreadLocal field,

UNCACHED

disables caching.

Since JRE 8u102 the Thread.getName() method does not allocate a new object.

You can place the selected value of the log4j2.contextSelector and other configuration properties in a log4j2.component.properties file at the root of your application’s classpath.

See Property Sources for more details.

Mixing synchronous and asynchronous loggers

Synchronous and asynchronous loggers can be combined in a single configuration. This gives you more flexibility at the cost of a slight performance loss (compared to making all loggers asynchronous).

To use this configuration, you need to keep the log4j2.contextSelector at its default value and use one of the AsyncRoot and AsyncLogger configuration elements designate the loggers you want to be asynchronous.

A configuration that mixes asynchronous loggers might look like:

  • XML

  • JSON

  • YAML

  • Properties

Snippet from an example log4j2.xml
<Loggers>
  <Root level="INFO">
    <AppenderRef ref="AUDIT"> (1)
      <MarkerFilter marker="AUDIT" onMatch="ACCEPT" onMismatch="DENY"/>
    </AppenderRef>
  </Root>
  <AsyncLogger name="com.example" level="TRACE">
    <AppenderRef ref="DEBUG_LOG"/> (2)
  </AsyncLogger>
</Loggers>
Snippet from an example log4j2.json
"Loggers": {
  "Root": {
    "level": "INFO",
    "AppenderRef": { (1)
      "ref": "AUDIT",
      "MarkerFilter": {
        "marker": "AUDIT",
        "onMatch": "ACCEPT",
        "onMismatch": "DENY"
      }
    }
  },
  "AsyncLogger": { (2)
    "name": "com.example",
    "level": "TRACE",
    "AppenderRef": {
      "ref": "DEBUG_LOG"
    }
  }
}
Snippet from an example log4j2.yaml
Loggers:
  Root:
    level: "INFO"
    AppenderRef: (1)
      ref: "AUDIT"
      MarkerFilter:
        marker: "AUDIT"
        onMatch: "ACCEPT"
        onMismatch: "DENY"
  AsyncLogger:
    name: "com.example"
    level: "TRACE"
    AppenderRef: (2)
      ref: "DEBUG_LOG"
Snippet from an example