You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by ma...@apache.org on 2018/04/08 18:28:52 UTC
logging-log4j2 git commit: LOG4J2-1802: Convert async loggers manual
page to asciidoc
Repository: logging-log4j2
Updated Branches:
refs/heads/master ddb5926b1 -> 812c96df8
LOG4J2-1802: Convert async loggers manual page to asciidoc
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/812c96df
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/812c96df
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/812c96df
Branch: refs/heads/master
Commit: 812c96df809bb908e45ce1ea070bd2f12c1bd164
Parents: ddb5926
Author: Matt Sicker <bo...@gmail.com>
Authored: Sun Apr 8 13:28:46 2018 -0500
Committer: Matt Sicker <bo...@gmail.com>
Committed: Sun Apr 8 13:28:46 2018 -0500
----------------------------------------------------------------------
src/site/asciidoc/manual/async.adoc | 610 ++++++++++++++++++++++
src/site/xdoc/manual/async.xml | 848 -------------------------------
2 files changed, 610 insertions(+), 848 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/812c96df/src/site/asciidoc/manual/async.adoc
----------------------------------------------------------------------
diff --git a/src/site/asciidoc/manual/async.adoc b/src/site/asciidoc/manual/async.adoc
new file mode 100644
index 0000000..65bc711
--- /dev/null
+++ b/src/site/asciidoc/manual/async.adoc
@@ -0,0 +1,610 @@
+= Log4j 2 Lock-free Asynchronous Loggers for Low-Latency Logging
+Remko Popma <rp...@apache.org>
+
+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.
+
+* *Asynchronous Loggers* 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.
+* *LMAX Disruptor technology*. Asynchronous Loggers internally use the
+link:#UnderTheHood[Disruptor], a lock-free inter-thread communication
+library, instead of queues, resulting in higher throughput and lower
+latency.
+* As part of the work for Async Loggers, *Asynchronous Appenders* 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.)
+
+[#Trade-offs]
+== Trade-offs
+
+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.
+
+=== Benefits
+
+* Higher peak link:#Performance[throughput]. With an asynchronous logger
+your application can log messages at 6 - 68 times the rate of a
+synchronous logger.
++
+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.
+* Lower logging response time link:#Latency[latency]. 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.
+
+=== Drawbacks
+
+* 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 `ExceptionHandler`, 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 link:#MixedSync-Async[combine] them and use asynchronous
+logging for debug/trace logging in addition to synchronous logging for
+the audit trail.)
+* 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 `logger.debug("My object is {}", myObject)` will use the
+state of the `myObject` parameter at the time of the call to
+`logger.debug()`. The log message will not change even if `myObject` is
+modified later. It is safe to asynchronously log mutable objects because
+most
+link:../log4j-api/apidocs/org/apache/logging/log4j/message/Message.html[`Message`]
+implementations built-in to Log4j take a snapshot of the parameters.
+There are some exceptions however:
+link:../log4j-api/apidocs/org/apache/logging/log4j/message/MapMessage.html[`MapMessage`]
+and
+link:../log4j-api/apidocs/org/apache/logging/log4j/message/StructuredDataMessage.html[`StructuredDataMessage`]
+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
+link:../log4j-api/apidocs/org/apache/logging/log4j/message/Message.html[`Message`]
+implementations should be designed with asynchronous use in mind, and
+either take a snapshot of their parameters at construction time, or
+document their thread-safety characteristics.
+* 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.
+* If the _sustained rate_ at which your application is logging messages
+is faster than the maximum sustained throughput of the underlying
+appender, the queue will fill up and the application will end up logging
+at the speed of the slowest appender. If this happens, consider
+selecting a link:../performance.html#whichAppender[faster appender], or
+logging less. If neither of these is an option, you may get better
+throughput and fewer latency spikes by logging synchronously.
+
+[#AllAsync]
+== Making All Loggers Asynchronous
+
+NOTE: _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._
+
+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 `log4j2.contextSelector` to
+`org.apache.logging.log4j.core.async.AsyncLoggerContextSelector`.
+
+By default, link:#Location[location] 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.
+
+A configuration that does not require location might look like:
+
+[source,xml]
+----
+<?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>
+----
+
+When `AsyncLoggerContextSelector` is used to make all loggers
+asynchronous, make sure to use normal `<root>` and `<logger>` 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 `<asyncRoot>` or `<asyncLogger>`. 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.
+
+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.
+
+The below properties can also be specified by creating a file named
+`log4j2.component.properties` and including this file in the classpath
+of the application.
+
+NOTE: System properties were renamed into a more consistent style in
+Log4j 2.10.0. All old property names are still supported which are
+documented link:configuration.html#SystemProperties[here].
+
+[[SysPropsAllAsync]]
+
+.System Properties to configure all asynchronous loggers
+[cols="5m,2,10a",options="header"]
+|===
+|System Property |Default Value |Description
+
+|log4j2.asyncLoggerExceptionHandler
+|`default handler`
+|
+Fully qualified name of a class that implements the
+`com.lmax.disruptor.ExceptionHandler` 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.
+
+If not specified, the default exception handler will print a message and
+stack trace to the standard error output stream.
+
+|log4j2.asyncLoggerRingBufferSize
+|256 * 1024
+|
+Size (number of slots) in the RingBuffer used by the asynchronous
+logging subsystem. Make this value large enough to deal with bursts of
+activity. The minimum size is 128. The RingBuffer will be pre-allocated
+at first use and will never grow or shrink during the life of the
+system.
+
+When the application is logging faster than the underlying appender can
+keep up with for a long enough time to fill up the queue, the behavious
+is determined by the
+link:../log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicy.html[AsyncQueueFullPolicy].
+
+|log4j2.asyncLoggerWaitStrategy
+|`Timeout`
+|Valid values: Block,
+Timeout, Sleep, Yield.
+`Block` 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.
+`Timeout` is a variation of the `Block` strategy that will periodically
+wake up from the lock condition await() call. This ensures that if a
+notification is missed somehow the consumer thread is not stuck but will
+recover with a small latency delay (default 10ms).
+`Sleep` 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.
+`Yield` 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.
+
+|log4j2.asyncLoggerThreadNameStrategy
+|`CACHED`
+|Valid values: CACHED, UNCACHED.
+By default, AsyncLogger caches the thread name in a ThreadLocal variable
+to improve performance. Specify the `UNCACHED` option if your
+application modifies the thread name at runtime (with
+`Thread.currentThread().setName()`) and you want to see the new thread
+name reflected in the log.
+
+|log4j2.clock
+|`SystemClock`
+|Implementation of the `org.apache.logging.log4j.core.time.Clock`
+interface that is used for timestamping the log events when all loggers
+are asynchronous.
+By default, `System.currentTimeMillis` is called on every log event.
+
+`CachedClock` 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.
+
+You can also specify the fully qualified class name of a custom class
+that implements the `Clock` interface.
+
+|===
+
+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
+link:configuration.html#asyncQueueFullPolicy[`log4j2.asyncQueueFullPolicy`
+and `log4j2.discardThreshold`].
+
+[#MixedSync-Async]
+== Mixing Synchronous and Asynchronous Loggers
+
+NOTE: _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._
+
+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
+`<asyncRoot>` or `<asyncLogger>` configuration elements to specify the
+loggers that need to be asynchronous. A configuration can contain only
+one root logger (either a `<root>` or an `<asyncRoot>` element), but
+otherwise async and non-async loggers may be combined. For example, a
+configuration file containing `<asyncLogger>` elements can also contain
+`<root>` and `<logger>` elements for the synchronous loggers.
+
+By default, link:#Location[location] 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.
+
+A configuration that mixes asynchronous loggers might look like:
+
+[source,xml]
+----
+<?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>
+----
+
+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.
+
+The below properties can also be specified by creating a file named
+`log4j2.component.properties` and including this file in the classpath
+of the application.
+
+NOTE: All system properties were renamed into a more consistent style in
+Log4j 2.10. All old property names are still supported which are
+documented link:configuration.html#SystemProperties[here].
+
+[[SysPropsMixedSync-Async]]
+
+.System Properties to configure mixed asynchronous and normal loggers
+[cols="5m,2,10a",options="header"]
+|===
+|System Property |Default Value |Description
+
+|log4j2.asyncLoggerConfigExceptionHandler
+|`default handler`
+|Fully qualified name of a class that implements the
+`com.lmax.disruptor.ExceptionHandler` 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.
+
+If not specified, the default exception handler will print a message and
+stack trace to the standard error output stream.
+
+|log4j2.asyncLoggerConfigRingBufferSize
+|256 * 1024
+|Size (number of slots) in the RingBuffer used by the asynchronous
+logging subsystem. Make this value large enough to deal with bursts of
+activity. The minimum size is 128. The RingBuffer will be pre-allocated
+at first use and will never grow or shrink during the life of the
+system.
+
+When the application is logging faster than the underlying appender can
+keep up with for a long enough time to fill up the queue, the behavious
+is determined by the
+link:../log4j-core/apidocs/org/apache/logging/log4j/core/async/AsyncQueueFullPolicy.html[AsyncQueueFullPolicy].
+
+|log4j2.asyncLoggerConfigWaitStrategy
+|`Timeout`
+|Valid values: Block,
+Timeout, Sleep, Yield. +
+`Block` 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. +
+`Timeout` is a variation of the `Block` strategy that will periodically
+wake up from the lock condition await() call. This ensures that if a
+notification is missed somehow the consumer thread is not stuck but will
+recover with a small latency delay (default 10ms). +
+`Sleep` 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. +
+`Yield` 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.
+|===
+
+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
+link:configuration.html#asyncQueueFullPolicy[`log4j2.asyncQueueFullPolicy`
+and `log4j2.discardThreshold`].
+
+[#Location]
+== Location, location, location...
+
+If one of the layouts is configured with a location-related attribute
+like HTML link:layouts.html#HtmlLocationInfo[locationInfo], or one of
+the patterns link:layouts.html#PatternClass[%C or $class],
+link:layouts.html#PatternFile[%F or %file],
+link:layouts.html#PatternLocation[%l or %location],
+link:layouts.html#PatternLine[%L or %line],
+link:layouts.html#PatternMethod[%M or %method], Log4j will take a
+snapshot of the stack, and walk the stack trace to find the location
+information.
+
+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.
+
+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
+link:../performance.html#asyncLoggingWithLocation[performance impact] 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.
+
+You can override the default behaviour in your logger or asynchronous
+appender configuration by specifying `includeLocation="true"`.
+
+[#Performance]
+== Asynchronous Logging Performance
+
+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:
+
+* First, warm up the JVM by logging 200,000 log messages of 500
+characters.
+* Repeat the warm-up 10 times, then wait 10 seconds for the I/O thread
+to catch up and buffers to drain.
+* Measure how long it takes to execute 256 * 1024 / threadCount calls to
+Logger.log and express the result in messages per second.
+* Repeat the test 5 times and average the results.
+
+The results below were obtained with log4j-2.0-beta5,
+disruptor-3.0.0.beta3, log4j-1.2.17 and logback-1.0.10.
+
+=== Logging Peak Throughput
+
+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.
+
+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.
+
+image:../images/async-vs-sync-throughput.png[Async loggers have much
+higher throughput than sync loggers.]
+
+=== Asynchronous Throughput Comparison with Other Logging Packages
+
+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.
+
+image:../images/async-throughput-comparison.png[Async loggers have the
+highest throughput.]
+
+On Solaris 10 (64bit) with JDK1.7.0_06, 4-core Xeon X5570 dual CPU
+@2.93Ghz with hyperthreading switched on (16 virtual cores):
+
+.Throughput per thread in messages/second
+[cols="h,>,>,>,>,>,>,>",options="header",]
+|=======================================================================
+|Logger |1 thread |2 threads |4 threads |8 threads |16 threads |32
+threads |64 threads
+|Log4j 2: Loggers all asynchronous |2,652,412 |909,119 |776,993 |516,365
+|239,246 |253,791 |288,997
+
+|Log4j 2: Loggers mixed sync/async |2,454,358 |839,394 |854,578 |597,913
+|261,003 |216,863 |218,937
+
+|Log4j 2: Async Appender |1,713,429 |603,019 |331,506 |149,408 |86,107
+|45,529 |23,980
+
+|Log4j1: Async Appender |2,239,664 |494,470 |221,402 |109,314 |60,580
+|31,706 |14,072
+
+|Logback: Async Appender |2,206,907 |624,082 |307,500 |160,096 |85,701
+|43,422 |21,303
+
+|Log4j 2: Synchronous |273,536 |136,523 |67,609 |34,404 |15,373 |7,903
+|4,253
+
+|Log4j1: Synchronous |326,894 |105,591 |57,036 |30,511 |13,900 |7,094
+|3,509
+
+|Logback: Synchronous |178,063 |65,000 |34,372 |16,903 |8,334 |3,985
+|1,967
+|=======================================================================
+
+On Windows 7 (64bit) with JDK1.7.0_11, 2-core Intel i5-3317u CPU
+@1.70Ghz with hyperthreading switched on (4 virtual cores):
+
+.Throughput per thread in messages/second
+[cols="h,>,>,>,>,>,>",options="header",]
+|=======================================================================
+|Logger |1 thread |2 threads |4 threads |8 threads |16 threads |32
+threads
+|Log4j 2: Loggers all asynchronous |1,715,344 |928,951 |1,045,265
+|1,509,109 |1,708,989 |773,565
+
+|Log4j 2: Loggers mixed sync/async |571,099 |1,204,774 |1,632,204
+|1,368,041 |462,093 |908,529
+
+|Log4j 2: Async Appender |1,236,548 |1,006,287 |511,571 |302,230
+|160,094 |60,152
+
+|Log4j1: Async Appender |1,373,195 |911,657 |636,899 |406,405 |202,777
+|162,964
+
+|Logback: Async Appender |1,979,515 |783,722 |582,935 |289,905 |172,463
+|133,435
+
+|Log4j 2: Synchronous |281,250 |225,731 |129,015 |66,590 |34,401 |17,347
+
+|Log4j1: Synchronous |147,824 |72,383 |32,865 |18,025 |8,937 |4,440
+
+|Logback: Synchronous |149,811 |66,301 |32,341 |16,962 |8,431 |3,610
+|=======================================================================
+
+[#Latency]
+=== Response Time Latency
+
+This section has been rewritten with the Log4j 2.6 release. The
+previous version only reported _service time_ instead of _response
+time_. See the link:../performance.html#responseTime[response time] 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 http://www.infoq.com/presentations/latency-response-time[How NOT to
+measure latency] presentation. (Now we know why this is also known as
+the "Oh s#@t!" presentation.)
+
+link:../performance.html#responseTime[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.
+
+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)
+
+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.
+
+image:../images/ResponseTimeAsyncLogging16Threads@8kEach.png[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]
+
+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.
+link:garbagefree.html[Garbage-free] async loggers have the best response
+time behaviour.
+
+image:../images/ResponseTimeAsyncLogging16Threads@8kEachLog4j2Only-labeled.png[image]
+
+[#UnderTheHood]
+== Under The Hood
+
+Asynchronous Loggers are implemented using the
+http://lmax-exchange.github.com/disruptor/[LMAX Disruptor] inter-thread
+messaging library. From the LMAX web site:
+
+____
+...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.
+____
+
+LMAX Disruptor internal performance comparisons with
+`java.util.concurrent.ArrayBlockingQueue` can be found
+https://github.com/LMAX-Exchange/disruptor/wiki/Performance-Results[here].
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/812c96df/src/site/xdoc/manual/async.xml
----------------------------------------------------------------------
diff --git a/src/site/xdoc/manual/async.xml b/src/site/xdoc/manual/async.xml
deleted file mode 100644
index 59b14c7..0000000
--- a/src/site/xdoc/manual/async.xml
+++ /dev/null
@@ -1,848 +0,0 @@
-<?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><root></tt> and <tt><logger></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><asyncRoot></tt>
- or <tt><asyncLogger></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 * 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.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.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.time.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><asyncRoot></tt> or <tt><asyncLogger></tt>
- configuration elements to specify the loggers that need to be asynchronous.
- A configuration can contain only one root logger (either a <tt><root></tt>
- or an <tt><asyncRoot></tt> element), but otherwise async and non-async loggers may be
- combined.
- For example, a configuration file containing <tt><asyncLogger></tt> elements
- can also contain <tt><root></tt> and
- <tt><logger></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 * 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>
- </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>