Garbage-free logging

Garbage collection pauses are a common cause of latency spikes and for many systems significant effort is spent on controlling these pauses. Log4j allocates temporary LogEvent, String, char[], byte[], etc. objects during steady state logging. This contributes to pressure on the garbage collector and increases the frequency with which garbage collection pauses occur. In garbage-free mode, Log4j buffers and reuses objects to lessen this pressure.

Extra tuning of any application will deviate you away from defaults and add up to the maintenance load. You are strongly advised to measure your application’s overall performance and then, if Log4j is found to be an important bottleneck factor, tune it carefully. When this happens, we also recommend you to evaluate your assumptions on a regular basis to check if they still hold. Remember, premature optimization is the root of all evil.

The act of logging is an interplay between the logging API (i.e., Log4j API) where the programmer publishes logs and a logging implementation (i.e., Log4j Core) where published logs get consumed; filtered, enriched, encoded, and written to files, databases, network sockets, etc. Both parties contain different features with different memory allocation characteristics. To achieve an end-to-end garbage-free logging system, they need to work hand in hand. Hence, we will discuss both:

  1. Log4j Core configuration

  2. Log4j API usage

Garbage-free logging is currently implemented for Log4j API and its reference implementation, Log4j Core. If you use another setup (e.g., a different logging API or implementation) this promise might not hold.

Quick start

If you want to have a garbage-free Log4j setup, but don’t want to spend time with the associated details, you can quickly get started with the following instructions:

  1. Set the following system properties to true:

  2. Use garbage-free

This should be sufficient for a majority of use cases. If not for yours, keep on reading.

Log4j Core configuration

In order to have a garbage-free Log4j Core, you need to

Properties

Garbage-free logging can be configured for Log4j Core using properties listed below. (See Configuration file on details how you can set these properties.)

log4j2.isWebapp

Env. variable

LOG4J_IS_WEBAPP

Type

boolean

Default value

true if the Servlet class on classpath,

false otherwise

Setting this property to true switches Log4j Core into "Web application mode" ("Web-app mode").

In this mode Log4j is optimized to work in a Servlet container.

This mode is incompatible with log4j2.enableThreadlocals.

log4j2.enableThreadlocals

Env. variable

LOG4J_ENABLE_THREADLOCALS

Type

boolean

Default value

false if Web-app mode is enabled,

true otherwise

Setting this property to true switches Log4j Core into "garbage-free mode" ("GC-free mode").

In this mode Log4j uses ThreadLocals for object pooling to prevent object allocations.

ThreadLocal fields holding non-JDK classes can cause memory leaks in web applications when the application server’s thread pool continues to reference these fields after the web application is undeployed. Hence, to avoid causing memory leaks, log4j2.enableThreadlocals by default reflects the opposite of log4j2.isWebapp.

log4j2.enableDirectEncoders

Env. variable

LOG4J_ENABLE_DIRECT_ENCODERS

Type

boolean

Default value

true

If true, garbage-aware layouts will directly encode log events into ByteBuffers provided by appenders.

This prevents allocating temporary String and char[] instances.

log4j2.encoderByteBufferSize

Env. variable

LOG4J_ENCODER_BYTE_BUFFER_SIZE

Type

int

Default value

8192

The size in bytes of the ByteBuffers stored in ThreadLocal fields by layouts and StringBuilderEncoders.

This setting is only used if log4j2.enableDirectEncoders is set to true.

log4j2.encoderCharBufferSize

Env. variable

LOG4J_ENCODER_CHAR_BUFFER_SIZE

Type

int

Default value

4096

The size in chars of the ByteBuffers stored in ThreadLocal fields StringBuilderEncoders.

This setting is only used if log4j2.enableDirectEncoders is set to true.

log4j2.initialReusableMsgSize

Env. variable

LOG4J_INITIAL_REUSABLE_MSG_SIZE

Type

int

Default value

128

In GC-free mode, this property determines the initial size of the reusable StringBuilders used by ReusableMessages for formatting purposes.

log4j2.maxReusableMsgSize

Env. variable

LOG4J_MAX_REUSABLE_MSG_SIZE

Type

int

Default value

518

In GC-free mode, this property determines the maximum size of the reusable StringBuilders used by ReusableMessages for formatting purposes.

The default value allows is equal to 2 × (2 × log4j.initialReusableMsgSize + 2) + 2 and allows the StringBuilder to be resized twice by the current JVM resize algorithm.

log4j2.layoutStringBuilderMaxSize

Env. variable

LOG4J_LAYOUT_STRING_BUILDER_MAX_SIZE

Type

int

Default value

2048

This property determines the maximum size of the reusable StringBuilders used to format LogEvents.

log4j2.unboxRingbufferSize

Env. variable

LOG4J_UNBOX_RINGBUFFER_SIZE

Type

int

Default value

32

The Unbox utility class can be used by users to format primitive values without incurring in the boxing allocation cost.

This property specifies the maximum number of primitive arguments to a log message that will be cached and usually does not need to be changed.

