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 <boa...@gmail.com> Authored: Sun Apr 8 13:28:46 2018 -0500 Committer: Matt Sicker <boa...@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 <rpo...@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/responsetimeasynclogging16thre...@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/responsetimeasynclogging16thre...@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="rpo...@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/responsetimeasynclogging16thre...@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/responsetimeasynclogging16thre...@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>