在被線上大量日誌輸出導致效能瓶頸毒打了很多次之後總結出的經驗

乾貨滿滿張雜湊發表於2021-10-27

由於線上業務量級比較大（日請求上億，日活使用者幾十萬），同時業務涉及邏輯很複雜，線上日誌級別我們採用的是 info 級別，導致線上日誌量非常龐大，經常遇到因為日誌寫入太慢導致的效能瓶頸（各微服務每小時日誌量加在一起約小 1000G）。下面將我們做的日誌效能提升與精簡日誌的規範列出，供大家參考。我們使用的日誌框架是 Log4j2

1. 使用 Log4j2 非同步日誌

首先，推薦日誌量大的時候，採用非同步日誌進行日誌輸出。好處是在 RingBuffer 滿之前，呼叫日誌 api 列印日誌的時候不會阻塞。壞處是增加日誌丟失的可能性，例如在程式異常退出的時候（例如 kill -9），在 RingBuffer 中的還沒輸出到檔案的日誌事件就會丟失。

這裡簡單說一下 Log4j2 非同步日誌的原理：Log4j2 非同步日誌基於高效能資料結構 Disruptor，Disruptor 是一個環形 buffer，做了很多效能優化（具體原理可以參考我的另一系列：高併發資料結構（disruptor）），Log4j2 對此的應用如下所示：

簡單來說，多執行緒通過 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}" immediateFlush="false">
    <PatternLayout pattern="${logFormat}"/>
    <Policies>
        <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
    </Policies>
    <DirectWriteRolloverStrategy maxFiles="72"/>
</RollingFile>

非同步日誌 logger 配置為（配置 includeLocation 為 false，避免每次列印日誌需要獲取呼叫堆疊的效能損耗，這個我們後面會提到），這裡的日誌級別是 info：

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

log4j component 額外配置為：

log4j2.component.properties:

# 當沒有日誌的時候，列印日誌的單執行緒通過 SLEEP 等待日誌事件到來。這樣 CPU 佔用較少的同時，也能在日誌到來時喚醒列印日誌的單執行緒延遲較低，這個後面會詳細分析
# 我們還進一步將其中的 Thread.yield() 修改為了 Thread.spinWait()
AsyncLoggerConfig.WaitStrategy=SLEEP

2. 關閉 includeLocation，在日誌內容中加入標誌位置的標記

日誌中我們可能會需要輸出當前輸出的日誌對應程式碼中的哪一類的哪一方法的哪一行，這個需要在執行時獲取堆疊。獲取堆疊，無論是在 Java 9 之前通過 Thorwable.getStackTrace()，還是通過 Java 9 之後的 StackWalker，獲取當前程式碼堆疊，都是一個非常消耗 CPU 效能的操作。在大量輸出日誌的時候，會成為嚴重的效能瓶頸，其原因是：

獲取堆疊屬於從 Java 程式碼執行，切換到 JVM 程式碼執行，是 JNI 呼叫。這個切換是有效能損耗的。
Java 9 之前通過新建異常獲取堆疊，Java 9 之後通過 Stackwalker 獲取。這兩種方式，截止目前 Java 17 版本，都在高併發情況下，有嚴重的效能問題，會吃掉大量 CPU。主要是底層 JVM 符號與常量池優化的問題。

所以，我們在日誌中不列印所在類方法。但是可以自己在日誌中新增類名方法名用於快速定位問題程式碼。一般 IDE 中會有這種模本輔助，例如我在 IDEA 中就自定義了這個快捷模板：

快捷鍵 cm 之後按 tab 就會變成類名-方法名的字串。

3. 配置 Disruptor 的等待策略為 SLEEP，但是最好能將其中的 Thread.yield 修改為 Thread.onSpinWait (這個修改僅針對 x86 機器部署)

Disruptor 的消費者做的事情其實就是不斷檢查是否有訊息到來，其實就是某個狀態位是否就緒，就緒後讀取訊息進行消費。至於如何不斷檢查，這個就是等待策略。Disruptor 中有很多等待策略，熟悉多處理器程式設計的對於等待策略肯定不會陌生，在這裡可以簡單理解為當任務沒有到來時，執行緒應該如何等待並且讓出 CPU 資源才能在任務到來時儘量快的開始工作。在 Log4j2 中，非同步日誌基於 Disruptor，同時使用 AsyncLoggerConfig.WaitStrategy 這個環境變數對於 Disruptor 的等待策略進行配置，目前最新版本的 Log4j2 中可以配置：

