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/08 00:58:20 UTC
svn commit: r1465503 - in /logging/log4j/log4j2/trunk: ./
core/src/main/java/org/apache/logging/log4j/core/appender/rolling/
log4j-async/src/main/java/org/apache/logging/log4j/async/appender/
log4j-async/src/test/java/org/apache/logging/log4j/async/app...
Author: rgoers
Date: Sun Apr 7 22:58:17 2013
New Revision: 1465503
URL: http://svn.apache.org/r1465503
Log:
LOG4J2-193 - RollingFastFileAppender (in log4j-async) did not roll over.
Added:
logging/log4j/log4j2/trunk/src/site/resources/images/async-vs-sync-throughput.png (with props)
Modified:
logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java
logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileAppender.java
logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileManager.java
logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileAppender.java
logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileManager.java
logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/appender/FastRollingFileAppenderRolloverTest.java
logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/perftest/PerfTestDriver.java
logging/log4j/log4j2/trunk/pom.xml
logging/log4j/log4j2/trunk/src/changes/changes.xml
logging/log4j/log4j2/trunk/src/site/resources/images/async-average-latency.png
logging/log4j/log4j2/trunk/src/site/resources/images/async-max-latency-99.99pct.png
logging/log4j/log4j2/trunk/src/site/resources/images/async-throughput-comparison.png
logging/log4j/log4j2/trunk/src/site/xdoc/manual/async.xml
logging/log4j/log4j2/trunk/src/site/xdoc/performance.xml
Modified: logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java (original)
+++ logging/log4j/log4j2/trunk/core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java Sun Apr 7 22:58:17 2013
@@ -106,14 +106,18 @@ public class RollingFileManager extends
try {
size = 0;
initialTime = System.currentTimeMillis();
- final OutputStream os = new FileOutputStream(getFileName(), isAppend());
- setOutputStream(os);
- } catch (final FileNotFoundException ex) {
+ createFileAfterRollover();
+ } catch (final IOException ex) {
LOGGER.error("FileManager (" + getFileName() + ") " + ex);
}
}
}
+ protected void createFileAfterRollover() throws IOException {
+ final OutputStream os = new FileOutputStream(getFileName(), isAppend());
+ setOutputStream(os);
+ }
+
/**
* Returns the pattern processor.
* @return The PatternProcessor.
Modified: logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileAppender.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileAppender.java?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileAppender.java (original)
+++ logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileAppender.java Sun Apr 7 22:58:17 2013
@@ -80,12 +80,6 @@ public final class FastFileAppender exte
// From a user's point of view, this means that all log events are
// _always_ available in the log file, without incurring the overhead
// of immediateFlush=true.
- //
- // without LOG4J2-164:
- // if (event.getClass() == RingBufferLogEvent.class) {
- // boolean isEndOfBatch = ((RingBufferLogEvent) event).isEndOfBatch();
- // ((FastFileManager) getManager()).setEndOfBatch(isEndOfBatch);
- // }
((FastFileManager) getManager()).setEndOfBatch(event.isEndOfBatch());
super.append(event);
}
Modified: logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileManager.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileManager.java?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileManager.java (original)
+++ logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastFileManager.java Sun Apr 7 22:58:17 2013
@@ -102,6 +102,16 @@ public class FastFileManager extends Out
}
buffer.clear();
}
+
+ @Override
+ public void close() {
+ flush();
+ try {
+ randomAccessFile.close();
+ } catch (final IOException ex) {
+ LOGGER.error("Unable to close RandomAccessFile " + getName() + ". " + ex);
+ }
+ }
/**
* Returns the name of the File being managed.
Modified: logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileAppender.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileAppender.java?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileAppender.java (original)
+++ logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileAppender.java Sun Apr 7 22:58:17 2013
@@ -79,7 +79,8 @@ public final class FastRollingFileAppend
*/
@Override
public void append(final LogEvent event) {
- ((RollingFileManager) getManager()).checkRollover(event);
+ FastRollingFileManager manager = (FastRollingFileManager) getManager();
+ manager.checkRollover(event);
// Leverage the nice batching behaviour of async Loggers/Appenders:
// we can signal the file manager that it needs to flush the buffer
@@ -87,13 +88,7 @@ public final class FastRollingFileAppend
// From a user's point of view, this means that all log events are
// _always_ available in the log file, without incurring the overhead
// of immediateFlush=true.
- //
- // without LOG4J2-164:
- // if (event.getClass() == RingBufferLogEvent.class) {
- // boolean isEndOfBatch = ((RingBufferLogEvent) event).isEndOfBatch();
- // ((FastRollingFileManager) getManager()).setEndOfBatch(isEndOfBatch);
- // }
- ((FastRollingFileManager) getManager()).setEndOfBatch(event.isEndOfBatch());
+ manager.setEndOfBatch(event.isEndOfBatch());
super.append(event);
}
@@ -133,20 +128,21 @@ public final class FastRollingFileAppend
* @return A FastRollingFileAppender.
*/
@PluginFactory
- public static FastRollingFileAppender createAppender(@PluginAttr("fileName") final String fileName,
- @PluginAttr("filePattern") final String filePattern,
- @PluginAttr("append") final String append,
- @PluginAttr("name") final String name,
- @PluginAttr("immediateFlush") final String immediateFlush,
- @PluginElement("policy") final TriggeringPolicy policy,
- @PluginElement("strategy") RolloverStrategy strategy,
- @PluginElement("layout") Layout<?> layout,
- @PluginElement("filter") final Filter filter,
- @PluginAttr("suppressExceptions") final String suppress,
- @PluginAttr("advertise") final String advertise,
- @PluginAttr("advertiseURI") final String advertiseURI,
- @PluginConfiguration final Configuration config) {
-
+ public static FastRollingFileAppender createAppender(
+ @PluginAttr("fileName") final String fileName,
+ @PluginAttr("filePattern") final String filePattern,
+ @PluginAttr("append") final String append,
+ @PluginAttr("name") final String name,
+ @PluginAttr("immediateFlush") final String immediateFlush,
+ @PluginElement("policy") final TriggeringPolicy policy,
+ @PluginElement("strategy") RolloverStrategy strategy,
+ @PluginElement("layout") Layout<?> layout,
+ @PluginElement("filter") final Filter filter,
+ @PluginAttr("suppressExceptions") final String suppress,
+ @PluginAttr("advertise") final String advertise,
+ @PluginAttr("advertiseURI") final String advertiseURI,
+ @PluginConfiguration final Configuration config) {
+
final boolean isAppend = append == null ? true : Boolean.valueOf(append);
final boolean handleExceptions = suppress == null ? true : Boolean.valueOf(suppress);
final boolean isFlush = immediateFlush == null ? true : Boolean.valueOf(immediateFlush);
Modified: logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileManager.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileManager.java?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileManager.java (original)
+++ logging/log4j/log4j2/trunk/log4j-async/src/main/java/org/apache/logging/log4j/async/appender/FastRollingFileManager.java Sun Apr 7 22:58:17 2013
@@ -33,7 +33,7 @@ public class FastRollingFileManager exte
private static FastRollingFileManagerFactory factory = new FastRollingFileManagerFactory();
private final boolean isImmediateFlush;
- private final RandomAccessFile randomAccessFile;
+ private RandomAccessFile randomAccessFile;
private final ByteBuffer buffer;
private ThreadLocal<Boolean> isEndOfBatch = new ThreadLocal<Boolean>();
@@ -79,6 +79,14 @@ public class FastRollingFileManager exte
}
@Override
+ protected void createFileAfterRollover() throws IOException {
+ this.randomAccessFile = new RandomAccessFile(getFileName(), "rw");
+ if (isAppend()) {
+ randomAccessFile.seek(randomAccessFile.length());
+ }
+ }
+
+ @Override
public void flush() {
buffer.flip();
try {
@@ -89,6 +97,16 @@ public class FastRollingFileManager exte
}
buffer.clear();
}
+
+ @Override
+ public void close() {
+ flush();
+ try {
+ randomAccessFile.close();
+ } catch (final IOException ex) {
+ LOGGER.error("Unable to close RandomAccessFile " + getName() + ". " + ex);
+ }
+ }
/**
* Factory to create a FastRollingFileManager.
Modified: logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/appender/FastRollingFileAppenderRolloverTest.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/appender/FastRollingFileAppenderRolloverTest.java?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/appender/FastRollingFileAppenderRolloverTest.java (original)
+++ logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/appender/FastRollingFileAppenderRolloverTest.java Sun Apr 7 22:58:17 2013
@@ -85,7 +85,7 @@ public class FastRollingFileAppenderRoll
String old2 = reader.readLine();
assertTrue("renamed file line 2", old2.contains(exceed));
String line = reader.readLine();
- // assertNull("No more lines", line);
+ assertNull("No more lines", line);
reader.close();
after1.delete();
}
Modified: logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/perftest/PerfTestDriver.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/perftest/PerfTestDriver.java?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/perftest/PerfTestDriver.java (original)
+++ logging/log4j/log4j2/trunk/log4j-async/src/test/java/org/apache/logging/log4j/async/perftest/PerfTestDriver.java Sun Apr 7 22:58:17 2013
@@ -165,16 +165,16 @@ public class PerfTestDriver {
private static Setup s(String config, String runner, String name,
String... systemProperties) throws IOException {
WaitStrategy wait = WaitStrategy.valueOf(System.getProperty(
- "WaitStrategy", "Block"));
+ "WaitStrategy", "Sleep"));
return new Setup(PerfTest.class, runner, name, config, 1, wait,
systemProperties);
}
- // single-threaded performance test
+ // multi-threaded performance test
private static Setup m(String config, String runner, String name,
int threadCount, String... systemProperties) throws IOException {
WaitStrategy wait = WaitStrategy.valueOf(System.getProperty(
- "WaitStrategy", "Block"));
+ "WaitStrategy", "Sleep"));
return new Setup(MTPerfTest.class, runner, name, config, threadCount,
wait, systemProperties);
}
@@ -189,161 +189,73 @@ public class PerfTestDriver {
long start = System.nanoTime();
List<Setup> tests = new ArrayList<PerfTestDriver.Setup>();
+ // includeLocation=false
tests.add(s("perf-logback.xml", LOGBK, "Sync"));
tests.add(s("perf-log4j12.xml", LOG12, "Sync"));
tests.add(s("perf3PlainNoLoc.xml", LOG20, "Sync"));
+ tests.add(s("perf3PlainNoLoc.xml", LOG20, "Loggers all async",
+ ALL_ASYNC, SYSCLOCK));
+ tests.add(s("perf7MixedNoLoc.xml", LOG20, "Loggers mixed sync/async"));
tests.add(s("perf-logback-async.xml", LOGBK, "Async Appender"));
tests.add(s("perf-log4j12-async.xml", LOG12, "Async Appender"));
- tests.add(s("perf5AsyncApndNoLoc.xml", LOG20,
- "Async Appender no location"));
- tests.add(s("perf3PlainNoLoc.xml", LOG20, "All async no loc SysClock",
- ALL_ASYNC, SYSCLOCK));
- tests.add(s("perf7MixedNoLoc.xml", LOG20, "Mixed async no location"));
+ tests.add(s("perf5AsyncApndNoLoc.xml", LOG20, "Async Appender"));
- for (int i = 32; i <= 64; i *= 2) {
+ // includeLocation=true
+ // tests.add(s("perf6AsyncApndLoc.xml", LOG20,
+ // "Async Appender includeLocation"));
+ // tests.add(s("perf8MixedLoc.xml", LOG20,
+ // "Mixed sync/async includeLocation"));
+ // tests.add(s("perf4PlainLocation.xml", LOG20,
+ // "Loggers all async includeLocation", ALL_ASYNC));
+ // tests.add(s("perf4PlainLocation.xml", LOG20,
+ // "Loggers all async includeLocation CachedClock", ALL_ASYNC,
+ // CACHEDCLOCK));
+ // tests.add(s("perf4PlainLocation.xml", LOG20,
+ // "Sync includeLocation"));
+
+ // appenders
+ // tests.add(s("perf1syncFile.xml", LOG20, "FileAppender"));
+ // tests.add(s("perf1syncFastFile.xml", LOG20, "FastFileAppender"));
+ // tests.add(s("perf2syncRollFile.xml", LOG20, "RollFileAppender"));
+ // tests.add(s("perf2syncRollFastFile.xml", LOG20,
+ // "RollFastFileAppender"));
+
+ final int MAX_THREADS = 16; // 64 takes a LONG time
+ for (int i = 2; i <= MAX_THREADS; i *= 2) {
+ // includeLocation = false
tests.add(m("perf-logback.xml", LOGBK, "Sync", i));
tests.add(m("perf-log4j12.xml", LOG12, "Sync", i));
tests.add(m("perf3PlainNoLoc.xml", LOG20, "Sync", i));
tests.add(m("perf-logback-async.xml", LOGBK, "Async Appender", i));
tests.add(m("perf-log4j12-async.xml", LOG12, "Async Appender", i));
- tests.add(m("perf5AsyncApndNoLoc.xml", LOG20,
- "Async Appender no location", i));
- tests.add(m("perf3PlainNoLoc.xml", LOG20,
- "All async no loc SysClock", i, ALL_ASYNC, SYSCLOCK));
+ tests.add(m("perf5AsyncApndNoLoc.xml", LOG20, "Async Appender", i));
+ tests.add(m("perf3PlainNoLoc.xml", LOG20, "Loggers all async", i,
+ ALL_ASYNC, SYSCLOCK));
tests.add(m("perf7MixedNoLoc.xml", LOG20,
- "Mixed async no location", i));
- }
+ "Loggers mixed sync/async", i));
- // Setup[] tests = new Setup[] { //
- // s("perf-logback.xml", LOGBK, "Sync"), //
- // s("perf-log4j12.xml", LOG12, "Sync"), //
- // s("perf3PlainNoLoc.xml", LOG20, "Sync"), //
- // s("perf-logback-async.xml", LOGBK, "Async Appender"), //
- // s("perf-log4j12-async.xml", LOG12, "Async Appender"), //
- // s("perf5AsyncApndNoLoc.xml", LOG20,
- // "Async Appender no location"),
- // s("perf3PlainNoLoc.xml", LOG20, "All async no loc SysClock",
- // ALL_ASYNC, SYSCLOCK), //
- // s("perf7MixedNoLoc.xml", LOG20, "Mixed async no location"), //
- //
- // m("perf-log4j12-async.xml", LOG12, "Async Appender", 2), //
- // m("perf-log4j12.xml", LOG12, "Sync", 2), //
- // m("perf-logback.xml", LOGBK, "Sync", 2), //
- // m("perf-logback-async.xml", LOGBK, "Async Appender", 2), //
- // m("perf3PlainNoLoc.xml", LOG20, "Sync", 2), //
- // m("perf3PlainNoLoc.xml", LOG20, "All async no loc CachedClock",
- // 2, ALL_ASYNC, CACHEDCLOCK), //
- // m("perf3PlainNoLoc.xml", LOG20, "All async no loc SysClock", 2,
- // ALL_ASYNC, SYSCLOCK), //
- //
- // m("perf-log4j12-async.xml", LOG12, "Async Appender", 4), //
- // m("perf-log4j12.xml", LOG12, "Sync", 4), //
- // m("perf-logback.xml", LOGBK, "Sync", 4), //
- // m("perf-logback-async.xml", LOGBK, "Async Appender", 4), //
- // m("perf3PlainNoLoc.xml", LOG20, "Sync", 4), //
- // m("perf3PlainNoLoc.xml", LOG20,
- // "All async no loc CachedClock",
- // 4, ALL_ASYNC, CACHEDCLOCK), //
- // m("perf3PlainNoLoc.xml", LOG20, "All async no loc SysClock",
- // 4,
- // ALL_ASYNC, SYSCLOCK), //
- //
- // m("perf-log4j12-async.xml", LOG12, "Async Appender", 8), //
- // m("perf-log4j12.xml", LOG12, "Sync", 8), //
- // m("perf-logback.xml", LOGBK, "Sync", 8), //
- // m("perf-logback-async.xml", LOGBK, "Async Appender", 8), //
- // m("perf3PlainNoLoc.xml", LOG20, "Sync", 8), //
- // m("perf3PlainNoLoc.xml", LOG20,
- // "All async no loc CachedClock",
- // 8, ALL_ASYNC, CACHEDCLOCK), //
- // m("perf3PlainNoLoc.xml", LOG20, "All async no loc SysClock",
- // 8,
- // ALL_ASYNC, SYSCLOCK), //
-
- // 2 threads
- // m("perf5AsyncApndNoLoc.xml", LOG20,"Async Appender no location",
- // 2), //
- // m("perf6AsyncApndLoc.xml",
- // LOG12,"Async Appender with location",
- // 2), //
- // m("perf7MixedNoLoc.xml", "Mixed async no location", 2), //
- // m("perf8MixedLoc.xml", "Mixed async with location", 2), //
- // m("perf4PlainLocation.xml",
- // "All async with location SysClock",
- // 2, ALL_ASYNC), //
- // m("perf4PlainLocation.xml",
- // "All async with location CachedClock", 2, ALL_ASYNC,
- // CACHEDCLOCK), //
- // m("perf4PlainLocation.xml", "All sync with location", 2), //
- // m("perf1syncFile.xml", "FileAppender", 2), //
- // m("perf1syncFastFile.xml", "FastFileAppender", 2), //
- // m("perf2syncRollFile.xml", "RollFileAppender", 2), //
- // m("perf2syncRollFastFile.xml", "RollFastFileAppender", 2), //
-
- // 4 threads
- // m("perf5AsyncApndNoLoc.xml", LOG20,"Async Appender no location",
- // 4), //
- // m("perf6AsyncApndLoc.xml", "Async Appender with location",
- // 4), //
- // m("perf7MixedNoLoc.xml", "Mixed async no location", 4), //
- // m("perf8MixedLoc.xml", "Mixed async with location", 4), //
- // m("perf4PlainLocation.xml",
- // "All async with location SysClock",
- // 4, ALL_ASYNC), //
- // m("perf4PlainLocation.xml",
- // "All async with location CachedClock", 4, ALL_ASYNC,
- // CACHEDCLOCK), //
- // m("perf4PlainLocation.xml", "All sync with location", 4), //
- // m("perf1syncFile.xml", "FileAppender", 4), //
- // m("perf1syncFastFile.xml", "FastFileAppender", 4), //
- // m("perf2syncRollFile.xml", "RollFileAppender", 4), //
- // m("perf2syncRollFastFile.xml", "RollFastFileAppender", 4), //
-
- // 8 threads
- // m("perf5AsyncApndNoLoc.xml", LOG20,
- // "Async Appender no location", 8), //
- // m("perf6AsyncApndLoc.xml", "Async Appender with location",
- // 8), //
- // m("perf7MixedNoLoc.xml", "Mixed async no location", 8), //
- // m("perf8MixedLoc.xml", "Mixed async with location", 8), //
- // m("perf4PlainLocation.xml",
- // "All async with location SysClock",
- // 8, ALL_ASYNC), //
- // m("perf4PlainLocation.xml",
- // "All async with location CachedClock", 8, ALL_ASYNC,
- // CACHEDCLOCK), //
- // m("perf4PlainLocation.xml", "All sync with location", 8), //
- // m("perf1syncFile.xml", "FileAppender", 8), //
- // m("perf1syncFastFile.xml", "FastFileAppender", 8), //
- // m("perf2syncRollFile.xml", "RollFileAppender", 8), //
- // m("perf2syncRollFastFile.xml", "RollFastFileAppender", 8), //
-
- // s("perf-log4j12-async.xml", LOG12, "Async Appender"), //
- // s("perf-log4j12.xml", LOG12, "Sync"), //
- // s("perf-logback.xml", LOGBK, "Sync"), //
- // s("perf-logback-async.xml", LOGBK, "Async Appender"), //
- // s("perf3PlainNoLoc.xml", LOG20, "Sync"), //
- // s("perf3PlainNoLoc.xml", LOG20, "All async no loc CachedClock",
- // ALL_ASYNC, CACHEDCLOCK), //
- // s("perf3PlainNoLoc.xml", LOG20, "All async no loc SysClock",
- // ALL_ASYNC, SYSCLOCK), //
- // s("perf5AsyncApndNoLoc.xml", LOG20,
- // "Async Appender no location"),
- //
- // s("perf6AsyncApndLoc.xml", "Async Appender with location"), //
- // s("perf7MixedNoLoc.xml", "Mixed async no location"), //
- // s("perf8MixedLoc.xml", "Mixed async with location"), //
- // s("perf4PlainLocation.xml", "All async with location SysClock",
- // ALL_ASYNC), //
- // s("perf4PlainLocation.xml",
- // "All async with location CachedClock", ALL_ASYNC,
- // CACHEDCLOCK), //
- // s("perf4PlainLocation.xml", "All sync with location"), //
- // s("perf1syncFile.xml", "FileAppender"), //
- // s("perf1syncFastFile.xml", "FastFileAppender"), //
- // s("perf2syncRollFile.xml", "RollFileAppender"), //
- // s("perf2syncRollFastFile.xml", "RollFastFileAppender"), //
- // };
+ // includeLocation=true
+ // tests.add(m("perf6AsyncApndLoc.xml", LOG20,
+ // "Async Appender includeLocation", i));
+ // tests.add(m("perf8MixedLoc.xml", LOG20,
+ // "Mixed sync/async includeLocation", i));
+ // tests.add(m("perf4PlainLocation.xml", LOG20,
+ // "Loggers all async includeLocation", i, ALL_ASYNC));
+ // tests.add(m("perf4PlainLocation.xml", LOG20,
+ // "Loggers all async includeLocation CachedClock", i,
+ // ALL_ASYNC, CACHEDCLOCK));
+ // tests.add(m("perf4PlainLocation.xml", LOG20,
+ // "Sync includeLocation", i));
+
+ // appenders
+ // tests.add(m("perf1syncFile.xml", LOG20, "FileAppender", i));
+ // tests.add(m("perf1syncFastFile.xml", LOG20, "FastFileAppender",
+ // i));
+ // tests.add(m("perf2syncRollFile.xml", LOG20, "RollFileAppender",
+ // i));
+ // tests.add(m("perf2syncRollFastFile.xml", LOG20,
+ // "RollFastFileAppender", i));
+ }
String java = args.length > 0 ? args[0] : "java";
int repeat = args.length > 1 ? Integer.parseInt(args[1]) : 5;
Modified: logging/log4j/log4j2/trunk/pom.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/pom.xml?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/pom.xml (original)
+++ logging/log4j/log4j2/trunk/pom.xml Sun Apr 7 22:58:17 2013
@@ -57,6 +57,18 @@
<email>sdeboy@apache.org</email>
</developer>
</developers>
+ <contributors>
+ <contributor>
+ <name>Remko Popma</name>
+ <email>remkop@yahoo.com</email>
+ <roles>
+ <role>log4j-async module development, testing and documentation</role>
+ </roles>
+ <timezone>+9</timezone>
+ <properties>
+ </properties>
+ </contributor>
+ </contributors>
<mailingLists>
<mailingList>
<name>log4j-user</name>
Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
+++ logging/log4j/log4j2/trunk/src/changes/changes.xml Sun Apr 7 22:58:17 2013
@@ -23,6 +23,12 @@
<body>
<release version="2.0-beta5" date="@TBD@" description="Bug fixes and enhancements">
+ <action issue="LOG4J2-195" dev="rgoers" type="fix" due-to="Remko Popma">
+ Unit tests now create files in the target directory.
+ </action>
+ <action issue="LOG4J2-193" dev="rgoers" type="fix" due-to="Remko Popma">
+ RollingFastFileAppender (in log4j-async) did not roll over.
+ </action>
<action issue="LOG4J2-199" dev="rgoers" type="fix" due-to="Remko Popma">
Highlight subprojects in sub-navigation.
</action>
Modified: logging/log4j/log4j2/trunk/src/site/resources/images/async-average-latency.png
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/site/resources/images/async-average-latency.png?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
Binary files - no diff available.
Modified: logging/log4j/log4j2/trunk/src/site/resources/images/async-max-latency-99.99pct.png
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/site/resources/images/async-max-latency-99.99pct.png?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
Binary files - no diff available.
Modified: logging/log4j/log4j2/trunk/src/site/resources/images/async-throughput-comparison.png
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/site/resources/images/async-throughput-comparison.png?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
Binary files - no diff available.
Added: logging/log4j/log4j2/trunk/src/site/resources/images/async-vs-sync-throughput.png
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/site/resources/images/async-vs-sync-throughput.png?rev=1465503&view=auto
==============================================================================
Binary file - no diff available.
Propchange: logging/log4j/log4j2/trunk/src/site/resources/images/async-vs-sync-throughput.png
------------------------------------------------------------------------------
svn:mime-type = application/octet-stream
Modified: 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=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/src/site/xdoc/manual/async.xml (original)
+++ logging/log4j/log4j2/trunk/src/site/xdoc/manual/async.xml Sun Apr 7 22:58:17 2013
@@ -479,7 +479,7 @@
<tt>ByteBuffer + RandomAccessFile</tt>
instead of a
<tt>BufferedOutputStream</tt>.
- We saw a 10-30% performance improvement compared to
+ We saw a 20-200% performance improvement compared to
FileAppender with "bufferedIO=true" in our
<a href="#FastFileAppenderPerformance">measurements</a>.
Similar to the FileAppender,
@@ -589,12 +589,11 @@
<tt>ByteBuffer + RandomAccessFile</tt>
instead of a
<tt>BufferedOutputStream</tt>.
- <!--
- We saw a 10-30% performance improvement compared to
+ We saw a 20-200% 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
@@ -843,11 +842,14 @@
</p>
</subsection>
<a name="Performance" />
- <subsection name="Performance Measurements">
+ <subsection name="Asynchronous Logging Performance">
<p>
- This section shows the results of our performance tests.
- The
- methodology used was the same for all tests:
+ The performance results below were all derived from running the
+ PerfTest, MTPerfTest and PerfTestDriver classes which can be found
+ in the Log4j 2 unit test source directory.
+ All tests were done using the
+ default settings (SystemClock and SleepingWaitStrategy).
+ 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
@@ -858,10 +860,42 @@
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>
+ <li>Throughput test: measure how long it takes to execute 256 *
+ 1024 / threadCount calls to Logger.log and express the
+ result in messages per second.</li>
+ <li>Repeat the test 5 times and average the results.</li>
</ul>
<h4>Logging Throughput</h4>
+ <p>
+ The graph below compares the throughput of synchronous loggers,
+ asynchronous appenders and asynchronous loggers. This
+ is the total throughput of all threads together.
+ In the test with 64 threads, asynchronous loggers are 12 times
+ faster than asynchronous appenders, and 68 times faster than
+ synchronous loggers.
+ </p>
+ <p>
+ Asynchronous loggers' throughput increases with the number of threads,
+ whereas both synchronous loggers and asynchronous appenders
+ have more or less constant throughput regardless of the number of
+ threads that are doing the logging.
+ </p>
+ <p><img src="../images/async-vs-sync-throughput.png" /></p>
+
+ <h4>Asynchronous Throughput Comparison with Other Logging Packages</h4>
+ <p>
+ We also compared throughput of asynchronous loggers to
+ the synchronous loggers and asynchronous appenders available
+ in other logging packages, specifically log4j-1.2.17 and
+ logback-1.0.10, with similar results.
+ For asynchronous appenders, total logging throughput of all
+ threads together remains roughly constant when adding more threads.
+ Asynchronous loggers make more effective use of the multiple cores
+ available on the machine in multi-threaded scenarios.
+ </p>
+ <p>
+ <img src="../images/async-throughput-comparison.png" />
+ </p>
<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>
@@ -876,7 +910,7 @@
</tr>
<tr>
<td>Log4j2: Loggers all asynchronous</td>
- <td align="right">1,655,952</td>
+ <td align="right">1,715,344</td>
<td align="right">928,951</td>
<td align="right">1,045,265</td>
<td align="right">1,509,109</td>
@@ -885,7 +919,7 @@
</tr>
<tr>
<td>Log4j2: Loggers mixed sync/async</td>
- <td align="right">534,592</td>
+ <td align="right">571,099</td>
<td align="right">1,204,774</td>
<td align="right">1,632,204</td>
<td align="right">1,368,041</td>
@@ -894,7 +928,7 @@
</tr>
<tr>
<td>Log4j2: Async Appender</td>
- <td align="right">1,091,563</td>
+ <td align="right">1,236,548</td>
<td align="right">1,006,287</td>
<td align="right">511,571</td>
<td align="right">302,230</td>
@@ -903,7 +937,7 @@
</tr>
<tr>
<td>Log4j1: Async Appender</td>
- <td align="right">1,336,667</td>
+ <td align="right">1,373,195</td>
<td align="right">911,657</td>
<td align="right">636,899</td>
<td align="right">406,405</td>
@@ -912,7 +946,7 @@
</tr>
<tr>
<td>Logback: Async Appender</td>
- <td align="right">2,231,044</td>
+ <td align="right">1,979,515</td>
<td align="right">783,722</td>
<td align="right">582,935</td>
<td align="right">289,905</td>
@@ -1046,26 +1080,13 @@
<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>Logger (Log4j 2)</th>
<th>1 thread</th>
<th>2 threads</th>
<th>4 threads</th>
@@ -1171,10 +1192,10 @@
</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>
+ <td align="right">278,369</td>
+ <td align="right">213,176</td>
+ <td align="right">125,300</td>
+ <td align="right">63,103</td>
</tr>
<tr>
<td>RollingFileAppender</td>
@@ -1183,11 +1204,11 @@
<td align="right">55,147</td>
<td align="right">28,153</td>
</tr>
- <caption align="top">Throughput per thread in operations/second
+ <caption align="top">Throughput per thread in messages/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>
+ <p>On Solaris 10 (64bit) with JDK1.7.0_06, 4-core dual Xeon X5570 CPU
+ @2.93GHz with hyperthreading switched off (8 virtual cores):</p>
<table>
<tr>
<th>Appender</th>
@@ -1212,10 +1233,10 @@
</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>
+ <td align="right">228,491</td>
+ <td align="right">135,355</td>
+ <td align="right">69,277</td>
+ <td align="right">32,484</td>
</tr>
<tr>
<td>RollingFileAppender</td>
@@ -1224,7 +1245,7 @@
<td align="right">55,766</td>
<td align="right">25,097</td>
</tr>
- <caption align="top">Throughput per thread in operations/second
+ <caption align="top">Throughput per thread in messages/second
</caption>
</table>
</subsection>
Modified: logging/log4j/log4j2/trunk/src/site/xdoc/performance.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/site/xdoc/performance.xml?rev=1465503&r1=1465502&r2=1465503&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/src/site/xdoc/performance.xml (original)
+++ logging/log4j/log4j2/trunk/src/site/xdoc/performance.xml Sun Apr 7 22:58:17 2013
@@ -212,7 +212,38 @@
strongly encouraged to configure their applications to run in server mode when using Log4j 2.
</p>
</li>
-
+ <li>
+ <b>Asynchronous Logging Performance Improvements</b>
+ <br />
+ <p>
+ Log4j 2 supports a new "<a href="manual/async.html">async</a>" module
+ which offers Asynchronous Loggers for high throughput and low latency logging.
+ Asynchronous Loggers are implemented using the
+ <a href="http://lmax-exchange.github.com/disruptor/">LMAX Disruptor</a>
+ inter-thread messaging library instead of the ArrayBlockingQueue used by Asynchronous Appenders.
+ </p><p>
+ Asynchronous Appenders already offered about 5 - 10 times more throughput than
+ synchronous loggers, but this advantage remained more or less constant
+ when more threads are logging. That is, if you double the number of threads
+ that are logging you would expect your total throughput to increase, but
+ this is not the case: the throughput per thread is roughly halved so your
+ total throughput remains more or less the same.
+ (Note that this happens even if the appender queue size is large enough to hold
+ all messages logged during the test, so this is not caused by disk I/O.)
+ </p><p>
+ Asynchronous Loggers have significantly higher throughput than the legacy Asynchronous Appenders,
+ especially in multithreaded scenarios. In one test with 64 threads,
+ Asynchronous Loggers were 12 times faster than the fastest Asynchronous Appender,
+ and 68 times faster than the fastest synchronous logger.
+ In addition to throughput, Asynchronous Loggers have attractive latency characteristics.
+ Not only is average latency lower compared to Asynchronous Appenders,
+ but when increasing the number of application threads that do logging,
+ worst-case latency remained almost constant (10 - 20 microseconds)
+ where Asynchronous Appenders start experiencing worst-case
+ latency spikes in the 100 millisecond range, a difference of four orders of magnitude.
+ See <a href="manual/async.html#Performance">Asynchronous Logging Performance</a> for details.
+ </p>
+ </li>
</ol>
<p>
The performance results above were all derived from running the DebugDisabledPerformanceComparison,