logging-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From rgo...@apache.org
Subject 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...
Date Sun, 07 Apr 2013 22:58:20 GMT
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,



Mime
View raw message