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.message.Message;
36  import org.apache.logging.log4j.message.MessageFactory;
37  import org.apache.logging.log4j.message.ReusableMessage;
38  import org.apache.logging.log4j.status.StatusLogger;
39  
40  import com.lmax.disruptor.EventTranslatorVararg;
41  import com.lmax.disruptor.dsl.Disruptor;
42  
43  /**
44   * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the
45   * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual
46   * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a
47   * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>)
48   * <p>
49   * To use AsyncLogger, specify the System property
50   * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a
51   * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers.
52   * <p>
53   * Note that for performance reasons, this logger does not include source location by default. You need to specify
54   * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your
55   * log4j.xml configuration will produce either a "?" character or no output at all.
56   * <p>
57   * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with
58   * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library,
59   * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will
60   * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner.
61   */
62  public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
63      // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE!
64      // Specifically, try to keep the hot methods to 35 bytecodes or less:
65      // this is within the MaxInlineSize threshold and makes these methods candidates for
66      // immediate inlining instead of waiting until they are designated "hot enough".
67  
68      private static final StatusLogger LOGGER = StatusLogger.getLogger();
69      private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable
70  
71      private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create();
72  
73      private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>();
74      private final AsyncLoggerDisruptor loggerDisruptor;
75  
76      private volatile boolean includeLocation; // reconfigurable
77      private volatile NanoClock nanoClock; // reconfigurable
78  
79      /**
80       * Constructs an {@code AsyncLogger} with the specified context, name and message factory.
81       *
82       * @param context context of this logger
83       * @param name name of this logger
84       * @param messageFactory message factory of this logger
85       * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor.
86       */
87      public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory,
88              final AsyncLoggerDisruptor loggerDisruptor) {
89          super(context, name, messageFactory);
90          this.loggerDisruptor = loggerDisruptor;
91          includeLocation = privateConfig.loggerConfig.isIncludeLocation();
92          nanoClock = context.getConfiguration().getNanoClock();
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(final Configuration newConfig) {
102         nanoClock = newConfig.getNanoClock();
103         includeLocation = newConfig.getLoggerConfig(name).isIncludeLocation();
104         super.updateConfiguration(newConfig);
105         LOGGER.trace("[{}] AsyncLogger {} uses {}.", getContext().getName(), getName(), nanoClock);
106     }
107 
108     // package protected for unit tests
109     NanoClock getNanoClock() {
110         return nanoClock;
111     }
112 
113     private RingBufferLogEventTranslator getCachedTranslator() {
114         RingBufferLogEventTranslator result = threadLocalTranslator.get();
115         if (result == null) {
116             result = new RingBufferLogEventTranslator();
117             threadLocalTranslator.set(result);
118         }
119         return result;
120     }
121 
122     @Override
123     public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,
124             final Throwable thrown) {
125 
126         if (loggerDisruptor.isUseThreadLocals()) {
127             logWithThreadLocalTranslator(fqcn, level, marker, message, thrown);
128         } else {
129             // LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web apps
130             logWithVarargTranslator(fqcn, level, marker, message, thrown);
131         }
132     }
133 
134     private boolean isReused(final Message message) {
135         return message instanceof ReusableMessage;
136     }
137 
138     /**
139      * Enqueues the specified log event data for logging in a background thread.
140      * <p>
141      * This re-uses a {@code RingBufferLogEventTranslator} instance cached in a {@code ThreadLocal} to avoid creating
142      * unnecessary objects with each event.
143      *
144      * @param fqcn fully qualified name of the caller
145      * @param level level at which the caller wants to log the message
146      * @param marker message marker
147      * @param message the log message
148      * @param thrown a {@code Throwable} or {@code null}
149      */
150     private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker,
151             final Message message, final Throwable thrown) {
152         // Implementation note: this method is tuned for performance. MODIFY WITH CARE!
153 
154         final RingBufferLogEventTranslator translator = getCachedTranslator();
155         initTranslator(translator, fqcn, level, marker, message, thrown);
156         initTranslatorThreadValues(translator);
157         publish(translator);
158     }
159 
160     private void publish(final RingBufferLogEventTranslator translator) {
161         if (!loggerDisruptor.tryPublish(translator)) {
162             handleRingBufferFull(translator);
163         }
164     }
165 
166     private void handleRingBufferFull(final RingBufferLogEventTranslator translator) {
167         final EventRoute eventRoute = loggerDisruptor.getEventRoute(translator.level);
168         switch (eventRoute) {
169             case ENQUEUE:
170                 loggerDisruptor.enqueueLogMessageInfo(translator);
171                 break;
172             case SYNCHRONOUS:
173                 logMessageInCurrentThread(translator.fqcn, translator.level, translator.marker, translator.message,
174                         translator.thrown);
175                 break;
176             case DISCARD:
177                 break;
178             default:
179                 throw new IllegalStateException("Unknown EventRoute " + eventRoute);
180         }
181     }
182 
183     private void initTranslator(final RingBufferLogEventTranslator translator, final String fqcn,
184             final Level level, final Marker marker, final Message message, final Throwable thrown) {
185 
186         translator.setBasicValues(this, name, marker, fqcn, level, message, //
187                 // don't construct ThrowableProxy until required
188                 thrown,
189 
190                 // config properties are taken care of in the EventHandler thread
191                 // in the AsyncLogger#actualAsyncLog method
192 
193                 // needs shallow copy to be fast (LOG4J2-154)
194                 ThreadContext.getImmutableContext(), //
195 
196                 // needs shallow copy to be fast (LOG4J2-154)
197                 ThreadContext.getImmutableStack(), //
198                 // location (expensive to calculate)
199                 calcLocationIfRequested(fqcn), //
200                 CLOCK.currentTimeMillis(), //
201                 nanoClock.nanoTime() //
202         );
203     }
204 
205     private void initTranslatorThreadValues(final RingBufferLogEventTranslator translator) {
206         // constant check should be optimized out when using default (CACHED)
207         if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) {
208             translator.updateThreadValues();
209         }
210     }
211 
212     /**
213      * Returns the caller location if requested, {@code null} otherwise.
214      *
215      * @param fqcn fully qualified caller name.
216      * @return the caller location if requested, {@code null} otherwise.
217      */
218     private StackTraceElement calcLocationIfRequested(final String fqcn) {
219         // location: very expensive operation. LOG4J2-153:
220         // Only include if "includeLocation=true" is specified,
221         // exclude if not specified or if "false" was specified.
222         return includeLocation ? Log4jLogEvent.calcLocation(fqcn) : null;
223     }
224 
225     /**
226      * Enqueues the specified log event data for logging in a background thread.
227      * <p>
228      * This creates a new varargs Object array for each invocation, but does not store any non-JDK classes in a
229      * {@code ThreadLocal} to avoid memory leaks in web applications (see LOG4J2-1172).
230      *
231      * @param fqcn fully qualified name of the caller
232      * @param level level at which the caller wants to log the message
233      * @param marker message marker
234      * @param message the log message
235      * @param thrown a {@code Throwable} or {@code null}
236      */
237     private void logWithVarargTranslator(final String fqcn, final Level level, final Marker marker,
238             final Message message, final Throwable thrown) {
239         // Implementation note: candidate for optimization: exceeds 35 bytecodes.
240 
241         final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
242         if (disruptor == null) {
243             LOGGER.error("Ignoring log event after Log4j has been shut down.");
244             return;
245         }
246         // if the Message instance is reused, there is no point in freezing its message here
247         if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND && !isReused(message)) { // LOG4J2-898: user may choose
248             message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
249         }
250         // calls the translateTo method on this AsyncLogger
251         disruptor.getRingBuffer().publishEvent(this, this, calcLocationIfRequested(fqcn), fqcn, level, marker, message,
252                 thrown);
253     }
254 
255     /*
256      * (non-Javadoc)
257      *
258      * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[])
259      */
260     @Override
261     public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) {
262         // Implementation note: candidate for optimization: exceeds 35 bytecodes.
263         final AsyncLogger asyncLogger = (AsyncLogger) args[0];
264         final StackTraceElement location = (StackTraceElement) args[1];
265         final String fqcn = (String) args[2];
266         final Level level = (Level) args[3];
267         final Marker marker = (Marker) args[4];
268         final Message message = (Message) args[5];
269         final Throwable thrown = (Throwable) args[6];
270 
271         // needs shallow copy to be fast (LOG4J2-154)
272         final Map<String, String> contextMap = ThreadContext.getImmutableContext();
273 
274         // needs shallow copy to be fast (LOG4J2-154)
275         final ContextStack contextStack = ThreadContext.getImmutableStack();
276 
277         final Thread currentThread = Thread.currentThread();
278         final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName();
279         event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown, contextMap,
280                 contextStack, currentThread.getId(), threadName, currentThread.getPriority(), location,
281                 CLOCK.currentTimeMillis(), nanoClock.nanoTime());
282     }
283 
284     /**
285      * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its
286      * toString() method
287      *
288      * @param fqcn fully qualified caller name
289      * @param level log level
290      * @param marker optional marker
291      * @param message log message
292      * @param thrown optional exception
293      */
294     void logMessageInCurrentThread(final String fqcn, final Level level, final Marker marker,
295             final Message message, final Throwable thrown) {
296         // bypass RingBuffer and invoke Appender directly
297         final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
298         strategy.log(this, getName(), fqcn, marker, level, message, thrown);
299     }
300 
301     /**
302      * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate thread.
303      *
304      * @param event the event to log
305      */
306     public void actualAsyncLog(final RingBufferLogEvent event) {
307         final Map<Property, Boolean> properties = privateConfig.loggerConfig.getProperties();
308         event.mergePropertiesIntoContextMap(properties, privateConfig.config.getStrSubstitutor());
309         final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
310         strategy.log(this, event);
311     }
312 }