一次鞭辟入裡的 Log4j2 非同步日誌輸出阻塞問題的定位

乾貨滿滿張雜湊發表於2021-07-06

一次鞭辟入裡的 Log4j2 日誌輸出阻塞問題的定位

問題現象

線上某個應用的某個例項突然出現某些次請求服務響應極慢的情況,有幾次請求超過 60s 才返回,並且通過日誌發現,服務執行緒並沒有做什麼很重的操作。這種情況斷斷續續持續了半小時左右。

核心問題定位

由於半小時後,服務例項恢復正常,並且出現請求極慢的次數並不太多,沒有能及時列印出現問題的時候執行緒堆疊採集相關資訊。但是,我們有自己的法寶,JFR(關於 JFR,請參考我的另一系列JFR全解)。

JFR 非常適合用來事後覆盤定位問題,並且配置得當的話,效能損耗極小,並且不像 APM 系統一樣需要額外的採集以及需要統一的服務程式進行整合展現。我們隨用隨取即可,但是 JFR 面向的是單程式的問題定位,找到問題程式,定位跨程式業務問題鏈路追蹤還是需要 APM 系統的。

我們通過如下命令採集對應時間段的 JFR:

jcmd 程式pid JFR.dump begin=2021-07-04T17:30:00.000Z end=2021-07-04T18:30:00.000Z

我們選擇的時間跨度比出問題的時間跨度大一些,這樣保證底層問題出現的時候也被採集寫入這個 dump 檔案。

對於歷史某些請求響應慢,我一般按照如下流程去看:

  1. 是否有 STW(Stop-the-world,參考我的另一篇文章:JVM相關 - SafePoint 與 Stop The World 全解):
  2. 是否有 GC 導致的長時間 STW
  3. 是否有其他原因導致程式所有執行緒進入 safepoint 導致 STW
  4. 是否 IO 花了太長時間,例如呼叫其他微服務,訪問各種儲存(硬碟,資料庫,快取等等)
  5. 是否在某些鎖上面阻塞太長時間?
  6. 是否 CPU 佔用過高,哪些執行緒導致的?

接下來我們來詳細分析,首先是 GC,從下圖看,並沒有能嚴重影響執行緒 STW 很長時間的:
image

然後檢視 safepoint 相關,發現也沒有什麼影響:

image

接著,我們檢視 IO 相關的事件,也並沒有發現業務相關的阻塞讀:

image

image

然後,我們檢視是否在某些鎖上面阻塞太長時間,終於發現異常:

image

通過堆疊,我們發現是** log4j2 列印日誌卡住了**。

問題分析

1. Java Monitor Blocked 的 Monitor Address 對於同一個物件也是會改變的

首先,對於 Java Monitor Blocked 這個事件,我們可以通過 Monitor Address 來判斷是否是同一個鎖。例如這裡我們發現這些執行緒都是阻塞在 FFFF 4C09 3188 這個地址的物件,這個地址是基於物件在 Java 堆中的相對地址得出的。

但是對於同一個物件,這個地址並不會是不變的,在每次 GC 掃描整理到這個物件物件的時候,如果有回收記憶體,一般這個地址就會改變。由於我們使用的是 G1,所以並不是每次 GC 都會掃描到這個物件,但是如果地址發生改變,一定是因為發生了 GC

2. log4j2 非同步日誌原理簡介

在我們的應用配置中,採用的日誌框架是 log4j2,採用的配置是非同步日誌配置。這裡簡單說一下 Log4j2 非同步日誌的原理:Log4j2 非同步日誌基於高效能資料結構 Disruptor,Disruptor 是一個環形 buffer,做了很多效能優化(具體原理可以參考我的另一系列:高併發資料結構(disruptor)),Log4j2 對此的應用如下所示:

image

簡單來說,多執行緒通過 log4j2 的門面類 org.apache.logging.log4j.Logger 進行日誌輸出,被封裝成為一個 org.apache.logging.log4j.core.LogEvent,放入到 Disruptor 的環形 buffer 中。在消費端有一個單執行緒消費這些 LogEvent 寫入對應的 Appender,我們這裡只有一個 Appender,其配置是:

<RollingFile name="file" append="true"
             filePattern="./app.log-%d{yyyy.MM.dd.HH}">
    <PatternLayout pattern="${logFormat}"/>
    <Policies>
        <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
    </Policies>
    <DirectWriteRolloverStrategy maxFiles="72"/>
</RollingFile>

非同步日誌 logger 配置為(配置 includeLocation 為 false,避免每次列印日誌需要獲取呼叫堆疊的效能損耗):

 <Asyncroot level="info" includeLocation="false">
    <appender-ref ref="file"/>
</Asyncroot>

log4j component 額外配置為:

log4j2.component.properties:

# 當沒有日誌的時候,消費執行緒通過 Block 等待日誌事件到來,這樣 CPU 佔用最少
AsyncLoggerConfig.WaitStrategy=Block

3. log4j2 disruptor 的 RingBuffer 的大小

既然是一個環形 Buffer,它的容量是有限的,我們這裡沒有修改它的大小,走的是預設配置,檢視其原始碼:

AsyncLoggerConfigDisruptor.java

public synchronized void start() {
    //省略其他程式碼
    ringBufferSize = DisruptorUtil.calculateRingBufferSize("AsyncLoggerConfig.RingBufferSize");
    disruptor = new Disruptor<>(factory, ringBufferSize, threadFactory, ProducerType.MULTI, waitStrategy);
}

DisruptorUtil.java

private static final int RINGBUFFER_MIN_SIZE = 128;
private static final int RINGBUFFER_DEFAULT_SIZE = 256 * 1024;
private static final int RINGBUFFER_NO_GC_DEFAULT_SIZE = 4 * 1024;

static int calculateRingBufferSize(final String propertyName) {
    //是否啟用了 ThreadLocal,如果是則為 4 kB,不是則為 256 kB
    int ringBufferSize = Constants.ENABLE_THREADLOCALS ? RINGBUFFER_NO_GC_DEFAULT_SIZE : RINGBUFFER_DEFAULT_SIZE;
    //讀取系統變數,以及 log4j2.component.properties 檔案獲取 propertyName(這裡是 AsyncLoggerConfig.RingBufferSize) 這個配置
    final String userPreferredRBSize = PropertiesUtil.getProperties().getStringProperty(propertyName,
            String.valueOf(ringBufferSize));
    try {
        int size = Integer.parseInt(userPreferredRBSize);
        //如果小於 128 位元組則按照 128 位元組設定
        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);
    }
    //取最近的 2 的 n 次方,因為對於 2 的 n 次方取餘等於對於 2^n-1 取與運算,這樣更快
    return Integers.ceilingNextPowerOfTwo(ringBufferSize);
}

如果啟用了 ThreadLocal 這種方式生成 LogEvent,每次不新生成的 LogEvent 用之前的,用 ThreadLocal 儲存的,這樣避免了建立新的 LogEvent。但是考慮下面這種情況:

logger.info("{}", someObj);

這樣會造成強引用,導致如果執行緒沒有新的日誌,這個 someObj 一直不能回收。所以針對 Web 應用,log4j2 預設是不啟用 ThreadLocal 的 方式生成 LogEvent

Constants.java

public static final boolean IS_WEB_APP = PropertiesUtil.getProperties().getBooleanProperty(
            "log4j2.is.webapp", isClassAvailable("javax.servlet.Servlet"));
public static final boolean ENABLE_THREADLOCALS = !IS_WEB_APP && PropertiesUtil.getProperties().getBooleanProperty(
            "log4j2.enable.threadlocals", true);

由此,可以看出,我們的 RingBuffer 的大小為 256 kB

4. RingBuffer 滿了 log4j2 會發生什麼?

當 RingBuffer 滿了,如果在 log4j2.component.properties 配置了 AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=false,則會 Wait(其實是 park) 在 Disruptor 的 produce 方法上,等待消費出下一個可以生產的環形 buffer 槽;預設這個配置為 true,即所有生產日誌的執行緒嘗試獲取全域性中的同一個鎖(private final Object queueFullEnqueueLock = new Object();):

DisruptorUtil.java

static final boolean ASYNC_CONFIG_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL = PropertiesUtil.getProperties()
        .getBooleanProperty("AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull", true);
private boolean synchronizeEnqueueWhenQueueFull() {
    return DisruptorUtil.ASYNC_CONFIG_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL
            // Background thread must never block
            && backgroundThreadId != Thread.currentThread().getId();
}