switch (strategyUp) {
    case "SLEEP":
        final long sleepTimeNs =
                parseAdditionalLongProperty(propertyName, "SleepTimeNs", 100L);
        final String key = getFullPropertyKey(propertyName, "Retries");
        final int retries =
                PropertiesUtil.getProperties().getIntegerProperty(key, 200);
        return new SleepingWaitStrategy(retries, sleepTimeNs);
    case "YIELD":
        return new YieldingWaitStrategy();
    case "BLOCK":
        return new BlockingWaitStrategy();
    case "BUSYSPIN":
        return new BusySpinWaitStrategy();
    case "TIMEOUT":
        return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
    default:
        return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
}

我們這裡使用其中策略最為均衡的 SleepingWaitStrategy。在當前的大多數應用中，執行緒的個數都遠大於 CPU 的個數，甚至是 RUNNABLE 的執行緒個數都遠大於 CPU 個數，使用基於 Wait 的 BusySpinWaitStrategy 會導致業務閒時突然來業務高峰的時候，日誌消費執行緒喚醒的不夠及時（CPU 一直被大量的 RUNNABLE 業務執行緒搶佔）。如果使用比較激進的 BusySpinWaitStrategy（一直呼叫 Thread.onSpinWait()）或者 YieldingWaitStrategy（先 SPIN 之後一直呼叫 Thread.yield()），則閒時也會有較高的 CPU 佔用。我們期望的是一種遞進的等待策略，例如：

在一定次數內，不斷 SPIN，應對日誌量特別多的時候，減少執行緒切換消耗。
在超過一定次數之後，開始不斷的呼叫 Thread.onSpinWait() 或者 Thread.yield()，使當前執行緒讓出 CPU 資源，應對間斷性的日誌高峰。
在第二步達到一定次數後，使用 Wait，或者 Thread.sleep() 這樣的函式阻塞當前執行緒，應對日誌低峰的時候，減少 CPU 消耗。

SleepingWaitStrategy 就是這樣一個策略，第二步採用的是 Thread.yield()，第三步採用的是 Thread.sleep()。同時，我們修改其中的 Thread.yield() 為 Thread.onSpinWait()，原因是：我們部署到的環境是 x86 的機器，在 x86 的環境下 Thread.onSpinWait() 在被呼叫一定次數後，C1 編譯器就會將其替換成使用 PAUSE 這個 x86 指令實現。參考 JVM 原始碼：

x86.ad

instruct onspinwait() %{
  match(OnSpinWait);
  ins_cost(200);

  format %{
    $$template
    $$emit$$"pause\t! membar_onspinwait"
  %}
  ins_encode %{
    __ pause();
  %}
  ins_pipe(pipe_slow);
%}

我們知道，CPU 並不會總直接操作記憶體，而是以快取行讀取後，快取在 CPU 快取記憶體上。但是對於這種不斷檢查檢查某個狀態位是否就緒的程式碼，不斷讀取 CPU 快取記憶體，會在當前 CPU 從匯流排收到這個 CPU 快取記憶體已經失效之前，都認為這個狀態為沒有變化。在業務忙時，匯流排可能非常繁忙，導致 SleepingWaitStrategy 的第二步一直檢查不到狀態位的更新導致進入第三步。

PAUSE 指令（參考：https://www.felixcloutier.com/x86/pause）是針對這種等待策略實現而產生的一個特殊指令，它會告訴處理器所執行的程式碼序列是一個不斷檢查某個狀態位是否就緒的程式碼（即 spin-wait loop），這樣的話，然後 CPU 分支預測就會據這個提示而避開記憶體序列衝突，CPU 就不會將這塊讀取的記憶體進行快取，也就是說對 spin-wait loop 不做快取，不做指令
重新排序等動作。從而提高 spin-wait loop 的執行效率。

這個指令使得針對 spin-wait loop 這種場景，Thread.onSpinWait()的效率要比 Thread.yield() 的效率要高。所以，我們修改 SleepingWaitStrategy 的 Thread.yield() 為 Thread.onSpinWait()。

4. 自定義異常格式化外掛，減少在異常集中發生的時候，因為列印異常棧日誌量過大導致進一步的效能問題

其實 JVM 有引數 -XX:+OmitStackTraceInFastThrow 可以在某一個異常丟擲過多次數時，自動省略異常堆疊。但是這個壞處在於：

