////
    Licensed to the Apache Software Foundation (ASF) under one or more
    contributor license agreements.  See the NOTICE file distributed with
    this work for additional information regarding copyright ownership.
    The ASF licenses this file to You under the Apache License, Version 2.0
    (the "License"); you may not use this file except in compliance with
    the License.  You may obtain a copy of the License at

         http://www.apache.org/licenses/LICENSE-2.0

    Unless required by applicable law or agreed to in writing, software
    distributed under the License is distributed on an "AS IS" BASIS,
    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    See the License for the specific language governing permissions and
    limitations under the License.
////
= Garbage-free Steady State Logging
Remko Popma <rpopma@apache.org>

////
Different applications have different performance requirements.
Some only need to worry about throughput, but for many
the most important performance consideration is latency (response time).
Users of such applications would consider it a serious problem
if the system becomes unresponsive for more than a few seconds, or even milliseconds in some cases.
In financial trading for example predictable low latency is so important that it is often considered
worthwhile to trade off some throughput in return for a consistent response time.
////

Garbage collection pauses are a common cause of latency spikes and for
many systems significant effort is spent on controlling these pauses.

Many logging libraries, including previous versions of Log4j, allocate
temporary objects like log event objects, Strings, char arrays, byte
arrays and more during steady state logging. This contributes to
pressure on the garbage collector and increases the frequency with which
GC pauses occur.

From version 2.6, Log4j runs in "garbage free" mode by default where
objects and buffers are reused and no temporary objects are allocated as
much as possible. There is also a "low garbage" mode which is not
completely garbage free but does not use ThreadLocal fields. This is the
default mode when Log4j link:#Config[detects] it is running in a web
application. Finally, it is possible to switch off all garbage-free
logic and run in "classic mode" instead. For details, see the
link:#Config[Configuration] section below.

