Asynchronous loggers

Asynchronous logging is a technique to improve 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

A classical queue-based asynchronous appender, which is available since Log4j 1.

See Asynchronous appender for more details.

Asynchronous loggers

Asynchronous loggers are a new feature available 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 greatly 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 own application. If benchmarks and profiling don’t show a statistically significant difference between asynchronous and synchronous logging solutions, the latter one is recommended, since it is the simplest one.

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 use only Root and Logger elements (cf. Logger configuration).

If you use AsyncRoot and AsyncLogger configuration elements, two asynchronous barriers will be created instead of one, which will impair 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 loss in performance (compared to making all loggers asynchronous).

In order 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 to designate the loggers that 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 log4j2.properties
rootLogger.level = INFO
rootLogger.appenderRef.0.ref = AUDIT (1)
rootLogger.appenderRef.0.filter.0.type = MarkerFilter
rootLogger.appenderRef.0.filter.0.marker = AUDIT
rootLogger.appenderRef.0.filter.0.onMatch = ACCEPT
rootLogger.appenderRef.0.filter.0.onMismatch = DENY

logger.0.type = AsyncLogger
logger.0.name = com.example
logger.0.level = TRACE
logger.0.appenderRef.0.ref = DEBUG_LOG (2)
1 All the appenders referenced by Root and Logger are called synchronously. This is especially important for audit logging, since exceptions can be forwarded to the caller.
2 All the appenders references by AsyncRoot and AsyncLogger are called asynchronously. These log statements will cause a smaller latency for the caller.

Tuning a mixed synchronous/asynchronous configuration

Since all AsyncRoot and AsyncLogger components share the same Disruptor instance, its configuration is available through configuration properties.

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

log4j2.asyncLoggerConfigExceptionHandler

Env. variable

LOG4J_ASYNC_LOGGER_CONFIG_EXCEPTION_HANDLER

Type

Class<? extends ExceptionHandler<? super Log4jEventWrapper>>

Default value

AsyncLoggerConfigDefaultExceptionHandler

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.asyncLoggerRingConfigBufferSize

Env. variable

LOG4J_ASYNC_LOGGER_CONFIG_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.asyncLoggerConfigWaitStrategy

Env. variable

LOG4J_ASYNC_LOGGER_CONFIG_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/virtualised environments.

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)

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.

Yield

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

See also Custom WaitStrategy for an alternative way to configure the wait strategy.

log4j2.asyncLoggerConfigTimeout

Env. variable

LOG4J_ASYNC_LOGGER_CONFIG_TIMEOUT

Type

int

Default value

10

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

log4j2.asyncLoggerConfigSleepTimeNs

Env. variable

LOG4J_ASYNC_LOGGER_CONFIG_SLEEP_TIME_NS

Type

long

Default value

100

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

log4j2.asyncLoggerConfigRetries

Env. variable

LOG4J_ASYNC_LOGGER_CONFIG_RETRIES

Type

int

Default value

200

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

log4j2.asyncLoggerConfigSynchronizeEnqueueWhenQueueFull

Env. variable

LOG4J_ASYNC_LOGGER_CONFIG_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.

You can place the values of configuration properties in a log4j2.component.properties file at the root of your application’s classpath.

See Property Sources for more details.

Common configuration properties

Regardless of the way you configure asynchronous loggers in Log4j, you can use the following properties to further tune your installation:

log4j2.formatMsgAsync

Env. variable

LOG4J_FORMAT_MSG_ASYNC

Type

boolean

Default value

false

If false, Log4j will make sure the message is formatted in the caller thread, otherwise the formatting will occur on the asynchronous thread.

Remark: messages annotated with AsynchronouslyFormattable will be formatted on the async thread regardless of this setting.

log4j2.asyncQueueFullPolicy

Env. variable

LOG4J_ASYNC_QUEUE_FULL_POLICY

Type

Class<? extends AsyncQueueFullPolicy> or predefined constant

Default value

Default

Determines the AsyncQueueFullPolicy to use when the underlying async component cannot keep up with the logging rate and the queue is filling up.

Its value should be the fully qualified class name of an AsyncQueueFullPolicy implementation or one of these predefined constants:

Default

blocks the calling thread until the event can be added to the queue.

Discard

when the queue is full, it drops the events whose level is equal or less than the threshold level (see log4j2.discardThreshold).

log4j2.discardThreshold

Env. variable

LOG4J_DISCARD_THRESHOLD

Type

Level

Default value

INFO

Determines the threshold level used by a Discard queue full policy. Log events whose level is not more severe than the threshold level will be discarded during a queue full event. See also log4j2.asyncQueueFullPolicy.

Custom WaitStrategy

The system properties mentioned in the section above allow only to choose from among a fixed set of wait strategies.

In order to use a custom wait strategy you need to:

  1. Use the mixed sync/async configuration method above,

  2. Implement the interface AsyncWaitStrategyFactory; the implementation must have a public no-arg constructor,

  3. Add an AsyncWaitStrategyFactory Log4j plugin to your configuration.

  • XML

  • JSON

  • YAML

  • Properties

Snippet from an example log4j2.xml
<AsyncWaitStrategyFactory class="com.example.AsyncWaitStrategyFactory"/>
Snippet from an example log4j2.json
"AsyncWaitStrategyFactor": {
  "class": "com.example.AsyncWaitStrategyFactory"
}
Snippet from an example log4j2.yaml
  AsyncWaitStrategyFactory:
    class: "com.example.AsyncWaitStrategyFactory"
Snippet from an example log4j2.properties
strategy.type = AsyncWaitStrategyFactory
strategy.class = com.exampleAsyncWaitStrategyFactory

Location information

Computing the location information (i.e., the caller class, method, file, and line number) of a log event is an expensive operation. The impact on asynchronous loggers and appenders is even higher, since the component must decide whether to compute it or not before crossing the asynchronous barrier. Hence, the location information is disabled by default for asynchronous loggers and appenders. In order to enable it for a certain logger, set its includeLocation attribute to true.

Exception handler

In order to handle exceptions that occur on the asynchronous thread, you can configure a custom ExceptionHandler<T>.

The exact type of handler depends on the configuration mode:

Full asynchronous

If all the loggers are asynchronous you need to:

Mixed synchronous/asynchronous

If you use a mix of synchronous and asynchronous loggers you need to: