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.message.Message;
036import org.apache.logging.log4j.message.MessageFactory;
037import org.apache.logging.log4j.message.ReusableMessage;
038import org.apache.logging.log4j.status.StatusLogger;
039
040import com.lmax.disruptor.EventTranslatorVararg;
041import com.lmax.disruptor.dsl.Disruptor;
042
043/**
044 * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform any I/O in the
045 * calling (application) thread, but instead hands off the work to another thread as soon as possible. The actual
046 * logging is performed in the background thread. It uses the LMAX Disruptor library for inter-thread communication. (<a
047 * href="http://lmax-exchange.github.com/disruptor/" >http://lmax-exchange.github.com/disruptor/</a>)
048 * <p>
049 * To use AsyncLogger, specify the System property
050 * {@code -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you obtain a
051 * Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers.
052 * <p>
053 * Note that for performance reasons, this logger does not include source location by default. You need to specify
054 * {@code includeLocation="true"} in the configuration or any %class, %location or %line conversion patterns in your
055 * log4j.xml configuration will produce either a "?" character or no output at all.
056 * <p>
057 * For best performance, use AsyncLogger with the RandomAccessFileAppender or RollingRandomAccessFileAppender, with
058 * immediateFlush=false. These appenders have built-in support for the batching mechanism used by the Disruptor library,
059 * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will
060 * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner.
061 */
062public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBufferLogEvent> {
063    // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE!
064    // Specifically, try to keep the hot methods to 35 bytecodes or less:
065    // this is within the MaxInlineSize threshold and makes these methods candidates for
066    // immediate inlining instead of waiting until they are designated "hot enough".
067
068    private static final StatusLogger LOGGER = StatusLogger.getLogger();
069    private static final Clock CLOCK = ClockFactory.getClock(); // not reconfigurable
070
071    private static final ThreadNameCachingStrategy THREAD_NAME_CACHING_STRATEGY = ThreadNameCachingStrategy.create();
072
073    private final ThreadLocal<RingBufferLogEventTranslator> threadLocalTranslator = new ThreadLocal<>();
074    private final AsyncLoggerDisruptor loggerDisruptor;
075
076    private volatile boolean includeLocation; // reconfigurable
077    private volatile NanoClock nanoClock; // reconfigurable
078
079    /**
080     * Constructs an {@code AsyncLogger} with the specified context, name and message factory.
081     *
082     * @param context context of this logger
083     * @param name name of this logger
084     * @param messageFactory message factory of this logger
085     * @param loggerDisruptor helper class that logging can be delegated to. This object owns the Disruptor.
086     */
087    public AsyncLogger(final LoggerContext context, final String name, final MessageFactory messageFactory,
088            final AsyncLoggerDisruptor loggerDisruptor) {
089        super(context, name, messageFactory);
090        this.loggerDisruptor = loggerDisruptor;
091        includeLocation = privateConfig.loggerConfig.isIncludeLocation();
092        nanoClock = context.getConfiguration().getNanoClock();
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        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(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}