You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rg...@apache.org on 2013/04/01 05:51:23 UTC
svn commit: r1463078 [4/4] - in /logging/log4j/log4j2/trunk: ./
core/src/main/java/org/apache/logging/log4j/core/
core/src/main/java/org/apache/logging/log4j/core/appender/
core/src/main/java/org/apache/logging/log4j/core/config/
core/src/main/java/org...
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="remkop@yahoo.com">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