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}