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/c9eff73f Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/c9eff73f Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/c9eff73f Branch: refs/heads/LOG4J-1181 Commit: c9eff73f84022d813ec14e82bab6a5827420c137 Parents: 908ae82 Author: rpopma <[email protected]> Authored: Wed Nov 11 20:42:34 2015 +0900 Committer: rpopma <[email protected]> Committed: Wed Nov 11 20:42:34 2015 +0900 ---------------------------------------------------------------------- .../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/c9eff73f/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/c9eff73f/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/c9eff73f/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/c9eff73f/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/c9eff73f/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/c9eff73f/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/c9eff73f/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/c9eff73f/src/changes/changes.xml ---------------------------------------------------------------------- diff --git a/src/changes/changes.xml b/src/changes/changes.xml index 13f4e9a..c82cc9d 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -42,6 +42,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>
