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