LOG4J2-1080 AsyncLogger fixes and optimizations - AsyncLogger now tries to publish to the ring buffer and falls back to AsyncEventRouter when the queue is full - falling back to AsyncEventRouter no longer calls EventRoute.logMessage() but internally switches on the enum to avoid unnecessarily re-populating the translator - EventRoute.logMessage() implementations for AsyncLogger have been removed - simplified RingBufferLogEventTranslator initialization - RingBufferLogEventTranslator thread-related fields are not modified by default unless ThreadNameCachingStrategy is UNCACHED - optimization for determining whether location should be calculated or not
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/a8bbdcd1 Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/a8bbdcd1 Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/a8bbdcd1 Branch: refs/heads/LOG4J2-1116 Commit: a8bbdcd1f355e98bc89c96c02e057380836dd6e0 Parents: 43cefdd Author: rpopma <rpo...@apache.org> Authored: Tue Mar 15 02:26:36 2016 +1100 Committer: rpopma <rpo...@apache.org> Committed: Tue Mar 15 02:26:36 2016 +1100 ---------------------------------------------------------------------- .../logging/log4j/core/async/AsyncLogger.java | 165 ++++++++----------- .../logging/log4j/core/async/EventRoute.java | 2 - 2 files changed, 68 insertions(+), 99 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/a8bbdcd1/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 226ba08..8817b29 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 @@ -74,6 +74,8 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>(); private final AsyncLoggerDisruptor loggerDisruptor; + // Reconfigurable. Volatile field nanoClock is always updated later, so no need to make includeLocation volatile. + private boolean includeLocation; private volatile NanoClock nanoClock; // reconfigurable /** @@ -88,6 +90,7 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf final AsyncLoggerDisruptor loggerDisruptor) { super(context, name, messageFactory); this.loggerDisruptor = loggerDisruptor; + includeLocation = privateConfig.loggerConfig.isIncludeLocation(); nanoClock = context.getConfiguration().getNanoClock(); } @@ -99,6 +102,7 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf @Override protected void updateConfiguration(Configuration newConfig) { super.updateConfiguration(newConfig); + includeLocation = privateConfig.loggerConfig.isIncludeLocation(); nanoClock = newConfig.getNanoClock(); LOGGER.trace("[{}] AsyncLogger {} uses {}.", getContext().getName(), getName(), nanoClock); } @@ -121,66 +125,10 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf 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! - - final EventRoute eventRoute = loggerDisruptor.getEventRoute(level); - eventRoute.logMessage(this, fqcn, level, marker, message, thrown); - } - - /** - * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its - * toString() method - * - * @param fqcn fully qualified caller name - * @param level log level - * @param marker optional marker - * @param message log message - * @param thrown optional exception - */ - 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); - } - - /** - * Enqueues the specified message to be logged in the background thread. - * - * @param fqcn fully qualified caller name - * @param level log level - * @param marker optional marker - * @param message log message - * @param thrown optional exception - */ - 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 the Message instance is reused, there is no point in freezing its message here - if (!isReused(message) && !Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose + if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND && !isReused(message)) { // LOG4J2-898: user may choose message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters } - logInBackground(fqcn, level, marker, message, thrown); - } - - private boolean isReused(final Message message) { - return message instanceof ReusableMessage; - } - - /** - * Enqueues the specified log event data for logging in a background thread. - * - * @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); @@ -190,6 +138,10 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf } } + private boolean isReused(final Message message) { + return message instanceof ReusableMessage; + } + /** * Enqueues the specified log event data for logging in a background thread. * <p> @@ -208,35 +160,35 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf final RingBufferLogEventTranslator translator = getCachedTranslator(); initTranslator(translator, fqcn, level, marker, message, thrown); - loggerDisruptor.enqueueLogMessageInfo(translator); + if (!loggerDisruptor.tryPublish(translator)) { + handleRingBufferFull(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 handleRingBufferFull(final RingBufferLogEventTranslator translator) { + final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level); + switch (eventRoute) { + case ENQUEUE: + loggerDisruptor.enqueueLogMessageInfo(translator); + break; + case SYNCHRONOUS: + logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message, + translator.thrown); + break; + case DISCARD: + break; + default: + throw new IllegalStateException("Unknown EventRoute " + eventRoute); + } } - private void initTranslatorPart1(final RingBufferLogEventTranslator translator, final String fqcn, + 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! - - translator.setValuesPart1(this, getName(), marker, fqcn, level, message, // + translator.setBasicValues(this, name, marker, fqcn, level, message, // // don't construct ThrowableProxy until required - thrown); - } - - private void initTranslatorPart2(final RingBufferLogEventTranslator translator, final String fqcn, - final Message message) { + thrown, - // Implementation note: this method is tuned for performance. MODIFY WITH CARE! - - final Thread currentThread = Thread.currentThread(); - translator.setValuesPart2( // config properties are taken care of in the EventHandler thread // in the AsyncLogger#actualAsyncLog method @@ -245,17 +197,33 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf // needs shallow copy to be fast (LOG4J2-154) ThreadContext.getImmutableStack(), // - - currentThread.getId(), // - - // Thread.currentThread().getName(), // - THREAD_NAME_CACHING_STRATEGY.getThreadName(), - - currentThread.getPriority(), // // location (expensive to calculate) - calcLocationIfRequested(fqcn), - eventTimeMillis(message), nanoClock.nanoTime() // - ); + calcLocationIfRequested(fqcn), // + eventTimeMillis(message), // + nanoClock.nanoTime() // + ); + // constant check should be optimized out when using default (CACHED) + if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) { + final Thread currentThread = Thread.currentThread(); + translator.setThreadValues( + currentThread.getId(), // + currentThread.getName(), // + currentThread.getPriority() // + ); + } + } + + /** + * 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. + return includeLocation ? Log4jLogEvent.calcLocation(fqcn) : null; } private long eventTimeMillis(final Message message) { @@ -325,17 +293,20 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf } /** - * Returns the caller location if requested, {@code null} otherwise. + * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its + * toString() method * - * @param fqcn fully qualified caller name. - * @return the caller location if requested, {@code null} otherwise. + * @param fqcn fully qualified caller name + * @param level log level + * @param marker optional marker + * @param message log message + * @param thrown optional exception */ - 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 ? Log4jLogEvent.calcLocation(fqcn) : null; + 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); } /** http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/a8bbdcd1/log4j-core/src/main/java/org/apache/logging/log4j/core/async/EventRoute.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/EventRoute.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/EventRoute.java index c778196..ce57008 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/EventRoute.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/EventRoute.java @@ -36,7 +36,6 @@ public enum EventRoute { @Override public void logMessage(final AsyncLogger asyncLogger, final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) { - asyncLogger.logMessageInBackgroundThread(fqcn, level, marker, message, thrown); } @Override @@ -56,7 +55,6 @@ public enum EventRoute { @Override public void logMessage(final AsyncLogger asyncLogger, final String fqcn, final Level level, final Marker marker, final Message message, final Throwable thrown) { - asyncLogger.logMessageInCurrentThread(fqcn, level, marker, message, thrown); } @Override