private final Object queueFullEnqueueLock = new Object();

private void enqueue(final LogEvent logEvent, final AsyncLoggerConfig asyncLoggerConfig) {
    //如果 AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=true,預設就是 true
    if (synchronizeEnqueueWhenQueueFull()) {
        synchronized (queueFullEnqueueLock) {
            disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
        }
    } else {
        //如果 AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=false
        disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
    }
}

預設配置的時候,異常堆疊和我們 JFR 中看到的一樣,舉個例子:

"Thread-0" #27 [13136] prio=5 os_prio=0 cpu=0.00ms elapsed=141.08s tid=0x0000022d6f2fbcc0 nid=0x3350 waiting for monitor entry  [0x000000399bcfe000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueue(AsyncLoggerConfigDisruptor.java:375)
	- waiting to lock <merged>(a java.lang.Object)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueueEvent(AsyncLoggerConfigDisruptor.java:330)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logInBackgroundThread(AsyncLoggerConfig.java:159)
	at org.apache.logging.log4j.core.async.EventRoute$1.logMessage(EventRoute.java:46)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.handleQueueFull(AsyncLoggerConfig.java:149)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logToAsyncDelegate(AsyncLoggerConfig.java:136)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:116)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:460)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:162)
	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2190)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2144)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2127)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2003)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1975)
	at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1312)
	省略業務方法堆疊

配置為 false 的時候,堆疊是這個樣子的:

"Thread-0" #27 [18152] prio=5 os_prio=0 cpu=0.00ms elapsed=5.68s tid=0x000002c1fa120e00 nid=0x46e8 runnable  [0x000000eda8efe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@17-loom/Native Method)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17-loom/LockSupport.java:410)
	at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
	at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
	at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:524)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueue(AsyncLoggerConfigDisruptor.java:379)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueueEvent(AsyncLoggerConfigDisruptor.java:330)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logInBackgroundThread(AsyncLoggerConfig.java:159)
	at org.apache.logging.log4j.core.async.EventRoute$1.logMessage(EventRoute.java:46)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.handleQueueFull(AsyncLoggerConfig.java:149)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logToAsyncDelegate(AsyncLoggerConfig.java:136)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:116)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:460)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:162)
	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2190)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2144)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2127)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2003)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1975)
	at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1312)

5. 為何會滿,我們的消費執行緒當時在幹啥?

我們來看下當時的消費執行緒是否有異常,由於當時硬碟 io 看系統監控並沒有異常所以這個執行緒很大可能是 Runnable 的,不斷的在寫入日誌。同時,我們知道,寫入檔案 java 底層基於 native 呼叫,所以我們檢視 JFR 的 native 方法採集。使用事件檢視器中的 Method Profiling Sample Native,右鍵點選,並選擇“使用所選型別事件建立新頁”:

image

在建立出來的新頁中,按照執行緒分組檢視,檢視 Log4j2 的 disruptor 消費執行緒,可以得出下圖:
image

可以看出:在出問題的時間段,採集到的寫入日誌檔案的事件數量明顯增多很多,並且,通過堆疊可以看到:

"Log4j2-TF-2-AsyncLoggerConfig-1" #26 [23680] daemon prio=5 os_prio=0 cpu=406.25ms elapsed=2.89s tid=0x0000022d6f3d4080 nid=0x5c80 runnable  [0x000000399bbfe000]
   java.lang.Thread.State: RUNNABLE
	at java.io.FileOutputStream.writeBytes(java.base@17-loom/Native Method)
	at java.io.FileOutputStream.write(java.base@17-loom/FileOutputStream.java:365)
	at org.apache.logging.log4j.core.appender.OutputStreamManager.writeToDestination(OutputStreamManager.java:261)
	- eliminated <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
	at org.apache.logging.log4j.core.appender.FileManager.writeToDestination(FileManager.java:272)
	- eliminated <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
	at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.writeToDestination(RollingFileManager.java:236)
	- eliminated <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
	at org.apache.logging.log4j.core.appender.OutputStreamManager.flushBuffer(OutputStreamManager.java:293)
	- locked <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
	at org.apache.logging.log4j.core.appender.OutputStreamManager.flush(OutputStreamManager.java:302)
	- locked <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:199)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190)
	at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181)
	at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:312)
	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:543)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:127)
	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:121)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logToAsyncLoggerConfigsOnCurrentThread(AsyncLoggerConfig.java:169)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:111)
	at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:97)
	at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)
	at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
	at java.lang.Thread.run(java.base@17-loom/Thread.java:1521)

