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. log4j.async.formatMessagesInBackground). 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 log4j-async-logger to you application’s dependencies, by adding the following dependency to your build tool:

  • Maven

  • Gradle

We assume you use log4j-bom for dependency management.

<dependency>
  <groupId>org.apache.logging.log4j</groupId>
  <artifactId>log4j-async-logger</artifactId>
  <scope>runtime</scope>
</dependency>

We assume you use log4j-bom for dependency management.

runtimeOnly 'org.apache.logging.log4j:log4j-async-logger'

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 log4j.loggerContext.selector 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.

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 log4j.loggerContext.selector 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

<?xml version="1.0" encoding="UTF-8"?>
<Configuration xmlns="https://logging.apache.org/xml/ns"
               xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
               xsi:schemaLocation="
                   https://logging.apache.org/xml/ns
                   https://logging.apache.org/xml/ns/log4j-config-2.xsd">
  <Appenders>
    <File name="AUDIT" fileName="logs/audit.log" ignoreExceptions="false">
      <JsonTemplateLayout/>
    </File>
    <File name="DEBUG_LOG" fileName="logs/debug.log">
      <PatternLayout/>
    </File>
  </Appenders>
  <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>
</Configuration>
{
  "Configuration": {
    "Appenders": [
      {
        "name": "AUDIT",
        "fileName": "logs/audit.log",
        "ignoreExceptions": false,
        "JsonTemplateLayout": {}
      },
      {
        "name": "DEBUG_LOG",
        "fileName": "logs/debug.log",
        "PatternLayout": {}
      }
    ]
  },
  "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"
      }
    }
  }
}
Configuration:
  Appenders:
    File:
      - name: "AUDIT"
        fileName: "logs/audit.log"
        ignoreExceptions: false
        JsonTemplateLayout: {}
      - name: "DEBUG_LOG"
        fileName: "logs/debug.log"
        PatternLayout: {}
  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"
appender.0.type = File
appender.0.name = AUDIT
appender.0.fileName = logs/audit.log
appender.0.ignoreExceptions = false
appender.0.layout.type = JsonTemplateLayout

appender.1.type = File
appender.1.name = DEBUG_LOG
appender.1.fileName = logs/debug.log
appender.1.layout.type = PatternLayout

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.

Common configuration properties

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.

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

log4j.async.formatMessagesInBackground

Env. variable

LOG4J_ASYNC_FORMAT_MESSAGES_IN_BACKGROUND

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.

log4j.async.queueFullPolicy.type

Env. variable

LOG4J_ASYNC_QUEUE_FULL_POLICY_TYPE

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 log4j.async.queueFullPolicy.discardThreshold).

log4j.async.queueFullPolicy.discardThreshold

Env. variable

LOG4J_ASYNC_QUEUE_FULL_POLICY_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 log4j.async.queueFullPolicy.type.

log4j.async.logger.configExceptionHandler

Env. variable

LOG4J_ASYNC_LOGGER_CONFIG_EXCEPTION_HANDLER

Type

Class< ? extends AsyncLoggerConfigExceptionHandler>

Default value

AsyncLoggerConfigDefaultExceptionHandler

Fully qualified name of a class that implements the AsyncLoggerConfigExceptionHandler 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.

This configuration property is used, when Log4j uses a mix of sync and async loggers.

See Mixing synchronous and asynchronous Loggers for more details.

log4j.async.logger.exceptionHandler

Env. variable

LOG4J_ASYNC_LOGGER_EXCEPTION_HANDLER

Type

Class< ? extends AsyncLoggerExceptionHandler>

Default value

AsyncLoggerDefaultExceptionHandler

Fully qualified name of a class that implements the AsyncLoggerExceptionHandler 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.

This configuration property is used, when Log4j uses exclusively asynchronous loggers.

See Making all loggers asynchronous for more details.

log4j.async.logger.synchronizeEnqueueWhenQueueFull

Env. variable

LOG4J_ASYNC_LOGGER_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL

Type

boolean

Default value

true

Synchronizes access to the LMAX Disruptor ring buffer for blocking enqueue operations when the queue is full. Users encountered excessive CPU utilization with LMAX 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.

log4j.async.logger.ringBuffer.size

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.

log4j.async.logger.waitStrategy.type

Env. variable

LOG4J_ASYNC_LOGGER_WAIT_STRATEGY_TYPE

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 log4j.async.logger.waitStrategy.timeout)

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 log4j.async.logger.waitStrategy.retries and log4j.async.logger.waitStrategy.sleepTimeNs). 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.

log4j.async.logger.waitStrategy.retries

Env. variable

LOG4J_ASYNC_LOGGER_WAIT_STRATEGY_RETRIES

Type

int

Default value

200

Total number of spin cycles and Thread.yield() cycles of Sleep (see log4j.async.logger.waitStrategy.type).

log4j.async.logger.waitStrategy.sleepTimeNs

Env. variable

LOG4J_ASYNC_LOGGER_WAIT_STRATEGY_SLEEP_TIME_NS

Type

long

Default value

100

Sleep time in nanoseconds of Sleep wait strategy (see log4j.async.logger.waitStrategy.type).

log4j.async.logger.waitStrategy.timeout

Env. variable

LOG4J_ASYNC_LOGGER_WAIT_STRATEGY_TIMEOUT

Type

int

Default value

10

Timeout in milliseconds of Timeout wait strategy (see log4j.async.logger.waitStrategy.type).

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

<?xml version="1.0" encoding="UTF-8"?>
<Configuration xmlns="https://logging.apache.org/xml/ns"
               xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
               xsi:schemaLocation="
                       https://logging.apache.org/xml/ns
                       https://logging.apache.org/xml/ns/log4j-config-2.xsd">
  <AsyncWaitStrategyFactory class="com.example.AsyncWaitStrategyFactory"/>
</Configuration>
{
  "Configuration": {
    "AsyncWaitStrategyFactor": {
      "class": "com.example.AsyncWaitStrategyFactory"
    }
  }
}
Configuration:
  AsyncWaitStrategyFactory:
    class: "com.example.AsyncWaitStrategyFactory"
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: