Example #1
0
/**
 * AsyncLogger is a logger designed for high throughput and low latency logging. It does not perform
 * any I/O in the calling (application) thread, but instead hands off the work to another thread as
 * soon as possible. The actual logging is performed in the background thread. It uses the LMAX
 * Disruptor library for inter-thread communication. (<a
 * href="http://lmax-exchange.github.com/disruptor/"
 * >http://lmax-exchange.github.com/disruptor/</a>)
 *
 * <p>To use AsyncLogger, specify the System property {@code
 * -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector} before you
 * obtain a Logger, and all Loggers returned by LogManager.getLogger will be AsyncLoggers.
 *
 * <p>Note that for performance reasons, this logger does not include source location by default.
 * You need to specify {@code includeLocation="true"} in the configuration or any %class, %location
 * or %line conversion patterns in your log4j.xml configuration will produce either a "?" character
 * or no output at all.
 *
 * <p>For best performance, use AsyncLogger with the RandomAccessFileAppender or
 * RollingRandomAccessFileAppender, with immediateFlush=false. These appenders have built-in support
 * for the batching mechanism used by the Disruptor library, and they will flush to disk at the end
 * of each batch. This means that even with immediateFlush=false, there will never be any items left
 * in the buffer; all log events will all be written to disk in a very efficient manner.
 */
public class AsyncLogger extends Logger {
  private static final long serialVersionUID = 1L;
  private static final int SLEEP_MILLIS_BETWEEN_DRAIN_ATTEMPTS = 50;
  private static final int MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN = 200;
  private static final int RINGBUFFER_MIN_SIZE = 128;
  private static final int RINGBUFFER_DEFAULT_SIZE = 256 * 1024;
  private static final StatusLogger LOGGER = StatusLogger.getLogger();
  private static final ThreadNameStrategy THREAD_NAME_STRATEGY = ThreadNameStrategy.create();

  /** Strategy for deciding whether thread name should be cached or not. */
  static enum ThreadNameStrategy { // LOG4J2-467
    CACHED {
      @Override
      public String getThreadName(final Info info) {
        return info.cachedThreadName;
      }
    },
    UNCACHED {
      @Override
      public String getThreadName(final Info info) {
        return Thread.currentThread().getName();
      }
    };

    abstract String getThreadName(Info info);

    static ThreadNameStrategy create() {
      final String name =
          PropertiesUtil.getProperties()
              .getStringProperty("AsyncLogger.ThreadNameStrategy", CACHED.name());
      try {
        return ThreadNameStrategy.valueOf(name);
      } catch (final Exception ex) {
        LOGGER.debug(
            "Using AsyncLogger.ThreadNameStrategy.CACHED: '{}' not valid: {}", name, ex.toString());
        return CACHED;
      }
    }
  }

  private static volatile Disruptor<RingBufferLogEvent> disruptor;
  private static final Clock CLOCK = ClockFactory.getClock();
  private static volatile NanoClock nanoClock = new DummyNanoClock();

  private static final ExecutorService EXECUTOR =
      Executors.newSingleThreadExecutor(new DaemonThreadFactory("AsyncLogger-"));

  static {
    initInfoForExecutorThread();
    LOGGER.debug("AsyncLogger.ThreadNameStrategy={}", THREAD_NAME_STRATEGY);
    final int ringBufferSize = calculateRingBufferSize();

    final WaitStrategy waitStrategy = createWaitStrategy();
    disruptor =
        new Disruptor<>(
            RingBufferLogEvent.FACTORY, ringBufferSize, EXECUTOR, ProducerType.MULTI, waitStrategy);
    disruptor.handleExceptionsWith(getExceptionHandler());
    disruptor.handleEventsWith(new RingBufferLogEventHandler());

    LOGGER.debug(
        "Starting AsyncLogger disruptor with ringbuffer size {}...",
        disruptor.getRingBuffer().getBufferSize());
    disruptor.start();
  }

  /**
   * Constructs an {@code AsyncLogger} with the specified context, name and message factory.
   *
   * @param context context of this logger
   * @param name name of this logger
   * @param messageFactory message factory of this logger
   */
  public AsyncLogger(
      final LoggerContext context, final String name, final MessageFactory messageFactory) {
    super(context, name, messageFactory);
  }

  private static int calculateRingBufferSize() {
    int ringBufferSize = RINGBUFFER_DEFAULT_SIZE;
    final String userPreferredRBSize =
        PropertiesUtil.getProperties()
            .getStringProperty("AsyncLogger.RingBufferSize", String.valueOf(ringBufferSize));
    try {
      int size = Integer.parseInt(userPreferredRBSize);
      if (size < RINGBUFFER_MIN_SIZE) {
        size = RINGBUFFER_MIN_SIZE;
        LOGGER.warn(
            "Invalid RingBufferSize {}, using minimum size {}.",
            userPreferredRBSize,
            RINGBUFFER_MIN_SIZE);
      }
      ringBufferSize = size;
    } catch (final Exception ex) {
      LOGGER.warn(
          "Invalid RingBufferSize {}, using default size {}.", userPreferredRBSize, ringBufferSize);
    }
    return Integers.ceilingNextPowerOfTwo(ringBufferSize);
  }

  /**
   * Initialize an {@code Info} object that is threadlocal to the consumer/appender thread. This
   * Info object uniquely has attribute {@code isAppenderThread} set to {@code true}. All other Info
   * objects will have this attribute set to {@code false}. This allows us to detect Logger.log()
   * calls initiated from the appender thread, which may cause deadlock when the RingBuffer is full.
   * (LOG4J2-471)
   */
  private static void initInfoForExecutorThread() {
    EXECUTOR.submit(
        new Runnable() {
          @Override
          public void run() {
            final boolean isAppenderThread = true;
            final Info info =
                new Info(
                    new RingBufferLogEventTranslator(), //
                    Thread.currentThread().getName(),
                    isAppenderThread);
            Info.THREADLOCAL.set(info);
          }
        });
  }

  private static WaitStrategy createWaitStrategy() {
    final String strategy =
        PropertiesUtil.getProperties().getStringProperty("AsyncLogger.WaitStrategy");
    LOGGER.debug("property AsyncLogger.WaitStrategy={}", strategy);
    if ("Sleep".equals(strategy)) {
      return new SleepingWaitStrategy();
    } else if ("Yield".equals(strategy)) {
      return new YieldingWaitStrategy();
    } else if ("Block".equals(strategy)) {
      return new BlockingWaitStrategy();
    }
    LOGGER.debug("disruptor event handler uses BlockingWaitStrategy");
    return new BlockingWaitStrategy();
  }

  private static ExceptionHandler<RingBufferLogEvent> getExceptionHandler() {
    final String cls =
        PropertiesUtil.getProperties().getStringProperty("AsyncLogger.ExceptionHandler");
    if (cls == null) {
      LOGGER.debug("No AsyncLogger.ExceptionHandler specified");
      return null;
    }
    try {
      @SuppressWarnings("unchecked")
      final ExceptionHandler<RingBufferLogEvent> result =
          Loader.newCheckedInstanceOf(cls, ExceptionHandler.class);
      LOGGER.debug("AsyncLogger.ExceptionHandler={}", result);
      return result;
    } catch (final Exception ignored) {
      LOGGER.debug("AsyncLogger.ExceptionHandler not set: error creating " + cls + ": ", ignored);
      return null;
    }
  }

  /** Tuple with the event translator and thread name for a thread. */
  static class Info {
    private static final ThreadLocal<Info> THREADLOCAL =
        new ThreadLocal<Info>() {
          @Override
          protected Info initialValue() {
            // by default, set isAppenderThread to false
            return new Info(
                new RingBufferLogEventTranslator(), Thread.currentThread().getName(), false);
          }
        };
    private final RingBufferLogEventTranslator translator;
    private final String cachedThreadName;
    private final boolean isAppenderThread;

    public Info(
        final RingBufferLogEventTranslator translator,
        final String threadName,
        final boolean appenderThread) {
      this.translator = translator;
      this.cachedThreadName = threadName;
      this.isAppenderThread = appenderThread;
    }

    // LOG4J2-467
    private String threadName() {
      return THREAD_NAME_STRATEGY.getThreadName(this);
    }
  }

  @Override
  public void logMessage(
      final String fqcn,
      final Level level,
      final Marker marker,
      final Message message,
      final Throwable thrown) {

    final Disruptor<RingBufferLogEvent> temp = disruptor;
    if (temp == null) { // LOG4J2-639
      LOGGER.fatal("Ignoring log event after log4j was shut down");
    } else {
      logMessage0(temp, fqcn, level, marker, message, thrown);
    }
  }

  private void logMessage0(
      final Disruptor<RingBufferLogEvent> theDisruptor,
      final String fqcn,
      final Level level,
      final Marker marker,
      final Message message,
      final Throwable thrown) {
    final Info info = Info.THREADLOCAL.get();
    logMessageInAppropriateThread(info, theDisruptor, fqcn, level, marker, message, thrown);
  }

  private void logMessageInAppropriateThread(
      final Info info,
      final Disruptor<RingBufferLogEvent> theDisruptor,
      final String fqcn,
      final Level level,
      final Marker marker,
      final Message message,
      final Throwable thrown) {
    if (!logMessageInCurrentThread(info, theDisruptor, fqcn, level, marker, message, thrown)) {
      logMessageInBackgroundThread(info, fqcn, level, marker, message, thrown);
    }
  }

  /**
   * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log()
   * from its toString() method
   *
   * @param info threadlocal information - used to determine if the current thread is the background
   *     appender thread
   * @param theDisruptor used to check if the buffer is full
   * @param fqcn fully qualified caller name
   * @param level log level
   * @param marker optional marker
   * @param message log message
   * @param thrown optional exception
   * @return {@code true} if the event has been logged in the current thread, {@code false} if it
   *     should be passed to the background thread
   */
  private boolean logMessageInCurrentThread(
      Info info,
      final Disruptor<RingBufferLogEvent> theDisruptor,
      final String fqcn,
      final Level level,
      final Marker marker,
      final Message message,
      final Throwable thrown) {
    if (info.isAppenderThread && theDisruptor.getRingBuffer().remainingCapacity() == 0) {
      // bypass RingBuffer and invoke Appender directly
      final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
      strategy.log(this, getName(), fqcn, marker, level, message, thrown);
      return true;
    }
    return false;
  }

  /**
   * Enqueues the specified message to be logged in the background thread.
   *
   * @param info holds some cached information
   * @param fqcn fully qualified caller name
   * @param level log level
   * @param marker optional marker
   * @param message log message
   * @param thrown optional exception
   */
  private void logMessageInBackgroundThread(
      Info info,
      final String fqcn,
      final Level level,
      final Marker marker,
      final Message message,
      final Throwable thrown) {

    message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters

    initLogMessageInfo(info, fqcn, level, marker, message, thrown);
    enqueueLogMessageInfo(info);
  }

  private void initLogMessageInfo(
      Info info,
      final String fqcn,
      final Level level,
      final Marker marker,
      final Message message,
      final Throwable thrown) {
    info.translator.setValues(
        this,
        getName(),
        marker,
        fqcn,
        level,
        message, //
        // don't construct ThrowableProxy until required
        thrown, //

        // config properties are taken care of in the EventHandler
        // thread in the #actualAsyncLog method

        // needs shallow copy to be fast (LOG4J2-154)
        ThreadContext.getImmutableContext(), //

        // needs shallow copy to be fast (LOG4J2-154)
        ThreadContext.getImmutableStack(), //

        // Thread.currentThread().getName(), //
        // info.cachedThreadName, //
        info.threadName(), //

        // location: very expensive operation. LOG4J2-153:
        // Only include if "includeLocation=true" is specified,
        // exclude if not specified or if "false" was specified.
        calcLocationIfRequested(fqcn),

        // System.currentTimeMillis());
        // CoarseCachedClock: 20% faster than system clock, 16ms gaps
        // CachedClock: 10% faster than system clock, smaller gaps
        // LOG4J2-744 avoid calling clock altogether if message has the timestamp
        eventTimeMillis(message), //
        nanoClock.nanoTime() //
        );
  }

  private long eventTimeMillis(final Message message) {
    return message instanceof TimestampMessage
        ? ((TimestampMessage) message).getTimestamp()
        : CLOCK.currentTimeMillis();
  }

  /**
   * Returns the caller location if requested, {@code null} otherwise.
   *
   * @param fqcn fully qualified caller name.
   * @return the caller location if requested, {@code null} otherwise.
   */
  private StackTraceElement calcLocationIfRequested(String fqcn) {
    final boolean includeLocation = privateConfig.loggerConfig.isIncludeLocation();
    return includeLocation ? location(fqcn) : null;
  }

  private void enqueueLogMessageInfo(Info info) {
    // LOG4J2-639: catch NPE if disruptor field was set to null after our check above
    try {
      // Note: do NOT use the temp variable above!
      // That could result in adding a log event to the disruptor after it was shut down,
      // which could cause the publishEvent method to hang and never return.
      disruptor.publishEvent(info.translator);
    } catch (final NullPointerException npe) {
      LOGGER.fatal("Ignoring log event after log4j was shut down.");
    }
  }

  private static StackTraceElement location(final String fqcnOfLogger) {
    return Log4jLogEvent.calcLocation(fqcnOfLogger);
  }

  /**
   * This method is called by the EventHandler that processes the RingBufferLogEvent in a separate
   * thread.
   *
   * @param event the event to log
   */
  public void actualAsyncLog(final RingBufferLogEvent event) {
    final Map<Property, Boolean> properties = privateConfig.loggerConfig.getProperties();
    event.mergePropertiesIntoContextMap(properties, privateConfig.config.getStrSubstitutor());
    final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
    strategy.log(this, event);
  }

  public static void stop() {
    final Disruptor<RingBufferLogEvent> temp = disruptor;

    // Must guarantee that publishing to the RingBuffer has stopped
    // before we call disruptor.shutdown()
    disruptor = null; // client code fails with NPE if log after stop = OK
    if (temp == null) {
      return; // stop() has already been called
    }

    // Calling Disruptor.shutdown() will wait until all enqueued events are fully processed,
    // but this waiting happens in a busy-spin. To avoid (postpone) wasting CPU,
    // we sleep in short chunks, up to 10 seconds, waiting for the ringbuffer to drain.
    for (int i = 0; hasBacklog(temp) && i < MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN; i++) {
      try {
        Thread.sleep(SLEEP_MILLIS_BETWEEN_DRAIN_ATTEMPTS); // give up the CPU for a while
      } catch (final InterruptedException e) { // ignored
      }
    }
    temp.shutdown(); // busy-spins until all events currently in the disruptor have been processed
    EXECUTOR.shutdown(); // finally, kill the processor thread
    Info.THREADLOCAL.remove(); // LOG4J2-323
  }

  /** Returns {@code true} if the specified disruptor still has unprocessed events. */
  private static boolean hasBacklog(final Disruptor<?> theDisruptor) {
    final RingBuffer<?> ringBuffer = theDisruptor.getRingBuffer();
    return !ringBuffer.hasAvailableCapacity(ringBuffer.getBufferSize());
  }

  /**
   * Creates and returns a new {@code RingBufferAdmin} that instruments the ringbuffer of the {@code
   * AsyncLogger}.
   *
   * @param contextName name of the global {@code AsyncLoggerContext}
   * @return a new {@code RingBufferAdmin} that instruments the ringbuffer
   */
  public static RingBufferAdmin createRingBufferAdmin(final String contextName) {
    return RingBufferAdmin.forAsyncLogger(disruptor.getRingBuffer(), contextName);
  }

  /**
   * Returns the {@code NanoClock} to use for creating the nanoTime timestamp of log events.
   *
   * @return the {@code NanoClock} to use for creating the nanoTime timestamp of log events
   */
  public static NanoClock getNanoClock() {
    return nanoClock;
  }

  /**
   * Sets the {@code NanoClock} to use for creating the nanoTime timestamp of log events.
   *
   * <p>FOR INTERNAL USE. This method may be called with a different {@code NanoClock}
   * implementation when the configuration changes.
   *
   * @param nanoClock the {@code NanoClock} to use for creating the nanoTime timestamp of log events
   */
  public static void setNanoClock(NanoClock nanoClock) {
    AsyncLogger.nanoClock = Objects.requireNonNull(nanoClock, "NanoClock must be non-null");
  }
}