日誌-log4j2基於AsyncLogger的非同步日誌列印

半夏之沫發表於2022-12-20
非同步

前言

在日誌-log4j2基於AsyncAppender的非同步日誌列印一文中，分析了Log4j2如何基於AsyncAppender來實現非同步日誌列印，本篇文章將分析Log4j2如何基於AsyncLogger來實現非同步日誌列印。

本篇文章會涉及部分Disruptor佇列的相關概念，如果不熟悉Disruptor佇列，可以先閱讀多執行緒學習-Disruptor佇列瞭解相關概念。

Log4j2版本：2.17.1

正文

首先搭建示例工程。引入依賴如下所示。

<dependencies>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-slf4j-impl</artifactId>
        <version>2.17.1</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-core</artifactId>
        <version>2.17.1</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-api</artifactId>
        <version>2.17.1</version>
    </dependency>

    <dependency>
        <groupId>com.lmax</groupId>
        <artifactId>disruptor</artifactId>
        <version>3.4.0</version>
    </dependency>
</dependencies>

列印日誌的測試類如下所示。

public class LearnLog4j2Async {

    private static final Logger logger = LoggerFactory
            .getLogger(LearnLog4j2Async.class);

    public static void main(String[] args) {
        logger.info("{} be happy every day.", "Lee");
    }

}

要使用AysncLogger，需要在Log4j2的配置檔案中使用<AsyncLogger>標籤配置一個非同步Logger，併為這個非同步Logger配置非非同步Appender。配置如下所示。

<?xml version="1.0" encoding="UTF-8"?>

<Configuration status="INFO">
    <Appenders>
        <!-- 配置兩個非非同步Appender -->
        <Console name="MyConsole" target="SYSTEM_OUT">
            <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%msg%n"/>
        </Console>
        <RollingFile name="MyFile" fileName="mylog.log"
                     filePattern="mylog.log.%i">
            <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY" />
            <PatternLayout pattern="%msg%n"/>
            <SizeBasedTriggeringPolicy size="20M"/>
        </RollingFile>
    </Appenders>

    <Loggers>
        <!-- 為根Logger配置非非同步Appender -->
        <Root level="INFO">
            <Appender-ref ref="MyConsole"/>
            <Appender-ref ref="MyFile"/>
        </Root>
        <!-- 定義一個非同步Logger併為其配置非非同步Appender -->
        <AsyncLogger name="com.lee.learn.log4j2.asynclogger.LearnLog4j2Async" level="INFO" additivity="false">
            <appender-ref ref="MyConsole"/>
        </AsyncLogger>
    </Loggers>
</Configuration>

已知Log4j2框架在首次獲取Logger時，會初始化LoggerContext，而初始化LoggerContext時有一個步驟就是將Log4j2配置物件XmlConfiguration設定給LoggerContext並啟動XmlConfiguration，這裡看一下XmlConfiguration的start()方法，如下所示。

public void start() {
    if (getState().equals(State.INITIALIZING)) {
        initialize();
    }
    LOGGER.debug("Starting configuration {}", this);
    this.setStarting();
    if (watchManager.getIntervalSeconds() >= 0) {
        watchManager.start();
    }
    // 判斷是否配置了AsyncLogger
    if (hasAsyncLoggers()) {
        // 呼叫asyncLoggerConfigDisruptor來啟動AsyncLogger
        asyncLoggerConfigDisruptor.start();
    }
    final Set<LoggerConfig> alreadyStarted = new HashSet<>();
    for (final LoggerConfig logger : loggerConfigs.values()) {
        logger.start();
        alreadyStarted.add(logger);
    }
    for (final Appender appender : appenders.values()) {
        appender.start();
    }
    if (!alreadyStarted.contains(root)) {
        root.start();
    }
    super.start();
    LOGGER.debug("Started configuration {} OK.", this);
}

在XmlConfiguration的start()方法中，需要關注的就是呼叫了asyncLoggerConfigDisruptor的start()方法來啟動AsyncLogger，asyncLoggerConfigDisruptor是一個AsyncLoggerConfigDisruptor物件，其在首次初始化AsyncLoggerConfig時被建立，如下所示。

protected AsyncLoggerConfig(final String name,
        final List<AppenderRef> appenders, final Filter filter,
        final Level level, final boolean additive,
        final Property[] properties, final Configuration config,
        final boolean includeLocation) {
    super(name, appenders, filter, level, additive, properties, config,
            includeLocation);
    // 在這裡呼叫XmlConfiguration的getAsyncLoggerConfigDelegate()方法來建立AsyncLoggerConfigDisruptor
    delegate = config.getAsyncLoggerConfigDelegate();
    delegate.setLogEventFactory(getLogEventFactory());
}

AsyncLoggerConfigDisruptor的start()方法中主要邏輯就是建立Disruptor高效能佇列，實現如下所示。

public synchronized void start() {
    if (disruptor != null) {
        LOGGER.trace("AsyncLoggerConfigDisruptor not starting new disruptor for this configuration, "
                + "using existing object.");
        return;
    }
    LOGGER.trace("AsyncLoggerConfigDisruptor creating new disruptor for this configuration.");
    // 計算Disruptor佇列大小，預設是4096
    ringBufferSize = DisruptorUtil.calculateRingBufferSize("AsyncLoggerConfig.RingBufferSize");
    // 建立等待策略，預設是TimeoutBlockingWaitStrategy
    final WaitStrategy waitStrategy = DisruptorUtil.createWaitStrategy("AsyncLoggerConfig.WaitStrategy");
    
    // 建立執行緒工廠
    final ThreadFactory threadFactory = new Log4jThreadFactory("AsyncLoggerConfig", true, Thread.NORM_PRIORITY) {
        @Override
        public Thread newThread(final Runnable r) {
            final Thread result = super.newThread(r);
            backgroundThreadId = result.getId();
            return result;
        }
    };
    // 建立佇列滿時的策略類，這裡和AsyncAppender裡的策略類是一樣的
    asyncQueueFullPolicy = AsyncQueueFullPolicyFactory.create();

    translator = mutable ? MUTABLE_TRANSLATOR : TRANSLATOR;
    // 建立填充RingBuffer的EventFactory
    // Disruptor佇列在初始化時會使用這個EventFactory來生成事件物件來填充滿RingBuffer
    factory = mutable ? MUTABLE_FACTORY : FACTORY;
    // 建立Disruptor佇列，指定生產者模式為MULTI，表示這是多生產者場景，一個AsyncLogger就是一個生產者
    disruptor = new Disruptor<>(factory, ringBufferSize, threadFactory, ProducerType.MULTI, waitStrategy);

    final ExceptionHandler<Log4jEventWrapper> errorHandler = DisruptorUtil.getAsyncLoggerConfigExceptionHandler();
    disruptor.setDefaultExceptionHandler(errorHandler);

    // 建立只有一個Log4jEventWrapperHandler的陣列
    // Log4jEventWrapperHandler實現了EventHandler介面
    // 所以Log4j2裡面使用的Disruptor佇列只有單消費者消費
    final Log4jEventWrapperHandler[] handlers = {new Log4jEventWrapperHandler()};
    disruptor.handleEventsWith(handlers);

    LOGGER.debug("Starting AsyncLoggerConfig disruptor for this configuration with ringbufferSize={}, "
            + "waitStrategy={}, exceptionHandler={}...", disruptor.getRingBuffer().getBufferSize(), waitStrategy
            .getClass().getSimpleName(), errorHandler);
    // 啟動Disruptor佇列
    disruptor.start();
    super.start();
}

在AsyncLoggerConfigDisruptor的start()方法中主要就是在進行Disruptor佇列的建立和啟動，所以如果使用了AsyncLogger，那麼儲存日誌訊息元素的Disruptor佇列在初始化LoggerContext時就會被建立並啟動。

現在看一下每一個AsyncLogger是如何向Disruptor佇列新增日誌訊息的。首先觀察一下一個AsyncLogger的具體內容。