log4j2 呼叫了很多次 flush, JFR 顯示採集到的事件,每次都呼叫了 flush。每次呼叫 flush,都會造成檔案真正寫的 native 呼叫。而消費慢的原因,其實就是這種 native 呼叫太多,系統寫入不過來了。

問題解決

我們可以通過以下四個方向解決這個問題:

  1. 減少日誌輸出,精簡日誌,這是比較基礎的方式,也是比較簡單的方式,但是身為一個技術人,我們不能滿足於此
  2. 增加硬碟 io,這個也是比較基礎簡單的解決方式
  3. 我們是否可以減少這個 flush 呢?答案是可以的,我們可以配置 Appender 的 immediateFlush 為 false
  4. 增加監控,針對堆疊包含 org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueue 的 java monitor block 事件進行監控,如果發現時間過長或者數量很多的事件則報警或者重建程式

1. 配置 Appender 的 immediateFlush 為 false

我們可以配置 Appender 的 immediateFlush 為 false,例如:

<RollingFile name="file" append="true"
             filePattern="./app.log-%d{yyyy.MM.dd.HH}"
             immediateFlush="false">
    <PatternLayout pattern="${logFormat}"/>
    <Policies>
        <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
    </Policies>
    <DirectWriteRolloverStrategy maxFiles="72"/>
</RollingFile>

這裡的原理對應原始碼:

AbstractOutputStreamAppender.java

protected void directEncodeEvent(final LogEvent event) {
    getLayout().encode(event, manager);
    //如果配置了 immdiateFlush (預設為 true)或者當前事件是 EndOfBatch
    if (this.immediateFlush || event.isEndOfBatch()) {
        manager.flush();
    }
}

那麼對於 Log4j2 Disruptor 非同步日誌來說,什麼時候 LogEventEndOfBatch 呢?是在消費到的 index 等於生產釋出到的最大 index 的時候,這也是比較符合效能設計考慮,即在沒有消費完的時候,儘可能地不 flush,消費完當前所有的時候再去 flush:

BatchEventProcessor.java

private void processEvents()
{
    T event = null;
    long nextSequence = sequence.get() + 1L;

    while (true)
    {
        try
        {
            final long availableSequence = sequenceBarrier.waitFor(nextSequence);
            if (batchStartAware != null)
            {
                batchStartAware.onBatchStart(availableSequence - nextSequence + 1);
            }

            while (nextSequence <= availableSequence)
            {
                event = dataProvider.get(nextSequence);
                //這裡 nextSequence == availableSequence 就是 EndOfBatch
                eventHandler.onEvent(event, nextSequence, nextSequence == availableSequence);
                nextSequence++;
            }

            sequence.set(availableSequence);
        }
        catch (final TimeoutException e)
        {
            notifyTimeout(sequence.get());
        }
        catch (final AlertException ex)
        {
            if (running.get() != RUNNING)
            {
                break;
            }
        }
        catch (final Throwable ex)
        {
            exceptionHandler.handleEventException(ex, nextSequence, event);
            sequence.set(nextSequence);
            nextSequence++;
        }
    }
}

2. 增加基於 JFR 事件監控

這個需要 Java 14 以上的版本

Configuration config = Configuration.getConfiguration("default");
//設定監控的鎖 block 時間超過多少就會採集
config.getSettings().put("jdk.JavaMonitorEnter#threshold", "1s");
try (var es = new RecordingStream(config)) {
    es.onEvent("jdk.JavaMonitorEnter", recordedEvent -> {
        //如果堆疊包含我們關注的,則報警
        if (recordedEvent.getStackTrace().getFrames().stream().anyMatch(recordedFrame -> recordedFrame.toString().contains("org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueue")))  {
            System.out.println("Alarm: " + recordedEvent);
        }
    });
    es.start();
}

微信搜尋“我的程式設計喵”關注公眾號,每日一刷,輕鬆提升技術,斬獲各種offer

image

相關文章