對於某個新異常，趕上流量高峰突然輸出很多異常，還是會有很多日誌列印出來。
對於一個已經啟動很久的程式，比如在 1 月 1 日丟擲了很多 A 異常，在 3 月 1 日又丟擲 A 異常卻沒有異常棧，這樣很難尋找這個異常棧在哪裡。

由於我們專案中使用了各種框架，有的使用了非同步框架，導致異常棧會非常非常長（有的甚至有 1000 行），所以其實最符合我們需求的是：

每次異常都輸出異常棧
但是異常棧只包括我們關心的包，其他的包都被省略

但是 Log4j2 官方只是提供了黑名單包的配置，也就是哪些包的異常棧被省略掉：

其實我們需要就是將這個黑名單變成白名單。於是，針對這種情況，我們根據官方原始碼，將其中的黑名單的判斷取反，從黑名單變成了白名單。並建立自定義異常格式化外掛：

import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.impl.CustomizedThrowableProxyRenderer;
import org.apache.logging.log4j.core.impl.ThrowableProxy;
import org.apache.logging.log4j.core.pattern.ConverterKeys;
import org.apache.logging.log4j.core.pattern.PatternConverter;
import org.apache.logging.log4j.core.pattern.ThrowablePatternConverter;

@Plugin(name = "CustomizedThrowablePatternConverter", category = PatternConverter.CATEGORY)
//配置 key 是 %cusEx 或者 %cusThrowable 或者 %cusException
@ConverterKeys({ "cusEx", "cusThrowable", "cusException" })
public class CustomizedThrowablePatternConverter extends ThrowablePatternConverter {
	public static CustomizedThrowablePatternConverter newInstance(final Configuration config, final String[] options) {
		return new CustomizedThrowablePatternConverter(config, options);
	}
	private CustomizedThrowablePatternConverter(final Configuration config, final String[] options) {
		super("CustomizedThrowable", "throwable", options, config);
	}

	@Override
	public void format(final LogEvent event, final StringBuilder toAppendTo) {
		final ThrowableProxy proxy = event.getThrownProxy();
		final Throwable throwable = event.getThrown();
		if ((throwable != null || proxy != null) && options.anyLines()) {
			if (proxy == null) {
				super.format(event, toAppendTo);
				return;
			}
			final int len = toAppendTo.length();
			if (len > 0 && !Character.isWhitespace(toAppendTo.charAt(len - 1))) {
				toAppendTo.append(' ');
			}
			//這裡的 CustomizedThrowableProxyRenderer 其實就是將 log4j2 的 ThrowableProxyRenderer 程式碼複製一份，之後將其中的黑名單判斷取反，變成白名單
			CustomizedThrowableProxyRenderer.formatExtendedStackTraceTo(proxy, toAppendTo, options.getIgnorePackages(),
					options.getTextRenderer(), getSuffix(event), options.getSeparator());
		}
	}
}

之後通過 layout %cusEx{filters(java, com.mycompany)}，這樣異常棧就只會輸出這些包開頭的異常堆疊，這裡是 java 和 com.mycompany 開頭的，輸出的堆疊類似於：

	... suppressed 27 lines
	at com.mycompany.spring.cloud.parent.web.common.undertow.jfr.JFRTracingFilter.doFilter(JFRTracingFilter.java:40) ~[spring-cloud-parent-web-common-2020.0.3-SNAPSHOT.jar!/:2020.0.3-SNAPSHOT]
	at com.mycompany.spring.cloud.parent.web.common.undertow.jfr.LazyJFRTracingFilter.doFilter(LazyJFRTracingFilter.java:23) ~[spring-cloud-parent-web-common-2020.0.3-SNAPSHOT.jar!/:2020.0.3-SNAPSHOT]
	... suppressed 46 lines
Caused by: com.alibaba.fastjson.JSONException: write javaBean error, fastjson version 1.2.75, class com.hopegaming.factsCenter.query.revo.controller.frontend.share.matches.MatchController$EventVO, fieldName : data
	... suppressed 8 lines
	... 74 more
Caused by: java.lang.NullPointerException
	at com.mycompany.OrderController.postOrder(OrderController.java:103) ~[classes!/:2020.0.3-SNAPSHOT]
	... suppressed 13 lines
	... 74 more

5. 監控 RingBuffer 的使用率大小，如果使用率超過一定比例並且持續一段時間，證明應用寫日誌過忙，需要進行動態擴容，並且暫時將流量從這個例項切走一部分

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。

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)

對於這種情況，我們需要監控。