那麼每一個AsyncLogger都持有一個AsyncLoggerConfig，所以可知AsyncLogger列印日誌會透過AsyncLoggerConfig來列印，下面看一下AsyncLogger的log()方法，如下所示。

protected void log(final LogEvent event, final LoggerConfigPredicate predicate) {
    // 只有predicate為ALL，ASYNC_LOGGER_ENTERED為false以及當前AsyncLogger有Appender時才列印
    // predicate表示允許的日誌列印型別，有ALL，ASYNCHRONOUS_ONLY和SYNCHRONOUS_ONLY三種
    // ASYNC_LOGGER_ENTERED是和執行緒繫結的原子布林值，即同一執行緒只能序列的呼叫logToAsyncDelegate()方法向Disruptor佇列新增日誌訊息
    if (predicate == LoggerConfigPredicate.ALL &&
            ASYNC_LOGGER_ENTERED.get() == Boolean.FALSE && hasAppenders()) {
        ASYNC_LOGGER_ENTERED.set(Boolean.TRUE);
        try {
            super.log(event, LoggerConfigPredicate.SYNCHRONOUS_ONLY);
            // 非同步日誌列印
            logToAsyncDelegate(event);
        } finally {
            ASYNC_LOGGER_ENTERED.set(Boolean.FALSE);
        }
    } else {
        super.log(event, predicate);
    }
}

在AsyncLogger的log()方法中，只有同時滿足如下條件才執行非同步日誌列印。

  1. 當前列印動作是全型別列印，即predicate等於LoggerConfigPredicate.ALL。LoggerConfigPredicate一共有三種列舉值，LoggerConfigPredicate.ASYNCHRONOUS_ONLY表示僅非同步列印，LoggerConfigPredicate.SYNCHRONOUS_ONLY表示僅同步列印，LoggerConfigPredicate.ALL表示同步非同步都可以；
  2. ASYNC_LOGGER_ENTERED的get()方法返回false。ASYNC_LOGGER_ENTERED是一個型別為ThreadLocal<Boolean>的變數，即同一執行緒只能序列的呼叫logToAsyncDelegate()方法向Disruptor佇列新增日誌訊息；
  3. 當前AsyncLogger有Appender。

滿足上述三點條件後，就會呼叫logToAsyncDelegate()方法來將日誌訊息新增到Disruptor佇列中，看一下其實現。

private void logToAsyncDelegate(final LogEvent event) {
    if (!isFiltered(event)) {
        populateLazilyInitializedFields(event);
        // 這裡的delegate就是AsyncLoggerConfigDisruptor
        // 透過AsyncLoggerConfigDisruptor將日誌訊息放入Disruptor的RingBuffer中
        if (!delegate.tryEnqueue(event, this)) {
            // Disruptor容量滿時執行策略類的邏輯，這裡與AsyncAppender中的策略是一致的
            handleQueueFull(event);
        }
    }
}

上述方法會呼叫AsyncLoggerConfigDisruptor的tryEnqueue()方法將日誌訊息新增到Disruptor佇列中，如下所示。

public boolean tryEnqueue(final LogEvent event, final AsyncLoggerConfig asyncLoggerConfig) {
    final LogEvent logEvent = prepareEvent(event);
    // 從Disruptor物件中取出RingBuffer，然後將日誌訊息新增到RingBuffer中併發布
    return disruptor.getRingBuffer().tryPublishEvent(translator, logEvent, asyncLoggerConfig);
}

日誌訊息新增到Disruptor佇列實際就是將日誌訊息LogEvent釋出到Disruptor的RingBuffer中，後續消費者就能夠從RingBuffer消費日誌訊息並基於Appender列印日誌。

