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.core.util.NanoClockFactory; 036import org.apache.logging.log4j.message.Message; 037import org.apache.logging.log4j.message.MessageFactory; 038import org.apache.logging.log4j.message.TimestampMessage; 039import org.apache.logging.log4j.status.StatusLogger; 040 041import com.lmax.disruptor.EventTranslatorVararg; 042import com.lmax.disruptor.dsl.Disruptor; 043 044/** 045 * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the 046 * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual 047 * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a 048 * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>) 049 * <p> 050 * To use AsyncLogger, specify the System property 051 * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a 052 * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers. 053 * <p> 054 * Note that for performance reasons, this logger does not include source location by default. You need to specify 055 * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your 056 * log4j.xml configuration will produce either a "?" character or no output at all. 057 * <p> 058 * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with 059 * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library, 060 * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will 061 * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner. 062 */ 063public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> { 064 // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE! 065 // Specifically, try to keep the hot methods to 35 bytecodes or less: 066 // this is within the MaxInlineSize threshold and makes these methods candidates for 067 // immediate inlining instead of waiting until they are designated "hot enough". 068 069 private static final long serialVersionUID = 1L; 070 private static final StatusLogger LOGGER = StatusLogger.getLogger(); 071 private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable 072 073 private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create(); 074 075 private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>(); 076 private final AsyncLoggerDisruptor loggerDisruptor; 077 078 private volatile NanoClock nanoClock; // reconfigurable 079 080 /** 081 * Constructs an {@code AsyncLogger} with the specified context, name and message factory. 082 * 083 * @param context context of this logger 084 * @param name name of this logger 085 * @param messageFactory message factory of this logger 086 * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor. 087 */ 088 public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory, 089 final AsyncLoggerDisruptor loggerDisruptor) { 090 super(context, name, messageFactory); 091 this.loggerDisruptor = loggerDisruptor; 092 nanoClock = NanoClockFactory.createNanoClock(); // based on initial configuration 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(Configuration newConfig) { 102 super.updateConfiguration(newConfig); 103 nanoClock = NanoClockFactory.createNanoClock(); 104 LOGGER.trace("[{}] AsyncLogger {} uses {}.", getContext().getName(), getName(), nanoClock); 105 } 106 107 // package protected for unit tests 108 NanoClock getNanoClock() { 109 return nanoClock; 110 } 111 112 private RingBufferLogEventTranslator getCachedTranslator() { 113 RingBufferLogEventTranslator result = threadLocalTranslator.get(); 114 if (result == null) { 115 result = new RingBufferLogEventTranslator(); 116 threadLocalTranslator.set(result); 117 } 118 return result; 119 } 120 121 @Override 122 public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message, 123 final Throwable thrown) { 124 125 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 126 127 if (loggerDisruptor.shouldLogInCurrentThread()) { 128 logMessageInCurrentThread(fqcn, level, marker, message, thrown); 129 } else { 130 logMessageInBackgroundThread(fqcn, level, marker, message, thrown); 131 } 132 } 133 134 /** 135 * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its 136 * toString() method 137 * 138 * @param fqcn fully qualified caller name 139 * @param level log level 140 * @param marker optional marker 141 * @param message log message 142 * @param thrown optional exception 143 * @return {@code true} if the event has been logged in the current thread, {@code false} if it should be passed to 144 * the background thread 145 */ 146 private void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker, 147 final Message message, final Throwable thrown) { 148 // bypass RingBuffer and invoke Appender directly 149 final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy(); 150 strategy.log(this, getName(), fqcn, marker, level, message, thrown); 151 } 152 153 /** 154 * Enqueues the specified message to be logged in the background thread. 155 * 156 * @param info holds some cached information 157 * @param fqcn fully qualified caller name 158 * @param level log level 159 * @param marker optional marker 160 * @param message log message 161 * @param thrown optional exception 162 */ 163 private void logMessageInBackgroundThread(final String fqcn, final Level level, final Marker marker, 164 final Message message, final Throwable thrown) { 165 166 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 167 168 if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose 169 message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters 170 } 171 logInBackground(fqcn, level, marker, message, thrown); 172 } 173 174 /** 175 * Enqueues the specified log event data for logging in a background thread. 176 * 177 * @param asyncLogger the {@code AsyncLogger} to call from the background thread 178 * @param location location information or {@code null} 179 * @param fqcn fully qualified name of the caller 180 * @param level level at which the caller wants to log the message 181 * @param marker message marker 182 * @param message the log message 183 * @param thrown a {@code Throwable} or {@code null} 184 */ 185 private void logInBackground(final String fqcn, final Level level, final Marker marker, final Message message, 186 final Throwable thrown) { 187 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 188 189 if (loggerDisruptor.isUseThreadLocals()) { 190 logWithThreadLocalTranslator(fqcn, level, marker, message, thrown); 191 } else { 192 // LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web apps 193 logWithVarargTranslator(fqcn, level, marker, message, thrown); 194 } 195 } 196 197 /** 198 * Enqueues the specified log event data for logging in a background thread. 199 * <p> 200 * This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating 201 * unnecessary objects with each event. 202 * 203 * @param fqcn fully qualified name of the caller 204 * @param level level at which the caller wants to log the message 205 * @param marker message marker 206 * @param message the log message 207 * @param thrown a {@code Throwable} or {@code null} 208 */ 209 private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker, 210 final Message message, final Throwable thrown) { 211 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 212 213 final RingBufferLogEventTranslator translator = getCachedTranslator(); 214 initTranslator(translator, fqcn, level, marker, message, thrown); 215 loggerDisruptor.enqueueLogMessageInfo(translator); 216 } 217 218 private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn, 219 final Level level, final Marker marker, final Message message, final Throwable thrown) { 220 221 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 222 223 initTranslatorPart1(translator, fqcn, level, marker, message, thrown); 224 initTranslatorPart2(translator, fqcn, message); 225 } 226 227 private void initTranslatorPart1(final RingBufferLogEventTranslator translator, final String fqcn, 228 final Level level, final Marker marker, final Message message, final Throwable thrown) { 229 230 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 231 232 translator.setValuesPart1(this, getName(), marker, fqcn, level, message, // 233 // don't construct ThrowableProxy until required 234 thrown); 235 } 236 237 private void initTranslatorPart2(final RingBufferLogEventTranslator translator, final String fqcn, 238 final Message message) { 239 240 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 241 242 translator.setValuesPart2( 243 // config properties are taken care of in the EventHandler thread 244 // in the AsyncLogger#actualAsyncLog method 245 246 // needs shallow copy to be fast (LOG4J2-154) 247 ThreadContext.getImmutableContext(), // 248 249 // needs shallow copy to be fast (LOG4J2-154) 250 ThreadContext.getImmutableStack(), // 251 252 // Thread.currentThread().getName(), // 253 THREAD_NAME_CACHING_STRATEGY.getThreadName(), // 254 255 // location (expensive to calculate) 256 calcLocationIfRequested(fqcn), 257 258 eventTimeMillis(message), // 259 nanoClock.nanoTime() // 260 ); 261 } 262 263 private long eventTimeMillis(final Message message) { 264 // Implementation note: this method is tuned for performance. MODIFY WITH CARE! 265 266 // System.currentTimeMillis()); 267 // CoarseCachedClock: 20% faster than system clock, 16ms gaps 268 // CachedClock: 10% faster than system clock, smaller gaps 269 // LOG4J2-744 avoid calling clock altogether if message has the timestamp 270 return message instanceof TimestampMessage ? ((TimestampMessage) message).getTimestamp() : CLOCK 271 .currentTimeMillis(); 272 } 273 274 /** 275 * Enqueues the specified log event data for logging in a background thread. 276 * <p> 277 * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a 278 * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172). 279 * 280 * @param asyncLogger the {@code AsyncLogger} to call from the background thread 281 * @param location location information or {@code null} 282 * @param fqcn fully qualified name of the caller 283 * @param level level at which the caller wants to log the message 284 * @param marker message marker 285 * @param message the log message 286 * @param thrown a {@code Throwable} or {@code null} 287 */ 288 private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker, 289 final Message message, final Throwable thrown) { 290 // Implementation note: candidate for optimization: exceeds 35 bytecodes. 291 292 final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor(); 293 if (disruptor == null) { 294 LOGGER.error("Ignoring log event after Log4j has been shut down."); 295 return; 296 } 297 // calls the translateTo method on this AsyncLogger 298 disruptor.getRingBuffer().publishEvent(this, this, calcLocationIfRequested(fqcn), fqcn, level, marker, message, 299 thrown); 300 } 301 302 /* 303 * (non-Javadoc) 304 * 305 * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[]) 306 */ 307 @Override 308 public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) { 309 // Implementation note: candidate for optimization: exceeds 35 bytecodes. 310 final AsyncLogger asyncLogger = (AsyncLogger) args[0]; 311 final StackTraceElement location = (StackTraceElement) args[1]; 312 final String fqcn = (String) args[2]; 313 final Level level = (Level) args[3]; 314 final Marker marker = (Marker) args[4]; 315 final Message message = (Message) args[5]; 316 final Throwable thrown = (Throwable) args[6]; 317 318 // needs shallow copy to be fast (LOG4J2-154) 319 final Map<String, String> contextMap = ThreadContext.getImmutableContext(); 320 321 // needs shallow copy to be fast (LOG4J2-154) 322 final ContextStack contextStack = ThreadContext.getImmutableStack(); 323 324 final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName(); 325 326 event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown, contextMap, 327 contextStack, threadName, location, eventTimeMillis(message), nanoClock.nanoTime()); 328 } 329 330 /** 331 * Returns the caller location if requested, {@code null} otherwise. 332 * 333 * @param fqcn fully qualified caller name. 334 * @return the caller location if requested, {@code null} otherwise. 335 */ 336 private StackTraceElement calcLocationIfRequested(String fqcn) { 337 // location: very expensive operation. LOG4J2-153: 338 // Only include if "includeLocation=true" is specified, 339 // exclude if not specified or if "false" was specified. 340 final boolean includeLocation = privateConfig.loggerConfig.isIncludeLocation(); 341 return includeLocation ? Log4jLogEvent.calcLocation(fqcn) : null; 342 } 343 344 /** 345 * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread. 346 * 347 * @param event the event to log 348 */ 349 public void actualAsyncLog(final RingBufferLogEvent event) { 350 final Map<Property, Boolean> properties = privateConfig.loggerConfig.getProperties(); 351 event.mergePropertiesIntoContextMap(properties, privateConfig.config.getStrSubstitutor()); 352 final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy(); 353 strategy.log(this, event); 354 } 355}