<?xml version="1.0"?>
<!-- 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. -->
<document xmlns="http://maven.apache.org/XDOC/2.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  xsi:schemaLocation="http://maven.apache.org/XDOC/2.0 http://maven.apache.org/xsd/xdoc-2.0.xsd">
  <properties>
    <title>Log4j 2 Lock-free Asynchronous Loggers for Low-Latency Logging</title>
    <author email="rpopma@apache.org">Remko Popma</author>
  </properties>
  <body>
    <section name="Asynchronous Loggers for Low-Latency Logging">
      <p>
        Asynchronous logging can improve your application's performance by executing the I/O operations
        in a separate thread. Log4j 2 makes a number of improvements in this area.
      </p>
      <ul>
        <li>
          <b>Asynchronous Loggers</b> are a new addition in Log4j 2.
          Their aim is to return from the call to Logger.log to the application as
          soon as possible. You can choose between making all Loggers asynchronous
          or using a mixture of synchronous and asynchronous Loggers. Making all
          Loggers asynchronous will give the best performance, while mixing
          gives you more flexibility.
        </li>
        <li>
          <b>LMAX Disruptor technology</b>. Asynchronous Loggers internally use the
          <a href="#UnderTheHood">Disruptor</a>, a lock-free inter-thread
          communication library, instead of queues, resulting in higher throughput and lower latency.
        </li>
        <li>
          As part of the work for Async Loggers, <b>Asynchronous Appenders</b> have
          been enhanced to flush to disk at the end of a batch (when the queue is empty).
          This produces the same result as configuring "immediateFlush=true", that is, all
          received log events are always available on disk, but is more efficient because it does not need to
          touch the disk on each and every log event. (Async Appenders use ArrayBlockingQueue internally and
          do not need the disruptor jar on the classpath.)
        </li>
      </ul>
      <a name="Trade-offs" />
      <subsection name="Trade-offs">
        <p>
          Although asynchronous logging can give significant performance benefits,
          there are situations where you may want to choose synchronous logging.
          This section describes some of the trade-offs of asynchronous logging.
        </p>
        <p>
          <b>Benefits</b>
        </p>
        <ul>
          <li>
            <p>Higher peak <a href="#Performance">throughput</a>. With an asynchronous logger
            your application can log messages at 6 - 68 times the rate of a synchronous logger.</p>
            <p>This is especially interesting for applications that occasionally need to log
              bursts of messages. Async logging can help prevent or dampen latency spikes by shortening
              the wait time until the next message can be logged. If the queue size is configured
              large enough to handle the burst, asynchronous logging will help prevent your
              application from falling behind (as much) during a sudden increase of activity.
            </p>
          </li>
          <li>
            Lower logging response time <a href="#Latency">latency</a>.
            Response time latency is the time it takes for a call to Logger.log to return under a given workload.
            Asynchronous Loggers have consistently lower latency than synchronous loggers or even
            queue-based asynchronous appenders.
          </li>
        </ul>
        <b>Drawbacks</b>
        <ul>
          <li>
            Error handling. If a problem happens during the logging process and an exception is thrown,
            it is less easy for an asynchronous logger or appender to signal this problem to the
            application. This can partly be alleviated by configuring an <tt>ExceptionHandler</tt>,
            but this may still not cover all cases. For this reason, if logging is part of your business logic,
            for example if you are using Log4j as an audit logging framework, we would
            recommend to synchronously log those audit messages.
            (Note that you can still <a href="#MixedSync-Async">combine</a> them
            and use asynchronous logging for debug/trace logging in addition to synchronous
            logging for the audit trail.)
          </li>
          <li>
            In some rare cases, care must be taken with mutable messages.
            Most of the time you don't need to worry about this. Log4 will ensure that log messages like
            <code>logger.debug("My object is {}", myObject)</code> will use the state of the
            <code>myObject</code> parameter at the time of the call to <code>logger.debug()</code>.
            The log message will not change even if <code>myObject</code> is modified later.
            It is safe to asynchronously log mutable objects because most
            <a class="javadoc" href="../log4j-api/apidocs/org/apache/logging/log4j/message/Message.html">Message</a>
            implementations built-in to Log4j take a snapshot of the parameters.
            There are some exceptions however:
            <a class="javadoc"
              href="../log4j-api/apidocs/org/apache/logging/log4j/message/MapMessage.html">MapMessage</a>
            and
            <a class="javadoc"
              href="../log4j-api/apidocs/org/apache/logging/log4j/message/StructuredDataMessage.html">StructuredDataMessage</a>
            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; you may or may not see the modifications in the resulting log output.
            Similarly, custom
            <a class="javadoc"
              href="../log4j-api/apidocs/org/apache/logging/log4j/message/Message.html">Message</a>
            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.
          </li>
          <li>If your application is running in an environment where CPU resources are scarce, like a machine
            with one CPU with a single core, starting another thread is not likely
            to give better performance.</li>
          <li>
            If the <em>sustained rate</em> 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 <a href="../performance.html#whichAppender">faster
            appender</a>, or logging less.
            If neither of these is an option, you may get better throughput and fewer latency spikes by
            logging synchronously.
          </li>
        </ul>
      </subsection>
      <a name="AllAsync" />
      <subsection name="Making All Loggers Asynchronous">
        <p>
          <i>Log4j-2.9 and higher require disruptor-3.3.4.jar or higher on the classpath.
          Prior to Log4j-2.9, disruptor-3.0.0.jar or higher was required.
          </i>
        </p>
        <p>
          This is simplest to configure and gives the best performance. To make all loggers asynchronous,
          add the disruptor jar to the classpath and set the system property <tt>log4j2.contextSelector</tt>
          to <tt>org.apache.logging.log4j.core.async.AsyncLoggerContextSelector</tt>.
        </p>
        <p>
          By default, <a href="#Location">location</a> is not passed to the I/O thread by
          asynchronous loggers. If one of your layouts or custom filters needs location information, you need to set
          "includeLocation=true" in the configuration of all relevant loggers, including the root logger.
        </p>
        <p>
          A configuration that does not require location might look like:
        </p>
        <pre class="prettyprint linenums"><![CDATA[<?xml version="1.0" encoding="UTF-8"?>

<!-- Don't forget to set system property
-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
     to make all loggers asynchronous. -->

<Configuration status="WARN">
  <Appenders>
    <!-- Async Loggers will auto-flush in batches, so switch off immediateFlush. -->
    <RandomAccessFile name="RandomAccessFile" fileName="async.log" immediateFlush="false" append="false">
      <PatternLayout>
        <Pattern>%d %p %c{1.} [%t] %m %ex%n</Pattern>
      </PatternLayout>
    </RandomAccessFile>
  </Appenders>
  <Loggers>
    <Root level="info" includeLocation="false">
      <AppenderRef ref="RandomAccessFile"/>
    </Root>
  </Loggers>
</Configuration>]]></pre>
        <p>
          When <tt>AsyncLoggerContextSelector</tt> is used to make all loggers asynchronous, make sure to use normal
          <tt>&lt;root&gt;</tt> and <tt>&lt;logger&gt;</tt> elements in the configuration. The
          AsyncLoggerContextSelector will ensure that all loggers are asynchronous, using a mechanism
          that is different from what happens when you configure <tt>&lt;asyncRoot&gt;</tt>
          or <tt>&lt;asyncLogger&gt;</tt>.
          The latter elements are intended for mixing async with sync loggers. If you use both mechanisms
          together you will end up with two background threads, where your application passes the log
          message to thread A, which passes the message to thread B, which then finally
          logs the message to disk. This works, but there will be an unnecessary step in the middle.
        </p>
        <p>
          There are a few system properties you can use to control aspects of the asynchronous logging subsystem.
          Some of these can be used to tune logging performance.
        </p>
        <p>
          The below properties can also be specified by creating a file named
          <tt>log4j2.component.properties</tt> and including this file in the classpath of the application.
        </p>
        <p>
          Note that system properties were renamed into a more consistent style in Log4j 2.10.0. All old property
          names are still supported which are documented <a href="configuration.html#SystemProperties">here</a>.
        </p>
        <a name="SysPropsAllAsync" />
        <table>
          <caption align="top">System Properties to configure all asynchronous loggers
          </caption>
          <tr>
            <th>System Property</th>
            <th>Default Value</th>
            <th>Description</th>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerExceptionHandler</td>
            <td>
              <tt>default handler</tt>
            </td>
            <td>
              Fully qualified name of a class that implements the <tt>com.lmax.disruptor.ExceptionHandler</tt>
              interface. The class needs to have a public zero-argument constructor.
              If specified, this class will be notified when an exception occurs while logging the messages.
              <p>
                If not specified, the default exception handler will print a message and stack trace to the standard
                error output stream.
              </p>
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerRingBufferSize</td>
            <td>256&#160;*&#160;1024</td>
            <td>
              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.
              <p>
                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
                <a href="../log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicy.html">AsyncQueueFullPolicy</a>.
              </p>
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerWaitStrategy</td>
            <td>
              <tt>Timeout</tt>
            </td>
            <td>
              Valid values: Block, Timeout, Sleep, Yield.
              <br />
              <tt>Block</tt> is 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.
              <br />
              <tt>Timeout</tt> is a variation of the <tt>Block</tt> 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 (default 10ms).
              <br />
              <tt>Sleep</tt> is 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. 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.
              <br />
              <tt>Yield</tt> is a strategy that uses a Thread.yield() for waiting for log events after an initially spinning.
              Yield is a good compromise between performance and CPU resource, but may use more CPU than Sleep
              in order to get the message logged to disk sooner.
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerTimeout</td>
            <td>
              <tt>10</tt>
            </td>
            <td>
              Timeout in milliseconds of <tt>TimeoutBlockingWaitStrategy</tt>. See
              the WaitStrategy System Property for details.
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerSleepTimeNs</td>
            <td>
              <tt>100</tt>
            </td>
            <td>
              Sleep time (in nanoseconds) of <tt>SleepingWaitStrategy</tt>. See
              the WaitStrategy System Property for details.
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerRetries</td>
            <td>
              <tt>200</tt>
            </td>
            <td>
              Total number of spin cycles and <tt>Thread.yield()</tt> cycles of <tt>SleepingWaitStrategy</tt>. See
              the WaitStrategy System Property for details.
            </td>
          </tr>
          <tr>
            <td>AsyncLogger.SynchronizeEnqueueWhenQueueFull</td>
            <td>
              <tt>true</tt>
            </td>
            <td>
              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 <tt>false</tt> may lead to very high CPU utilization when the async logging queue is full.
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerThreadNameStrategy</td>
            <td>
              <tt>CACHED</tt>
            </td>
            <td>
              Valid values: CACHED, UNCACHED.
              <br />
              By default, AsyncLogger caches the thread name in a ThreadLocal variable to improve performance.
              Specify the <tt>UNCACHED</tt> option if your application modifies the thread name at runtime (with
              <tt>Thread.currentThread().setName()</tt>)
              and you want to see the new thread name reflected in the log.
            </td>
          </tr>
          <tr>
            <td>log4j2.clock</td>
            <td>
              <tt>SystemClock</tt>
            </td>
            <td>
              <p>
                Implementation of the <tt>org.apache.logging.log4j.core.util.Clock</tt>
                interface that is used for timestamping the log events when all loggers are asynchronous.
                <br />
                By default, <tt>System.currentTimeMillis</tt> is called on every log event.
              </p>
              <p>
                <tt>CachedClock</tt> is an optimization intended for low-latency applications where
                time stamps are generated from a clock that updates its internal time in a background thread once
                every millisecond, or every 1024 log events, whichever comes first.
                This reduces logging latency a little, at the cost of some precision in the logged time stamps.
                Unless you are logging many events, you may see "jumps" of 10-16 milliseconds between log time stamps.
                WEB APPLICATION WARNING: The use of a background thread may cause issues
                for web applications and OSGi applications so CachedClock is not recommended for this kind
                of applications.
              </p>
              <p>
                You can also specify the fully qualified class name of a custom class that implements the
                <tt>Clock</tt> interface.
              </p>
            </td>
          </tr>
        </table>
        <p>
          There are also a few system properties that can be used to maintain application throughput even when
          the underlying appender cannot keep up with the logging rate and the queue is filling up.
          See the details for system properties
          <a href="configuration.html#asyncQueueFullPolicy"><tt>log4j2.asyncQueueFullPolicy</tt> and
            <tt>log4j2.discardThreshold</tt></a>.
        </p>
      </subsection>
      <a name="MixedSync-Async" />
      <subsection name="Mixing Synchronous and Asynchronous Loggers">
        <p>
          <i>Log4j-2.9 and higher require disruptor-3.3.4.jar or higher on the classpath.
            Prior to Log4j-2.9, disruptor-3.0.0.jar or higher was required.
          There is no need to set system property "Log4jContextSelector" to any value.</i></p>
        <p>
          Synchronous and asynchronous loggers can be combined in configuration.
          This gives you more flexibility at the cost of a slight loss in performance (compared to making
          all loggers asynchronous). Use the <tt>&lt;asyncRoot&gt;</tt> or <tt>&lt;asyncLogger&gt;</tt>
          configuration elements to specify the loggers that need to be asynchronous.
          A configuration can contain only one root logger (either a <tt>&lt;root&gt;</tt>
          or an <tt>&lt;asyncRoot&gt;</tt> element), but otherwise async and non-async loggers may be
          combined.
          For example, a configuration file containing <tt>&lt;asyncLogger&gt;</tt> elements
          can also contain <tt>&lt;root&gt;</tt> and
          <tt>&lt;logger&gt;</tt> elements for the synchronous loggers.
        </p>
        <p>
          By default, <a href="#Location">location</a> is not passed to the I/O thread by asynchronous loggers.
          If one of your layouts or custom filters needs location information, you need to set
          "includeLocation=true" in the configuration of all relevant loggers, including the root logger.
        </p>
        <p>
          A configuration that mixes asynchronous loggers might look like:
        </p>
        <pre class="prettyprint linenums"><![CDATA[<?xml version="1.0" encoding="UTF-8"?>

<!-- No need to set system property "log4j2.contextSelector" to any value
     when using <asyncLogger> or <asyncRoot>. -->

<Configuration status="WARN">
  <Appenders>
    <!-- Async Loggers will auto-flush in batches, so switch off immediateFlush. -->
    <RandomAccessFile name="RandomAccessFile" fileName="asyncWithLocation.log"
              immediateFlush="false" append="false">
      <PatternLayout>
        <Pattern>%d %p %class{1.} [%t] %location %m %ex%n</Pattern>
      </PatternLayout>
    </RandomAccessFile>
  </Appenders>
  <Loggers>
    <!-- pattern layout actually uses location, so we need to include it -->
    <AsyncLogger name="com.foo.Bar" level="trace" includeLocation="true">
      <AppenderRef ref="RandomAccessFile"/>
    </AsyncLogger>
    <Root level="info" includeLocation="true">
      <AppenderRef ref="RandomAccessFile"/>
    </Root>
  </Loggers>
</Configuration>]]></pre>
        <p>
          There are a few system properties you can use to control aspects of the asynchronous logging subsystem.
          Some of these can be used to tune logging performance.
        </p>
        <p>
          The below properties can also be specified by creating a file named
          <tt>log4j2.component.properties</tt> and including this file in the classpath of the application.
        </p>
        <p>
          Note that system properties were renamed into a more consistent style in Log4j 2.10. All old property
          names are still supported which are documented <a href="configuration.html#SystemProperties">here</a>.
        </p>
        <a name="SysPropsMixedSync-Async" />
        <table>
          <caption align="top">System Properties to configure mixed asynchronous and normal loggers</caption>
          <tr>
            <th>System Property</th>
            <th>Default Value</th>
            <th>Description</th>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerConfigExceptionHandler</td>
            <td>
              <tt>default handler</tt>
            </td>
            <td>
              Fully qualified name of a class that implements the <tt>com.lmax.disruptor.ExceptionHandler</tt>
              interface. The class needs to have a public zero-argument constructor.
              If specified, this class will be notified when an exception occurs while logging the messages.
              <p>
                If not specified, the default exception handler will print a message and stack trace to the standard
                error output stream.
              </p>
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerConfigRingBufferSize</td>
            <td>256&#160;*&#160;1024</td>
            <td>
              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.
              <p>
                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 behavious is determined by the
                <a href="../log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicy.html">AsyncQueueFullPolicy</a>.
              </p>
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerConfigWaitStrategy</td>
            <td>
              <tt>Timeout</tt>
            </td>
            <td>
              Valid values: Block, Timeout, Sleep, Yield.
              <br />
              <tt>Block</tt> is 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.
              <br />
              <tt>Timeout</tt> is a variation of the <tt>Block</tt> 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 (default 10ms).
              <br />
              <tt>Sleep</tt> is 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. 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.
              <br />
              <tt>Yield</tt> is a strategy that uses a Thread.yield() for waiting for log events after an initially spinning.
              Yield is a good compromise between performance and CPU resource, but may use more CPU than Sleep
              in order to get the message logged to disk sooner.
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerConfigTimeout</td>
            <td>
              <tt>10</tt>
            </td>
            <td>
              Timeout in milliseconds of <tt>TimeoutBlockingWaitStrategy</tt>. See
              the WaitStrategy System Property for details.
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerConfigSleepTimeNs</td>
            <td>
              <tt>100</tt>
            </td>
            <td>
              Sleep time (in nanoseconds) of <tt>SleepingWaitStrategy</tt>. See
              the WaitStrategy System Property for details.
            </td>
          </tr>
          <tr>
            <td>log4j2.asyncLoggerConfigRetries</td>
            <td>
              <tt>200</tt>
            </td>
            <td>
              Total number of spin cycles and <tt>Thread.yield()</tt> cycles of <tt>SleepingWaitStrategy</tt>. See
              the WaitStrategy System Property for details.
            </td>
          </tr>
          <tr>
            <td>AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull</td>
            <td>
              <tt>true</tt>
            </td>
            <td>
              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 <tt>false</tt> may lead to very high CPU utilization when the async logging queue is full.
            </td>
          </tr>
        </table>
        <p>
          There are also a few system properties that can be used to maintain application throughput even when
          the underlying appender cannot keep up with the logging rate and the queue is filling up.
          See the details for system properties
          <a href="configuration.html#asyncQueueFullPolicy"><tt>log4j2.asyncQueueFullPolicy</tt> and
            <tt>log4j2.discardThreshold</tt></a>.
        </p>
      </subsection>
      <a name="Location" />
      <subsection name="Location, location, location...">
        <p>
          If one of the layouts is configured with a location-related attribute like HTML
          <a href="layouts.html#HtmlLocationInfo">locationInfo</a>,
          or one of the patterns <a href="layouts.html#PatternClass">%C or $class</a>,
          <a href="layouts.html#PatternFile">%F or %file</a>,
          <a href="layouts.html#PatternLocation">%l or %location</a>,
          <a href="layouts.html#PatternLine">%L or %line</a>,
          <a href="layouts.html#PatternMethod">%M or %method</a>,
          Log4j will take a snapshot of the stack, and walk the stack trace to find the location information.
        </p>
        <p>
          This is an expensive operation: 1.3 - 5 times slower for synchronous loggers. Synchronous loggers wait as
          long as possible before they take this stack snapshot. If no location is required, the snapshot will never be taken.
        </p>
        <p>
          However, asynchronous loggers need to make this decision before passing the
          log message to another thread; the location information will be lost after that point.
          The <a href="../performance.html#asyncLoggingWithLocation">performance impact</a> of taking a stack trace snapshot is even higher for asynchronous loggers:
          logging with location is 30-100 times slower than without location.
          For this reason, asynchronous loggers and asynchronous appenders do not include location information by default.
        </p>
        <p>
          You can override the default behaviour in your logger or asynchronous appender configuration
          by specifying <tt>includeLocation="true"</tt>.
        </p>
        <p>
        </p>
      </subsection>
      <a name="Performance" />
      <subsection name="Asynchronous Logging Performance">
        <p>
          The throughput performance results below were derived from running the PerfTest, MTPerfTest and PerfTestDriver
          classes which can be found in the Log4j 2 unit test source directory.
          For throughput tests, the methodology used was:
        </p>
        <ul>
          <li>First, warm up the JVM by logging 200,000 log messages of 500 characters.
          </li>
          <li>Repeat the warm-up 10 times, then wait 10 seconds for the I/O thread to catch up and buffers to drain.</li>
          <li>Measure how long it takes to execute 256 * 1024 / threadCount calls to Logger.log
            and express the result in messages per second.
          </li>
          <li>Repeat the test 5 times and average the results.</li>
        </ul>
        <p>The results below were obtained with log4j-2.0-beta5, disruptor-3.0.0.beta3,
          log4j-1.2.17 and logback-1.0.10.
        </p>
        <h4>Logging Peak Throughput</h4>
        <p>
          The graph below compares the throughput of synchronous loggers, asynchronous appenders and asynchronous
          loggers. This is the total throughput of all threads together. In the test with 64 threads,
          asynchronous loggers are 12 times faster than asynchronous appenders, and 68 times faster than
          synchronous loggers.
        </p>
        <p>
          Asynchronous loggers' throughput increases with the number of threads,
          whereas both synchronous loggers and asynchronous appenders
          have more or less constant throughput regardless of the number of
          threads that are doing the logging.
        </p>
        <p>
          <img src="../images/async-vs-sync-throughput.png"
            alt="Async loggers have much higher throughput than sync loggers." />
        </p>

        <h4>Asynchronous Throughput Comparison with Other Logging Packages</h4>
        <p>
          We also compared peak throughput of asynchronous loggers to the synchronous loggers and asynchronous
          appenders available in other logging packages, specifically log4j-1.2.17 and
          logback-1.0.10, with similar results. For asynchronous appenders, total logging throughput of all
          threads together remains roughly constant when adding more threads.
          Asynchronous loggers make more effective use of the multiple cores
          available on the machine in multi-threaded scenarios.
        </p>
        <p>
          <img src="../images/async-throughput-comparison.png" alt="Async loggers have the highest throughput." />
        </p>
        <p>On Solaris 10 (64bit) with JDK1.7.0_06, 4-core Xeon X5570 dual CPU
          @2.93Ghz with hyperthreading switched on (16 virtual cores):
        </p>
        <table>
          <caption align="top">Throughput per thread in
            messages/second</caption>
          <tr>
            <th>Logger</th>
            <th>1 thread</th>
            <th>2 threads</th>
            <th>4 threads</th>
            <th>8 threads</th>
            <th>16 threads</th>
            <th>32 threads</th>
            <th>64 threads</th>
          </tr>
          <tr>
            <td>Log4j 2: Loggers all asynchronous</td>
            <td align="right">2,652,412</td>
            <td align="right">909,119</td>
            <td align="right">776,993</td>
            <td align="right">516,365</td>
            <td align="right">239,246</td>
            <td align="right">253,791</td>
            <td align="right">288,997</td>
          </tr>
          <tr>
            <td>Log4j 2: Loggers mixed sync/async</td>
            <td align="right">2,454,358</td>
            <td align="right">839,394</td>
            <td align="right">854,578</td>
            <td align="right">597,913</td>
            <td align="right">261,003</td>
            <td align="right">216,863</td>
            <td align="right">218,937</td>
          </tr>
          <tr>
            <td>Log4j 2: Async Appender</td>
            <td align="right">1,713,429</td>
            <td align="right">603,019</td>
            <td align="right">331,506</td>
            <td align="right">149,408</td>
            <td align="right">86,107</td>
            <td align="right">45,529</td>
            <td align="right">23,980</td>
          </tr>
          <tr>
            <td>Log4j1: Async Appender</td>
            <td align="right">2,239,664</td>
            <td align="right">494,470</td>
            <td align="right">221,402</td>
            <td align="right">109,314</td>
            <td align="right">60,580</td>
            <td align="right">31,706</td>
            <td align="right">14,072</td>
          </tr>
          <tr>
            <td>Logback: Async Appender</td>
            <td align="right">2,206,907</td>
            <td align="right">624,082</td>
            <td align="right">307,500</td>
            <td align="right">160,096</td>
            <td align="right">85,701</td>
            <td align="right">43,422</td>
            <td align="right">21,303</td>
          </tr>
          <tr>
            <td>Log4j 2: Synchronous</td>
            <td align="right">273,536</td>
            <td align="right">136,523</td>
            <td align="right">67,609</td>
            <td align="right">34,404</td>
            <td align="right">15,373</td>
            <td align="right">7,903</td>
            <td align="right">4,253</td>
          </tr>
          <tr>
            <td>Log4j1: Synchronous</td>
            <td align="right">326,894</td>
            <td align="right">105,591</td>
            <td align="right">57,036</td>
            <td align="right">30,511</td>
            <td align="right">13,900</td>
            <td align="right">7,094</td>
            <td align="right">3,509</td>
          </tr>
          <tr>
            <td>Logback: Synchronous</td>
            <td align="right">178,063</td>
            <td align="right">65,000</td>
            <td align="right">34,372</td>
            <td align="right">16,903</td>
            <td align="right">8,334</td>
            <td align="right">3,985</td>
            <td align="right">1,967</td>
          </tr>
        </table>
        <p />
        <p>On Windows 7 (64bit) with JDK1.7.0_11, 2-core Intel i5-3317u CPU
          @1.70Ghz with hyperthreading switched on (4 virtual cores):
        </p>
        <table>
          <caption align="top">Throughput per thread in
            messages/second</caption>
          <tr>
            <th>Logger</th>
            <th>1 thread</th>
            <th>2 threads</th>
            <th>4 threads</th>
            <th>8 threads</th>
            <th>16 threads</th>
            <th>32 threads</th>
          </tr>
          <tr>
            <td>Log4j 2: Loggers all asynchronous</td>
            <td align="right">1,715,344</td>
            <td align="right">928,951</td>
            <td align="right">1,045,265</td>
            <td align="right">1,509,109</td>
            <td align="right">1,708,989</td>
            <td align="right">773,565</td>
          </tr>
          <tr>
            <td>Log4j 2: Loggers mixed sync/async</td>
            <td align="right">571,099</td>
            <td align="right">1,204,774</td>
            <td align="right">1,632,204</td>
            <td align="right">1,368,041</td>
            <td align="right">462,093</td>
            <td align="right">908,529</td>
          </tr>
          <tr>
            <td>Log4j 2: Async Appender</td>
            <td align="right">1,236,548</td>
            <td align="right">1,006,287</td>
            <td align="right">511,571</td>
            <td align="right">302,230</td>
            <td align="right">160,094</td>
            <td align="right">60,152</td>
          </tr>
          <tr>
            <td>Log4j1: Async Appender</td>
            <td align="right">1,373,195</td>
            <td align="right">911,657</td>
            <td align="right">636,899</td>
            <td align="right">406,405</td>
            <td align="right">202,777</td>
            <td align="right">162,964</td>
          </tr>
          <tr>
            <td>Logback: Async Appender</td>
            <td align="right">1,979,515</td>
            <td align="right">783,722</td>
            <td align="right">582,935</td>
            <td align="right">289,905</td>
            <td align="right">172,463</td>
            <td align="right">133,435</td>
          </tr>
          <tr>
            <td>Log4j 2: Synchronous</td>
            <td align="right">281,250</td>
            <td align="right">225,731</td>
            <td align="right">129,015</td>
            <td align="right">66,590</td>
            <td align="right">34,401</td>
            <td align="right">17,347</td>
          </tr>
          <tr>
            <td>Log4j1: Synchronous</td>
            <td align="right">147,824</td>
            <td align="right">72,383</td>
            <td align="right">32,865</td>
            <td align="right">18,025</td>
            <td align="right">8,937</td>
            <td align="right">4,440</td>
          </tr>
          <tr>
            <td>Logback: Synchronous</td>
            <td align="right">149,811</td>
            <td align="right">66,301</td>
            <td align="right">32,341</td>
            <td align="right">16,962</td>
            <td align="right">8,431</td>
            <td align="right">3,610</td>
          </tr>
        </table>

        <a name="Latency" />
        <h4>Response Time Latency</h4>
        <table>
          <tr><td>This section has been rewritten with the Log4j 2.6 release.
            The previous version only reported <em>service time</em> instead of <em>response time</em>.
            See the <a href="../performance.html#responseTime">response time</a> side bar on the
            performance page on why this is too optimistic.
            Furthermore the previous version reported average latency, which does not make sense since
            latency is not a normal distribution.
            Finally, the previous version of this section only reported the maximum latency of up to 99.99%
            of the measurements, which does not tell you how bad the worst 0.01% were.
            This is unfortunate because often the "outliers" are all that matter when it comes to response time.
            From this release we will try to do better and report response time latency
            across the full range of percentages, including all the outliers.
            Our thanks to Gil Tene for his
            <a href="http://www.infoq.com/presentations/latency-response-time">How NOT to measure latency</a>
            presentation. (Now we know why this is also known as the "Oh s#@t!" presentation.)
          </td></tr>
        </table>
        <p><a href="../performance.html#responseTime">Response time</a> is how long it takes to log a message under a certain load.
          What is often reported as latency is actually <em>service time</em>: 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.
        </p>
        <p>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:
        </p>
        <ul>
          <li>-Xms1G -Xmx1G (prevent heap resizing during the test)</li>
          <!--
          <li>-XX:+UnlockDiagnosticVMOptions -XX:GuaranteedSafepointInterval=500000 (by default Hotspot schedules a
            safepoint pause every second. Reduce jitter by postponing this for the duration of the test.)</li>
            -->
          <li>-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
            -DAsyncLogger.WaitStrategy=busyspin (to use Async Loggers. The BusySpin wait strategy reduces some jitter.)</li>
          <li><b>classic mode: </b>-Dlog4j2.enable.threadlocals=false -Dlog4j2.enable.direct.encoders=false<br />
            <b>garbage-free mode: </b>-Dlog4j2.enable.threadlocals=true -Dlog4j2.enable.direct.encoders=true</li>
          <li>-XX:CompileCommand=dontinline,org.apache.logging.log4j.core.async.perftest.NoOpIdleStrategy::idle</li>
          <li>-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution
            -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime (to eyeball GC and safepoint pauses)</li>
        </ul>
        <p>
          The graph below compares response time latency of the
          ArrayBlockingQueue-based asynchronous appenders in Logback 1.1.7, Log4j 1.2.17 to the
          various options for asynchronous logging that Log4j 2.6 offers.
          Under a workload of 128,000 messages per second, using 16 threads (each logging at a rate of 8,000 messages
          per second), we see that Logback 1.1.7, Log4j 1.2.17 experience latency spikes that are orders
          of magnitude larger than Log4j 2.
        </p>
        <p>
          <img src="../images/ResponseTimeAsyncLogging16Threads@8kEach.png"
               alt="When 16 threads generate a total workload of 128,000 msg/sec, Logback 1.1.7 and
               Log4j 1.2.17 experience latency spikes that are orders of magnitude larger than Log4j 2" />
        </p>
        <p>
          The graph below zooms in on the Log4j 2 results for the same test.
          We see that the worst-case response time is highest for the ArrayBlockingQueue-based Async Appender.
          <a href="garbagefree.html">Garbage-free</a> async loggers have the best response time behaviour.
        </p>
        <p>
          <img src="../images/ResponseTimeAsyncLogging16Threads@8kEachLog4j2Only-labeled.png" alt="" />
        </p>

      </subsection>
      <!-- <a name="PerformanceTuning" /> <subsection name="Async Logger
        Performance Tuning"> <p>While the default settings should give good results
        out of the box, you may want to change settings to improve your logging throughput
        and/or latency. We suggest the following steps for tuning your logging performance:</p>
        <ol> <li>Create a base line by running the performance tests in your environment.</li>
        <li>Change a parameter (e.g. WaitStrategy or RingBufferSize) and run the
        tests again. Check performance results.</li> <li>Repeat (2) until you find
        a parameter combination that gives acceptable performance.</li> </ol> <p>Use
        the following command to run the performance tests:</p> <blockquote> <tt>java
        -cp log4j-async-2.0-tests.jar:log4j-async-2.0.jar:disruptor-3.0.0.jar:log4j-api-2.0.jar:log4j-core-2.0.jar
        \<br /> [-DWaitStrategy=Sleep] [-DRingBufferSize=262144] org.apache.logging.log4j.async.perftest.PerfTestDriver
        [path-to-java] [repeats]</tt> <br /><br /> [<b>WaitStrategy</b>] is an optional
        system property with valid values "Block", "Sleep", or "Yield". Details are
        documented under "System Properties to configure ... loggers". <br /> [<b>RingBufferSize</b>]
        is an optional system property with an integer value of at least 128. Details
        are documented under "System Properties to configure ... loggers". <br />
        [<b>path-to-java</b>] is an optional parameter that is the full path to the
        "java" executable. Specify this if just running "java" in the current directory
        does not specify the version of java that you want to test with. <br /> [<b>repeats</b>]
        is an optional parameter that specifies how often each test is repeated.
        The default is 5. </blockquote> <p>For reference, below are some of the numbers
        we used to determine the default settings. (Solaris 10 (64bit), 2.93GHz Xeon
        X5570 with JDK1.7.0_06):</p> <table> <caption align="top">Throughput in log
        messages/second per thread</caption> <tr> <th>Logger</th> <th>WaitStrategy</th>
        <th>1 thread</th> <th>2 threads</th> <th>4 threads</th> <th>8 threads</th>
        </tr> <tr> <td rowspan="3" valign="top">All Async System Clock</td> <td align="center">Block</td>
        <td align="right">1,717,261</td> <td align="right">727,075</td> <td align="right">263,760</td>
        <td align="right">150,533</td> </tr> <tr> <td align="center">Sleep</td> <td
        align="right">1,568,623</td> <td align="right">948,653</td> <td align="right">629,951</td>
        <td align="right">651,340</td> </tr> <tr> <td align="center">Yield</td> <td
        align="right">1,618,103</td> <td align="right">884,314</td> <td align="right">628,008</td>
        <td align="right">675,879</td> </tr> <tr> <td rowspan="3" valign="top">All
        Async Cached Clock</td> <td align="center">Block</td> <td align="right">2,771,734</td>
        <td align="right">642,899</td> <td align="right">331,003</td> <td align="right">172,877</td>
        </tr> <tr> <td align="center">Sleep</td> <td align="right">2,393,901</td>
        <td align="right">1,211,425</td> <td align="right">770,416</td> <td align="right">632,361</td>
        </tr> <tr> <td align="center">Yield</td> <td align="right">2,331,763</td>
        <td align="right">1,132,529</td> <td align="right">684,109</td> <td align="right">671,957</td>
        </tr> <tr> <td rowspan="3" valign="top">Mixed Async</td> <td align="center">Block</td>
        <td align="right">1,347,853</td> <td align="right">443,652</td> <td align="right">251,433</td>
        <td align="right">136,152</td> </tr> <tr> <td align="center">Sleep</td> <td
        align="right">1,371,511</td> <td align="right">567,829</td> <td align="right">407,676</td>
        <td align="right">408,071</td> </tr> <tr> <td align="center">Yield</td> <td
        align="right">1,360,267</td> <td align="right">675,570</td> <td align="right">389,609</td>
        <td align="right">391,969</td> </tr> </table> </subsection> -->
      <a name="UnderTheHood" />
      <subsection name="Under The Hood">
        <p>
          Asynchronous Loggers are implemented using the
          <a href="http://lmax-exchange.github.com/disruptor/">LMAX Disruptor</a>
          inter-thread messaging library. From the LMAX web site:
        </p>
        <blockquote>
          <p>... using queues to pass data between stages of the system was introducing latency, so we
            focused on optimising this area. The Disruptor is the result of our research and testing.
            We found that cache misses at the CPU-level, and locks requiring kernel arbitration are both
            extremely costly, so we created a framework which has "mechanical sympathy" for
            the hardware it's running on, and that's lock-free.
          </p>
        </blockquote>

        <p>
          LMAX Disruptor internal performance comparisons with <tt>java.util.concurrent.ArrayBlockingQueue</tt>
          can be found
          <a href="https://github.com/LMAX-Exchange/disruptor/wiki/Performance-Results">here</a>.
        </p>
      </subsection>
    </section>
  </body>
</document>
