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

log4j.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 log4j.enableThreadlocals.

log4j.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 log4j.isWebapp.

log4j.gc.enableDirectEncoders

Env. variable

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

log4j.gc.encoderByteBufferSize

Env. variable

LOG4J_GC_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 log4j.gc.enableDirectEncoders is set to true.

log4j.gc.encoderCharBufferSize

Env. variable

LOG4J_GC_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 log4j.gc.enableDirectEncoders is set to true.

log4j.gc.initialReusableMsgSize

Env. variable

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

log4j.gc.maxReusableMsgSize

Env. variable

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

log4j.gc.layoutStringBuilderMaxSize

Env. variable

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

log4j.recycler.capacity

Env. variable

LOG4J_RECYCLER_CAPACITY

Type

int

Default value

2C rounded to the next power of 2 (C denoting the number of available processors)

Denotes the buffer capacity for a recycler. For a queueing recycler, it corresponds to the queue size. For a thread local recycler, it corresponds to the per-thread buffer size.

If an invalid capacity is provided (i.e., if the capacity is zero or negative), the default value will be used.

log4j.recycler.factory

Env. variable

LOG4J_RECYCLER_FACTORY

Type

String

Default value

null

If provided, available recycler factory providers will be sorted in order, and the first one whose name matching with this property value will be used.

If missing or the selection fails, the default will be used.

log4j.recycler.conversant.spinPolicy

Env. variable LOG4J_RECYCLER_CONVERSANT_SPIN_POLICY

Type

SpinPolicy

Default value

WAITING

Denotes the strategy adopted by the Conversant Disruptor, when the queue is fully used. This configuration property is only used if the conversant-disrutor recycler is used.

See Conversant Disruptor Javadoc for details.

log4j.threadContext.map.type

Env. variable

LOG4J_THREAD_CONTEXT_MAP_TYPE

Type

Class<? extends ThreadContextMap> or predefined constant

Default value

WebApp

Fully specified class name of a custom ThreadContextMap implementation class or 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.

log4j.threadContext.map.garbageFree

Env. variable

LOG4J_THREAD_CONTEXT_MAP_GARBAGE_FREE

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 log4j.gc.enableDirectEncoders configuration 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.

Recyclers

Log4j contains the recycler abstraction that models the buffer-and-reuse strategy used to operate without any extra memory allocations at steady state. Recyclers implement the RecyclerFactoryProvider interface in log4j-kit (a dependency of log4j-core) and provide themselves as a ServiceLoader. Hence, you can easily implement custom recyclers and inject them using the ServiceLoader mechanism.

Log4j chooses a recycler using the following procedure:

  1. Using ServiceLoader mechanism, loads all available RecyclerFactoryProvider implementations

  2. Sorts providers (the lower order value will come first)

  3. If log4j.recycler.factory is provided, the first provider whose name matching with this property value will be used. Otherwise, the first provider will be used.

The predefined recycler factory providers are as follows:

Dummy recycler

Module

log4j-kit

Name

dummy

Order

900

Does not recycle anything; all instances are freshly created. (Not recommended for production! Intended as a test utility.)

Thread-local recycler

Module

log4j-kit

Name

threadLocal

Order

Integer.MAX_VALUE, if javax.servlet.Servlet or jakarta.servlet.Servlet is in the classpath;
700, otherwise

Pools objects in a fixed-size queue stored in a ThreadLocal. If pool runs out of capacity (see log4j.recycler.capacity), it will start creating fresh instances for new requests.

Note that it is effectively disabled for servlet environments.

Queueing recycler

Module

log4j-kit

Name

queue

Order

800

Pools objects in a fixed-size ArrayBlockingQueue queue. If pool runs out of capacity (see log4j.recycler.capacity), it will start creating fresh instances for new requests.

JCTools MPMC recycler

Module

log4j-jctools

Name

jctools-mpmc

Order

600

Pools objects in a fixed-size JCTools MPMC queue. If pool runs out of capacity (see log4j.recycler.capacity), it will start creating fresh instances for new requests.

Conversant Disruptor recycler

Module

log4j-conversant

Name

conversant-disruptor

Order

600

Pools objects in a fixed-size ring buffer. If pool runs out of capacity (see log4j.recycler.capacity), a spin policy is applied (see log4j.recycler.conversant.spinPolicy).

The capacity of this recycler must be at least 8 and a power of 2.

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 log4j.async.logger.waitStrategy.type 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 log4j.threadContext.map.garbageFree configuration property to true.

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

  • Scoped Context is not garbage-free.

  • Logging very large messages (i.e., more than log4j.gc.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.