logging-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From rpo...@apache.org
Subject svn commit: r1592463 - in /logging/log4j/log4j2/trunk: log4j-core/src/main/java/org/apache/logging/log4j/core/async/ log4j-core/src/main/java/org/apache/logging/log4j/core/config/ src/changes/
Date Mon, 05 May 2014 07:58:07 GMT
Author: rpopma
Date: Mon May  5 07:58:06 2014
New Revision: 1592463

URL: http://svn.apache.org/r1592463
Log:
LOG4J2-392 Resolved a problem with the previous solution that resulted in dropped events with
slow appenders when application is stopped

Modified:
    logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
    logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
    logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java
    logging/log4j/log4j2/trunk/src/changes/changes.xml

Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java?rev=1592463&r1=1592462&r2=1592463&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
(original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
Mon May  5 07:58:06 2014
@@ -16,18 +16,10 @@
  */
 package org.apache.logging.log4j.core.async;
 
-import com.lmax.disruptor.BlockingWaitStrategy;
-import com.lmax.disruptor.ExceptionHandler;
-import com.lmax.disruptor.RingBuffer;
-import com.lmax.disruptor.SleepingWaitStrategy;
-import com.lmax.disruptor.WaitStrategy;
-import com.lmax.disruptor.YieldingWaitStrategy;
-import com.lmax.disruptor.dsl.Disruptor;
-import com.lmax.disruptor.dsl.ProducerType;
-import com.lmax.disruptor.util.Util;
 import java.util.Map;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Executors;
+
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.Marker;
 import org.apache.logging.log4j.ThreadContext;
@@ -43,6 +35,16 @@ import org.apache.logging.log4j.message.
 import org.apache.logging.log4j.message.MessageFactory;
 import org.apache.logging.log4j.status.StatusLogger;
 
+import com.lmax.disruptor.BlockingWaitStrategy;
+import com.lmax.disruptor.ExceptionHandler;
+import com.lmax.disruptor.RingBuffer;
+import com.lmax.disruptor.SleepingWaitStrategy;
+import com.lmax.disruptor.WaitStrategy;
+import com.lmax.disruptor.YieldingWaitStrategy;
+import com.lmax.disruptor.dsl.Disruptor;
+import com.lmax.disruptor.dsl.ProducerType;
+import com.lmax.disruptor.util.Util;
+
 /**
  * AsyncLogger is a logger designed for high throughput and low latency logging.
  * It does not perform any I/O in the calling (application) thread, but instead
@@ -290,28 +292,30 @@ public class AsyncLogger extends Logger 
         if (temp == null) {
             return; // stop() has already been called
         }
-        temp.shutdown();
 
-        // Wait up to 10 seconds for the ringbuffer to drain,
-        // in case we received a burst of events right before the application was stopped.
-        final RingBuffer<RingBufferLogEvent> ringBuffer = temp.getRingBuffer();
-        for (int i = 0; i < MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN; i++) {
-            if (ringBuffer.hasAvailableCapacity(ringBuffer.getBufferSize())) {
-                break; // no more events queued, we can safely kill the processor thread
-            }
+        // Calling Disruptor.shutdown() will wait until all enqueued events are fully processed,
+        // but this waiting happens in a busy-spin. To avoid (postpone) wasting CPU,
+        // we sleep in short chunks, up to 10 seconds, waiting for the ringbuffer to drain.
+        for (int i = 0; hasBacklog(temp) && i < MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN;
i++) {
             try {
-                // give ringbuffer some time to drain...
-                // noinspection BusyWait
-                Thread.sleep(SLEEP_MILLIS_BETWEEN_DRAIN_ATTEMPTS);
-            } catch (final InterruptedException e) {
-                // ignored
+                Thread.sleep(SLEEP_MILLIS_BETWEEN_DRAIN_ATTEMPTS); // give up the CPU for
a while
+            } catch (final InterruptedException e) { // ignored
             }
         }
+        temp.shutdown(); // busy-spins until all events currently in the disruptor have been
processed
         executor.shutdown(); // finally, kill the processor thread
         threadlocalInfo.remove(); // LOG4J2-323
     }
 
     /**
+     * Returns {@code true} if the specified disruptor still has unprocessed events.
+     */
+    private static boolean hasBacklog(Disruptor<?> disruptor) {
+        final RingBuffer<?> ringBuffer = disruptor.getRingBuffer();
+        return !ringBuffer.hasAvailableCapacity(ringBuffer.getBufferSize());
+    }
+
+    /**
      * Creates and returns a new {@code RingBufferAdmin} that instruments the
      * ringbuffer of the {@code AsyncLogger}.
      *

Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java?rev=1592463&r1=1592462&r2=1592463&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
(original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper.java
Mon May  5 07:58:06 2014
@@ -58,14 +58,13 @@ import com.lmax.disruptor.util.Util;
  */
 class AsyncLoggerConfigHelper {
 
-    private static final int MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN = 20;
-    private static final int HALF_A_SECOND = 500;
+    private static final int MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN = 200;
+    private static final int SLEEP_MILLIS_BETWEEN_DRAIN_ATTEMPTS = 50;
     private static final int RINGBUFFER_MIN_SIZE = 128;
     private static final int RINGBUFFER_DEFAULT_SIZE = 256 * 1024;
     private static final Logger LOGGER = StatusLogger.getLogger();
 
-    private static ThreadFactory threadFactory = new DaemonThreadFactory(
-            "AsyncLoggerConfig-");
+    private static ThreadFactory threadFactory = new DaemonThreadFactory("AsyncLoggerConfig-");
     private static volatile Disruptor<Log4jEventWrapper> disruptor;
     private static ExecutorService executor;
 
@@ -256,7 +255,9 @@ class AsyncLoggerConfigHelper {
         }
         final Disruptor<Log4jEventWrapper> temp = disruptor;
         if (temp == null) {
-            LOGGER.trace("AsyncLoggerConfigHelper: disruptor already shut down: ref count
is {}.", count);
+            LOGGER.trace("AsyncLoggerConfigHelper: disruptor already shut down: ref count
is {}. (Resetting to zero.)",
+                    count);
+            count = 0; // ref count must not be negative or #claim() will not work correctly
             return; // disruptor was already shut down by another thread
         }
         LOGGER.trace("AsyncLoggerConfigHelper: shutting down disruptor: ref count is {}.",
count);
@@ -264,32 +265,36 @@ class AsyncLoggerConfigHelper {
         // Must guarantee that publishing to the RingBuffer has stopped
         // before we call disruptor.shutdown()
         disruptor = null; // client code fails with NPE if log after stop = OK
-        temp.shutdown();
 
-        // wait up to 10 seconds for the ringbuffer to drain
-        final RingBuffer<Log4jEventWrapper> ringBuffer = temp.getRingBuffer();
-        for (int i = 0; i < MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN; i++) {
-            if (ringBuffer.hasAvailableCapacity(ringBuffer.getBufferSize())) {
-                break;
-            }
+        // Calling Disruptor.shutdown() will wait until all enqueued events are fully processed,
+        // but this waiting happens in a busy-spin. To avoid (postpone) wasting CPU,
+        // we sleep in short chunks, up to 10 seconds, waiting for the ringbuffer to drain.
+        for (int i = 0; hasBacklog(temp) && i < MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN;
i++) {
             try {
-                // give ringbuffer some time to drain...
-                Thread.sleep(HALF_A_SECOND);
-            } catch (final InterruptedException e) {
-                // ignored
+                Thread.sleep(SLEEP_MILLIS_BETWEEN_DRAIN_ATTEMPTS); // give up the CPU for
a while
+            } catch (final InterruptedException e) { // ignored
             }
         }
+        temp.shutdown(); // busy-spins until all events currently in the disruptor have been
processed
         executor.shutdown(); // finally, kill the processor thread
         executor = null; // release reference to allow GC
     }
 
     /**
+     * Returns {@code true} if the specified disruptor still has unprocessed events.
+     */
+    private static boolean hasBacklog(Disruptor<?> disruptor) {
+        final RingBuffer<?> ringBuffer = disruptor.getRingBuffer();
+        return !ringBuffer.hasAvailableCapacity(ringBuffer.getBufferSize());
+    }
+
+    /**
      * Initialize the threadlocal that allows us to detect Logger.log() calls 
      * initiated from the appender thread, which may cause deadlock when the 
      * RingBuffer is full. (LOG4J2-471)
      */
     private static void initThreadLocalForExecutorThread() {
-        executor.submit(new Runnable(){
+        executor.submit(new Runnable() {
             @Override
             public void run() {
                 isAppenderThread.set(Boolean.TRUE);
@@ -311,12 +316,12 @@ class AsyncLoggerConfigHelper {
      *          calling thread needs to process the event itself
      */
     public boolean callAppendersFromAnotherThread(final LogEvent event) {
-        
+
         // LOG4J2-471: prevent deadlock when RingBuffer is full and object
         // being logged calls Logger.log() from its toString() method
         if (isAppenderThread.get() == Boolean.TRUE //
                 && disruptor.getRingBuffer().remainingCapacity() == 0) {
-            
+
             // bypass RingBuffer and invoke Appender directly
             return false;
         }

Modified: logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java?rev=1592463&r1=1592462&r2=1592463&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java
(original)
+++ logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java
Mon May  5 07:58:06 2014
@@ -22,13 +22,12 @@ import java.io.InputStream;
 import java.io.Serializable;
 import java.util.Collection;
 import java.util.Collections;
-import java.util.HashSet;
 import java.util.List;
 import java.util.Map;
-import java.util.Set;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.ConcurrentMap;
 import java.util.concurrent.CopyOnWriteArrayList;
+
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
@@ -40,8 +39,8 @@ import org.apache.logging.log4j.core.app
 import org.apache.logging.log4j.core.appender.ConsoleAppender;
 import org.apache.logging.log4j.core.async.AsyncLoggerConfig;
 import org.apache.logging.log4j.core.async.AsyncLoggerContextSelector;
-import org.apache.logging.log4j.core.config.plugins.util.PluginBuilder;
 import org.apache.logging.log4j.core.config.plugins.PluginFactory;
+import org.apache.logging.log4j.core.config.plugins.util.PluginBuilder;
 import org.apache.logging.log4j.core.config.plugins.util.PluginManager;
 import org.apache.logging.log4j.core.config.plugins.util.PluginType;
 import org.apache.logging.log4j.core.filter.AbstractFilterable;
@@ -114,8 +113,6 @@ public abstract class AbstractConfigurat
 
     private LoggerConfig root = new LoggerConfig();
 
-    private final boolean started = false;
-
     private final ConcurrentMap<String, Object> componentMap = new ConcurrentHashMap<String,
Object>();
 
     protected PluginManager pluginManager;
@@ -187,17 +184,18 @@ public abstract class AbstractConfigurat
             }
         }
         // similarly, first stop AsyncLoggerConfig Disruptor thread(s)
-        Set<LoggerConfig> alreadyStopped = new HashSet<LoggerConfig>();
         for (final LoggerConfig logger : loggers.values()) {
             if (logger instanceof AsyncLoggerConfig) {
-                logger.clearAppenders();
+                // LOG4J2-520, LOG4J2-392:
+                // Important: do not clear appenders until after all AsyncLoggerConfigs
+                // have been stopped! Stopping the last AsyncLoggerConfig will
+                // shut down the disruptor and wait for all enqueued events to be processed.
+                // Only *after this* the appenders can be cleared or events will be lost.
                 logger.stopFilter();
-                alreadyStopped.add(logger);
             }
         }
         if (root instanceof AsyncLoggerConfig) {
             root.stopFilter();
-            alreadyStopped.add(root);
         }
 
         // Stop the appenders in reverse order in case they still have activity.
@@ -215,15 +213,12 @@ public abstract class AbstractConfigurat
             }
         }
         for (final LoggerConfig logger : loggers.values()) {
-            if (alreadyStopped.contains(logger)) {
-                continue;
-            }
+            // AsyncLoggerConfig objects may be stopped multiple times, that's okay...
             logger.clearAppenders();
             logger.stopFilter();
         }
-        if (!alreadyStopped.contains(root)) {
-            root.stopFilter();
-        }
+        // If root is an AsyncLoggerConfig it may already be stopped. Stopping it twice is
okay.
+        root.stopFilter();
         stopFilter();
         if (advertiser != null && advertisement != null) {
             advertiser.unadvertise(advertisement);

Modified: logging/log4j/log4j2/trunk/src/changes/changes.xml
URL: http://svn.apache.org/viewvc/logging/log4j/log4j2/trunk/src/changes/changes.xml?rev=1592463&r1=1592462&r2=1592463&view=diff
==============================================================================
--- logging/log4j/log4j2/trunk/src/changes/changes.xml (original)
+++ logging/log4j/log4j2/trunk/src/changes/changes.xml Mon May  5 07:58:06 2014
@@ -22,6 +22,10 @@
   </properties>
   <body>
     <release version="2.0-rc2" date="2014-MM-DD" description="Bug fixes and enhancements">
+      <action issue="LOG4J2-392" dev="rpopma" type="fix" due-to="Andre Bogus">
+        Resolved a problem with the previous solution that resulted in dropped events
+        with slow appenders when application is stopped.
+      </action>
       <action issue="LOG4J2-613" dev="mattsicker" type="fix">
         The OSGi version of log4j-web imports Servlet 2.5 at minimum instead of 3.0.
       </action>



Mime
View raw message