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 2015/11/21 01:41:02 UTC
[22/35] logging-log4j2 git commit: LOG4J2-1172 Fixed ThreadLocal leak
[AsyncLogger$Info] on Tomcat when using AsyncLoggerContextSelector
LOG4J2-1172 Fixed ThreadLocal leak [AsyncLogger$Info] on Tomcat when
using AsyncLoggerContextSelector
* Log4jWebInitializerImpl.start() now detects if the LoggerContext is an
AsyncLoggerContext, and if so,
signals the AsyncLoggerContext that it is used in a web app and should
not use custom ThreadLocals.
* Depending on whether the AsyncLoggerContext has been signalled to
avoid ThreadLocals or not,
AsyncLogger now either re-uses a per-thread
RingBufferLogEventTranslator instance (cached in a ThreadLocal),
or (for web apps) creates a new varargs object array for each event.
* Inner class AsyncLogger.Info has been removed.
* ThreadNameCachingStrategy is now a top-level class.
* The cached Thread name is stored in a ThreadLocal<String> in
ThreadNameCachingStrategy.
* NanoClock is now a non-static field in AsyncLogger.
* AsyncLogger is now responsible for updating the NanoClock when the
Configuration changes.
* Determining if the current thread is the background thread is now done
by comparing thread IDs, without requiring a ThreadLocal.
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/494c04d1
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/494c04d1
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/494c04d1
Branch: refs/heads/LOG4J2-89
Commit: 494c04d1db18a89efb57e768a3167948fd13fad1
Parents: b9adcad
Author: rpopma <rp...@apache.org>
Authored: Wed Nov 11 20:42:34 2015 +0900
Committer: Ralph Goers <rg...@apache.org>
Committed: Fri Nov 20 17:39:22 2015 -0700
----------------------------------------------------------------------
.../logging/log4j/core/async/AsyncLogger.java | 266 +++++++++++++------
.../log4j/core/async/AsyncLoggerContext.java | 8 +
.../log4j/core/async/AsyncLoggerDisruptor.java | 119 ++++++---
.../apache/logging/log4j/core/async/Info.java | 109 --------
.../log4j/core/async/AsyncLoggerTest.java | 6 +-
.../core/async/AsyncLoggerTestNanoTime.java | 17 +-
.../log4j/web/Log4jWebInitializerImpl.java | 4 +
src/changes/changes.xml | 3 +
8 files changed, 308 insertions(+), 224 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/494c04d1/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
index b2a6ec5..503e596 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java
@@ -17,26 +17,28 @@
package org.apache.logging.log4j.core.async;
import java.util.Map;
-import java.util.Objects;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.ThreadContext;
+import org.apache.logging.log4j.ThreadContext.ContextStack;
import org.apache.logging.log4j.core.Logger;
import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.Property;
import org.apache.logging.log4j.core.config.ReliabilityStrategy;
import org.apache.logging.log4j.core.impl.Log4jLogEvent;
import org.apache.logging.log4j.core.util.Clock;
import org.apache.logging.log4j.core.util.ClockFactory;
import org.apache.logging.log4j.core.util.Constants;
-import org.apache.logging.log4j.core.util.DummyNanoClock;
import org.apache.logging.log4j.core.util.NanoClock;
+import org.apache.logging.log4j.core.util.NanoClockFactory;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.message.MessageFactory;
import org.apache.logging.log4j.message.TimestampMessage;
import org.apache.logging.log4j.status.StatusLogger;
+import com.lmax.disruptor.EventTranslatorVararg;
import com.lmax.disruptor.dsl.Disruptor;
/**
@@ -58,15 +60,23 @@ import com.lmax.disruptor.dsl.Disruptor;
* and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will
* never be any items left in the buffer; all log events will all be written to disk in a very efficient manner.
*/
-public class AsyncLogger extends Logger {
+public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
+ // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE!
+ // Specifically, try to keep the hot methods to 35 bytecodes or less:
+ // this is within the MaxInlineSize threshold and makes these methods candidates for
+ // immediate inlining instead of waiting until they are designated "hot enough".
private static final long serialVersionUID = 1L;
private static final StatusLogger LOGGER = StatusLogger.getLogger();
+ private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable
- private static final Clock CLOCK = ClockFactory.getClock();
- private static volatile NanoClock nanoClock = new DummyNanoClock();
+ private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create();
+
+ private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>();
private final AsyncLoggerDisruptor loggerDisruptor;
+ private volatile NanoClock nanoClock; // reconfigurable
+
/**
* Constructs an {@code AsyncLogger} with the specified context, name and message factory.
*
@@ -79,30 +89,45 @@ public class AsyncLogger extends Logger {
final AsyncLoggerDisruptor loggerDisruptor) {
super(context, name, messageFactory);
this.loggerDisruptor = loggerDisruptor;
+ nanoClock = NanoClockFactory.createNanoClock(); // based on initial configuration
}
+ /*
+ * (non-Javadoc)
+ *
+ * @see org.apache.logging.log4j.core.Logger#updateConfiguration(org.apache.logging.log4j.core.config.Configuration)
+ */
@Override
- public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,
- final Throwable thrown) {
+ protected void updateConfiguration(Configuration newConfig) {
+ super.updateConfiguration(newConfig);
+ nanoClock = NanoClockFactory.createNanoClock();
+ LOGGER.trace("[{}] AsyncLogger {} uses {}.", getContext().getName(), getName(), nanoClock);
+ }
+
+ // package protected for unit tests
+ NanoClock getNanoClock() {
+ return nanoClock;
+ }
- final Disruptor<RingBufferLogEvent> temp = loggerDisruptor.getDisruptor();
- if (temp == null) { // LOG4J2-639
- LOGGER.fatal("Ignoring log event after log4j was shut down");
- } else {
- logMessage0(temp, fqcn, level, marker, message, thrown);
+ private RingBufferLogEventTranslator getCachedTranslator() {
+ RingBufferLogEventTranslator result = threadLocalTranslator.get();
+ if (result == null) {
+ result = new RingBufferLogEventTranslator();
+ threadLocalTranslator.set(result);
}
+ return result;
}
- private void logMessage0(final Disruptor<RingBufferLogEvent> theDisruptor, final String fqcn, final Level level,
- final Marker marker, final Message message, final Throwable thrown) {
- final Info info = Info.get();
- logMessageInAppropriateThread(info, theDisruptor, fqcn, level, marker, message, thrown);
- }
+ @Override
+ public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,
+ final Throwable thrown) {
+
+ // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
- private void logMessageInAppropriateThread(final Info info, final Disruptor<RingBufferLogEvent> theDisruptor,
- final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) {
- if (!logMessageInCurrentThread(info, theDisruptor, fqcn, level, marker, message, thrown)) {
- logMessageInBackgroundThread(info, fqcn, level, marker, message, thrown);
+ if (loggerDisruptor.shouldLogInCurrentThread()) {
+ logMessageInCurrentThread(fqcn, level, marker, message, thrown);
+ } else {
+ logMessageInBackgroundThread(fqcn, level, marker, message, thrown);
}
}
@@ -110,8 +135,6 @@ public class AsyncLogger extends Logger {
* LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its
* toString() method
*
- * @param info threadlocal information - used to determine if the current thread is the background appender thread
- * @param theDisruptor used to check if the buffer is full
* @param fqcn fully qualified caller name
* @param level log level
* @param marker optional marker
@@ -120,15 +143,11 @@ public class AsyncLogger extends Logger {
* @return {@code true} if the event has been logged in the current thread, {@code false} if it should be passed to
* the background thread
*/
- private boolean logMessageInCurrentThread(Info info, final Disruptor<RingBufferLogEvent> theDisruptor,
- final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) {
- if (info.isAppenderThread && theDisruptor.getRingBuffer().remainingCapacity() == 0) {
- // bypass RingBuffer and invoke Appender directly
- final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
- strategy.log(this, getName(), fqcn, marker, level, message, thrown);
- return true;
- }
- return false;
+ private void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker,
+ final Message message, final Throwable thrown) {
+ // bypass RingBuffer and invoke Appender directly
+ final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
+ strategy.log(this, getName(), fqcn, marker, level, message, thrown);
}
/**
@@ -141,24 +160,88 @@ public class AsyncLogger extends Logger {
* @param message log message
* @param thrown optional exception
*/
- private void logMessageInBackgroundThread(Info info, final String fqcn, final Level level, final Marker marker,
+ private void logMessageInBackgroundThread(final String fqcn, final Level level, final Marker marker,
final Message message, final Throwable thrown) {
+ // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
+
if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose
message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
}
- initLogMessageInfo(info, fqcn, level, marker, message, thrown);
- loggerDisruptor.enqueueLogMessageInfo(info.translator);
+ logInBackground(fqcn, level, marker, message, thrown);
+ }
+
+ /**
+ * Enqueues the specified log event data for logging in a background thread.
+ *
+ * @param asyncLogger the {@code AsyncLogger} to call from the background thread
+ * @param location location information or {@code null}
+ * @param fqcn fully qualified name of the caller
+ * @param level level at which the caller wants to log the message
+ * @param marker message marker
+ * @param message the log message
+ * @param thrown a {@code Throwable} or {@code null}
+ */
+ private void logInBackground(final String fqcn, final Level level, final Marker marker, final Message message,
+ final Throwable thrown) {
+ // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
+
+ if (loggerDisruptor.isUseThreadLocals()) {
+ logWithThreadLocalTranslator(fqcn, level, marker, message, thrown);
+ } else {
+ // LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web apps
+ logWithVarargTranslator(fqcn, level, marker, message, thrown);
+ }
}
- private void initLogMessageInfo(Info info, final String fqcn, final Level level, final Marker marker,
+ /**
+ * Enqueues the specified log event data for logging in a background thread.
+ * <p>
+ * This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating
+ * unnecessary objects with each event.
+ *
+ * @param fqcn fully qualified name of the caller
+ * @param level level at which the caller wants to log the message
+ * @param marker message marker
+ * @param message the log message
+ * @param thrown a {@code Throwable} or {@code null}
+ */
+ private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker,
final Message message, final Throwable thrown) {
- info.translator.setValues(this, getName(), marker, fqcn, level, message, //
+ // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
+
+ final RingBufferLogEventTranslator translator = getCachedTranslator();
+ initTranslator(translator, fqcn, level, marker, message, thrown);
+ loggerDisruptor.enqueueLogMessageInfo(translator);
+ }
+
+ private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn,
+ final Level level, final Marker marker, final Message message, final Throwable thrown) {
+
+ // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
+
+ initTranslatorPart1(translator, fqcn, level, marker, message, thrown);
+ initTranslatorPart2(translator, fqcn, message);
+ }
+
+ private void initTranslatorPart1(final RingBufferLogEventTranslator translator, final String fqcn,
+ final Level level, final Marker marker, final Message message, final Throwable thrown) {
+
+ // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
+
+ translator.setValuesPart1(this, getName(), marker, fqcn, level, message, //
// don't construct ThrowableProxy until required
- thrown, //
+ thrown);
+ }
+
+ private void initTranslatorPart2(final RingBufferLogEventTranslator translator, final String fqcn,
+ final Message message) {
+
+ // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
- // config properties are taken care of in the EventHandler
- // thread in the #actualAsyncLog method
+ translator.setValuesPart2(
+ // config properties are taken care of in the EventHandler thread
+ // in the AsyncLogger#actualAsyncLog method
// needs shallow copy to be fast (LOG4J2-154)
ThreadContext.getImmutableContext(), //
@@ -167,41 +250,95 @@ public class AsyncLogger extends Logger {
ThreadContext.getImmutableStack(), //
// Thread.currentThread().getName(), //
- // info.cachedThreadName, //
- info.threadName(), //
+ THREAD_NAME_CACHING_STRATEGY.getThreadName(), //
- // location: very expensive operation. LOG4J2-153:
- // Only include if "includeLocation=true" is specified,
- // exclude if not specified or if "false" was specified.
+ // location (expensive to calculate)
calcLocationIfRequested(fqcn),
- // System.currentTimeMillis());
- // CoarseCachedClock: 20% faster than system clock, 16ms gaps
- // CachedClock: 10% faster than system clock, smaller gaps
- // LOG4J2-744 avoid calling clock altogether if message has the timestamp
eventTimeMillis(message), //
nanoClock.nanoTime() //
);
}
private long eventTimeMillis(final Message message) {
+ // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
+
+ // System.currentTimeMillis());
+ // CoarseCachedClock: 20% faster than system clock, 16ms gaps
+ // CachedClock: 10% faster than system clock, smaller gaps
+ // LOG4J2-744 avoid calling clock altogether if message has the timestamp
return message instanceof TimestampMessage ? ((TimestampMessage) message).getTimestamp() : CLOCK
.currentTimeMillis();
}
/**
+ * Enqueues the specified log event data for logging in a background thread.
+ * <p>
+ * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a
+ * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172).
+ *
+ * @param asyncLogger the {@code AsyncLogger} to call from the background thread
+ * @param location location information or {@code null}
+ * @param fqcn fully qualified name of the caller
+ * @param level level at which the caller wants to log the message
+ * @param marker message marker
+ * @param message the log message
+ * @param thrown a {@code Throwable} or {@code null}
+ */
+ private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker,
+ final Message message, final Throwable thrown) {
+ // Implementation note: candidate for optimization: exceeds 35 bytecodes.
+
+ final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
+ if (disruptor == null) {
+ LOGGER.error("Ignoring log event after Log4j has been shut down.");
+ return;
+ }
+ // calls the translateTo method on this AsyncLogger
+ disruptor.getRingBuffer().publishEvent(this, this, calcLocationIfRequested(fqcn), fqcn, level, marker, message,
+ thrown);
+ }
+
+ /*
+ * (non-Javadoc)
+ *
+ * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[])
+ */
+ @Override
+ public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) {
+ // Implementation note: candidate for optimization: exceeds 35 bytecodes.
+ final AsyncLogger asyncLogger = (AsyncLogger) args[0];
+ final StackTraceElement location = (StackTraceElement) args[1];
+ final String fqcn = (String) args[2];
+ final Level level = (Level) args[3];
+ final Marker marker = (Marker) args[4];
+ final Message message = (Message) args[5];
+ final Throwable thrown = (Throwable) args[6];
+
+ // needs shallow copy to be fast (LOG4J2-154)
+ final Map<String, String> contextMap = ThreadContext.getImmutableContext();
+
+ // needs shallow copy to be fast (LOG4J2-154)
+ final ContextStack contextStack = ThreadContext.getImmutableStack();
+
+ final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName();
+
+ event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown, contextMap,
+ contextStack, threadName, location, eventTimeMillis(message), nanoClock.nanoTime());
+ }
+
+ /**
* Returns the caller location if requested, {@code null} otherwise.
*
* @param fqcn fully qualified caller name.
* @return the caller location if requested, {@code null} otherwise.
*/
private StackTraceElement calcLocationIfRequested(String fqcn) {
+ // location: very expensive operation. LOG4J2-153:
+ // Only include if "includeLocation=true" is specified,
+ // exclude if not specified or if "false" was specified.
final boolean includeLocation = privateConfig.loggerConfig.isIncludeLocation();
- return includeLocation ? location(fqcn) : null;
- }
-
- private static StackTraceElement location(final String fqcnOfLogger) {
- return Log4jLogEvent.calcLocation(fqcnOfLogger);
+ return includeLocation ? Log4jLogEvent.calcLocation(fqcn) : null;
}
/**
@@ -215,25 +352,4 @@ public class AsyncLogger extends Logger {
final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
strategy.log(this, event);
}
-
- /**
- * Returns the {@code NanoClock} to use for creating the nanoTime timestamp of log events.
- *
- * @return the {@code NanoClock} to use for creating the nanoTime timestamp of log events
- */
- public static NanoClock getNanoClock() {
- return nanoClock;
- }
-
- /**
- * Sets the {@code NanoClock} to use for creating the nanoTime timestamp of log events.
- * <p>
- * FOR INTERNAL USE. This method may be called with a different {@code NanoClock} implementation when the
- * configuration changes.
- *
- * @param nanoClock the {@code NanoClock} to use for creating the nanoTime timestamp of log events
- */
- public static void setNanoClock(NanoClock nanoClock) {
- AsyncLogger.nanoClock = Objects.requireNonNull(nanoClock, "NanoClock must be non-null");
- }
}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/494c04d1/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
index 1a891cd..2e075e0 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
@@ -114,4 +114,12 @@ public class AsyncLoggerContext extends LoggerContext {
public RingBufferAdmin createRingBufferAdmin() {
return loggerDisruptor.createRingBufferAdmin(getName());
}
+
+ /**
+ * Signals this context whether it is allowed to use ThreadLocal objects for efficiency.
+ * @param useThreadLocals whether this context is allowed to use ThreadLocal objects
+ */
+ public void setUseThreadLocals(final boolean useThreadLocals) {
+ loggerDisruptor.setUseThreadLocals(useThreadLocals);
+ }
}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/494c04d1/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java
index af991a5..987d0bc 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java
@@ -40,9 +40,12 @@ class AsyncLoggerDisruptor {
private static final int MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN = 200;
private static final StatusLogger LOGGER = StatusLogger.getLogger();
- private String contextName;
- private ExecutorService executor;
private volatile Disruptor<RingBufferLogEvent> disruptor;
+ private ExecutorService executor;
+ private String contextName;
+
+ private boolean useThreadLocalTranslator;
+ private long backgroundThreadId;
AsyncLoggerDisruptor(String contextName) {
this.contextName = contextName;
@@ -67,15 +70,16 @@ class AsyncLoggerDisruptor {
*/
synchronized void start() {
if (disruptor != null) {
- LOGGER.trace("[{}] AsyncLoggerHelper not starting new disruptor for this context, using existing object.",
+ LOGGER.trace(
+ "[{}] AsyncLoggerDisruptor not starting new disruptor for this context, using existing object.",
contextName);
return;
}
- LOGGER.trace("[{}] AsyncLoggerHelper creating new disruptor for this context.", contextName);
+ LOGGER.trace("[{}] AsyncLoggerDisruptor creating new disruptor for this context.", contextName);
final int ringBufferSize = DisruptorUtil.calculateRingBufferSize("AsyncLogger.RingBufferSize");
final WaitStrategy waitStrategy = DisruptorUtil.createWaitStrategy("AsyncLogger.WaitStrategy");
executor = Executors.newSingleThreadExecutor(new DaemonThreadFactory("AsyncLogger[" + contextName + "]"));
- Info.initExecutorThreadInstance(executor);
+ backgroundThreadId = DisruptorUtil.getExecutorThreadId(executor);
disruptor = new Disruptor<>(RingBufferLogEvent.FACTORY, ringBufferSize, executor, ProducerType.MULTI,
waitStrategy);
@@ -91,29 +95,9 @@ class AsyncLoggerDisruptor {
+ "exceptionHandler={}...", contextName, disruptor.getRingBuffer().getBufferSize(), waitStrategy
.getClass().getSimpleName(), errorHandler);
disruptor.start();
- }
-
- void enqueueLogMessageInfo(final RingBufferLogEventTranslator translator) {
- // LOG4J2-639: catch NPE if disruptor field was set to null in release()
- try {
- // Note: we deliberately access the volatile disruptor field afresh here.
- // Avoiding this and using an older reference could result in adding a log event to the disruptor after it
- // was shut down, which could cause the publishEvent method to hang and never return.
- disruptor.publishEvent(translator);
- } catch (final NullPointerException npe) {
- LOGGER.fatal("[{}] Ignoring log event after log4j was shut down.", contextName);
- }
- }
- /**
- * Creates and returns a new {@code RingBufferAdmin} that instruments the ringbuffer of the {@code AsyncLogger}.
- *
- * @param jmxContextName name of the {@code AsyncLoggerContext}
- * @return a new {@code RingBufferAdmin} that instruments the ringbuffer
- */
- public RingBufferAdmin createRingBufferAdmin(final String jmxContextName) {
- final RingBuffer<RingBufferLogEvent> ring = disruptor == null ? null : disruptor.getRingBuffer();
- return RingBufferAdmin.forAsyncLogger(ring, jmxContextName);
+ LOGGER.trace("[{}] AsyncLoggers use a {} translator", contextName, useThreadLocalTranslator ? "threadlocal"
+ : "vararg");
}
/**
@@ -123,10 +107,10 @@ class AsyncLoggerDisruptor {
synchronized void stop() {
final Disruptor<RingBufferLogEvent> temp = getDisruptor();
if (temp == null) {
- LOGGER.trace("[{}] AsyncLoggerHelper: disruptor for this context already shut down.", contextName);
+ LOGGER.trace("[{}] AsyncLoggerDisruptor: disruptor for this context already shut down.", contextName);
return; // disruptor was already shut down by another thread
}
- LOGGER.debug("[{}] AsyncLoggerHelper: shutting down disruptor for this context.", contextName);
+ LOGGER.debug("[{}] AsyncLoggerDisruptor: shutting down disruptor for this context.", contextName);
// We 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. This is by design.
@@ -142,10 +126,9 @@ class AsyncLoggerDisruptor {
}
temp.shutdown(); // busy-spins until all events currently in the disruptor have been processed
- LOGGER.trace("[{}] AsyncLoggerHelper: shutting down disruptor executor.", contextName);
+ LOGGER.trace("[{}] AsyncLoggerDisruptor: shutting down disruptor executor.", contextName);
executor.shutdown(); // finally, kill the processor thread
executor = null;
- // Info.THREADLOCAL.remove(); // LOG4J2-323
}
/**
@@ -156,4 +139,78 @@ class AsyncLoggerDisruptor {
return !ringBuffer.hasAvailableCapacity(ringBuffer.getBufferSize());
}
+ /**
+ * Creates and returns a new {@code RingBufferAdmin} that instruments the ringbuffer of the {@code AsyncLogger}.
+ *
+ * @param jmxContextName name of the {@code AsyncLoggerContext}
+ * @return a new {@code RingBufferAdmin} that instruments the ringbuffer
+ */
+ public RingBufferAdmin createRingBufferAdmin(final String jmxContextName) {
+ final RingBuffer<RingBufferLogEvent> ring = disruptor == null ? null : disruptor.getRingBuffer();
+ return RingBufferAdmin.forAsyncLogger(ring, jmxContextName);
+ }
+
+ /**
+ * Returns {@code true} if the current log event should be logged in the current thread, {@code false} if it should
+ * be logged in a background thread. (LOG4J2-471)
+ *
+ * @return whether the current log event should be logged in the current thread
+ */
+ boolean shouldLogInCurrentThread() {
+ return currentThreadIsAppenderThread() && isRingBufferFull();
+ }
+
+ /**
+ * Returns {@code true} if the current thread is the Disruptor background thread, {@code false} otherwise.
+ *
+ * @return whether this thread is the Disruptor background thread.
+ */
+ private boolean currentThreadIsAppenderThread() {
+ return Thread.currentThread().getId() == backgroundThreadId;
+ }
+
+ /**
+ * Returns {@code true} if the Disruptor is {@code null} because it has been stopped, or if its Ringbuffer is full.
+ *
+ * @return {@code true} if the disruptor is currently not usable
+ */
+ private boolean isRingBufferFull() {
+ final Disruptor<RingBufferLogEvent> theDisruptor = this.disruptor;
+ return theDisruptor == null || theDisruptor.getRingBuffer().remainingCapacity() == 0;
+ }
+
+ void enqueueLogMessageInfo(final RingBufferLogEventTranslator translator) {
+ // LOG4J2-639: catch NPE if disruptor field was set to null in stop()
+ try {
+ // Note: we deliberately access the volatile disruptor field afresh here.
+ // Avoiding this and using an older reference could result in adding a log event to the disruptor after it
+ // was shut down, which could cause the publishEvent method to hang and never return.
+ disruptor.publishEvent(translator);
+ } catch (final NullPointerException npe) {
+ LOGGER.fatal("[{}] Ignoring log event after log4j was shut down.", contextName);
+ }
+ }
+
+ /**
+ * Returns whether it is allowed to store non-JDK classes in ThreadLocal objects for efficiency.
+ *
+ * @return whether AsyncLoggers are allowed to use ThreadLocal objects
+ * @since 2.5
+ * @see <a href="https://issues.apache.org/jira/browse/LOG4J2-1172">LOG4J2-1172</a>
+ */
+ public boolean isUseThreadLocals() {
+ return useThreadLocalTranslator;
+ }
+
+ /**
+ * Signals this AsyncLoggerDisruptor whether it is allowed to store non-JDK classes in ThreadLocal objects for
+ * efficiency.
+ *
+ * @param allow whether AsyncLoggers are allowed to use ThreadLocal objects
+ * @since 2.5
+ * @see <a href="https://issues.apache.org/jira/browse/LOG4J2-1172">LOG4J2-1172</a>
+ */
+ public void setUseThreadLocals(final boolean allow) {
+ useThreadLocalTranslator = allow;
+ }
}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/494c04d1/log4j-core/src/main/java/org/apache/logging/log4j/core/async/Info.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/Info.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/Info.java
deleted file mode 100644
index b589951..0000000
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/Info.java
+++ /dev/null
@@ -1,109 +0,0 @@
-/*
- * Licensed to the Apache Software Foundation (ASF) under one or more
- * contributor license agreements. See the NOTICE file distributed with
- * this work for additional information regarding copyright ownership.
- * The ASF licenses this file to You under the Apache license, Version 2.0
- * (the "License"); you may not use this file except in compliance with
- * the License. You may obtain a copy of the License at
- *
- * http://www.apache.org/licenses/LICENSE-2.0
- *
- * Unless required by applicable law or agreed to in writing, software
- * distributed under the License is distributed on an "AS IS" BASIS,
- * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
- * See the license for the specific language governing permissions and
- * limitations under the license.
- */
-
-package org.apache.logging.log4j.core.async;
-
-import java.util.concurrent.ExecutorService;
-
-import org.apache.logging.log4j.status.StatusLogger;
-import org.apache.logging.log4j.util.PropertiesUtil;
-
-/**
- * Tuple with the event translator and thread name for a thread.
- */
-class Info {
- /**
- * Strategy for deciding whether thread name should be cached or not.
- */
- enum ThreadNameStrategy { // LOG4J2-467
- CACHED {
- @Override
- public String getThreadName(final Info info) {
- return info.cachedThreadName;
- }
- },
- UNCACHED {
- @Override
- public String getThreadName(final Info info) {
- return Thread.currentThread().getName();
- }
- };
- abstract String getThreadName(Info info);
-
- static Info.ThreadNameStrategy create() {
- final String name = PropertiesUtil.getProperties().getStringProperty("AsyncLogger.ThreadNameStrategy",
- CACHED.name());
- try {
- final Info.ThreadNameStrategy result = ThreadNameStrategy.valueOf(name);
- LOGGER.debug("AsyncLogger.ThreadNameStrategy={}", result);
- return result;
- } catch (final Exception ex) {
- LOGGER.debug("Using AsyncLogger.ThreadNameStrategy.CACHED: '{}' not valid: {}", name, ex.toString());
- return CACHED;
- }
- }
- }
-
- private static final StatusLogger LOGGER = StatusLogger.getLogger();
- private static final Info.ThreadNameStrategy THREAD_NAME_STRATEGY = ThreadNameStrategy.create();
- private static final ThreadLocal<Info> THREADLOCAL = new ThreadLocal<Info>();
-
- final RingBufferLogEventTranslator translator;
- final boolean isAppenderThread;
- private final String cachedThreadName;
-
- Info(final RingBufferLogEventTranslator translator, final String threadName, final boolean appenderThread) {
- this.translator = translator;
- this.cachedThreadName = threadName;
- this.isAppenderThread = appenderThread;
- }
-
- /**
- * Initialize an {@code Info} object that is threadlocal to the consumer/appender thread. This Info object
- * uniquely has attribute {@code isAppenderThread} set to {@code true}. All other Info objects will have this
- * attribute set to {@code false}. This allows us to detect Logger.log() calls initiated from the appender
- * thread, which may cause deadlock when the RingBuffer is full. (LOG4J2-471)
- *
- * @param executor runs the appender thread
- */
- public static void initExecutorThreadInstance(final ExecutorService executor) {
- executor.submit(new Runnable() {
- @Override
- public void run() {
- final boolean isAppenderThread = true;
- final Info info = new Info(new RingBufferLogEventTranslator(), //
- Thread.currentThread().getName(), isAppenderThread);
- THREADLOCAL.set(info);
- }
- });
- }
-
- static Info get() {
- Info result = THREADLOCAL.get();
- if (result == null) {
- // by default, set isAppenderThread to false
- result = new Info(new RingBufferLogEventTranslator(), Thread.currentThread().getName(), false);
- THREADLOCAL.set(result);
- }
- return result;
- }
-
- // LOG4J2-467
- String threadName() {
- return THREAD_NAME_STRATEGY.getThreadName(this);
- }
-}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/494c04d1/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTest.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTest.java
index 6c545d7..319d37e 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTest.java
@@ -21,7 +21,6 @@ import java.io.File;
import java.io.FileReader;
import org.apache.logging.log4j.LogManager;
-import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.CoreLoggerContexts;
import org.apache.logging.log4j.core.config.ConfigurationFactory;
import org.apache.logging.log4j.core.util.Constants;
@@ -53,7 +52,7 @@ public class AsyncLoggerTest {
final File file = new File("target", "AsyncLoggerTest.log");
// System.out.println(f.getAbsolutePath());
file.delete();
- final Logger log = LogManager.getLogger("com.foo.Bar");
+ final AsyncLogger log = (AsyncLogger) LogManager.getLogger("com.foo.Bar");
final String msg = "Async logger msg";
log.info(msg, new InternalError("this is not a real error"));
CoreLoggerContexts.stopLoggerContext(false, file); // stop async thread
@@ -71,7 +70,8 @@ public class AsyncLoggerTest {
@Test
public void testNanoClockInitiallyDummy() {
- assertTrue(AsyncLogger.getNanoClock() instanceof DummyNanoClock);
+ final AsyncLogger log = (AsyncLogger) LogManager.getLogger("com.foo.Bar");
+ assertTrue(log.getNanoClock() instanceof DummyNanoClock);
}
}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/494c04d1/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestNanoTime.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestNanoTime.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestNanoTime.java
index 0288f85..bebb0ce 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestNanoTime.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestNanoTime.java
@@ -22,11 +22,12 @@ import java.io.FileReader;
import java.util.concurrent.TimeUnit;
import org.apache.logging.log4j.LogManager;
-import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.CoreLoggerContexts;
import org.apache.logging.log4j.core.config.ConfigurationFactory;
import org.apache.logging.log4j.core.util.Constants;
import org.apache.logging.log4j.core.util.DummyNanoClock;
+import org.apache.logging.log4j.core.util.NanoClockFactory;
+import org.apache.logging.log4j.core.util.NanoClockFactory.Mode;
import org.apache.logging.log4j.core.util.SystemNanoClock;
import org.apache.logging.log4j.util.Strings;
import org.junit.AfterClass;
@@ -55,15 +56,19 @@ public class AsyncLoggerTestNanoTime {
final File file = new File("target", "NanoTimeToFileTest.log");
// System.out.println(f.getAbsolutePath());
file.delete();
- final Logger log = LogManager.getLogger("com.foo.Bar");
+ final AsyncLogger log = (AsyncLogger) LogManager.getLogger("com.foo.Bar");
final long before = System.nanoTime();
log.info("Use actual System.nanoTime()");
- assertTrue("using SystemNanoClock", AsyncLogger.getNanoClock() instanceof SystemNanoClock);
+ assertTrue("using SystemNanoClock", log.getNanoClock() instanceof SystemNanoClock);
- final long DUMMYNANOTIME = 123;
- AsyncLogger.setNanoClock(new DummyNanoClock(DUMMYNANOTIME));
+ NanoClockFactory.setMode(Mode.Dummy);
+ final long DUMMYNANOTIME = 0;
+
+ // trigger a new nano clock lookup
+ log.updateConfiguration(log.getContext().getConfiguration());
+
log.info("Use dummy nano clock");
- assertTrue("using SystemNanoClock", AsyncLogger.getNanoClock() instanceof DummyNanoClock);
+ assertTrue("using SystemNanoClock", log.getNanoClock() instanceof DummyNanoClock);
CoreLoggerContexts.stopLoggerContext(file); // stop async thread
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/494c04d1/log4j-web/src/main/java/org/apache/logging/log4j/web/Log4jWebInitializerImpl.java
----------------------------------------------------------------------
diff --git a/log4j-web/src/main/java/org/apache/logging/log4j/web/Log4jWebInitializerImpl.java b/log4j-web/src/main/java/org/apache/logging/log4j/web/Log4jWebInitializerImpl.java
index 825e1a9..17f4ece 100644
--- a/log4j-web/src/main/java/org/apache/logging/log4j/web/Log4jWebInitializerImpl.java
+++ b/log4j-web/src/main/java/org/apache/logging/log4j/web/Log4jWebInitializerImpl.java
@@ -29,6 +29,7 @@ import javax.servlet.ServletContext;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.AbstractLifeCycle;
import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.async.AsyncLoggerContext;
import org.apache.logging.log4j.core.config.Configurator;
import org.apache.logging.log4j.core.impl.ContextAnchor;
import org.apache.logging.log4j.core.impl.Log4jContextFactory;
@@ -108,6 +109,9 @@ final class Log4jWebInitializerImpl extends AbstractLifeCycle implements Log4jWe
} else {
this.initializeNonJndi(location);
}
+ if (this.loggerContext instanceof AsyncLoggerContext) {
+ ((AsyncLoggerContext) this.loggerContext).setUseThreadLocals(false);
+ }
this.servletContext.setAttribute(CONTEXT_ATTRIBUTE, this.loggerContext);
super.setStarted();
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/494c04d1/src/changes/changes.xml
----------------------------------------------------------------------
diff --git a/src/changes/changes.xml b/src/changes/changes.xml
index 16e214a..9dd732f 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -48,6 +48,9 @@
<action issue="LOG4J2-1187" dev="ggregory" type="add">
Support use case for java.sql.DriverManager.setLogStream(PrintStream).
</action>
+ <action issue="LOG4J2-1172" dev="rpopma" type="fix">
+ Fixed ThreadLocal leak [AsyncLogger$Info] on Tomcat when using AsyncLoggerContextSelector.
+ </action>
<action issue="LOG4J2-1176" dev="rpopma" type="fix">
Fixed memory leak when log4j jars are in Tomcat's lib folder.
</action>