首先想到的是程式外部採集系統指標監控：現在服務都提倡上雲，並實現雲原生服務。對於雲服務，儲存日誌很可能使用 NFS（Network File System），例如 AWS 的 EFS。這種 NFS 一動都可以動態的控制 IO 最大承載，但是服務的增長是很難預估完美的，並且高併發業務流量基本都是一瞬間到達，僅通過 IO 定時採集很難評估到真正的流量尖峰（例如 IO 定時採集是 5s 一次，但是在某一秒內突然到達很多流量，導致程式內大多執行緒阻塞，這之後採集 IO 看到 IO 壓力貌似不大的樣子）。並且，由於執行緒的阻塞，導致可能我們看到的 CPU 佔用貌似也不高的樣子。所以，外部定時採集指標，很難真正定位到日誌流量問題。

然後我們考慮程式自己監控，暴露介面給外部監控定時檢查，例如 K8s 的 pod 健康檢查等等。在程式的日誌寫入壓力過大的時候，新擴容一個例項；啟動完成後，在註冊中心將這個日誌壓力大的程式的狀態設定為暫時下線（例如 Eureka 置為 OUT_OF_SERVICE，Nacos 置為 PAUSED），讓流量轉發到其他例項。待日誌壓力小之後，再修改狀態為 UP，繼續服務。

Log4j2 對於每一個 AsyncLogger 配置，都會建立一個獨立的 RingBuffer，例如下面的 Log4j2 配置：

<!--省略了除了 loggers 以外的其他配置-->
 <loggers>
    <!--default logger -->
    <Asyncroot level="info" includeLocation="true">
        <appender-ref ref="console"/>
    </Asyncroot>
    <AsyncLogger name="RocketmqClient" level="error" additivity="false" includeLocation="true">
        <appender-ref ref="console"/>
    </AsyncLogger>
    <AsyncLogger name="com.alibaba.druid.pool.DruidDataSourceStatLoggerImpl" level="error" additivity="false" includeLocation="true">
        <appender-ref ref="console"/>
    </AsyncLogger>
    <AsyncLogger name="org.mybatis" level="error" additivity="false" includeLocation="true">
        <appender-ref ref="console"/>
    </AsyncLogger>
</loggers>

這個配置包含 4 個 AsyncLogger，對於每個 AsyncLogger 都會建立一個 RingBuffer。Log4j2 也考慮到了監控 AsyncLogger 這種情況，所以將 AsyncLogger 的監控暴露成為一個 MBean（JMX Managed Bean）。

相關原始碼如下：

Server.java

private static void registerLoggerConfigs(final LoggerContext ctx, final MBeanServer mbs, final Executor executor)
        throws InstanceAlreadyExistsException, MBeanRegistrationException, NotCompliantMBeanException {

    //獲取 log4j2.xml 配置中的 loggers 標籤下的所有配置值
    final Map<String, LoggerConfig> map = ctx.getConfiguration().getLoggers();
    //遍歷每個 key，其實就是 logger 的 name
    for (final String name : map.keySet()) {
        final LoggerConfig cfg = map.get(name);
        final LoggerConfigAdmin mbean = new LoggerConfigAdmin(ctx, cfg);
        //對於每個 logger 註冊一個 LoggerConfigAdmin
        register(mbs, mbean, mbean.getObjectName());
        //如果是非同步日誌配置，則註冊一個 RingBufferAdmin
        if (cfg instanceof AsyncLoggerConfig) {
            final AsyncLoggerConfig async = (AsyncLoggerConfig) cfg;
            final RingBufferAdmin rbmbean = async.createRingBufferAdmin(ctx.getName());
            register(mbs, rbmbean, rbmbean.getObjectName());
        }
    }
}

建立的 MBean 的類原始碼：RingBufferAdmin.java

public class RingBufferAdmin implements RingBufferAdminMBean {
    private final RingBuffer<?> ringBuffer;
    private final ObjectName objectName;
    //... 省略其他我們不關心的程式碼
    
    public static final String DOMAIN = "org.apache.logging.log4j2";
    String PATTERN_ASYNC_LOGGER_CONFIG = DOMAIN + ":type=%s,component=Loggers,name=%s,subtype=RingBuffer";
    
    //建立 RingBufferAdmin，名稱格式符合 Mbean 的名稱格式
    public static RingBufferAdmin forAsyncLoggerConfig(final RingBuffer<?> ringBuffer, 
            final String contextName, final String configName) {
        final String ctxName = Server.escape(contextName);
        //對於 RootLogger，這裡 cfgName 為空字串
        final String cfgName = Server.escape(configName);
        final String name = String.format(PATTERN_ASYNC_LOGGER_CONFIG, ctxName, cfgName);
        return new RingBufferAdmin(ringBuffer, name);
    }
    