[#jfr]
== A Contrived Example

To highlight the difference that garbage-free logging can make, we used
Java Flight Recorder to measure a simple application that does nothing
but log a simple string as often as possible for about 12 seconds.

The application was configured to use Async Loggers, a RandomAccessFile
appender and a "%d %p %c{1.} [%t] %m %ex%n" pattern layout. (Async
Loggers used the Yield WaitStrategy.)

Mission Control shows that with Log4j 2.5 this application allocates
memory at a rate of about 809 MB/sec, resulting in 141 minor
collections. Log4j 2.6 does not allocate temporary objects in this
configuration, and as a result the same application with Log4j 2.6 has a
memory allocation rate of 1.6 MB/sec and was GC-free with 0 (zero)
garbage collections.

[cols="2*"]
|===
|link:../images/log4j-2.5-FlightRecording.png[image:../images/log4j-2.5-FlightRecording-thumbnail40pct.png[image]] +
With Log4j 2.5: memory allocation rate 809 MB/sec, 141 minor
collections.
|link:../images/log4j-2.6-FlightRecording.png[image:../images/log4j-2.6-FlightRecording-thumbnail40pct.png[image]] +
Log4j 2.6 did not allocate temporary objects: 0 (zero) garbage
collections.
|===

[#Config]
== Configuration

Garbage-free logging in Log4j 2.6 is partially implemented by reusing
objects in ThreadLocal fields, and partially by reusing buffers when
converting text to bytes.

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. To avoid
causing memory leaks, Log4j will not use these ThreadLocals when it
detects that it is used in a web application (when the
`javax.servlet.Servlet` class is in the classpath, or when system
property `log4j2.isWebapp` is set to "true").

Some garbage-reducing functionality does not rely on ThreadLocals and is
enabled by default for all applications: in Log4j 2.6, converting log
events to text and text to bytes can be done by directly encoding text
into a reused ByteBuffer without creating intermediary Strings, char
arrays and byte arrays. So while logging is not completely garbage-free
for web applications yet, the pressure on the garbage collector can
still be significantly reduced.

NOTE: As of version 2.6, a Log4j configuration containing a
`<Properties>` section will result in temporary objects being created
during steady-state logging.

NOTE: The Async Logger Timeout wait strategy (the default) and the
Block wait strategy cause
`java.util.concurrent.locks.AbstractQueuedSynchronizer$Node` objects to
be created. The Yield and Sleep wait strategies are garbage-free. (See
link:async.html#SysPropsAllAsync[here] and
link:async.html#SysPropsMixedSync-Async[here].)

=== Disabling Garbage-free Logging

There are two separate system properties for manually controlling the
mechanisms Log4j uses to avoid creating temporary objects:

* `log4j2.enableThreadlocals` - if "true" (the default for non-web
applications) objects are stored in ThreadLocal fields and reused,
otherwise new objects are created for each log event.
* `log4j2.enableDirectEncoders` - if "true" (the default) log events are
converted to text and this text is converted to bytes without creating
temporary objects. Note: _synchronous_ logging performance may be worse
for multi-threaded applications in this mode due to synchronization on
the shared buffer. If your application is multi-threaded and logging
performance is important, consider using Async Loggers.
* The ThreadContext map is _not_ garbage-free by default, but from Log4j
2.7 it can be configured to be garbage-free by setting system property
`log4j2.garbagefreeThreadContextMap` to "true".

Instead of system properties, the above properties can also be specified
in a file named `log4j2.component.properties` by including this file in
the classpath of the application. See the
link:configuration.html#SystemProperties[manual regarding system
properties] for more info.

[#Appenders]
=== Supported Appenders

The following link:appenders.html[appenders] are garbage-free during
steady-state logging:

* Console
* File
* RollingFile (some temporary objects are created during file rollover)
* RandomAccessFile
* RollingRandomAccessFile (some temporary objects are created during
file rollover)
* MemoryMappedFile

Any other appenders not in the above list (including AsyncAppender)
create temporary objects during steady-state logging. Instead of
AsyncAppender, use link:async.html[Async Loggers] to log asynchronously
in a garbage-free manner.

[#Filters]
=== Supported Filters

The following link:filters.html[filters] are garbage-free during
steady-state logging:

* CompositeFilter (adding and removing element filters creates temporary
objects for thread safety)
* DynamicThresholdFilter
* LevelRangeFilter (garbage free since 2.8)
* MapFilter (garbage free since 2.8)
* MarkerFilter (garbage free since 2.8)
* StructuredDataFilter (garbage free since 2.8)
* ThreadContextMapFilter (garbage free since 2.8)
* ThresholdFilter (garbage free since 2.8)
* TimeFilter (garbage free since 2.8)

Other filters like BurstFilter, RegexFilter and ScriptFilter are not
trivial to make garbage free, and there is currently no plan to change
them.

[#Layouts]
=== Supported Layouts

==== GelfLayout

GelfLayout is garbage-free when used with compressionType="OFF", as long
as no additional field contains '${' (variable substitution).

==== PatternLayout

PatternLayout with the following limited set of conversion patterns is
garbage-free. Format modifiers to control such things as field width,
padding, left and right justification will not generate garbage.

[cols="1,2"]
|===
|Conversion Pattern |Description

|%c{precision}, %logger{precision}
|Logger name

|%d, %date
a|
Note: Only the predefined date formats are garbage-free: (millisecond
separator may be either a comma ',' or a period '.')

!===
!Pattern !Example

!%d{DEFAULT}
!2012-11-02 14:34:02,781

!%d{ISO8601}
!2012-11-02T14:34:02,781

!%d{ISO8601_BASIC}
!20121102T143402,781

!%d{ABSOLUTE}
!14:34:02,781

!%d{DATE}
!02 Nov 2012 14:34:02,781

!%d{COMPACT}
!20121102143402781

!%d{HH:mm:ss,SSS}
!14:34:02,781

!%d{dd MMM yyyy HH:mm:ss,SSS}
!02 Nov 2012 14:34:02,781

!%d{HH:mm:ss}{GMT+0}
!18:34:02

!%d{UNIX}
!1351866842

!%d{UNIX_MILLIS}
!1351866842781
!===

|%enc{pattern}, %encode{pattern}
|Encodes special characters such as
'\n' and HTML characters to help prevent log forging and some XSS
attacks that could occur when displaying logs in a web browser -
garbage-free since 2.8

|%equals{pattern}{test}{substitution},
%equalsIgnoreCase{pattern}{test}{substitution}
|Replaces occurrences
of 'test', a string, with its replacement 'substitution' in the string
resulting from evaluation of the pattern - garbage-free since 2.8

|%highlight{pattern}{style}
|Adds ANSI colors - garbage-free since 2.7
(unless nested pattern is not garbage free)

|%K{key}, %map{key}, %MAP{key}
|Outputs the entries in a
link:../log4j-api/apidocs/org/apache/logging/log4j/message/MapMessage.html[MapMessage],
if one is present in the event - garbage-free since 2.8.

|%m, %msg, %message
|Log message (garbage-free unless message text
contains '${')

|%marker
|The full name of the marker (including parents) - garbage-free
since 2.8

|%markerSimpleName
|The simple name of the marker (not including
parents)

|%maxLen, %maxLength
|Truncates another pattern to some max number of
characters - garbage-free since 2.8

|%n
|The platform dependent line separator

|%N, %nano
|System.nanoTime() when the event was logged

|%notEmpty{pattern}, %varsNotEmpty{pattern},
%variablesNotEmpty{pattern}
|Outputs the result of evaluating the
pattern if and only if all variables in the pattern are not empty -
garbage-free since 2.8

|%p, %level
|The level of the logging event

|%r, %relative
|The number of milliseconds elapsed since the JVM was
started until the creation of the logging event - garbage-free since 2.8

|%sn, %sequenceNumber
|A sequence number that will be incremented in
every event - garbage-free since 2.8

|%style{pattern}{ANSI style}
|Style the message - garbage-free since
2.7 (unless nested pattern is not garbage free)

|%T, %tid, %threadId
|The ID of the thread that generated the logging
event

|%t, %tn, %thread, %threadName
|The name of the thread that generated
the logging event

|%tp
|The priority of the thread that generated the logging event

|%X{key[,key2...]}, %mdc{key[,key2...]}, %MDC{key[,key2...]}
|Outputs
the Thread Context Map (also known as the Mapped Diagnostic Context or
MDC) associated with the thread that generated the logging event -
garbage-free since 2.8

|literal text
|Garbage-free unless literal contains '${' (variable
substitution)
|===

Other PatternLayout conversion patterns, and other Layouts may be
updated to avoid creating temporary objects in future releases. (Patches
welcome!)

NOTE: Logging exceptions and stack traces will create temporary
objects with any layout. (However, Layouts will only create these
temporary objects when an exception actually occurs.) We haven't figured
out a way to log exceptions and stack traces without creating temporary
objects. That is unfortunate, but you probably still want to log them
when they happen.

****
NOTE: patterns containing regular expressions and lookups for property
substitution will result in temporary objects being created during
steady-state logging.

Including location information is done by walking the stacktrace of an
exception, which creates temporary objects, so the following patterns
are not garbage-free:

* %C, %class - Class Name
* %F, %file - File Location
* %l, %location - Location
* %L, %line - Line Location
* %M, %method - Method Location

Also, the pattern converters for formatting Throwables are not
garbage-free:

* %ex, %exception, %throwable - The Throwable trace bound to the
LoggingEvent
* %rEx, %rException %rThrowable - Same as %ex but with wrapping
exceptions
* %xEx, %xException, %xThrowable - Same as %ex but with class packaging
information
* %u, %uuid - Creates a new random or time-based UUID while formatting

****

[#api]
=== API Changes

Methods have been added to the `Logger` interface so that no vararg
array objects are created when logging messages with up to ten
parameters.

Also, methods have been added to the `Logger` interface to log
`java.lang.CharSequence` messages. User-defined objects that implement
the `CharSequence` interface can be logged without creating temporary
objects: Log4j will try to turn CharSequence messages, Object messages
and message parameters into text by appending them to a StringBuilder as
a CharSequence. This avoids calling `toString()` on these objects.

An alternative is to implement the
http://logging.apache.org/log4j/2.x/log4j-api/xref/org/apache/logging/log4j/util/StringBuilderFormattable.html[`org.apache.logging.log4j.util.StringBuilderFormattable`]
interface. If an object is logged that implements this interface, its
`formatTo` method is called instead of `toString()`.

Log4j may call `toString()` on message and parameter objects when
garbage-free logging is disabled (when system property
`log4j2.enableThreadlocals` is set to "false".)

[#codeImpact]
=== Impact on Application Code: 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.

[source,java]
----
import static org.apache.logging.log4j.util.Unbox.box;

// ...
public void garbageFree() {
    logger.debug("Prevent primitive autoboxing {} {}", box(10L), box(2.6d));
}
----

****
NOTE: not all logging is garbage free. Specifically:

* The ThreadContext map is not garbage-free by default, but can be
configured to be garbage-free by setting system property
`log4j2.garbagefreeThreadContextMap` to "true".
* The ThreadContext stack is not garbage-free.
* Logging more than 10 parameters creates vararg arrays.
* Logging very large messages (more than 518 characters) when all
loggers are Async Loggers will cause the internal StringBuilder in the
RingBuffer to be trimmed back to their max size.
* Logging messages containing '${': substituting a ${variable} 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 is
garbage-free: `logger.debug(() -> callExpensiveMethod())`.
* The `Logger.traceEntry` and `Logger.traceExit` methods create
temporary objects.
****

[#Performance]
== Performance

[#Latency]
=== Response Time Latency

Response time is how long it takes to log a message under a certain
load. What is often reported as latency is actually _service time_: how
long it took to perform the operation. This hides the fact that a single
spike in service time adds queueing delay for many of the subsequent
operations. Service time is easy to measure (and often looks good on
paper) but is irrelevant for users since it omits the time spent waiting
for service. For this reason we report response time: service time plus
wait time. See the link:../performance.html#responseTime[response time
section] of the performance page for more detail.

The response time test results below were all derived from running the
ResponseTimeTest class which can be found in the Log4j 2 unit test
source directory. If you want to run these tests yourself, here are the
command line options we used:

* -Xms1G -Xmx1G (prevent heap resizing during the test)
* -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
-DAsyncLogger.WaitStrategy=busyspin (to use Async Loggers. The BusySpin
wait strategy reduces some jitter.)
* *classic mode:* -Dlog4j2.enable.threadlocals=false
-Dlog4j2.enable.direct.encoders=false +
*garbage-free mode:* -Dlog4j2.enable.threadlocals=true
-Dlog4j2.enable.direct.encoders=true
* -XX:CompileCommand=dontinline,org.apache.logging.log4j.core.async.perftest.NoOpIdleStrategy::idle
* -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps
-XX:+PrintTenuringDistribution -XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCApplicationStoppedTime (to eyeball GC and safepoint pauses)

=== Async Loggers

The graph below compares "classic" logging to garbage-free logging
response time behaviour for Log4j's Async Loggers. In the graph, "100k"
means logging at a sustained load of 100,000 messages/second, "800k" is
a sustained load of 800,000 messages/second.

image:../images/ResponseTimeAsyncClassicVsGcFree-label.png[image]

In *classic* mode we see numerous minor garbage collections which pause
the application threads for 3 milliseconds or more. This quickly adds up
to response time delays of almost 10 milliseconds. As you can see in the
graph, increasing the load shifts the curve to the left (there are more
spikes). This makes sense: logging more means more pressure on the
garbage collector resulting in more minor GC pauses. We experimented a
little with reducing the load to 50,000 or even 5000 messages/second,
but this did not eliminate the 3 millisecond pauses, it just made them
occur less frequently. Note that all GC pauses in this test are minor GC
pauses. We did not see any full garbage collections.

In *garbage-free* mode, maximum response time remains well below 1
millisecond under a wide range of loads. (Max 780 us at 800,000
messages/sec, max 407 us at 600,000 messages/sec, with the 99% around 5
us for all loads up to 800,000 messages/sec.) Increasing or decreasing
the load does not change the response time behaviour. We did not
investigate the cause of the 200-300 microsecond pauses we saw in these
tests.

When we increased the load further we begin to see larger response time
pauses for both classic and garbage-free logging. At sustained loads of
1 million messages/second or more we start to approach the maximum
throughput of the underlying RandomAccessFile Appender (see the
synchronous logging throughput chart below). At these loads the
ringbuffer starts to fill up and backpressure kicks in: attempting to
add another message when the ringbuffer is full will block until a free
slot becomes available. We start to see response times of tens of
milliseconds or more; and attempting to increase the load even more
results in larger and larger response time spikes.

=== Synchronous File Logging

With synchronous file logging, garbage-free logging still performs
better than classic logging, but the difference is less pronounced.

At a workload of 100,000 messages/second, classic logging max response
time was a little over 2 milliseconds where garbage-free logging was a
little over 1 millisecond. When the workload is increased to 300,000
messages/second, classic logging shows response time pauses of 6
milliseconds where the garbage-free response times were less than 3
milliseconds. It may be possible to improve on this, we did not
investigate further yet.

image:../images/ResponseTimeSyncClassicVsGcFree.png[image]

The above results are obtained with the ResponseTimeTest class which can
be found in the Log4j 2 unit test source directory, running on JDK
1.8.0_45 on RHEL 6.5 (Linux 2.6.32-573.1.1.el6.x86_64) with 10-core Xeon
CPU E5-2660 v3 @2.60GHz with hyperthreading switched on (20 virtual
cores).

[#Throughput]
=== Classic Logging has Slightly Higher Throughput

Throughput is slightly worse for garbage-free logging, compared to
classic logging. This is true for both synchronous and asynchronous
logging. The graph below compares the sustained throughput of
synchronous logging to a file with Log4j 2.6 in garbage-free mode,
classic mode and Log4j 2.5.

image:../images/garbage-free2.6-SyncThroughputLinux.png[Throughput of
Log4j 2.6 in garbage-free mode is slightly worse than in classic mode,
but on par with 2.5 and much better than alternatives logging libraries]

The results above are obtained with the
http://openjdk.java.net/projects/code-tools/jmh/[JMH] Java benchmark
harness. See the FileAppenderBenchmark source code in the log4j-perf
module.

[#UnderTheHood]
== Under the Hood

Custom Message implementations that implement
`org.apache.logging.log4j.util.StringBuilderFormattable` can be
converted to text by garbage-free Layouts without creating temporary
objects. PatternLayout uses this mechanism and other layouts that
convert LogEvents to text will likely also look for this interface.

Custom Layouts that want to be garbage-free should implement the
`Encoder<LogEvent>` interface. For custom Layouts that convert a
LogEvent to a text representation, the
`org.apache.logging.log4j.core.layout.StringBuilderEncoder` class may be
useful to convert this text to bytes in a garbage-free manner.

Custom Appenders that want to be garbage-free should provide their
Layout with a `ByteBufferDestination` implementation that the Layout can
directly write into.

`AbstractOutputStreamAppender` has been modified to make the
ConsoleAppender, (Rolling)FileAppender,
(Rolling)RandomAccessFileAppender and MemoryMappedFileAppender
garbage-free. 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, system property
`log4j2.enable.direct.encoders` can be set to "false" to revert to the
pre-Log4j 2.6 behaviour.

////
TODO Applications that wish to reuse custom Message instances with Async Loggers should let
their Message classes implement the `org.apache.logging.log4j.message.ReusableMessage` interface.
TODO This is not sufficient: see LOG4J2-1342, would be nice if we could solve this in a generic way.
////