You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rp...@apache.org on 2016/05/04 15:44:56 UTC
[1/2] logging-log4j2 git commit: LOG4J2-1297 small improvements
Repository: logging-log4j2
Updated Branches:
refs/heads/master 247537fc3 -> 0ba569c52
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/master
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>
[2/2] logging-log4j2 git commit: LOG4J2-1179 small improvements
Posted by rp...@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/master
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.