    //獲取 RingBuffer 的大小
    @Override
    public long getBufferSize() {
        return ringBuffer == null ? 0 : ringBuffer.getBufferSize();
    }
    //獲取 RingBuffer 剩餘的大小
    @Override
    public long getRemainingCapacity() {
        return ringBuffer == null ? 0 : ringBuffer.remainingCapacity();
    }
    public ObjectName getObjectName() {
        return objectName;
    }
}

我們可以通過 JConsole 檢視對應的 MBean：

其中 2f0e140b 為 LoggerContext 的 name。

我們的微服務專案中使用了 spring boot，並且整合了 prometheus。我們可以通過將 Log4j2 RingBuffer 大小作為指標暴露到 prometheus 中，通過如下程式碼：

import io.micrometer.core.instrument.Gauge;
import io.micrometer.prometheus.PrometheusMeterRegistry;
import lombok.extern.log4j.Log4j2;
import org.apache.commons.lang3.StringUtils;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.jmx.RingBufferAdminMBean;
import org.springframework.beans.factory.ObjectProvider;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.actuate.autoconfigure.metrics.export.ConditionalOnEnabledMetricsExport;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.event.ContextRefreshedEvent;
import org.springframework.context.event.EventListener;

import javax.annotation.PostConstruct;
import javax.management.ObjectName;
import java.lang.management.ManagementFactory;

@Log4j2
@Configuration(proxyBeanMethods = false)
//需要在引入了 prometheus 並且 actuator 暴露了 prometheus 埠的情況下才載入
@ConditionalOnEnabledMetricsExport("prometheus")
public class Log4j2Configuration {
    @Autowired
    private ObjectProvider<PrometheusMeterRegistry> meterRegistry;
    //只初始化一次
    private volatile boolean isInitialized = false;

    //需要在 ApplicationContext 重新整理之後進行註冊
    //在載入 ApplicationContext 之前，日誌配置就已經初始化好了
    //但是 prometheus 的相關 Bean 載入比較複雜，並且隨著版本更迭改動比較多，所以就直接偷懶，在整個 ApplicationContext 重新整理之後再註冊
    // ApplicationContext 可能 refresh 多次，例如呼叫 /actuator/refresh，還有就是多 ApplicationContext 的場景
    // 這裡為了簡單，通過一個簡單的 isInitialized 判斷是否是第一次初始化，保證只初始化一次
    @EventListener(ContextRefreshedEvent.class)
    public synchronized void init() {
        if (!isInitialized) {
            //通過 LogManager 獲取 LoggerContext，從而獲取配置
            LoggerContext loggerContext = (LoggerContext) LogManager.getContext(false);
            org.apache.logging.log4j.core.config.Configuration configuration = loggerContext.getConfiguration();
            //獲取 LoggerContext 的名稱，因為 Mbean 的名稱包含這個
            String ctxName = loggerContext.getName();
            configuration.getLoggers().keySet().forEach(k -> {
                try {
                    //針對 RootLogger，它的 cfgName 是空字串，為了顯示好看，我們在 prometheus 中將它命名為 root
                    String cfgName = StringUtils.isBlank(k) ? "" : k;
                    String gaugeName = StringUtils.isBlank(k) ? "root" : k;
                    Gauge.builder(gaugeName + "_logger_ring_buffer_remaining_capacity", () ->
                    {
                        try {
                            return (Number) ManagementFactory.getPlatformMBeanServer()
                                    .getAttribute(new ObjectName(
                                            //按照 Log4j2 原始碼中的命名方式組裝名稱
                                            String.format(RingBufferAdminMBean.PATTERN_ASYNC_LOGGER_CONFIG, ctxName, cfgName)
                                            //獲取剩餘大小，注意這個是嚴格區分大小寫的
                                    ), "RemainingCapacity");
                        } catch (Exception e) {
                            log.error("get {} ring buffer remaining size error", k, e);
                        }
                        return -1;
                    }).register(meterRegistry.getIfAvailable());
                } catch (Exception e) {
                    log.error("Log4j2Configuration-init error: {}", e.getMessage(), e);
                }
            });
            isInitialized = true;
        }
    }
}

增加這個程式碼之後，請求 /actuator/prometheus 之後，可以看到對應的返回：

