You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by mi...@apache.org on 2016/05/04 16:20:49 UTC
[1/5] logging-log4j2 git commit: LOG4J2-1179 edited text
Repository: logging-log4j2
Updated Branches:
refs/heads/LOG4J2-1347 0fb4ed116 -> 17f984e4a
LOG4J2-1179 edited text
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/e629aa00
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/e629aa00
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/e629aa00
Branch: refs/heads/LOG4J2-1347
Commit: e629aa001842bdb38f76ab01d5a4d0caee940819
Parents: c5669e4
Author: rpopma <rp...@apache.org>
Authored: Wed May 4 22:10:24 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Wed May 4 22:10:24 2016 +0900
----------------------------------------------------------------------
src/site/xdoc/performance.xml | 99 +++++++++++++++++++++++---------------
1 file changed, 60 insertions(+), 39 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/e629aa00/src/site/xdoc/performance.xml
----------------------------------------------------------------------
diff --git a/src/site/xdoc/performance.xml b/src/site/xdoc/performance.xml
index 16ac240..55100aa 100644
--- a/src/site/xdoc/performance.xml
+++ b/src/site/xdoc/performance.xml
@@ -41,52 +41,70 @@
(java.util.logging "JUL", Logback, Log4j 1.2 and Log4j 2.6),
and document some performance trade-offs for Log4j 2 functionality.
</p>
- <h2>Benchmarks</h2>
+ <h3>Benchmarks</h3>
<p>Performance can mean different things to different people. Common terms in this context are
throughput and latency: <em>Throughput</em> is a measure of capacity and can be expressed in a single number:
how many messages can be logged in a certain period of time.
<em>Response time latency</em> is how long it takes to log a message.
This cannot be expressed in a single number because each measurement has its own
response time and we are often most interested in the outliers: how many there were and how large they were.</p>
- <p>We will measure and compare three performance indicators: </p>
+ <p>When evaluating a logging framework's performance these may be useful questions to ask:</p>
<ul>
- <li><b>Peak throughput</b> is the maximum throughput measured over a short period of time.
- This number is useful for systems that need to log bursts of messages followed by periods of
- relative quiet. Many systems that react to external events behave like this,
- but for systems that need to log a lot at a constant high rate (for example, batch jobs)
+ <li>What is its <b>peak throughput</b>?
+ Many systems that react to external events need to log bursts of messages followed by periods of
+ relative quiet.
+ This number is the maximum throughput measured over a short period of time and gives some idea
+ of how well the logging library deals with bursts.
+ For systems that need to log a lot at a constant high rate (for example, batch jobs)
this is less likely to be a useful measure of performance.</li>
- <li><b>Maximum sustained throughput</b> is the throughput averaged over a long time.
+ <li>What is the <b>maximum sustained throughput</b>? This is the throughput averaged over a long time.
This is a useful measure of the "upper limit" of the capacity of the logging library.
It is not recommended that reactive applications actually log at this rate since under this load
they will likely experience jitter and large response time spikes.</li>
- <li><p>
- <b>Response time</b> is the total amount of time it takes to log a message and is the sum of the
- service time and wait time. The service time is the time it takes to do the work to log the message.
+ <li><p>What is its <b>response time</b> behaviour under various loads?
+ Response time is the total amount of time it takes to log a message and is the sum of the
+ service time and wait time.
+ The <b>service time</b> is the time it takes to do the work to log the message.
As the workload increases, the service time often varies little:
to do X amount of work it always takes X amount of time.
- The wait time is how long the request had to wait in a queue before being serviced.
+ The <b>wait time</b> is how long the request had to wait in a queue before being serviced.
<em>As the workload increases, wait time often grows to many times the service time.</em>
</p>
- <p>
- What is often measured and reported as <em>latency</em> is actually <em>service time</em>,
- which unfortunately hides the wait time.
- The below graph shows response time and service time of the same system under a load of 100,000 messages
- per second. Out of 25 million measurements, only ~50 are more than 200 microseconds, less than 0.001%.
- In a service time-only graph this would hardly be visible.
- However, the wait time adds up and the response time graph shows that in reality many more events are impacted
- by these delays.
- </p>
- <p><img src="images/ResponseTimeVsServiceTimeAsyncLoggers.png" /></p>
- <p>
- To learn more, watch Gil Tene's
- <a href="http://www.infoq.com/presentations/latency-response-time">How NOT to measure latency</a>
- (and prepare to be shocked).
- </p>
</li>
</ul>
- <h2>Logging Library Performance Comparison</h2>
+ <table>
+ <tr><td>
+ <h5>Sidebar: Why Care About Response Time Latency?</h5>
+ <table border="0" style="border: 0">
+ <tr style="border: 0">
+ <td width="50%" style="border: 0"><p>
+ What is often measured and reported as <em>latency</em> is actually <em>service time</em>,
+ which unfortunately hides the wait time. This may present results that are more optimistic than what
+ users experience.
+ </p><p>
+ The graph on the right illustrates how much more optimistic service time is than response time.
+ The graph shows response time and service time for the same system under a load of 100,000 messages
+ per second. Out of 25 million measurements, only ~50 are more than 21 microseconds, less than 0.001%.
+ In a service time-only graph this would hardly be visible.
+ However, the wait time adds up and the response time graph shows that in reality many more events are
+ impacted by these delays.
+ </p>
+ <p>
+ To learn more, watch Gil Tene's eye-opening presentation
+ <a href="http://www.infoq.com/presentations/latency-response-time">How NOT to measure
+ latency</a>..
+ </p>
+ </td>
+ <td width="50%" style="border: 0"><a href="images/ResponseTimeVsServiceTimeAsyncLoggers.png"><img
+ src="images/ResponseTimeVsServiceTimeAsyncLoggers.png" width="480" height="288"/></a>
+ </td>
+ </tr>
+ </table>
+ </td></tr>
+ </table>
+ <h3>Logging Library Performance Comparison</h3>
- <h3>Asynchronous Logging - Peak Throughput Comparison</h3>
+ <h4>Asynchronous Logging - Peak Throughput Comparison</h4>
<p>Asynchronous Logging is useful to deal with bursts of events. How this works is that
a minimum amount of work is done by the application thread to capture all required information in a log event,
and this log event is then put on a queue for later processing by a background thread.
@@ -100,19 +118,22 @@
With a blocking queue, multi-threaded applications often experience lock contention when trying to
enqueue the log event.
</p>
- <p>The graph below illustrates the difference in peak throughput.
+ <p>The graph below illustrates the difference a lock-free data structure can make to peak throughput.
For details, see the <a href="manual/async.html">Async
Loggers</a> manual page.</p>
<p><img src="images/async-throughput-comparison.png" alt="Peak throughput comparison" />
</p>
<p>The results above were obtained with log4j-2.0-beta5, disruptor-3.0.0.beta3,
- log4j-1.2.17 and logback-1.0.10.
+ log4j-1.2.17 and logback-1.0.10. The PerfTest, MTPerfTest and PerfTestDriver
+ classes that generated these results can be found in the Log4j 2 unit test source directory.
</p>
- <h3>Synchronous File Logging - Sustained Throughput Comparison</h3>
- <p>The graph below compares Log4j 2.6 in garbage-free mode to Log4j 2.6 "classic" mode (which allocates
+ <h4>Synchronous File Logging - Sustained Throughput Comparison</h4>
+ <p>Here we look at the maximum sustained throughput of logging to a file.
+ The graph below compares Log4j 2.6 in garbage-free mode to Log4j 2.6 "classic" mode (which allocates
temporary objects for every logging call), Log4j 1.2.17, Logback 1.1.7 and
- Java util logging (JUL) on Oracle Java 1.8.0_45. The Log4j 2.x results use the RandomAccessFile appender.
+ Java util logging (JUL) on Oracle Java 1.8.0_45.</p>
+ <p>The Log4j 2.x results are for the RandomAccessFile appender.
Log4j 1.2.17, Logback and JUL use their respective File appenders. ImmediateFlush was set to <tt>false</tt> for all
loggers that support this. The JUL results are for the <tt>XMLFormatter</tt> (which in our measurements was
about twice as fast as the <tt>SimpleFormatter</tt>).</p>
@@ -123,12 +144,12 @@
<a href="http://openjdk.java.net/projects/code-tools/jmh/">JMH</a> Java benchmark harness.
See the <tt>org.apache.logging.log4j.perf.jmh.FileAppenderBenchmark</tt> source code in the log4j-perf module.</p>
- <h3>Synchronous File Logging - Response Time Comparison</h3>
+ <h4>Synchronous File Logging - Response Time Comparison</h4>
- <h3>Synchronous Socket Sustained Throughput Comparison</h3>
- <h3>Synchronous Syslog Sustained Throughput Comparison</h3>
+ <h4>Synchronous Socket Sustained Throughput Comparison</h4>
+ <h4>Synchronous Syslog Sustained Throughput Comparison</h4>
- <h2>Trade-offs</h2>
+ <h3>Trade-offs</h3>
<!--
<p>The user should be aware of the following performance issues.</p>
@@ -241,7 +262,7 @@
Log4j 2's fine-grained filtering capabilities.
</p>
-->
- <h3>Advanced Filtering</h3>
+ <h4>Advanced Filtering</h4>
<p>
Both Logback and Log4j 2 support advanced filtering. Logback calls them TurboFilters while
Log4j 2 has a single Filter object. Advanced filtering provides the capability to filter
@@ -299,7 +320,7 @@
</tr>
</table>
- <h3>Client vs Server</h3>
+ <h4>Client vs Server</h4>
<p>
Java supports a "client" and a "server" mode of operation. By default, applications that are
run in Java 5 on machines with 2 CPUs or more and 2GB of memory or more on operating systems
[4/5] logging-log4j2 git commit: LOG4J2-1179 small improvements
Posted by mi...@apache.org.
LOG4J2-1179 small improvements
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/0ba569c5
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/0ba569c5
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/0ba569c5
Branch: refs/heads/LOG4J2-1347
Commit: 0ba569c52d88385636a44af0ae272a8534454de8
Parents: 6eb9c78
Author: rpopma <rp...@apache.org>
Authored: Thu May 5 00:45:17 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Thu May 5 00:45:17 2016 +0900
----------------------------------------------------------------------
src/site/xdoc/performance.xml | 40 +++++++++++++++++++++++++-------------
1 file changed, 26 insertions(+), 14 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/0ba569c5/src/site/xdoc/performance.xml
----------------------------------------------------------------------
diff --git a/src/site/xdoc/performance.xml b/src/site/xdoc/performance.xml
index 55100aa..947e211 100644
--- a/src/site/xdoc/performance.xml
+++ b/src/site/xdoc/performance.xml
@@ -84,7 +84,7 @@
</p><p>
The graph on the right illustrates how much more optimistic service time is than response time.
The graph shows response time and service time for the same system under a load of 100,000 messages
- per second. Out of 25 million measurements, only ~50 are more than 21 microseconds, less than 0.001%.
+ per second. Out of 24 million measurements, only ~50 are more than 250 microseconds, less than 0.001%.
In a service time-only graph this would hardly be visible.
However, the wait time adds up and the response time graph shows that in reality many more events are
impacted by these delays.
@@ -92,7 +92,7 @@
<p>
To learn more, watch Gil Tene's eye-opening presentation
<a href="http://www.infoq.com/presentations/latency-response-time">How NOT to measure
- latency</a>..
+ latency</a>.
</p>
</td>
<td width="50%" style="border: 0"><a href="images/ResponseTimeVsServiceTimeAsyncLoggers.png"><img
@@ -105,7 +105,7 @@
<h3>Logging Library Performance Comparison</h3>
<h4>Asynchronous Logging - Peak Throughput Comparison</h4>
- <p>Asynchronous Logging is useful to deal with bursts of events. How this works is that
+ <p>Asynchronous logging is useful to deal with bursts of events. How this works is that
a minimum amount of work is done by the application thread to capture all required information in a log event,
and this log event is then put on a queue for later processing by a background thread.
As long as the queue is sized large enough, the application threads should be able to spend
@@ -118,8 +118,16 @@
With a blocking queue, multi-threaded applications often experience lock contention when trying to
enqueue the log event.
</p>
- <p>The graph below illustrates the difference a lock-free data structure can make to peak throughput.
- For details, see the <a href="manual/async.html">Async
+ <p>The graph below illustrates the difference a lock-free data structure can make to throughput
+ in multi-threaded scenarios. <em>Log4j 2 scales better with the number of threads:
+ an application with more threads can log more. The other logging libraries suffer
+ from lock contention and total throughput stays constant or drops when more threads are logging.
+ This means that with the other logging libraries, each individual thread will be able to log less.</em></p>
+ <p>Bear in mind that this is <em>peak</em> throughput: Log4j 2 gives better throughput up to a point, but
+ once the queue is full, the appender thread needs to wait until a slot becomes available in the queue,
+ and throughput will drop to the maximum sustained throughput of the underlying appenders at best.
+ </p>
+ <p>For details, see the <a href="manual/async.html">Async
Loggers</a> manual page.</p>
<p><img src="images/async-throughput-comparison.png" alt="Peak throughput comparison" />
</p>
@@ -130,15 +138,19 @@
<h4>Synchronous File Logging - Sustained Throughput Comparison</h4>
<p>Here we look at the maximum sustained throughput of logging to a file.
- The graph below compares Log4j 2.6 in garbage-free mode to Log4j 2.6 "classic" mode (which allocates
- temporary objects for every logging call), Log4j 1.2.17, Logback 1.1.7 and
- Java util logging (JUL) on Oracle Java 1.8.0_45.</p>
- <p>The Log4j 2.x results are for the RandomAccessFile appender.
- Log4j 1.2.17, Logback and JUL use their respective File appenders. ImmediateFlush was set to <tt>false</tt> for all
- loggers that support this. The JUL results are for the <tt>XMLFormatter</tt> (which in our measurements was
- about twice as fast as the <tt>SimpleFormatter</tt>).</p>
- <p>Our test results suggest that the throughput of the other logging frameworks we tested
- will rapidly decline in multi-threaded applications.</p>
+ This is is synchronous logging, so there is no background thread; the message formatting and disk I/O
+ takes place in the application thread that calls the logger. </p>
+ <p>The graph below compares Log4j 2.6's RandomAccessFile appender
+ to the respective File appenders of Log4j 1.2.17, Logback 1.1.7 and
+ Java util logging (JUL) on Oracle Java 1.8.0_45. ImmediateFlush was set to false for all
+ loggers that support this. The JUL results are for the XMLFormatter (which in our measurements was
+ about twice as fast as the SimpleFormatter).</p>
+ <p><em>Log4j 2's sustained throughput drops a little when more threads are logging simultaneously,
+ but its fine-grained locking pays off and throughput stays relatively high.
+ The other logging frameworks' throughput drops dramatically in multi-threaded applications:
+ Log4j 1.2 has 1/4th of its single-threaded capacity,
+ Logback has 1/10th of its single-threaded capacity, and JUL steadily drops from 1/4th to 1/10th of its
+ single-threaded throughput as more threads are added.</em></p>
<p><img src="images/SyncThroughputLoggerComparisonLinux.png" /></p>
<p>The synchronous logging throughput results above are obtained with the
<a href="http://openjdk.java.net/projects/code-tools/jmh/">JMH</a> Java benchmark harness.
[5/5] logging-log4j2 git commit: Merge branch 'master' into
LOG4J2-1347
Posted by mi...@apache.org.
Merge branch 'master' into LOG4J2-1347
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/17f984e4
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/17f984e4
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/17f984e4
Branch: refs/heads/LOG4J2-1347
Commit: 17f984e4a391db16df4fab0622cbf22459429377
Parents: 0fb4ed1 0ba569c
Author: Mikael St�ldal <mi...@magine.com>
Authored: Wed May 4 18:20:40 2016 +0200
Committer: Mikael St�ldal <mi...@magine.com>
Committed: Wed May 4 18:20:40 2016 +0200
----------------------------------------------------------------------
src/site/xdoc/manual/garbagefree.xml | 8 +-
src/site/xdoc/performance.xml | 127 +++++++++++++++++++-----------
2 files changed, 85 insertions(+), 50 deletions(-)
----------------------------------------------------------------------
[2/5] logging-log4j2 git commit: Merge remote-tracking branch
'origin/master'
Posted by mi...@apache.org.
Merge remote-tracking branch 'origin/master'
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/247537fc
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/247537fc
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/247537fc
Branch: refs/heads/LOG4J2-1347
Commit: 247537fc34fb3b2d7ed10ec4a0a3f9ddd6c1c8a1
Parents: e629aa0 acce51a
Author: rpopma <rp...@apache.org>
Authored: Wed May 4 22:10:36 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Wed May 4 22:10:36 2016 +0900
----------------------------------------------------------------------
src/changes/changes.xml | 3 +++
src/site/xdoc/runtime-dependencies.xml | 3 ++-
2 files changed, 5 insertions(+), 1 deletion(-)
----------------------------------------------------------------------
[3/5] logging-log4j2 git commit: LOG4J2-1297 small improvements
Posted by mi...@apache.org.
LOG4J2-1297 small improvements
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/6eb9c787
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/6eb9c787
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/6eb9c787
Branch: refs/heads/LOG4J2-1347
Commit: 6eb9c78772d0b41a16d236523385484098743c8c
Parents: 247537f
Author: rpopma <rp...@apache.org>
Authored: Thu May 5 00:45:03 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Thu May 5 00:45:03 2016 +0900
----------------------------------------------------------------------
src/site/xdoc/manual/garbagefree.xml | 8 +++++---
1 file changed, 5 insertions(+), 3 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/6eb9c787/src/site/xdoc/manual/garbagefree.xml
----------------------------------------------------------------------
diff --git a/src/site/xdoc/manual/garbagefree.xml b/src/site/xdoc/manual/garbagefree.xml
index e552f15..1aab709 100644
--- a/src/site/xdoc/manual/garbagefree.xml
+++ b/src/site/xdoc/manual/garbagefree.xml
@@ -382,10 +382,9 @@ public void garbageFree() {
</p>
-->
<table>
- <tr><td>I encourage everyone to take the red pill and watch Gil Tene's presentation
+ <tr><td>For more information on this topic please watch Gil Tene's eye-opening presentation
<a href="http://www.infoq.com/presentations/latency-response-time">How NOT to measure latency</a>.
- Be warned, this talk is about removing the wool from your eyes.
- You will learn a lot but may not always like what you've learnt.</td></tr>
+ </td></tr>
</table>
<p>The response time test results below were all derived from running the ResponseTimeTest class
which can be found in the Log4j 2 unit test source directory. If you want to run these tests yourself,
@@ -393,12 +392,15 @@ public void garbageFree() {
</p>
<ul>
<li>-Xms1G -Xmx1G (prevent heap resizing during the test)</li>
+ <!--
<li>-XX:+UnlockDiagnosticVMOptions -XX:GuaranteedSafepointInterval=500000 (by default Hotspot schedules a
safepoint pause every second. Reduce jitter by postponing this for the duration of the test.)</li>
+ -->
<li>-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
-DAsyncLogger.WaitStrategy=busyspin (to use Async Loggers. The BusySpin wait strategy reduces some jitter.)</li>
<li><b>classic mode: </b>-Dlog4j2.enable.threadlocals=false -Dlog4j2.enable.direct.encoders=false<br />
<b>garbage-free mode: </b>-Dlog4j2.enable.threadlocals=true -Dlog4j2.enable.direct.encoders=true</li>
+ <li>-XX:CompileCommand=dontinline,org.apache.logging.log4j.core.async.perftest.NoOpIdleStrategy::idle</li>
<li>-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime (to eyeball GC and safepoint pauses)</li>
</ul>