現在最後分析消費者執行緒的啟動和消費邏輯。已知在初始化Log4j2的LoggerContext時會完成Disruptor佇列的建立和啟動，實際就是在Disruptor啟動也就是Disruptor的start()方法執行時，會將消費者執行緒執行起來，這裡的消費者是BatchEventProcessor，其本質是一個Runnable，所以最終會呼叫到BatchEventProcessor的run()方法，在run()方法中會迴圈的從Disruptor物件的RingBuffer中獲取訊息元素並將訊息元素交由EventHandler處理，整個這一塊兒邏輯是屬於Disruptor佇列的邏輯，這裡不再贅述，但是處理訊息的EventHandler是由Log4j2提供的Log4jEventWrapperHandler，這個在前面的分析中已經知道，所以看一下Log4jEventWrapperHandler的onEvent()方法。

public void onEvent(final Log4jEventWrapper event, final long sequence, final boolean endOfBatch)
        throws Exception {
    event.event.setEndOfBatch(endOfBatch);
    // 從Log4jEventWrapper中將AsyncLoggerConfig獲取出來並在當前執行緒中完成日誌列印
    event.loggerConfig.logToAsyncLoggerConfigsOnCurrentThread(event.event);
    event.clear();

    notifyIntermediateProgress(sequence);
}

void logToAsyncLoggerConfigsOnCurrentThread(final LogEvent event) {
    // 呼叫AsyncLoggerConfig的log()方法來列印日誌
    // 有兩點需要注意：
    // 1. 這裡的log()方法和新增日誌訊息到佇列中的log()方法是同一個
    // 2. 允許的列印行為被指定為LoggerConfigPredicate.ASYNCHRONOUS_ONLY，即同步列印
    log(event, LoggerConfigPredicate.ASYNCHRONOUS_ONLY);
}

protected void log(final LogEvent event, final LoggerConfigPredicate predicate) {
    if (predicate == LoggerConfigPredicate.ALL &&
            ASYNC_LOGGER_ENTERED.get() == Boolean.FALSE && hasAppenders()) {
        ASYNC_LOGGER_ENTERED.set(Boolean.TRUE);
        try {
            super.log(event, LoggerConfigPredicate.SYNCHRONOUS_ONLY);
            logToAsyncDelegate(event);
        } finally {
            ASYNC_LOGGER_ENTERED.set(Boolean.FALSE);
        }
    } else {
        // 呼叫父物件也就是LoggerConfig來列印日誌，後續就是同步日誌列印流程了
        super.log(event, predicate);
    }
}

Log4jEventWrapperHandler的onEvent()方法中，會將消費到的日誌訊息最終呼叫到和這條日誌繫結的AsyncLoggerConfig的log()方法來列印日誌，與生產訊息的時候呼叫到AsyncLoggerConfig#log方法不同，這時呼叫AsyncLoggerConfig#log方法傳入的predicate為LoggerConfigPredicate.ASYNCHRONOUS_ONLY，所以會直接呼叫AsyncLoggerConfig的父物件LoggerConfig來列印日誌，後續就是同步列印日誌的流程，這裡不再贅述。

總結

當使用AsyncLogger來實現非同步日誌列印時，儲存日誌元素的佇列為Disruptor高效能佇列，該佇列相較於傳統的阻塞佇列，優勢如下。

  1. 使用RingBuffer環形陣列儲存元素，且在初始化佇列時會將陣列元素全部初始化出來，實現物件迴圈利用，避免頻繁垃圾回收；
  2. 透過填充快取行的方式避免了偽共享，充分利用快取帶來的效率提升；
  3. 使用CAS操作代替加鎖操作，避免加解鎖帶來的效能損耗。

使用Disruptor作為阻塞佇列是Log4j2效能提升的一大重要原因。

其次，所有AsyncLogger是共用同一個Disruptor佇列的，每個AsyncLogger作為生產者可以併發的向Disruptor中新增日誌元素，同時在消費者端存在一個消費者迴圈的從Disruptor中消費日誌元素，每一條被消費的日誌元素會被消費者呼叫到和這條日誌繫結的LoggerConfig來完成列印，也就是可以理解為有多個生產者向Disruptor佇列中生產日誌元素，然後只有一個消費者從Disruptor佇列消費日誌元素並呼叫Appender完成日誌列印，整個過程可以用下圖進行示意和總結。

相關文章