//省略其他的
# HELP root_logger_ring_buffer_remaining_capacity  
# TYPE root_logger_ring_buffer_remaining_capacity gauge
root_logger_ring_buffer_remaining_capacity 262144.0
# HELP org_mybatis_logger_ring_buffer_remaining_capacity  
# TYPE org_mybatis_logger_ring_buffer_remaining_capacity gauge
org_mybatis_logger_ring_buffer_remaining_capacity 262144.0
# HELP com_alibaba_druid_pool_DruidDataSourceStatLoggerImpl_logger_ring_buffer_remaining_capacity  
# TYPE com_alibaba_druid_pool_DruidDataSourceStatLoggerImpl_logger_ring_buffer_remaining_capacity gauge
com_alibaba_druid_pool_DruidDataSourceStatLoggerImpl_logger_ring_buffer_remaining_capacity 262144.0
# HELP RocketmqClient_logger_ring_buffer_remaining_capacity  
# TYPE RocketmqClient_logger_ring_buffer_remaining_capacity gauge
RocketmqClient_logger_ring_buffer_remaining_capacity 262144.0

這樣，當這個值為 0 持續一段時間後（就代表 RingBuffer 滿了，日誌生成速度已經遠大於消費寫入 Appender 的速度了），我們就認為這個應用日誌負載過高了。

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

在被線上大量日誌輸出導致效能瓶頸，執行緒Block的坑
2024-06-03
執行緒BloC
JVM 輸出 GC 日誌導致 JVM 卡住，我 TM 人傻了
2022-06-17
JVMGC
slf4j 更新版本導致無日誌輸出
2018-01-05
近期業務大量突增微服務效能優化總結-2.開發日誌輸出異常堆疊的過濾外掛
2021-11-02
微服務優化
啟動tomcat時，日誌裡大量輸出建立資料來源dataSource的日誌
2018-03-16
Tomcat
reportbuilder 日誌輸出
2014-04-24
UI
Python輸出日誌
2012-08-06
Python
經驗分享：MySQL日誌維護策略總結
2015-08-31
MySql
python如何輸出日誌？
2021-09-11
Python
Java日誌輸出問題
2016-12-07
Java
awk多行日誌排序輸出
2013-11-15
排序
指令碼日誌的標準輸出
2024-08-31
指令碼
Oracle歸檔日誌比聯機重做日誌小很多的情況總結
2017-12-22
Oracle
大量邏輯讀的瓶頸分析和優化
2010-04-01
優化
python日誌重複輸出
2018-06-21
Python
Java中的輸入輸出總結
2016-11-29
Java
11G flashback data archive 導致產生大量歸檔日誌
2012-08-14
Hive
【RMAN】rman的日誌輸出功能演示
2009-07-21
利用PerfDog分析遊戲效能瓶頸
2020-04-01
遊戲
物化檢視匯出匯入可能導致物化檢視日誌的失效
2010-07-21
Java 如何正確地輸出日誌
2019-03-04
Java
C#按照日期輸出程式日誌
2018-11-27
C#
被 GANs 虐千百遍後，我總結出來的 10 條訓練經驗
2019-08-15
23【線上日誌分析】之改造CDH的HDFS的NN,DN程式，日誌輸出為json格式
2017-03-31
JSON
另一種列印輸出日誌資訊的方式
2018-05-31
在Docker中，很多應用容器都是預設後臺執行的，怎麼檢視它們的輸出和日誌資訊？
2024-03-09
Docker
如何利用NLog輸出結構化日誌，並在Kibana優雅分析日誌？
2020-08-06
用 pprof 找出程式碼效能瓶頸
2020-06-09
Chrome執行時效能瓶頸分析
2019-05-08
Chrome
wait event監測效能瓶頸
2011-12-20
AI
如何正確定義效能瓶頸
2024-03-09
24【線上日誌分析】之Tomcat的支援log4j,日誌輸出為json格式
2017-03-31
TomcatJSON
操作日誌記錄(包括輸出至自定義日誌檔案)
2020-10-16
失敗登入行為輸出至alert日誌
2021-02-19
實用技巧：快速定位Zuul的效能瓶頸
2021-09-09
Zuul
實時檢視模擬器的日誌輸出
2016-11-09
Laravel 中輸出 SQL 語句的到 log 日誌
2017-08-23
LaravelSQL
讀取popen輸出結果時未截斷字串導致的命令列注入
2018-03-08
字串命令列