View Javadoc
1   /*
2    * Licensed to the Apache Software Foundation (ASF) under one or more
3    * contributor license agreements. See the NOTICE file distributed with
4    * this work for additional information regarding copyright ownership.
5    * The ASF licenses this file to You under the Apache license, Version 2.0
6    * (the "License"); you may not use this file except in compliance with
7    * the License. You may obtain a copy of the License at
8    *
9    *      http://www.apache.org/licenses/LICENSE-2.0
10   *
11   * Unless required by applicable law or agreed to in writing, software
12   * distributed under the License is distributed on an "AS IS" BASIS,
13   * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14   * See the license for the specific language governing permissions and
15   * limitations under the license.
16   */
17  package org.apache.logging.log4j.core.async;
18  
19  import java.util.List;
20  
21  import org.apache.logging.log4j.Level;
22  import org.apache.logging.log4j.Marker;
23  import org.apache.logging.log4j.ThreadContext;
24  import org.apache.logging.log4j.ThreadContext.ContextStack;
25  import org.apache.logging.log4j.core.ContextDataInjector;
26  import org.apache.logging.log4j.core.Logger;
27  import org.apache.logging.log4j.core.LoggerContext;
28  import org.apache.logging.log4j.core.config.Configuration;
29  import org.apache.logging.log4j.core.config.Property;
30  import org.apache.logging.log4j.core.config.ReliabilityStrategy;
31  import org.apache.logging.log4j.core.impl.ContextDataFactory;
32  import org.apache.logging.log4j.core.impl.ContextDataInjectorFactory;
33  import org.apache.logging.log4j.core.util.Clock;
34  import org.apache.logging.log4j.core.util.ClockFactory;
35  import org.apache.logging.log4j.core.util.NanoClock;
36  import org.apache.logging.log4j.message.Message;
37  import org.apache.logging.log4j.message.MessageFactory;
38  import org.apache.logging.log4j.message.ReusableMessage;
39  import org.apache.logging.log4j.spi.AbstractLogger;
40  import org.apache.logging.log4j.status.StatusLogger;
41  import org.apache.logging.log4j.util.StackLocatorUtil;
42  import org.apache.logging.log4j.util.StringMap;
43  
44  import com.lmax.disruptor.EventTranslatorVararg;
45  import com.lmax.disruptor.dsl.Disruptor;
46  
47  /**
48   * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the
49   * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual
50   * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a
51   * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>)
52   * <p>
53   * To use AsyncLogger, specify the System property
54   * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a
55   * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers.
56   * <p>
57   * Note that for performance reasons, this logger does not include source location by default. You need to specify
58   * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your
59   * log4j.xml configuration will produce either a "?" character or no output at all.
60   * <p>
61   * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with
62   * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library,
63   * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will
64   * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner.
65   */
66  public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
67      // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE!
68      // Specifically, try to keep the hot methods to 35 bytecodes or less:
69      // this is within the MaxInlineSize threshold and makes these methods candidates for
70      // immediate inlining instead of waiting until they are designated "hot enough".
71  
72      private static final StatusLogger LOGGER = StatusLogger.getLogger();
73      private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable
74      private static final ContextDataInjector CONTEXT_DATA_INJECTOR = ContextDataInjectorFactory.createInjector();
75  
76      private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create();
77  
78      private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>();
79      private final AsyncLoggerDisruptor loggerDisruptor;
80  
81      private volatile boolean includeLocation; // reconfigurable
82      private volatile NanoClock nanoClock; // reconfigurable
83  
84      /**
85       * Constructs an {@code AsyncLogger} with the specified context, name and message factory.
86       *
87       * @param context context of this logger
88       * @param name name of this logger
89       * @param messageFactory message factory of this logger
90       * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor.
91       */
92      public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory,
93              final AsyncLoggerDisruptor loggerDisruptor) {
94          super(context, name, messageFactory);
95          this.loggerDisruptor = loggerDisruptor;
96          includeLocation = privateConfig.loggerConfig.isIncludeLocation();
97          nanoClock = context.getConfiguration().getNanoClock();
98      }
99  
100     /*
101      * (non-Javadoc)
102      *
103      * @see org.apache.logging.log4j.core.Logger#updateConfiguration(org.apache.logging.log4j.core.config.Configuration)
104      */
105     @Override
106     protected void updateConfiguration(final Configuration newConfig) {
107         nanoClock = newConfig.getNanoClock();
108         includeLocation = newConfig.getLoggerConfig(name).isIncludeLocation();
109         super.updateConfiguration(newConfig);
110     }
111 
112     // package protected for unit tests
113     NanoClock getNanoClock() {
114         return nanoClock;
115     }
116 
117     private RingBufferLogEventTranslator getCachedTranslator() {
118         RingBufferLogEventTranslator result = threadLocalTranslator.get();
119         if (result == null) {
120             result = new RingBufferLogEventTranslator();
121             threadLocalTranslator.set(result);
122         }
123         return result;
124     }
125 
126     @Override
127     public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,
128             final Throwable thrown) {
129 
130         if (loggerDisruptor.isUseThreadLocals()) {
131             logWithThreadLocalTranslator(fqcn, level, marker, message, thrown);
132         } else {
133             // LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web apps
134             logWithVarargTranslator(fqcn, level, marker, message, thrown);
135         }
136     }
137 
138     private boolean isReused(final Message message) {
139         return message instanceof ReusableMessage;
140     }
141 
142     /**
143      * Enqueues the specified log event data for logging in a background thread.
144      * <p>
145      * This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating
146      * unnecessary objects with each event.
147      *
148      * @param fqcn fully qualified name of the caller
149      * @param level level at which the caller wants to log the message
150      * @param marker message marker
151      * @param message the log message
152      * @param thrown a {@code Throwable} or {@code null}
153      */
154     private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker,
155             final Message message, final Throwable thrown) {
156         // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
157 
158         final RingBufferLogEventTranslator translator = getCachedTranslator();
159         initTranslator(translator, fqcn, level, marker, message, thrown);
160         initTranslatorThreadValues(translator);
161         publish(translator);
162     }
163 
164     private void publish(final RingBufferLogEventTranslator translator) {
165         if (!loggerDisruptor.tryPublish(translator)) {
166             handleRingBufferFull(translator);
167         }
168     }
169 
170     private void handleRingBufferFull(final RingBufferLogEventTranslator translator) {
171         if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
172             // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
173             final Message message = AsyncQueueFullMessageUtil.transform(translator.message);
174             logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, message,
175                     translator.thrown);
176             return;
177         }
178         final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level);
179         switch (eventRoute) {
180             case ENQUEUE:
181                 loggerDisruptor.enqueueLogMessageInfo(translator);
182                 break;
183             case SYNCHRONOUS:
184                 logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message,
185                         translator.thrown);
186                 break;
187             case DISCARD:
188                 break;
189             default:
190                 throw new IllegalStateException("Unknown EventRoute " + eventRoute);
191         }
192     }
193 
194     private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn,
195             final Level level, final Marker marker, final Message message, final Throwable thrown) {
196 
197         translator.setBasicValues(this, name, marker, fqcn, level, message, //
198                 // don't construct ThrowableProxy until required
199                 thrown,
200 
201                 // needs shallow copy to be fast (LOG4J2-154)
202                 ThreadContext.getImmutableStack(), //
203 
204                 // location (expensive to calculate)
205                 calcLocationIfRequested(fqcn), //
206                 CLOCK, //
207                 nanoClock //
208         );
209     }
210 
211     private void initTranslatorThreadValues(final RingBufferLogEventTranslator translator) {
212         // constant check should be optimized out when using default (CACHED)
213         if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) {
214             translator.updateThreadValues();
215         }
216     }
217 
218     /**
219      * Returns the caller location if requested, {@code null} otherwise.
220      *
221      * @param fqcn fully qualified caller name.
222      * @return the caller location if requested, {@code null} otherwise.
223      */
224     private StackTraceElement calcLocationIfRequested(final String fqcn) {
225         // location: very expensive operation. LOG4J2-153:
226         // Only include if "includeLocation=true" is specified,
227         // exclude if not specified or if "false" was specified.
228         return includeLocation ? StackLocatorUtil.calcLocation(fqcn) : null;
229     }
230 
231     /**
232      * Enqueues the specified log event data for logging in a background thread.
233      * <p>
234      * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a
235      * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172).
236      *
237      * @param fqcn fully qualified name of the caller
238      * @param level level at which the caller wants to log the message
239      * @param marker message marker
240      * @param message the log message
241      * @param thrown a {@code Throwable} or {@code null}
242      */
243     private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker,
244             final Message message, final Throwable thrown) {
245         // Implementation note: candidate for optimization: exceeds 35 bytecodes.
246 
247         final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
248         if (disruptor == null) {
249             LOGGER.error("Ignoring log event after Log4j has been shut down.");
250             return;
251         }
252         // if the Message instance is reused, there is no point in freezing its message here
253         if (!isReused(message)) {
254             InternalAsyncUtil.makeMessageImmutable(message);
255         }
256         StackTraceElement location = null;
257         // calls the translateTo method on this AsyncLogger
258         if (!disruptor.getRingBuffer().tryPublishEvent(this,
259                 this, // asyncLogger: 0
260                 (location = calcLocationIfRequested(fqcn)), // location: 1
261                 fqcn, // 2
262                 level, // 3
263                 marker, // 4
264                 message, // 5
265                 thrown)) { // 6
266             handleRingBufferFull(location, fqcn, level, marker, message, thrown);
267         }
268     }
269 
270     /*
271      * (non-Javadoc)
272      *
273      * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[])
274      */
275     @Override
276     public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) {
277         // Implementation note: candidate for optimization: exceeds 35 bytecodes.
278         final AsyncLogger asyncLogger = (AsyncLogger) args[0];
279         final StackTraceElement location = (StackTraceElement) args[1];
280         final String fqcn = (String) args[2];
281         final Level level = (Level) args[3];
282         final Marker marker = (Marker) args[4];
283         final Message message = (Message) args[5];
284         final Throwable thrown = (Throwable) args[6];
285 
286         // needs shallow copy to be fast (LOG4J2-154)
287         final ContextStack contextStack = ThreadContext.getImmutableStack();
288 
289         final Thread currentThread = Thread.currentThread();
290         final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName();
291         event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown,
292                 // config properties are taken care of in the EventHandler thread
293                 // in the AsyncLogger#actualAsyncLog method
294                 CONTEXT_DATA_INJECTOR.injectContextData(null, (StringMap) event.getContextData()),
295                 contextStack, currentThread.getId(), threadName, currentThread.getPriority(), location,
296                 CLOCK, nanoClock);
297     }
298 
299     /**
300      * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its
301      * toString() method
302      *
303      * @param fqcn fully qualified caller name
304      * @param level log level
305      * @param marker optional marker
306      * @param message log message
307      * @param thrown optional exception
308      */
309     void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker,
310             final Message message, final Throwable thrown) {
311         // bypass RingBuffer and invoke Appender directly
312         final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
313         strategy.log(this, getName(), fqcn, marker, level, message, thrown);
314     }
315 
316     private void handleRingBufferFull(final StackTraceElement location,
317                                       final String fqcn,
318                                       final Level level,
319                                       final Marker marker,
320                                       final Message msg,
321                                       final Throwable thrown) {
322         if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
323             // If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
324             final Message message = AsyncQueueFullMessageUtil.transform(msg);
325             logMessageInCurrentThread(fqcn, level, marker, message, thrown);
326             return;
327         }
328         final EventRoute eventRoute = loggerDisruptor.getEventRoute(level);
329         switch (eventRoute) {
330             case ENQUEUE:
331                 loggerDisruptor.getDisruptor().getRingBuffer().publishEvent(this,
332                         this, // asyncLogger: 0
333                         location, // location: 1
334                         fqcn, // 2
335                         level, // 3
336                         marker, // 4
337                         msg, // 5
338                         thrown); // 6
339                 break;
340             case SYNCHRONOUS:
341                 logMessageInCurrentThread(fqcn, level, marker, msg, thrown);
342                 break;
343             case DISCARD:
344                 break;
345             default:
346                 throw new IllegalStateException("Unknown EventRoute " + eventRoute);
347         }
348     }
349 
350     /**
351      * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread.
352      * Merges the contents of the configuration map into the contextData, after replacing any variables in the property
353      * values with the StrSubstitutor-supplied actual values.
354      *
355      * @param event the event to log
356      */
357     public void actualAsyncLog(final RingBufferLogEvent event) {
358         final List<Property> properties = privateConfig.loggerConfig.getPropertyList();
359 
360         if (properties != null) {
361             StringMap contextData = (StringMap) event.getContextData();
362             if (contextData.isFrozen()) {
363                 final StringMap temp = ContextDataFactory.createContextData();
364                 temp.putAll(contextData);
365                 contextData = temp;
366             }
367             for (int i = 0; i < properties.size(); i++) {
368                 final Property prop = properties.get(i);
369                 if (contextData.getValue(prop.getName()) != null) {
370                     continue; // contextMap overrides config properties
371                 }
372                 final String value = prop.isValueNeedsLookup() //
373                         ? privateConfig.config.getStrSubstitutor().replace(event, prop.getValue()) //
374                         : prop.getValue();
375                 contextData.putValue(prop.getName(), value);
376             }
377             event.setContextData(contextData);
378         }
379 
380         final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
381         strategy.log(this, event);
382     }
383 }