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.List; 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.ContextDataInjector; 026import org.apache.logging.log4j.core.Logger; 027import org.apache.logging.log4j.core.LoggerContext; 028import org.apache.logging.log4j.core.config.Configuration; 029import org.apache.logging.log4j.core.config.Property; 030import org.apache.logging.log4j.core.config.ReliabilityStrategy; 031import org.apache.logging.log4j.core.impl.ContextDataFactory; 032import org.apache.logging.log4j.core.impl.ContextDataInjectorFactory; 033import org.apache.logging.log4j.core.util.Clock; 034import org.apache.logging.log4j.core.util.ClockFactory; 035import org.apache.logging.log4j.core.util.NanoClock; 036import org.apache.logging.log4j.message.Message; 037import org.apache.logging.log4j.message.MessageFactory; 038import org.apache.logging.log4j.message.ReusableMessage; 039import org.apache.logging.log4j.status.StatusLogger; 040import org.apache.logging.log4j.util.StackLocatorUtil; 041import org.apache.logging.log4j.util.StringMap; 042 043import com.lmax.disruptor.EventTranslatorVararg; 044import com.lmax.disruptor.dsl.Disruptor; 045 046/** 047 * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the 048 * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual 049 * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a 050 * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>) 051 * <p> 052 * To use AsyncLogger, specify the System property 053 * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a 054 * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers. 055 * <p> 056 * Note that for performance reasons, this logger does not include source location by default. You need to specify 057 * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your 058 * log4j.xml configuration will produce either a "?" character or no output at all. 059 * <p> 060 * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with 061 * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library, 062 * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will 063 * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner. 064 */ 065public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> { 066 // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE! 067 // Specifically, try to keep the hot methods to 35 bytecodes or less: 068 // this is within the MaxInlineSize threshold and makes these methods candidates for 069 // immediate inlining instead of waiting until they are designated "hot enough". 070 071 private static final StatusLogger LOGGER = StatusLogger.getLogger(); 072 private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable 073 private static final ContextDataInjector CONTEXT_DATA_INJECTOR = ContextDataInjectorFactory.createInjector(); 074 075 private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create(); 076 077 private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>(); 078 private final AsyncLoggerDisruptor loggerDisruptor; 079 080 private volatile boolean includeLocation; // reconfigurable 081 private volatile NanoClock nanoClock; // reconfigurable 082 083 /** 084 * Constructs an {@code AsyncLogger} with the specified context, name and message factory. 085 * 086 * @param context context of this logger 087 * @param name name of this logger 088 * @param messageFactory message factory of this logger 089 * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor. 090 */ 091 public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory, 092 final AsyncLoggerDisruptor loggerDisruptor) { 093 super(context, name, messageFactory); 094 this.loggerDisruptor = loggerDisruptor; 095 includeLocation = privateConfig.loggerConfig.isIncludeLocation(); 096 nanoClock = context.getConfiguration().getNanoClock(); 097 } 098 099 /* 100 * (non-Javadoc) 101 * 102 * @see org.apache.logging.log4j.core.Logger#updateConfiguration(org.apache.logging.log4j.core.config.Configuration) 103 */ 104 @Override 105 protected void updateConfiguration(final Configuration newConfig) { 106 nanoClock = newConfig.getNanoClock(); 107 includeLocation = newConfig.getLoggerConfig(name).isIncludeLocation(); 108 super.updateConfiguration(newConfig); 109 } 110 111 // package protected for unit tests 112 NanoClock getNanoClock() { 113 return nanoClock; 114 } 115 116 private RingBufferLogEventTranslator getCachedTranslator() { 117 RingBufferLogEventTranslator result = threadLocalTranslator.get(); 118 if (result == null) { 119 result = new RingBufferLogEventTranslator(); 120 threadLocalTranslator.set(result); 121 } 122 return result; 123 } 124 125 @Override 126 public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, 127 final Throwable thrown) { 128 129 if (loggerDisruptor.isUseThreadLocals()) { 130 logWithThreadLocalTranslator(fqcn, level, marker, message, thrown); 131 } else { 132 // LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web apps 133 logWithVarargTranslator(fqcn, level, marker, message, thrown); 134 } 135 } 136 137 private boolean isReused(final Message message) { 138 return message instanceof ReusableMessage; 139 } 140 141 /** 142 * Enqueues the specified log event data for logging in a background thread. 143 * <p> 144 * This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating 145 * unnecessary objects with each event. 146 * 147 * @param fqcn fully qualified name of the caller 148 * @param level level at which the caller wants to log the message 149 * @param marker message marker 150 * @param message the log message 151 * @param thrown a {@code Throwable} or {@code null} 152 */ 153 private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker, 154 final Message message, final Throwable thrown) { 155 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 156 157 final RingBufferLogEventTranslator translator = getCachedTranslator(); 158 initTranslator(translator, fqcn, level, marker, message, thrown); 159 initTranslatorThreadValues(translator); 160 publish(translator); 161 } 162 163 private void publish(final RingBufferLogEventTranslator translator) { 164 if (!loggerDisruptor.tryPublish(translator)) { 165 handleRingBufferFull(translator); 166 } 167 } 168 169 private void handleRingBufferFull(final RingBufferLogEventTranslator translator) { 170 if (Logger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031 171 // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock 172 final Message message = AsyncQueueFullMessageUtil.transform(translator.message); 173 logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, message, 174 translator.thrown); 175 return; 176 } 177 final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level); 178 switch (eventRoute) { 179 case ENQUEUE: 180 loggerDisruptor.enqueueLogMessageInfo(translator); 181 break; 182 case SYNCHRONOUS: 183 logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message, 184 translator.thrown); 185 break; 186 case DISCARD: 187 break; 188 default: 189 throw new IllegalStateException("Unknown EventRoute " + eventRoute); 190 } 191 } 192 193 private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn, 194 final Level level, final Marker marker, final Message message, final Throwable thrown) { 195 196 translator.setBasicValues(this, name, marker, fqcn, level, message, // 197 // don't construct ThrowableProxy until required 198 thrown, 199 200 // needs shallow copy to be fast (LOG4J2-154) 201 ThreadContext.getImmutableStack(), // 202 203 // location (expensive to calculate) 204 calcLocationIfRequested(fqcn), // 205 CLOCK.currentTimeMillis(), // 206 nanoClock.nanoTime() // 207 ); 208 } 209 210 private void initTranslatorThreadValues(final RingBufferLogEventTranslator translator) { 211 // constant check should be optimized out when using default (CACHED) 212 if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) { 213 translator.updateThreadValues(); 214 } 215 } 216 217 /** 218 * Returns the caller location if requested, {@code null} otherwise. 219 * 220 * @param fqcn fully qualified caller name. 221 * @return the caller location if requested, {@code null} otherwise. 222 */ 223 private StackTraceElement calcLocationIfRequested(final String fqcn) { 224 // location: very expensive operation. LOG4J2-153: 225 // Only include if "includeLocation=true" is specified, 226 // exclude if not specified or if "false" was specified. 227 return includeLocation ? StackLocatorUtil.calcLocation(fqcn) : null; 228 } 229 230 /** 231 * Enqueues the specified log event data for logging in a background thread. 232 * <p> 233 * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a 234 * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172). 235 * 236 * @param fqcn fully qualified name of the caller 237 * @param level level at which the caller wants to log the message 238 * @param marker message marker 239 * @param message the log message 240 * @param thrown a {@code Throwable} or {@code null} 241 */ 242 private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker, 243 final Message message, final Throwable thrown) { 244 // Implementation note: candidate for optimization: exceeds 35 bytecodes. 245 246 final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor(); 247 if (disruptor == null) { 248 LOGGER.error("Ignoring log event after Log4j has been shut down."); 249 return; 250 } 251 // if the Message instance is reused, there is no point in freezing its message here 252 if (!isReused(message)) { 253 InternalAsyncUtil.makeMessageImmutable(message); 254 } 255 StackTraceElement location = null; 256 // calls the translateTo method on this AsyncLogger 257 if (!disruptor.getRingBuffer().tryPublishEvent(this, 258 this, // asyncLogger: 0 259 (location = calcLocationIfRequested(fqcn)), // location: 1 260 fqcn, // 2 261 level, // 3 262 marker, // 4 263 message, // 5 264 thrown)) { // 6 265 handleRingBufferFull(location, fqcn, level, marker, message, thrown); 266 } 267 } 268 269 /* 270 * (non-Javadoc) 271 * 272 * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[]) 273 */ 274 @Override 275 public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) { 276 // Implementation note: candidate for optimization: exceeds 35 bytecodes. 277 final AsyncLogger asyncLogger = (AsyncLogger) args[0]; 278 final StackTraceElement location = (StackTraceElement) args[1]; 279 final String fqcn = (String) args[2]; 280 final Level level = (Level) args[3]; 281 final Marker marker = (Marker) args[4]; 282 final Message message = (Message) args[5]; 283 final Throwable thrown = (Throwable) args[6]; 284 285 // needs shallow copy to be fast (LOG4J2-154) 286 final ContextStack contextStack = ThreadContext.getImmutableStack(); 287 288 final Thread currentThread = Thread.currentThread(); 289 final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName(); 290 event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown, 291 // config properties are taken care of in the EventHandler thread 292 // in the AsyncLogger#actualAsyncLog method 293 CONTEXT_DATA_INJECTOR.injectContextData(null, (StringMap) event.getContextData()), 294 contextStack, currentThread.getId(), threadName, currentThread.getPriority(), location, 295 CLOCK.currentTimeMillis(), nanoClock.nanoTime()); 296 } 297 298 /** 299 * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its 300 * toString() method 301 * 302 * @param fqcn fully qualified caller name 303 * @param level log level 304 * @param marker optional marker 305 * @param message log message 306 * @param thrown optional exception 307 */ 308 void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker, 309 final Message message, final Throwable thrown) { 310 // bypass RingBuffer and invoke Appender directly 311 final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy(); 312 strategy.log(this, getName(), fqcn, marker, level, message, thrown); 313 } 314 315 private void handleRingBufferFull(final StackTraceElement location, 316 final String fqcn, 317 final Level level, 318 final Marker marker, 319 final Message msg, 320 final Throwable thrown) { 321 if (Logger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031 322 // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock 323 final Message message = AsyncQueueFullMessageUtil.transform(msg); 324 logMessageInCurrentThread(fqcn, level, marker, message, thrown); 325 return; 326 } 327 final EventRoute eventRoute = loggerDisruptor.getEventRoute(level); 328 switch (eventRoute) { 329 case ENQUEUE: 330 loggerDisruptor.getDisruptor().getRingBuffer().publishEvent(this, 331 this, // asyncLogger: 0 332 location, // location: 1 333 fqcn, // 2 334 level, // 3 335 marker, // 4 336 msg, // 5 337 thrown); // 6 338 break; 339 case SYNCHRONOUS: 340 logMessageInCurrentThread(fqcn, level, marker, msg, thrown); 341 break; 342 case DISCARD: 343 break; 344 default: 345 throw new IllegalStateException("Unknown EventRoute " + eventRoute); 346 } 347 } 348 349 /** 350 * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread. 351 * Merges the contents of the configuration map into the contextData, after replacing any variables in the property 352 * values with the StrSubstitutor-supplied actual values. 353 * 354 * @param event the event to log 355 */ 356 public void actualAsyncLog(final RingBufferLogEvent event) { 357 final List<Property> properties = privateConfig.loggerConfig.getPropertyList(); 358 359 if (properties != null) { 360 StringMap contextData = (StringMap) event.getContextData(); 361 if (contextData.isFrozen()) { 362 final StringMap temp = ContextDataFactory.createContextData(); 363 temp.putAll(contextData); 364 contextData = temp; 365 } 366 for (int i = 0; i < properties.size(); i++) { 367 final Property prop = properties.get(i); 368 if (contextData.getValue(prop.getName()) != null) { 369 continue; // contextMap overrides config properties 370 } 371 final String value = prop.isValueNeedsLookup() // 372 ? privateConfig.config.getStrSubstitutor().replace(event, prop.getValue()) // 373 : prop.getValue(); 374 contextData.putValue(prop.getName(), value); 375 } 376 event.setContextData(contextData); 377 } 378 379 final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy(); 380 strategy.log(this, event); 381 } 382}