| //// |
| 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 |
| |
| https://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. |
| //// |
| = Lock-free Asynchronous Loggers for Low-Latency Logging |
| Remko Popma <rpopma@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 behaviour |
| 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. |
| |
| |AsyncLogger.SynchronizeEnqueueWhenQueueFull |
| |`true` |
| |Synchronizes access to the Disruptor ring buffer for blocking enqueue operations when the queue is full. |
| Users encountered excessive CPU utilization with Disruptor v3.4.2 when the application |
| was logging more than the underlying appender could keep up with and the ring buffer became full, |
| especially when the number of application threads vastly outnumbered the number of cores. |
| CPU utilization is significantly reduced by restricting access to the enqueue operation. Setting this value |
| to `false` may lead to very high CPU utilization when the async logging queue is full. |
| |
| |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. |
| |
| |AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull |
| |`true` |
| |Synchronizes access to the Disruptor ring buffer for blocking enqueue operations when the queue is full. |
| Users encountered excessive CPU utilization with Disruptor v3.4.2 when the application |
| was logging more than the underlying appender could keep up with and the ring buffer became full, |
| especially when the number of application threads vastly outnumbered the number of cores. |
| CPU utilization is significantly reduced by restricting access to the enqueue operation. Setting this value |
| to `false` may lead to very high CPU utilization when the async logging queue is full. |
| |
| |=== |
| |
| 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]. |