動態

詳情 返回 返回

日誌-log4j2基於AsyncLogger的異步日誌打印 - 動態 詳情

大家好，我是半夏之沫 😁😁 一名金融科技領域的JAVA系統研發😊😊
我希望將自己工作和學習中的經驗以最樸實，最嚴謹的方式分享給大家，共同進步👉💓👈
👉👉👉👉👉👉👉👉💓寫作不易，期待大家的關注和點贊💓👈👈👈👈👈👈👈👈
👉👉👉👉👉👉👉👉💓關注微信公眾號【技術探界】 💓👈👈👈👈👈👈👈👈

前言

在日誌-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完成日誌打印，整個過程可以用下圖進行示意和總結。

大家好，我是半夏之沫 😁😁 一名金融科技領域的JAVA系統研發😊😊
我希望將自己工作和學習中的經驗以最樸實，最嚴謹的方式分享給大家，共同進步👉💓👈
👉👉👉👉👉👉👉👉💓寫作不易，期待大家的關注和點贊💓👈👈👈👈👈👈👈👈
👉👉👉👉👉👉👉👉💓關注微信公眾號【技術探界】 💓👈👈👈👈👈👈👈👈
logger , log4j2 , 日誌 , slf4j , async
user avatar simonbaker_5ec61c266b1df 頭像 iceblue 頭像 mochou_5b3c64f18b5f1 頭像 hz_linmu 頭像
點贊 4 用戶, 點贊了這篇動態!
點贊

Add a new 評論

Some HTML is okay.