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/04/29 16:32:25 UTC
[1/6] logging-log4j2 git commit: Add link to homepage in readme
Repository: logging-log4j2
Updated Branches:
refs/heads/LOG4J2-1347 1b134cf3c -> d9f2a3447
Add link to homepage in readme
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/61bfad23
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/61bfad23
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/61bfad23
Branch: refs/heads/LOG4J2-1347
Commit: 61bfad23eb216e488e3803e15e2f5e4c00f67ba7
Parents: 7c36904
Author: Matt Sicker <bo...@gmail.com>
Authored: Wed Apr 27 13:15:05 2016 -0500
Committer: Matt Sicker <bo...@gmail.com>
Committed: Wed Apr 27 13:15:05 2016 -0500
----------------------------------------------------------------------
README.md | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/61bfad23/README.md
----------------------------------------------------------------------
diff --git a/README.md b/README.md
index de73e82..8757d1b 100644
--- a/README.md
+++ b/README.md
@@ -1,4 +1,4 @@
-# Apache Log4j 2
+# [Apache Log4j 2](http://logging.apache.org/log4j/2.x/)
Apache Log4j 2 is an upgrade to Log4j that provides significant improvements over its predecessor, Log4j 1.x,
and provides many of the improvements available in Logback while fixing some inherent problems in Logback's architecture.
[4/6] 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/0e815dd9
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/0e815dd9
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/0e815dd9
Branch: refs/heads/LOG4J2-1347
Commit: 0e815dd956b78a719677637e4ea6b2d10ca068f8
Parents: f2f0faa 4d5c162
Author: rpopma <rp...@apache.org>
Authored: Fri Apr 29 01:37:50 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Fri Apr 29 01:37:50 2016 +0900
----------------------------------------------------------------------
README.md | 5 ++++-
src/site/xdoc/articles.xml | 8 ++++++++
src/site/xdoc/manual/appenders.xml | 4 ++--
src/site/xdoc/manual/markers.xml | 5 +++--
4 files changed, 17 insertions(+), 5 deletions(-)
----------------------------------------------------------------------
[6/6] 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/d9f2a344
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/d9f2a344
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/d9f2a344
Branch: refs/heads/LOG4J2-1347
Commit: d9f2a3447b1b267dbdc5f8d92e16c5d34c21edd2
Parents: 1b134cf 21a9a13
Author: Mikael Ståldal <mi...@magine.com>
Authored: Fri Apr 29 16:32:15 2016 +0200
Committer: Mikael Ståldal <mi...@magine.com>
Committed: Fri Apr 29 16:32:15 2016 +0200
----------------------------------------------------------------------
README.md | 2 +-
.../core/async/perftest/ResponseTimeTest.java | 72 +++++++++++------
.../ResponseTimeAsyncClassicVsGcFree-label.png | Bin 0 -> 31517 bytes
.../images/ResponseTimeSyncClassicVsGcFree.png | Bin 0 -> 38428 bytes
src/site/xdoc/manual/appenders.xml | 4 +-
src/site/xdoc/manual/garbagefree.xml | 81 ++++++++++++++++---
6 files changed, 119 insertions(+), 40 deletions(-)
----------------------------------------------------------------------
[2/6] logging-log4j2 git commit: Fix typos in appenders manual
Posted by mi...@apache.org.
Fix typos in appenders manual
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/4d5c1620
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/4d5c1620
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/4d5c1620
Branch: refs/heads/LOG4J2-1347
Commit: 4d5c162032f74ec3e6d4495a1ed3344e6a3f85b8
Parents: 61bfad2
Author: Matt Sicker <bo...@gmail.com>
Authored: Wed Apr 27 13:29:57 2016 -0500
Committer: Matt Sicker <bo...@gmail.com>
Committed: Wed Apr 27 13:29:57 2016 -0500
----------------------------------------------------------------------
src/site/xdoc/manual/appenders.xml | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/4d5c1620/src/site/xdoc/manual/appenders.xml
----------------------------------------------------------------------
diff --git a/src/site/xdoc/manual/appenders.xml b/src/site/xdoc/manual/appenders.xml
index 9dcb0c2..7290037 100644
--- a/src/site/xdoc/manual/appenders.xml
+++ b/src/site/xdoc/manual/appenders.xml
@@ -2232,7 +2232,7 @@ public class JpaLogEntity extends AbstractLogEventWrapperEntity {
<h5>TimeBased Triggering Policy</h5>
<p>
The <code>TimeBasedTriggeringPolicy</code> causes a rollover once the date/time pattern no longer
- applies to the active file. This policy accepts an <code>increment</code> attribute which indicates how
+ applies to the active file. This policy accepts an <code>interval</code> attribute which indicates how
frequently the rollover should occur based on the time pattern and a <code>modulate</code> boolean
attribute.
</p>
@@ -2256,7 +2256,7 @@ public class JpaLogEntity extends AbstractLogEventWrapperEntity {
<td>boolean</td>
<td>Indicates whether the interval should be adjusted to cause the next rollover to occur on
the interval boundary. For example, if the item is hours, the current hour is 3 am and the
- interval is 4 then then the first rollover will occur at 4 am and then next ones will occur at
+ interval is 4 then the first rollover will occur at 4 am and then next ones will occur at
8 am, noon, 4pm, etc.</td>
</tr>
</table>
[3/6] logging-log4j2 git commit: LOG4J2-1297 prepare all threads in
advance, use CountDownLatch to start real test after warmup done;
don't call System.gc() for garbage-free test
Posted by mi...@apache.org.
LOG4J2-1297 prepare all threads in advance, use CountDownLatch to start real test after warmup done; don't call System.gc() for garbage-free test
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/f2f0faa9
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/f2f0faa9
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/f2f0faa9
Branch: refs/heads/LOG4J2-1347
Commit: f2f0faa91655e8394ceaf2a3481e33cd55c9f935
Parents: 370d95f
Author: rpopma <rp...@apache.org>
Authored: Fri Apr 29 01:37:26 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Fri Apr 29 01:37:26 2016 +0900
----------------------------------------------------------------------
.../core/async/perftest/ResponseTimeTest.java | 72 +++++++++++++-------
1 file changed, 46 insertions(+), 26 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/f2f0faa9/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java
index c4c51d2..7f01cdf 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java
@@ -16,6 +16,14 @@
*/
package org.apache.logging.log4j.core.async.perftest;
+import org.HdrHistogram.Histogram;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.async.DefaultAsyncEventRouter;
+import org.apache.logging.log4j.core.async.EventRoute;
+import org.apache.logging.log4j.core.util.Constants;
+
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.PrintStream;
@@ -24,24 +32,18 @@ import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
-import org.HdrHistogram.Histogram;
-import org.apache.logging.log4j.Level;
-import org.apache.logging.log4j.LogManager;
-import org.apache.logging.log4j.Logger;
-import org.apache.logging.log4j.core.async.AsyncLoggerContextSelector;
-import org.apache.logging.log4j.core.async.DefaultAsyncEventRouter;
-import org.apache.logging.log4j.core.async.EventRoute;
-
/**
* Latency test showing both service time and response time.
* <p>Service time = time to perform the desired operation, response time = service time + queueing time.</p>
*/
// RUN
// java -XX:+UnlockDiagnosticVMOptions -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution
-// -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime
+// -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:GuaranteedSafepointInterval=500000
// -XX:CompileCommand=dontinline,org.apache.logging.log4j.core.async.perftest.NoOpIdleStrategy::idle
// -cp HdrHistogram-2.1.8.jar:disruptor-3.3.4.jar:log4j-api-2.6-SNAPSHOT.jar:log4j-core-2.6-SNAPSHOT.jar:log4j-core-2.6-SNAPSHOT-tests.jar
-// -DAsyncLogger.WaitStrategy=yield org.apache.logging.log4j.core.async.perftest.ResponseTimeTest 1 50000
+// -DAsyncLogger.WaitStrategy=busyspin -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
+// -Dlog4j2.enable.threadlocals=true -Dlog4j2.enable.direct.encoders=true
+// -Xms1G -Xmx1G org.apache.logging.log4j.core.async.perftest.ResponseTimeTest 1 100000
//
// RUN recording in Java Flight Recorder:
// %JAVA_HOME%\bin\java -XX:+UnlockCommercialFeatures -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -XX:+FlightRecorder -XX:StartFlightRecording=duration=10m,filename=replayStats-2.6-latency.jfr -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:CompileCommand=dontinline,org.apache.logging.log4j.core.async.perftest.NoOpIdleStrategy::idle -DAsyncLogger.WaitStrategy=yield -Dorg.apache.logging.log4j.simplelog.StatusLogger.level=TRACE -cp .;HdrHistogram-2.1.8.jar;disruptor-3.3.4.jar;log4j-api-2.6-SNAPSHOT.jar;log4j-core-2.6-SNAPSHOT.jar;log4j-core-2.6-SNAPSHOT-tests.jar org.apache.logging.log4j.core.async.perftest.ResponseTimeTest 1 50000
@@ -59,8 +61,11 @@ public class ResponseTimeTest {
// print to console if ringbuffer is full
System.setProperty("log4j2.AsyncEventRouter", PrintingDefaultAsyncEventRouter.class.getName());
System.setProperty("AsyncLogger.RingBufferSize", String.valueOf(256 * 1024));
- System.setProperty("Log4jContextSelector", AsyncLoggerContextSelector.class.getName());
+ //System.setProperty("Log4jContextSelector", AsyncLoggerContextSelector.class.getName());
System.setProperty("log4j.configurationFile", "perf3PlainNoLoc.xml");
+ if (System.getProperty("AsyncLogger.WaitStrategy") == null) {
+ System.setProperty("AsyncLogger.WaitStrategy", "Yield");
+ }
Logger logger = LogManager.getLogger();
logger.info("Starting..."); // initializes Log4j
@@ -80,20 +85,32 @@ public class ResponseTimeTest {
List<Histogram> warmupResponseTmHistograms = new ArrayList<>(threadCount);
final int WARMUP_COUNT = 50000 / threadCount;
- runLatencyTest(logger, WARMUP_DURATION_MILLIS, WARMUP_COUNT, loadMessagesPerSec, idleStrategy,
- warmupServiceTmHistograms, warmupResponseTmHistograms, threadCount);
- System.out.println("Warmup done.");
- Thread.sleep(1000);
+ final CountDownLatch warmupLatch = new CountDownLatch(threadCount + 1);
+ Thread[] warmup = createLatencyTest(logger, WARMUP_DURATION_MILLIS, WARMUP_COUNT, warmupLatch, loadMessagesPerSec,
+ idleStrategy, warmupServiceTmHistograms, warmupResponseTmHistograms, threadCount);
- // Actual test: run as many iterations of 5,000,000 calls to logger.log as we can in 4 minutes.
- long start = System.currentTimeMillis();
List<Histogram> serviceTmHistograms = new ArrayList<>(threadCount);
List<Histogram> responseTmHistograms = new ArrayList<>(threadCount);
final long TEST_DURATION_MILLIS = TimeUnit.MINUTES.toMillis(4);
- final int COUNT = (5000 * 1000) / threadCount;
- runLatencyTest(logger, TEST_DURATION_MILLIS, COUNT, loadMessagesPerSec, idleStrategy, serviceTmHistograms,
- responseTmHistograms, threadCount);
+ final int COUNT = (1000 * 1000) / threadCount;
+ final CountDownLatch actualLatch = new CountDownLatch(threadCount + 1);
+ Thread[] actual = createLatencyTest(logger, TEST_DURATION_MILLIS, COUNT, actualLatch, loadMessagesPerSec, idleStrategy,
+ serviceTmHistograms, responseTmHistograms, threadCount);
+
+ warmupLatch.countDown();
+ await(warmup);
+ System.out.println("Warmup done.");
+ if (!Constants.ENABLE_DIRECT_ENCODERS || !Constants.ENABLE_THREADLOCALS) {
+ System.gc();
+ Thread.sleep(5000);
+ }
+ System.out.println("Starting measured run.");
+
+ // Actual test: run as many iterations of 5,000,000 calls to logger.log as we can in 4 minutes.
+ long start = System.currentTimeMillis();
+ actualLatch.countDown(); // start the actual test threads
+ await(actual);
long end = System.currentTimeMillis();
// ... and report the results
@@ -125,13 +142,12 @@ public class ResponseTimeTest {
return result;
}
- public static void runLatencyTest(final Logger logger, final long durationMillis, final int samples,
- final double loadMessagesPerSec, final IdleStrategy idleStrategy,
+ public static Thread[] createLatencyTest(final Logger logger, final long durationMillis, final int samples,
+ final CountDownLatch latch, final double loadMessagesPerSec, final IdleStrategy idleStrategy,
final List<Histogram> serviceTmHistograms, final List<Histogram> responseTmHistograms,
final int threadCount) throws InterruptedException {
final Thread[] threads = new Thread[threadCount];
- final CountDownLatch LATCH = new CountDownLatch(threadCount);
for (int i = 0; i < threadCount; i++) {
final Histogram serviceTmHist = new Histogram(TimeUnit.SECONDS.toNanos(10), 3);
final Histogram responseTmHist = new Histogram(TimeUnit.SECONDS.toNanos(10), 3);
@@ -142,9 +158,9 @@ public class ResponseTimeTest {
threads[i] = new Thread("latencytest-" + i) {
@Override
public void run() {
- LATCH.countDown();
+ latch.countDown();
try {
- LATCH.await(); // wait until all threads are ready to go
+ latch.await(); // wait until all threads are ready to go
} catch (InterruptedException e) {
interrupt();
return;
@@ -157,7 +173,11 @@ public class ResponseTimeTest {
};
threads[i].start();
}
- for (int i = 0; i < threadCount; i++) {
+ return threads;
+ }
+
+ private static void await(final Thread[] threads) throws InterruptedException {
+ for (int i = 0; i < threads.length; i++) {
threads[i].join();
}
}
[5/6] logging-log4j2 git commit: LOG4J2-1297 added latency graphs,
text on latency performance comparison
Posted by mi...@apache.org.
LOG4J2-1297 added latency graphs, text on latency performance comparison
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/21a9a137
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/21a9a137
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/21a9a137
Branch: refs/heads/LOG4J2-1347
Commit: 21a9a1371aaa03a2e028e089b4d357d94c5b428b
Parents: 0e815dd
Author: rpopma <rp...@apache.org>
Authored: Fri Apr 29 23:08:17 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Fri Apr 29 23:08:17 2016 +0900
----------------------------------------------------------------------
.../ResponseTimeAsyncClassicVsGcFree-label.png | Bin 0 -> 31517 bytes
.../images/ResponseTimeSyncClassicVsGcFree.png | Bin 0 -> 38428 bytes
src/site/xdoc/manual/garbagefree.xml | 81 ++++++++++++++++---
3 files changed, 70 insertions(+), 11 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/21a9a137/src/site/resources/images/ResponseTimeAsyncClassicVsGcFree-label.png
----------------------------------------------------------------------
diff --git a/src/site/resources/images/ResponseTimeAsyncClassicVsGcFree-label.png b/src/site/resources/images/ResponseTimeAsyncClassicVsGcFree-label.png
new file mode 100644
index 0000000..f2f1c03
Binary files /dev/null and b/src/site/resources/images/ResponseTimeAsyncClassicVsGcFree-label.png differ
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/21a9a137/src/site/resources/images/ResponseTimeSyncClassicVsGcFree.png
----------------------------------------------------------------------
diff --git a/src/site/resources/images/ResponseTimeSyncClassicVsGcFree.png b/src/site/resources/images/ResponseTimeSyncClassicVsGcFree.png
new file mode 100644
index 0000000..869acd4
Binary files /dev/null and b/src/site/resources/images/ResponseTimeSyncClassicVsGcFree.png differ
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/21a9a137/src/site/xdoc/manual/garbagefree.xml
----------------------------------------------------------------------
diff --git a/src/site/xdoc/manual/garbagefree.xml b/src/site/xdoc/manual/garbagefree.xml
index c6cf8ca..2ecfaee 100644
--- a/src/site/xdoc/manual/garbagefree.xml
+++ b/src/site/xdoc/manual/garbagefree.xml
@@ -53,7 +53,7 @@
</p>
<p>
The application was configured to use Async Loggers, a RandomAccessFile appender and a
- "%d %p %c{1.} [%t] %m %ex%n" pattern layout.
+ "%d %p %c{1.} [%t] %m %ex%n" pattern layout. (Async Loggers used the Yield WaitStrategy.)
</p>
<p>
Mission Control shows that with Log4j 2.5 this application allocates memory at a rate of about 809 MB/sec,
@@ -99,8 +99,17 @@
So while logging is not completely garbage-free for web applications yet,
the pressure on the garbage collector can still be significantly reduced.
</p>
- <table><tr><td><b>Caution:</b> as of version 2.6, a Log4j configuration containing a <tt><Properties></tt> section
+ <table><tr><td><p>
+ <b>Note 1:</b> as of version 2.6, a Log4j configuration containing a <tt><Properties></tt> section
will result in temporary objects being created during steady-state logging.
+ </p>
+ <p>
+ <b>Note 2:</b> the Async Logger Timeout wait strategy (the default) and the Block wait strategy
+ cause <tt>java.util.concurrent.locks.AbstractQueuedSynchronizer$Node</tt> objects to be created.
+ The Yield and Sleep wait strategies are garbage-free. (See
+ <a href="async.html#SysPropsAllAsync">here</a> and
+ <a href="async.html#SysPropsMixedSync-Async">here</a>.)
+ </p>
</td></tr></table>
<h4>Disabling Garbage-free Logging</h4>
<p>
@@ -112,7 +121,7 @@
objects are stored in ThreadLocal fields and reused, otherwise new
objects are created for each log event.</li>
<li><tt>log4j2.enable.direct.encoders</tt> - if "true" (the default) log events are converted to text and this
- text is converted to bytes without creating temporary objects. Caution:
+ text is converted to bytes without creating temporary objects. Note:
<em>synchronous</em> logging performance may be worse for multi-threaded applications in this mode due to
synchronization on the shared buffer. If your application is multi-threaded and logging performance
is important, consider using Async Loggers.
@@ -165,7 +174,7 @@
</tr>
<tr>
<td>%d, %date</td>
- <td>Caution: Only the predefined date formats are garbage-free: (millisecond separator may be either
+ <td>Note: Only the predefined date formats are garbage-free: (millisecond separator may be either
a comma ',' or a period '.')
<table>
<tr>
@@ -266,7 +275,7 @@
We haven't figured out a way to log exceptions and stack traces without creating temporary objects.
That is unfortunate, but you probably still want to log them when they happen.
</p>
- <table><tr><td><b>Caution:</b> patterns containing regular expressions and lookups for property substitution
+ <table><tr><td><b>Note:</b> patterns containing regular expressions and lookups for property substitution
will result in temporary objects being created during steady-state logging.
<p>
Including location information is done by walking the stacktrace of an exception, which creates temporary
@@ -327,7 +336,7 @@ public void garbageFree() {
</pre>
<table><tr><td>
<p>
- <b>Caution:</b> not all logging is garbage free. Specifically:
+ <b>Note:</b> not all logging is garbage free. Specifically:
</p>
<ul>
<li>The ThreadContext map and stack are not garbage-free yet.</li>
@@ -353,13 +362,63 @@ public void garbageFree() {
<a name="Performance" />
<subsection name="Performance">
<a name="Latency" />
- <h4>Response Time of Garbage-free Logging is Consistently Better with Fewer Spikes</h4>
- <p>TODO: add latency histogram: Response time distribution of Async Loggers 2.5 vs 2.6 in garbage-free mode under various loads.</p>
- <p>TODO: add latency histogram: Response time distribution of synchronous logging vs 2.6 in garbage-free mode under various loads.</p>
+ <h4>Response Time Latency</h4>
+ <p>Response time is how long it takes to log a message under a certain load.
+ When measuring, each messsage has its own response time. Typically the vast majority of measurements
+ are in a certain low range, with a small number of large outliers. When talking about latency,
+ we are usually interested in the outliers: how many there are and how large they are.
+ "Average latency" is meaningless.
+ </p>
+ <p>Commonly what is reported as latency is <em>service time</em>: how long it took to perform the operation.
+ This omits the queueing effect: we were trying to log at a certain rate, say 100,000 messages per second.
+ A single spike in service time can delay many of the subsequent messages.
+ <em>Response time</em> includes the effect of spikes.
+ </p>
+ <h4>Async Loggers</h4>
+ <p>The graph below compares "classic" logging to
+ garbage-free logging response time behaviour for Log4j's Async Loggers.
+ In the graph, "100k" means logging at a sustained load of 100,000 messages/second, "800k" is
+ 800,000 messages/second.
+ </p>
+ <p>In classic mode we see numerous minor garbage collections which pause the application threads
+ for 3 milliseconds or more. This quickly adds up to response time delays of almost 10
+ milliseconds.
+ As you can see in the graph, increasing the load shifts the curve to the left (there are more spikes).
+ This makes sense: logging more means more pressure on the garbage collector resulting in more minor GC pauses.
+ We experimented a little with reducing the load to 50,000 or even 5000 messages/second,
+ but this did not eliminate the 3 millisecond pauses, it just made them occur less frequently.
+ Note that all GC pauses in this test are minor GC pauses. We did not see any full garbage collections.</p>
+ <p>In garbage-free mode, maximum response time remains well below 1 millisecond under a wide range of loads.
+ (Max 780 us at 800,000 messages/sec, max 407 us at 600,000 messages/sec, with the 99% around 5 us for
+ all loads up to 800,000 messages/sec.) Increasing or decreasing the load does not change the response time
+ behaviour. We did not investigate the cause of the 200-300 microsecond pauses we saw in these tests.
+ </p>
+ <p>
+ TODO title should include "lower is better".
+ TODO legend should be "microseconds" (full)
+ </p>
+
+ <p><img src="../images/ResponseTimeAsyncClassicVsGcFree-label.png" /></p>
+ <p>
+ When we increased the load further we begin to see larger response time pauses for both classic and
+ garbage-free logging.
+ At sustained loads of 1 million messages/second or more we start to approach the maximum throughput of
+ the underlying RandomAccessFile Appender (see the synchronous logging throughput chart below).
+ At these loads the ringbuffer starts to fill up and backpressure kicks in: attempting to add another message
+ when the ringbuffer is full will block until a free slot becomes available. We start to see 20 millisecond
+ response times or more; and attempting to increase the load even more results in larger and larger
+ response time spikes.
+ </p>
+ <h4>Synchronous Logging</h4>
+ <p>For both classic and garbage-free logging, synchronous logging showed response times of 3-5 milliseconds
+ even at loads of 100,000 messages/second. It may be possible to improve on this, we did not investigate
+ further yet.</p>
+ <p><img src="../images/ResponseTimeSyncClassicVsGcFree.png" /></p>
<a name="Throughput" />
- <h4>Throughput of Garbage-free Logging May Be Worse (But It's All Relative)</h4>
- <p>In our measurements, Log4j 2.6 in garbage-free mode had the highest throughput in single-threaded scenarios. In multi-threaded
+ <h4>Throughput of Garbage-free and Classic Logging is Similar</h4>
+ <p>Throughput is roughly similar for garbage-free and classic logging.
+ In our measurements, Log4j 2.6 in garbage-free mode had the highest throughput in single-threaded scenarios. In multi-threaded
scenarios, Log4j 2.6 "classic" had the highest throughput, with Log4j 2.6 in garbage-free mode and Log4j 2.5
not far behind. Our test results suggest that the throughput of the other logging frameworks we tested
will rapidly decline in multi-threaded applications.</p>