log4j2.threadContextMap

Env. variable

LOG4J_THREAD_CONTEXT_MAP

Type

Class<? extends ThreadContextMap> or predefined constant

Default value

WebApp

Fully specified class name of a custom ThreadContextMap implementation class or (since version 2.24.0) one of the predefined constants:

NoOp

to disable the thread context,

WebApp

a web application-safe implementation, that only binds JRE classes to ThreadLocal to prevent memory leaks,

GarbageFree

a garbage-free implementation.

log4j2.garbagefreeThreadContextMap

Env. variable

LOG4J_GARBAGEFREE_THREAD_CONTEXT_MAP

Default value

false

If set to true selects a garbage-free thread context map implementation.

Layouts

The following layouts can be configured to run garbage-free during steady-state logging. To understand which configuration knobs exhibit what kind of allocation behaviour, see their dedicated pages.

Implementation notes

Garbage-free layouts need to implement the Encoder<LogEvent> interface. StringBuilderEncoder helps with encoding text to bytes in a garbage-free manner.

Appenders

The following appenders are garbage-free during steady-state logging:

Any other appender not shared in the above list (including AsyncAppender) is not garbage-free.

Implementation notes

Garbage-free appenders need to provide their layout with a ByteBufferDestination implementation that the layout can directly write into.

AbstractOutputStreamAppender has been modified to make the following appenders garbage-free:

  • ConsoleAppender

  • (Rolling)FileAppender

  • (Rolling)RandomAccessFileAppender

  • MemoryMappedFileAppender

An effort has been made to minimize impact on custom appenders that extend AbstractOutputStreamAppender, but it is impossible to guarantee that changing the superclass will not impact any and all subclasses. Custom appenders that extend AbstractOutputStreamAppender should verify that they still function correctly. In case there is a problem, the log4j2.enableDirectEncoders system property can be set to false to revert to the pre-Log4j 2.6 behaviour.

Filters

The following filters are garbage-free during steady-state logging:

Any other filter not shared in the above list is not garbage-free.

Limitations

There are certain caveats associated with the configuration of garbage-free logging:

Property substitutions

Some property substitutions (e.g., ones using Date Lookup) might result in temporary objects being created during steady-state logging.

Asynchronous logger wait strategies

As of version 2.18.0, the default asynchronous logger wait strategy (i.e., Timeout) is garbage-free while running against both LMAX Disruptor 3 and 4. See log4j2.asyncLoggerWaitStrategy for details on predefined wait strategies.

Log4j API usage

Log4j API contains several features to facilitate garbage-free logging:

Parameterized message arguments

The Logger interface contains methods for parameterized messages up to 10 arguments. Logging more than 10 parameters creates vararg arrays.

Encoding custom objects

When a message parameter contains an unknown type by the layout, it will encode by calling toString() on these objects. Most objects don’t have garbage-free toString() methods. Objects themselves can implement their own garbage-free encoders by either extending from Java’s CharSequence or Log4j’s StringBuilderFormattable.

Avoiding autoboxing

We made an effort to make logging garbage-free without requiring code changes in existing applications, but there is one area where this was not possible. When logging primitive values (i.e. int, double, boolean, etc.) the JVM autoboxes these primitive values to their Object wrapper equivalents, creating garbage.

Log4j provides an Unbox utility to prevent autoboxing of primitive parameters. This utility contains a thread-local pool of reused StringBuilder`s. The `Unbox.box(primitive) methods write directly into a StringBuilder, and the resulting text will be copied into the final log message text without creating temporary objects.

import static org.apache.logging.log4j.util.Unbox.box;

LOGGER.debug("Prevent primitive autoboxing {} {}", box(10L), box(2.6d));

This utility contains a ThreadLocal pool of reused StringBuilders. The pool size is configured by the log4j2.unboxRingbufferSize system property. The Unbox.box(primitive) methods write directly into a StringBuilder, and the resulting text will be copied into the final log message text without creating temporary objects.

Limitations

Not all Log4j API feature set is garbage-free, specifically:

  • The ThreadContext map (aka. MDC) is not garbage-free by default, but can be configured to be garbage-free by setting the log4j2.garbagefreeThreadContextMap system property to true.

  • The ThreadContext stack (aka. NDC) is not garbage-free.

  • Logging very large messages (i.e., more than log4j2.maxReusableMsgSize characters, which defaults to 518), when all loggers are asynchronous loggers, will cause the internal StringBuilder in the RingBuffer to be trimmed back to their configured maximum size.

  • Logging messages containing ${variable} substitutions creates temporary objects.

  • Logging a lambda as a parameter:

    LOGGER.info("lambda value is {}", () -> callExpensiveMethod());

    creates a vararg array. Logging a lambda expression by itself:

    LOGGER.debug(() -> callExpensiveMethod());

    is garbage-free.

  • The traceEntry() and traceExit() methods create temporary objects.

  • Time calculations are not garbage-free when the log4j2.usePreciseClock system property (defaults to false) is set to true.