001/* 002 * Licensed to the Apache Software Foundation (ASF) under one or more 003 * contributor license agreements. See the NOTICE file distributed with 004 * this work for additional information regarding copyright ownership. 005 * The ASF licenses this file to You under the Apache license, Version 2.0 006 * (the "License"); you may not use this file except in compliance with 007 * the License. You may obtain a copy of the License at 008 * 009 * http://www.apache.org/licenses/LICENSE-2.0 010 * 011 * Unless required by applicable law or agreed to in writing, software 012 * distributed under the License is distributed on an "AS IS" BASIS, 013 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 014 * See the license for the specific language governing permissions and 015 * limitations under the license. 016 */ 017package org.apache.logging.log4j.core.async; 018 019import java.util.Map; 020 021import org.apache.logging.log4j.Level; 022import org.apache.logging.log4j.Marker; 023import org.apache.logging.log4j.ThreadContext; 024import org.apache.logging.log4j.ThreadContext.ContextStack; 025import org.apache.logging.log4j.core.Logger; 026import org.apache.logging.log4j.core.LoggerContext; 027import org.apache.logging.log4j.core.config.Configuration; 028import org.apache.logging.log4j.core.config.Property; 029import org.apache.logging.log4j.core.config.ReliabilityStrategy; 030import org.apache.logging.log4j.core.impl.Log4jLogEvent; 031import org.apache.logging.log4j.core.util.Clock; 032import org.apache.logging.log4j.core.util.ClockFactory; 033import org.apache.logging.log4j.core.util.Constants; 034import org.apache.logging.log4j.core.util.NanoClock; 035import org.apache.logging.log4j.message.Message; 036import org.apache.logging.log4j.message.MessageFactory; 037import org.apache.logging.log4j.message.ReusableMessage; 038import org.apache.logging.log4j.status.StatusLogger; 039 040import com.lmax.disruptor.EventTranslatorVararg; 041import com.lmax.disruptor.dsl.Disruptor; 042 043/** 044 * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the 045 * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual 046 * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a 047 * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>) 048 * <p> 049 * To use AsyncLogger, specify the System property 050 * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a 051 * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers. 052 * <p> 053 * Note that for performance reasons, this logger does not include source location by default. You need to specify 054 * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your 055 * log4j.xml configuration will produce either a "?" character or no output at all. 056 * <p> 057 * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with 058 * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library, 059 * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will 060 * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner. 061 */ 062public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> { 063 // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE! 064 // Specifically, try to keep the hot methods to 35 bytecodes or less: 065 // this is within the MaxInlineSize threshold and makes these methods candidates for 066 // immediate inlining instead of waiting until they are designated "hot enough". 067 068 private static final StatusLogger LOGGER = StatusLogger.getLogger(); 069 private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable 070 071 private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create(); 072 073 private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>(); 074 private final AsyncLoggerDisruptor loggerDisruptor; 075 076 private volatile boolean includeLocation; // reconfigurable 077 private volatile NanoClock nanoClock; // reconfigurable 078 079 /** 080 * Constructs an {@code AsyncLogger} with the specified context, name and message factory. 081 * 082 * @param context context of this logger 083 * @param name name of this logger 084 * @param messageFactory message factory of this logger 085 * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor. 086 */ 087 public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory, 088 final AsyncLoggerDisruptor loggerDisruptor) { 089 super(context, name, messageFactory); 090 this.loggerDisruptor = loggerDisruptor; 091 includeLocation = privateConfig.loggerConfig.isIncludeLocation(); 092 nanoClock = context.getConfiguration().getNanoClock(); 093 } 094 095 /* 096 * (non-Javadoc) 097 * 098 * @see org.apache.logging.log4j.core.Logger#updateConfiguration(org.apache.logging.log4j.core.config.Configuration) 099 */ 100 @Override 101 protected void updateConfiguration(final Configuration newConfig) { 102 nanoClock = newConfig.getNanoClock(); 103 includeLocation = newConfig.getLoggerConfig(name).isIncludeLocation(); 104 super.updateConfiguration(newConfig); 105 LOGGER.trace("[{}] AsyncLogger {} uses {}.", getContext().getName(), getName(), nanoClock); 106 } 107 108 // package protected for unit tests 109 NanoClock getNanoClock() { 110 return nanoClock; 111 } 112 113 private RingBufferLogEventTranslator getCachedTranslator() { 114 RingBufferLogEventTranslator result = threadLocalTranslator.get(); 115 if (result == null) { 116 result = new RingBufferLogEventTranslator(); 117 threadLocalTranslator.set(result); 118 } 119 return result; 120 } 121 122 @Override 123 public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, 124 final Throwable thrown) { 125 126 if (loggerDisruptor.isUseThreadLocals()) { 127 logWithThreadLocalTranslator(fqcn, level, marker, message, thrown); 128 } else { 129 // LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web apps 130 logWithVarargTranslator(fqcn, level, marker, message, thrown); 131 } 132 } 133 134 private boolean isReused(final Message message) { 135 return message instanceof ReusableMessage; 136 } 137 138 /** 139 * Enqueues the specified log event data for logging in a background thread. 140 * <p> 141 * This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating 142 * unnecessary objects with each event. 143 * 144 * @param fqcn fully qualified name of the caller 145 * @param level level at which the caller wants to log the message 146 * @param marker message marker 147 * @param message the log message 148 * @param thrown a {@code Throwable} or {@code null} 149 */ 150 private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker, 151 final Message message, final Throwable thrown) { 152 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 153 154 final RingBufferLogEventTranslator translator = getCachedTranslator(); 155 initTranslator(translator, fqcn, level, marker, message, thrown); 156 initTranslatorThreadValues(translator); 157 publish(translator); 158 } 159 160 private void publish(final RingBufferLogEventTranslator translator) { 161 if (!loggerDisruptor.tryPublish(translator)) { 162 handleRingBufferFull(translator); 163 } 164 } 165 166 private void handleRingBufferFull(final RingBufferLogEventTranslator translator) { 167 final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level); 168 switch (eventRoute) { 169 case ENQUEUE: 170 loggerDisruptor.enqueueLogMessageInfo(translator); 171 break; 172 case SYNCHRONOUS: 173 logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message, 174 translator.thrown); 175 break; 176 case DISCARD: 177 break; 178 default: 179 throw new IllegalStateException("Unknown EventRoute " + eventRoute); 180 } 181 } 182 183 private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn, 184 final Level level, final Marker marker, final Message message, final Throwable thrown) { 185 186 translator.setBasicValues(this, name, marker, fqcn, level, message, // 187 // don't construct ThrowableProxy until required 188 thrown, 189 190 // config properties are taken care of in the EventHandler thread 191 // in the AsyncLogger#actualAsyncLog method 192 193 // needs shallow copy to be fast (LOG4J2-154) 194 ThreadContext.getImmutableContext(), // 195 196 // needs shallow copy to be fast (LOG4J2-154) 197 ThreadContext.getImmutableStack(), // 198 // location (expensive to calculate) 199 calcLocationIfRequested(fqcn), // 200 CLOCK.currentTimeMillis(), // 201 nanoClock.nanoTime() // 202 ); 203 } 204 205 private void initTranslatorThreadValues(final RingBufferLogEventTranslator translator) { 206 // constant check should be optimized out when using default (CACHED) 207 if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) { 208 translator.updateThreadValues(); 209 } 210 } 211 212 /** 213 * Returns the caller location if requested, {@code null} otherwise. 214 * 215 * @param fqcn fully qualified caller name. 216 * @return the caller location if requested, {@code null} otherwise. 217 */ 218 private StackTraceElement calcLocationIfRequested(final String fqcn) { 219 // location: very expensive operation. LOG4J2-153: 220 // Only include if "includeLocation=true" is specified, 221 // exclude if not specified or if "false" was specified. 222 return includeLocation ? Log4jLogEvent.calcLocation(fqcn) : null; 223 } 224 225 /** 226 * Enqueues the specified log event data for logging in a background thread. 227 * <p> 228 * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a 229 * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172). 230 * 231 * @param fqcn fully qualified name of the caller 232 * @param level level at which the caller wants to log the message 233 * @param marker message marker 234 * @param message the log message 235 * @param thrown a {@code Throwable} or {@code null} 236 */ 237 private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker, 238 final Message message, final Throwable thrown) { 239 // Implementation note: candidate for optimization: exceeds 35 bytecodes. 240 241 final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor(); 242 if (disruptor == null) { 243 LOGGER.error("Ignoring log event after Log4j has been shut down."); 244 return; 245 } 246 // if the Message instance is reused, there is no point in freezing its message here 247 if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND && !isReused(message)) { // LOG4J2-898: user may choose 248 message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters 249 } 250 // calls the translateTo method on this AsyncLogger 251 disruptor.getRingBuffer().publishEvent(this, this, calcLocationIfRequested(fqcn), fqcn, level, marker, message, 252 thrown); 253 } 254 255 /* 256 * (non-Javadoc) 257 * 258 * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[]) 259 */ 260 @Override 261 public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) { 262 // Implementation note: candidate for optimization: exceeds 35 bytecodes. 263 final AsyncLogger asyncLogger = (AsyncLogger) args[0]; 264 final StackTraceElement location = (StackTraceElement) args[1]; 265 final String fqcn = (String) args[2]; 266 final Level level = (Level) args[3]; 267 final Marker marker = (Marker) args[4]; 268 final Message message = (Message) args[5]; 269 final Throwable thrown = (Throwable) args[6]; 270 271 // needs shallow copy to be fast (LOG4J2-154) 272 final Map<String, String> contextMap = ThreadContext.getImmutableContext(); 273 274 // needs shallow copy to be fast (LOG4J2-154) 275 final ContextStack contextStack = ThreadContext.getImmutableStack(); 276 277 final Thread currentThread = Thread.currentThread(); 278 final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName(); 279 event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown, contextMap, 280 contextStack, currentThread.getId(), threadName, currentThread.getPriority(), location, 281 CLOCK.currentTimeMillis(), nanoClock.nanoTime()); 282 } 283 284 /** 285 * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its 286 * toString() method 287 * 288 * @param fqcn fully qualified caller name 289 * @param level log level 290 * @param marker optional marker 291 * @param message log message 292 * @param thrown optional exception 293 */ 294 void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker, 295 final Message message, final Throwable thrown) { 296 // bypass RingBuffer and invoke Appender directly 297 final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy(); 298 strategy.log(this, getName(), fqcn, marker, level, message, thrown); 299 } 300 301 /** 302 * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread. 303 * 304 * @param event the event to log 305 */ 306 public void actualAsyncLog(final RingBufferLogEvent event) { 307 final Map<Property, Boolean> properties = privateConfig.loggerConfig.getProperties(); 308 event.mergePropertiesIntoContextMap(properties, privateConfig.config.getStrSubstitutor()); 309 final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy(); 310 strategy.log(this, event); 311 } 312}