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.Logger;
26  import org.apache.logging.log4j.core.LoggerContext;
27  import org.apache.logging.log4j.core.config.Configuration;
28  import org.apache.logging.log4j.core.config.Property;
29  import org.apache.logging.log4j.core.config.ReliabilityStrategy;
30  import org.apache.logging.log4j.core.impl.ContextDataFactory;
31  import org.apache.logging.log4j.core.ContextDataInjector;
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.util.StackLocatorUtil;
40  import org.apache.logging.log4j.util.StringMap;
41  import org.apache.logging.log4j.status.StatusLogger;
42  
43  import com.lmax.disruptor.EventTranslatorVararg;
44  import com.lmax.disruptor.dsl.Disruptor;
45  
46  /**
47   * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the
48   * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual
49   * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a
50   * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>)
51   * <p>
52   * To use AsyncLogger, specify the System property
53   * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a
54   * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers.
55   * <p>
56   * Note that for performance reasons, this logger does not include source location by default. You need to specify
57   * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your
58   * log4j.xml configuration will produce either a "?" character or no output at all.
59   * <p>
60   * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with
61   * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library,
62   * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will
63   * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner.
64   */
65  public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
66      // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE!
67      // Specifically, try to keep the hot methods to 35 bytecodes or less:
68      // this is within the MaxInlineSize threshold and makes these methods candidates for
69      // immediate inlining instead of waiting until they are designated "hot enough".
70  
71      private static final StatusLogger LOGGER = StatusLogger.getLogger();
72      private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable
73      private static final ContextDataInjector CONTEXT_DATA_INJECTOR = ContextDataInjectorFactory.createInjector();
74  
75      private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create();
76  
77      private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>();
78      private final AsyncLoggerDisruptor loggerDisruptor;
79  
80      private volatile boolean includeLocation; // reconfigurable
81      private volatile NanoClock nanoClock; // reconfigurable
82  
83      /**
84       * Constructs an {@code AsyncLogger} with the specified context, name and message factory.
85       *
86       * @param context context of this logger
87       * @param name name of this logger
88       * @param messageFactory message factory of this logger
89       * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor.
90       */
91      public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory,
92              final AsyncLoggerDisruptor loggerDisruptor) {
93          super(context, name, messageFactory);
94          this.loggerDisruptor = loggerDisruptor;
95          includeLocation = privateConfig.loggerConfig.isIncludeLocation();
96          nanoClock = context.getConfiguration().getNanoClock();
97      }
98  
99      /*
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         final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level);
171         switch (eventRoute) {
172             case ENQUEUE:
173                 loggerDisruptor.enqueueLogMessageInfo(translator);
174                 break;
175             case SYNCHRONOUS:
176                 logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message,
177                         translator.thrown);
178                 break;
179             case DISCARD:
180                 break;
181             default:
182                 throw new IllegalStateException("Unknown EventRoute " + eventRoute);
183         }
184     }
185 
186     private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn,
187             final Level level, final Marker marker, final Message message, final Throwable thrown) {
188 
189         translator.setBasicValues(this, name, marker, fqcn, level, message, //
190                 // don't construct ThrowableProxy until required
191                 thrown,
192 
193                 // needs shallow copy to be fast (LOG4J2-154)
194                 ThreadContext.getImmutableStack(), //
195 
196                 // location (expensive to calculate)
197                 calcLocationIfRequested(fqcn), //
198                 CLOCK.currentTimeMillis(), //
199                 nanoClock.nanoTime() //
200         );
201     }
202 
203     private void initTranslatorThreadValues(final RingBufferLogEventTranslator translator) {
204         // constant check should be optimized out when using default (CACHED)
205         if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) {
206             translator.updateThreadValues();
207         }
208     }
209 
210     /**
211      * Returns the caller location if requested, {@code null} otherwise.
212      *
213      * @param fqcn fully qualified caller name.
214      * @return the caller location if requested, {@code null} otherwise.
215      */
216     private StackTraceElement calcLocationIfRequested(final String fqcn) {
217         // location: very expensive operation. LOG4J2-153:
218         // Only include if "includeLocation=true" is specified,
219         // exclude if not specified or if "false" was specified.
220         return includeLocation ? StackLocatorUtil.calcLocation(fqcn) : null;
221     }
222 
223     /**
224      * Enqueues the specified log event data for logging in a background thread.
225      * <p>
226      * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a
227      * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172).
228      *
229      * @param fqcn fully qualified name of the caller
230      * @param level level at which the caller wants to log the message
231      * @param marker message marker
232      * @param message the log message
233      * @param thrown a {@code Throwable} or {@code null}
234      */
235     private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker,
236             final Message message, final Throwable thrown) {
237         // Implementation note: candidate for optimization: exceeds 35 bytecodes.
238 
239         final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
240         if (disruptor == null) {
241             LOGGER.error("Ignoring log event after Log4j has been shut down.");
242             return;
243         }
244         // if the Message instance is reused, there is no point in freezing its message here
245         if (!isReused(message)) {
246             InternalAsyncUtil.makeMessageImmutable(message);
247         }
248         // calls the translateTo method on this AsyncLogger
249         disruptor.getRingBuffer().publishEvent(this, this, calcLocationIfRequested(fqcn), fqcn, level, marker, message,
250                 thrown);
251     }
252 
253     /*
254      * (non-Javadoc)
255      *
256      * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[])
257      */
258     @Override
259     public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) {
260         // Implementation note: candidate for optimization: exceeds 35 bytecodes.
261         final AsyncLogger asyncLogger = (AsyncLogger) args[0];
262         final StackTraceElement location = (StackTraceElement) args[1];
263         final String fqcn = (String) args[2];
264         final Level level = (Level) args[3];
265         final Marker marker = (Marker) args[4];
266         final Message message = (Message) args[5];
267         final Throwable thrown = (Throwable) args[6];
268 
269         // needs shallow copy to be fast (LOG4J2-154)
270         final ContextStack contextStack = ThreadContext.getImmutableStack();
271 
272         final Thread currentThread = Thread.currentThread();
273         final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName();
274         event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown,
275                 // config properties are taken care of in the EventHandler thread
276                 // in the AsyncLogger#actualAsyncLog method
277                 CONTEXT_DATA_INJECTOR.injectContextData(null, (StringMap) event.getContextData()),
278                 contextStack, currentThread.getId(), threadName, currentThread.getPriority(), location,
279                 CLOCK.currentTimeMillis(), nanoClock.nanoTime());
280     }
281 
282     /**
283      * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its
284      * toString() method
285      *
286      * @param fqcn fully qualified caller name
287      * @param level log level
288      * @param marker optional marker
289      * @param message log message
290      * @param thrown optional exception
291      */
292     void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker,
293             final Message message, final Throwable thrown) {
294         // bypass RingBuffer and invoke Appender directly
295         final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
296         strategy.log(this, getName(), fqcn, marker, level, message, thrown);
297     }
298 
299     /**
300      * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread.
301      * Merges the contents of the configuration map into the contextData, after replacing any variables in the property
302      * values with the StrSubstitutor-supplied actual values.
303      *
304      * @param event the event to log
305      */
306     public void actualAsyncLog(final RingBufferLogEvent event) {
307         final List<Property> properties = privateConfig.loggerConfig.getPropertyList();
308 
309         if (properties != null) {
310             StringMap contextData = (StringMap) event.getContextData();
311             if (contextData.isFrozen()) {
312                 final StringMap temp = ContextDataFactory.createContextData();
313                 temp.putAll(contextData);
314                 contextData = temp;
315             }
316             for (int i = 0; i < properties.size(); i++) {
317                 final Property prop = properties.get(i);
318                 if (contextData.getValue(prop.getName()) != null) {
319                     continue; // contextMap overrides config properties
320                 }
321                 final String value = prop.isValueNeedsLookup() //
322                         ? privateConfig.config.getStrSubstitutor().replace(event, prop.getValue()) //
323                         : prop.getValue();
324                 contextData.putValue(prop.getName(), value);
325             }
326             event.setContextData(contextData);
327         }
328 
329         final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
330         strategy.log(this, event);
331     }
332 }