Added: logging/log4j/log4j2/trunk/src/site/xdoc/manual/async.xml URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/site/xdoc/manual/async.xml?rev=1463078&view=auto ============================================================================== --- logging/log4j/log4j2/trunk/src/site/xdoc/manual/async.xml (added) +++ logging/log4j/log4j2/trunk/src/site/xdoc/manual/async.xml Mon Apr 1 03:51:21 2013 @@ -0,0 +1,1377 @@ +<?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> + <properties> + <title>Log4j2 Asynchronous Logging</title> + <author email="[email protected]">Remko Popma</author> + </properties> + <body> + <section name="Asynchronous Logging"> + <p> + Asynchronous logging can improve your application's + performance by executing the I/O operations + in a separate thread. + Log4j2 makes a number of improvements in this area. + </p> + <ul> + <li> + <b>Asynchronous Loggers</b> + are a new addition to Log4j2. + 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>Asynchronous Appenders</b> + already existed in Log4j 1.x, but 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. + </li> + <li> + <b>Fast File Appenders</b> + are an alternative to Buffered File + Appenders. Under the hood, these + new appenders use a ByteBuffer + RandomAccessFile instead + of a BufferedOutputStream. In our testing + this was about 10-30% faster. + These appenders can also be used + with synchronous loggers + and will give the same performance benefits. + </li> + <li><b>LMAX Disruptor technology</b>. The Asynchronous Loggers + internally + use the <a href="#UnderTheHood">Disruptor</a> inter-thread + communication library instead of queues, resulting in higher + throughput and lower latency.</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>Higher <a href="#Performance">throughput</a>. + With an asynchronous logger + your application can log messages at 6 - 68 times + the rate of a synchronous logger. + </li> + <li> + Lower logging <a href="#Latency">latency</a>. + Latency is the time it takes for a call to Logger.log to return. + Asynchronous Loggers have consistently lower latency + than synchronous loggers or even queue-based asynchronous appenders. + Applications interested in low latency often care + not only about average latency, but also about worst-case latency. + Our performance comparison shows that Asynchronous + Loggers also do better when comparing the maximum latency + of 99% or even 99.99% of observations with other logging methods. + </li> + <li>Prevent or dampen latency spikes during bursts of events. + If the queue size is configured large enough to handle + spikes, asynchronous logging will help prevent your + application from falling behind (as much) during + sudden bursts of activity. + </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> + </ul> + </subsection> + <a name="AllAsync" /> + <subsection name="Making All Loggers Asynchronous"> + <p> + This is simplest to configure and gives the best performance. + To make all loggers asynchronous, add log4j-async.jar + and disruptor-3.0.0.jar to the classpath + and set the system property <tt>Log4jContextSelector</tt> + to + <tt>org.apache.logging.log4j.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: + <pre class="prettyprint linenums"><![CDATA[<?xml version="1.0" encoding="UTF-8"?> +<configuration status="OFF"> + <appenders> + <FastFile name="FastFile" fileName="async.log" immediateFlush="false" append="false"> + <PatternLayout> + <pattern>%d %p %c{1.} [%t] %m %ex%n</pattern> + </PatternLayout> + </FastFile> + </appenders> + <loggers> + <root level="info" includeLocation="false"> + <appender-ref ref="FastFile"/> + </root> + </loggers> +</configuration>]]></pre> + </p> + <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> + <table> + <tr> + <th>System Property</th> + <th>Default Value</th> + <th>Description</th> + </tr> + <tr> + <td>AsyncLogger.ExceptionHandler</td> + <td> + <tt>null</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. + </td> + </tr> + <tr> + <td>AsyncLogger.RingBufferSize</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. + </td> + </tr> + <tr> + <td>AsyncLogger.WaitStrategy</td> + <td> + <tt>Sleep</tt> + </td> + <td> + Valid values: Block, 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>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>AsyncLogger.Clock</td> + <td> + <tt>SystemClock</tt> + </td> + <td> + Implementation of the + <tt>org.apache.logging.log4j.async.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. + <br /> + <tt>CachedClock</tt> + is an optimization 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. + <br /> + You can also specify a fully qualified class name + of a custom class that implements the + <tt>Clock</tt> + interface. + </td> + </tr> + <caption align="top">System Properties to configure all + asynchronous loggers + </caption> + </table> + </subsection> + <a name="MixedSync-Async" /> + <subsection name="Mixing Synchronous and Asynchronous Loggers"> + <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. The same configuration file can also + contain + <tt><root></tt> + and + <tt><logger></tt> + elements for the synchronous loggers. + </p> + <p> + There is no need to set the system property + "Log4jContextSelector" to any value. + </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: + <pre class="prettyprint linenums"><![CDATA[<?xml version="1.0" encoding="UTF-8"?> +<configuration status="OFF"> + <appenders> + <FastFile name="FastFile" fileName="asyncWithLocation.log" + immediateFlush="false" append="false"> + <PatternLayout> + <pattern>%d %p %class{1.} [%t] %location %m %ex%n</pattern> + </PatternLayout> + </FastFile> + </appenders> + <loggers> + <asyncLogger name="com.foo.Bar" level="trace" includeLocation="true"><!-- pattern actually uses location, so need to include it --> + <appender-ref ref="FastFile"/> + </asyncLogger> + <root level="info" includeLocation="true"> + <appender-ref ref="FastFile"/> + </root> + </loggers> +</configuration>]]></pre> + </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> + <table> + <tr> + <th>System Property</th> + <th>Default Value</th> + <th>Description</th> + </tr> + <tr> + <td>AsyncLoggerConfig.ExceptionHandler</td> + <td> + <tt>null</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. + </td> + </tr> + <tr> + <td>AsyncLoggerConfig.RingBufferSize</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. + </td> + </tr> + <tr> + <td>AsyncLoggerConfig.WaitStrategy</td> + <td> + <tt>Sleep</tt> + </td> + <td> + Valid values: Block, 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>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> + <caption align="top">System Properties to configure mixed + asynchronous and normal loggers + </caption> + </table> + </subsection> + <a name="Location" /> + <subsection name="Location, location, location..."> + <p> + If one of the layouts is + configured with a location-related attribute like %line, + %location, %class 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. + </p><p> + The performance impact of taking a stack trace snapshot is even + higher for asynchronous loggers: logging with location is + 4 - 20 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 + <tt>includeLocation="true"</tt>. + </p> + <p> + </p> + </subsection> + <a name="FastFileAppender" /> + <subsection name="FastFileAppender"> + <p> + The FastFileAppender is similar to the standard + <a href="appenders.html#FileAppender">FileAppender</a> + except it is always buffered (this cannot be switched off) + and internally it uses a + <tt>ByteBuffer + RandomAccessFile</tt> + instead of a + <tt>BufferedOutputStream</tt>. + We saw a 10-30% performance improvement compared to + FileAppender with "bufferedIO=true" in our + <a href="#FastFileAppenderPerformance">measurements</a>. + Similar to the FileAppender, + FastFileAppender uses a FastFileManager to actually perform the + file I/O. While FastFileAppender + from different Configurations + cannot be shared, the FastFileManagers can be if the Manager is + accessible. For example, two webapps in a + servlet container can have + their own configuration and safely + write to the same file if Log4j + is in a ClassLoader that is common to + both of them. + </p> + <table> + <tr> + <th>Parameter Name</th> + <th>Type</th> + <th>Description</th> + </tr> + <tr> + <td>append</td> + <td>boolean</td> + <td>When true - the default, records will be appended to the end + of the file. When set to false, + the file will be cleared before + new records are written. + </td> + </tr> + <tr> + <td>fileName</td> + <td>String</td> + <td>The name of the file to write to. If the file, or any of its + parent directories, do not exist, + they will be created. + </td> + </tr> + <tr> + <td>filters</td> + <td>Filter</td> + <td>A Filter to determine if the event should be handled by this + Appender. More than one Filter + may be used by using a CompositeFilter. + </td> + </tr> + <tr> + <td>immediateFlush</td> + <td>boolean</td> + <td>When set to true, each write will be followed by a flush. + This will guarantee the data is written + to disk but could impact performance. + This option is only necessary when using this + appender with synchronous loggers. Asynchronous loggers will + automatically flush at the end of a batch, which also guarantees + the data is written to disk but is more efficient. + </td> + </tr> + <tr> + <td>layout</td> + <td>Layout</td> + <td>The Layout to use to format the LogEvent</td> + </tr> + <tr> + <td>name</td> + <td>String</td> + <td>The name of the Appender.</td> + </tr> + <tr> + <td>suppressExceptions</td> + <td>boolean</td> + <td>The default is true, causing exceptions to be internally + logged and then ignored. When set to + false exceptions will be + percolated to the caller. + </td> + </tr> + <caption align="top">FastFileAppender Parameters</caption> + </table> + <p> + Here is a sample FastFile configuration: + + <pre class="prettyprint linenums"><![CDATA[<?xml version="1.0" encoding="UTF-8"?> +<configuration status="warn" name="MyApp" packages=""> + <appenders> + <FastFile name="MyFile" fileName="logs/app.log"> + <PatternLayout> + <pattern>%d %p %c{1.} [%t] %m%n</pattern> + </PatternLayout> + </FastFile> + </appenders> + <loggers> + <root level="error"> + <appender-ref ref="MyFile"/> + </root> + </loggers> +</configuration>]]></pre> + </p> + </subsection> + <a name="FastRollingFileAppender" /> + <subsection name="FastRollingFileAppender"> + <p> + The FastRollingFileAppender is similar to the standard + <a href="appenders.html#RollingFileAppender">RollingFileAppender</a> + except it is always buffered (this cannot be switched off) + and + internally it uses a + <tt>ByteBuffer + RandomAccessFile</tt> + instead of a + <tt>BufferedOutputStream</tt>. + <!-- + We saw a 10-30% performance improvement compared to + RollingFileAppender with "bufferedIO=true" + in our + <a href="#FastFileAppenderPerformance">measurements</a>. + --> + The FastRollingFileAppender writes + to the File named in the + fileName parameter + and rolls the file over according the + TriggeringPolicy + and the RolloverPolicy. + + Similar to the RollingFileAppender, + FastRollingFileAppender uses a FastRollingFileManager + to actually perform the + file I/O and perform the rollover. While FastRollingFileAppender + from different Configurations cannot be + shared, the FastRollingFileManagers can be + if the Manager is accessible. + For example, two webapps in a servlet + container can have their own configuration and safely write to the + same file if Log4j is in a ClassLoader that is common to both of them. + </p> + <p> + A FastRollingFileAppender requires a + <a href="#TriggeringPolicies">TriggeringPolicy</a> + and a + <a href="#RolloverStrategies">RolloverStrategy</a>. + The triggering policy determines if a rollover should + be performed + while the RolloverStrategy defines how the rollover + should be done. + If no RolloverStrategy + is configured, FastRollingFileAppender will + use the + <a href="appenders.html#DefaultRolloverStrategy">DefaultRolloverStrategy</a>. + </p> + <p> + File locking is not supported by the FastRollingFileAppender. + </p> + <table> + <tr> + <th>Parameter Name</th> + <th>Type</th> + <th>Description</th> + </tr> + <tr> + <td>append</td> + <td>boolean</td> + <td>When true - the default, records will be appended to the end + of the file. When set to false, + the file will be cleared before + new records are written. + </td> + </tr> + <tr> + <td>filter</td> + <td>Filter</td> + <td>A Filter to determine if the event should be handled by this + Appender. More than one Filter + may be used by using a + CompositeFilter. + </td> + </tr> + <tr> + <td>fileName</td> + <td>String</td> + <td>The name of the file to write to. If the file, or any of its + parent directories, do not exist, + they will be created. + </td> + </tr> + <tr> + <td>filePattern</td> + <td>String</td> + <td> + The pattern of the file name of the archived log file. The format + of the pattern should is + dependent on the RolloverPolicy that is + used. The DefaultRolloverPolicy + will accept both + a date/time + pattern compatible with + <a + href="http://download.oracle.com/javase/6/docs/api/java/text/SimpleDateFormat.html";> + SimpleDateFormat</a> + + and/or a %i which represents an integer counter. The pattern + also supports interpolation at + runtime so any of the Lookups (such + as the + <a href="./lookups.html#DateLookup">DateLookup</a> + can + be included in the pattern. + </td> + </tr> + <tr> + <td>immediateFlush</td> + <td>boolean</td> + <td>When set to true, each write will be followed by a flush. This + will guarantee the data is written + to disk but could impact + performance. + This option is only necessary when using this + appender with + synchronous loggers. Asynchronous loggers will + automatically + flush at the end of a batch, which also guarantees + the data + is written to disk but is more efficient. + </td> + </tr> + <tr> + <td>layout</td> + <td>Layout</td> + <td>The Layout to use to format the LogEvent</td> + </tr> + + <tr> + <td>name</td> + <td>String</td> + <td>The name of the Appender.</td> + </tr> + <tr> + <td>policy</td> + <td>TriggeringPolicy</td> + <td>The policy to use to determine if a rollover should occur. + </td> + </tr> + <tr> + <td>strategy</td> + <td>RolloverStrategy</td> + <td>The strategy to use to determine the name and location of the + archive file. + </td> + </tr> + <tr> + <td>suppressExceptions</td> + <td>boolean</td> + <td>The default is true, causing exceptions to be internally + logged and then ignored. When set to + false exceptions will be + percolated to the caller. + </td> + </tr> + <caption align="top">FastRollingFileAppender Parameters</caption> + </table> + <a name="TriggeringPolicies" /> + <h4>Triggering Policies</h4> + <p> + See + <a href="appenders.html#TriggeringPolicies">RollingFileAppender Triggering Policies</a>. + </p> + <a name="RolloverStrategies" /> + <h4>Rollover Strategies</h4> + <p> + See + <a href="appenders.html#RolloverStrategies">RollingFileAppender Rollover Strategies</a>. + </p> + + <p> + Below is a sample configuration that uses a FastRollingFileAppender + with both the time and size based + triggering policies, will create + up to 7 archives on the same day (1-7) that + are stored in a + directory + based on the current year and month, and will compress + each + archive using gzip: + + <pre class="prettyprint linenums"><![CDATA[<?xml version="1.0" encoding="UTF-8"?> +<configuration status="warn" name="MyApp" packages=""> + <appenders> + <FastRollingFile name="FastRollingFile" fileName="logs/app.log" + filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz"> + <PatternLayout> + <pattern>%d %p %c{1.} [%t] %m%n</pattern> + </PatternLayout> + <Policies> + <TimeBasedTriggeringPolicy /> + <SizeBasedTriggeringPolicy size="250 MB"/> + </Policies> + </FastRollingFile> + </appenders> + <loggers> + <root level="error"> + <appender-ref ref="FastRollingFile"/> + </root> + </loggers> +</configuration>]]></pre> + </p> + <p> + This second example shows a rollover strategy that will keep up to + 20 files before removing them. + <pre class="prettyprint linenums"><![CDATA[<?xml version="1.0" encoding="UTF-8"?> +<configuration status="warn" name="MyApp" packages=""> + <appenders> + <FastRollingFile name="FastRollingFile" fileName="logs/app.log" + filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz"> + <PatternLayout> + <pattern>%d %p %c{1.} [%t] %m%n</pattern> + </PatternLayout> + <Policies> + <TimeBasedTriggeringPolicy /> + <SizeBasedTriggeringPolicy size="250 MB"/> + </Policies> + <DefaultRolloverStrategy max="20"/> + </FastRollingFile> + </appenders> + <loggers> + <root level="error"> + <appender-ref ref="FastRollingFile"/> + </root> + </loggers> +</configuration>]]></pre> + </p> + <p> + Below is a sample configuration that uses a FastRollingFileAppender + with both the time and size based + triggering policies, will create + up to 7 archives on the same day (1-7) that + are stored in a + directory + based on the current year and month, and will compress + each + archive using gzip and will roll every 6 hours when the hour is + divisible + by 6: + + <pre class="prettyprint linenums"><![CDATA[<?xml version="1.0" encoding="UTF-8"?> +<configuration status="warn" name="MyApp" packages=""> + <appenders> + <FastRollingFile name="FastRollingFile" fileName="logs/app.log" + filePattern="logs/$${date:yyyy-MM}/app-%d{yyyy-MM-dd-HH}-%i.log.gz"> + <PatternLayout> + <pattern>%d %p %c{1.} [%t] %m%n</pattern> + </PatternLayout> + <Policies> + <TimeBasedTriggeringPolicy interval="6" modulate="true"/> + <SizeBasedTriggeringPolicy size="250 MB"/> + </Policies> + </FastRollingFile> + </appenders> + <loggers> + <root level="error"> + <appender-ref ref="FastRollingFile"/> + </root> + </loggers> +</configuration>]]></pre> + </p> + </subsection> + <a name="Performance" /> + <subsection name="Performance Measurements"> + <p> + This section shows the results of our performance tests. + The + methodology used was the same for all tests: + </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>Latency test: at less than saturation, measure how + long a call to Logger.log takes. + Pause for 10 microseconds * threadCount between measurements. + Repeat this 5 million times, and measure average latency, + latency of 99% of observations and 99.99% of observations.</li> + <li>Throughput test: measure how long it takes to log 256 * + 1024 / threadCount messages of 500 characters.</li> + </ul> + <h4>Logging Throughput</h4> + <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> + <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>Log4j2: Loggers all asynchronous</td> + <td align="right">1,655,952</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>Log4j2: Loggers mixed sync/async</td> + <td align="right">534,592</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>Log4j2: Async Appender</td> + <td align="right">1,091,563</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,336,667</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">2,231,044</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>Log4j2: 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> + <caption align="top">Throughput per thread in messages/second + </caption> + </table> + <p></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> + <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>Log4j2: 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>Log4j2: 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>Log4j2: 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>Log4j2: 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> + <caption align="top">Throughput per thread in messages/second + </caption> + </table> + <p> + In the above two environments, with the + default settings (SystemClock and SleepingWaitStrategy), + asynchronous logging + processes 6 - 68 times the number of log events in the same time + as synchronous logging. These numbers may also give you an + idea of the performance trade-off when choosing between + <a href="#AllAsync">All Async</a> and the more flexible + <a href="#MixedSync-Async">Mixed Async</a> logging. + </p> + <p>Note that the numbers above are throughput <i>per thread</i>. + The graph below shows the total throughput of all threads together. + <img src="../images/async-throughput-comparison.png" /></p> + + <h4>Throughput of Logging With Location (includeLocation="true")</h4> + <p>On Solaris 10 (64bit) with JDK1.7.0_06, 4-core Xeon X5570 dual CPU + @2.93Ghz with hyperthreading switched off (8 virtual cores):</p> + <table> + <tr> + <th>Logger</th> + <th>1 thread</th> + <th>2 threads</th> + <th>4 threads</th> + <th>8 threads</th> + </tr> + <tr> + <td>Loggers all asynchronous</td> + <td align="right">75,862</td> + <td align="right">88,775</td> + <td align="right">80,240</td> + <td align="right">68,077</td> + </tr> + <tr> + <td>Loggers mixed sync/async</td> + <td align="right">61,993</td> + <td align="right">66,164</td> + <td align="right">55,735</td> + <td align="right">52,843</td> + </tr> + <tr> + <td>Async Appender</td> + <td align="right">47,033</td> + <td align="right">52,426</td> + <td align="right">50,882</td> + <td align="right">36,905</td> + </tr> + <tr> + <td>Synchronous</td> + <td align="right">31,054</td> + <td align="right">33,175</td> + <td align="right">29,791</td> + <td align="right">23,628</td> + </tr> + <caption align="top">Throughput in log messages/second + per thread</caption> + </table> + <p>As expected, logging location information + has a large performance impact. Asynchronous loggers are 4 - 20 + times slower, while synchronous loggers are 1.3 - 5 times slower. + However, if you do need location information, + asynchronous logging will still be faster than synchronous logging.</p> + + <a name="Latency" /> + <h4>Latency</h4> + <p>The latency comparison below is done by logging at + less than saturation, measuring how long a call to Logger.log + takes to return. After each call to Logger.log, the test waits + for 10 microseconds * threadCount before continuing. + Each thread logs 5 million messages. + </p> + <p> + <img src="../images/async-average-latency.png" /> + </p> + <p> + The scale of the latency comparison graphs is logarithmic, not linear. + That makes it a bit difficult to see, but the average latency of + asynchronous loggers is half to one third of the latency of + ArrayBlockingQueue-based asynchronous appenders in scenarios + up to 8 threads. With more threads, the average latency of + asynchronous appenders is orders of magnitude larger than + asynchronous loggers. + </p> + <p> + Applications interested in low latency often care not only about + average latency, but also about worst-case latency. + The graph below shows that asynchronous loggers also do + better when comparing the maximum latency of 99.99% of + observations with other logging methods. + The worst case latency of asynchronous loggers remains more or + less the same (around 10-20 microseconds) in multi-threaded scenarios where + ArrayBlockingQueue-based asynchronous appenders have more outliers + with latencies of over 100 milliseconds per call to Logger.log. + </p> + <p> + <img src="../images/async-max-latency-99.99pct.png" /> + </p> + + <a name="FastFileAppenderPerformance" /> + <h4>FileAppender vs. FastFileAppender</h4> + <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> + <tr> + <th>Appender</th> + <th>1 thread</th> + <th>2 threads</th> + <th>4 threads</th> + <th>8 threads</th> + </tr> + <tr> + <td>FastFileAppender</td> + <td align="right">250,438</td> + <td align="right">169,939</td> + <td align="right">109,074</td> + <td align="right">58,845</td> + </tr> + <tr> + <td>FileAppender</td> + <td align="right">186,695</td> + <td align="right">118,587</td> + <td align="right">57,012</td> + <td align="right">28,846</td> + </tr> + <tr> + <td>RollingFastFileAppender</td> + <td align="right">104,254</td> + <td align="right">39,345</td> + <td align="right">16,971</td> + <td align="right">9,465</td> + </tr> + <tr> + <td>RollingFileAppender</td> + <td align="right">182,518</td> + <td align="right">114,690</td> + <td align="right">55,147</td> + <td align="right">28,153</td> + </tr> + <caption align="top">Throughput per thread in operations/second + </caption> + </table> + <p>On Solaris 10 (64bit) with JDK1.7.0_06, 4-core Xeon X5570 CPU + @2.93GHz with hyperthreading switched on (8 virtual cores):</p> + <table> + <tr> + <th>Appender</th> + <th>1 thread</th> + <th>2 threads</th> + <th>4 threads</th> + <th>8 threads</th> + </tr> + <tr> + <td>FastFileAppender</td> + <td align="right">240,760</td> + <td align="right">128,713</td> + <td align="right">66,555</td> + <td align="right">30,544</td> + </tr> + <tr> + <td>FileAppender</td> + <td align="right">172,517</td> + <td align="right">106,587</td> + <td align="right">55,885</td> + <td align="right">25,675</td> + </tr> + <tr> + <td>RollingFastFileAppender</td> + <td align="right">78,715</td> + <td align="right">31,426</td> + <td align="right">17,881</td> + <td align="right">8,727</td> + </tr> + <tr> + <td>RollingFileAppender</td> + <td align="right">186,422</td> + <td align="right">97,737</td> + <td align="right">55,766</td> + <td align="right">25,097</td> + </tr> + <caption align="top">Throughput per thread in operations/second + </caption> + </table> + </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> + <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> + <caption align="top">Throughput in log messages/second per thread</caption> + </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> \ No newline at end of file
