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.Map;
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.Log4jLogEvent;
31  import org.apache.logging.log4j.core.util.Clock;
32  import org.apache.logging.log4j.core.util.ClockFactory;
33  import org.apache.logging.log4j.core.util.Constants;
34  import org.apache.logging.log4j.core.util.NanoClock;
35  import org.apache.logging.log4j.core.util.NanoClockFactory;
36  import org.apache.logging.log4j.message.Message;
37  import org.apache.logging.log4j.message.MessageFactory;
38  import org.apache.logging.log4j.message.TimestampMessage;
39  import org.apache.logging.log4j.status.StatusLogger;
40  
41  import com.lmax.disruptor.EventTranslatorVararg;
42  import com.lmax.disruptor.dsl.Disruptor;
43  
44  /**
45   * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the
46   * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual
47   * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a
48   * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>)
49   * <p>
50   * To use AsyncLogger, specify the System property
51   * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a
52   * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers.
53   * <p>
54   * Note that for performance reasons, this logger does not include source location by default. You need to specify
55   * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your
56   * log4j.xml configuration will produce either a "?" character or no output at all.
57   * <p>
58   * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with
59   * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library,
60   * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will
61   * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner.
62   */
63  public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
64      // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE!
65      // Specifically, try to keep the hot methods to 35 bytecodes or less:
66      // this is within the MaxInlineSize threshold and makes these methods candidates for
67      // immediate inlining instead of waiting until they are designated "hot enough".
68  
69      private static final long serialVersionUID = 1L;
70      private static final StatusLogger LOGGER = StatusLogger.getLogger();
71      private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable
72  
73      private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create();
74  
75      private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>();
76      private final AsyncLoggerDisruptor loggerDisruptor;
77  
78      private volatile NanoClock nanoClock; // reconfigurable
79  
80      /**
81       * Constructs an {@code AsyncLogger} with the specified context, name and message factory.
82       *
83       * @param context context of this logger
84       * @param name name of this logger
85       * @param messageFactory message factory of this logger
86       * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor.
87       */
88      public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory,
89              final AsyncLoggerDisruptor loggerDisruptor) {
90          super(context, name, messageFactory);
91          this.loggerDisruptor = loggerDisruptor;
92          nanoClock = NanoClockFactory.createNanoClock(); // based on initial configuration
93      }
94  
95      /*
96       * (non-Javadoc)
97       * 
98       * @see org.apache.logging.log4j.core.Logger#updateConfiguration(org.apache.logging.log4j.core.config.Configuration)
99       */
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 }