一、背景

2024 年 4 月的一個寧靜的夜晚，正當大家忙完一天的工作準備休息時，應急群里“咚咚咚”開始報警，提示我們余利寶業務的贖回接口成功率下降。

通過 Monitor 監控發現，該接口的耗時已經超過了網關配置的超時閾值(2s)，我們臨時調整超時閾值止血后，就在排查問題的根因。具體排查過程不是我這篇文章的重點，故忽略，但最終我們發現最近上線新加的相鄰兩行的日志中，時間相差近 1.5s，難道這就是問題的根源嗎？

后來，我們去掉了這兩行日志后緊急發布，事實證明我們的思路是對的。緊急發布后，該接口的耗時由之前的 2s 左右，優化到了 600ms 左右。后來我們分析發現：該接口在打印日志時，由于要實現日志脫敏，故在 Logger.info 入口處實現了脫敏功能，但是大日志脫敏比較耗時，從而導致該接口的同步調用耗時激增到 1.5s 左右（后面我們會說如何解決這個問題）。我的天吶，一行日志竟是性能優化的金鑰匙！！！🤣

但這里有一個問題，我們是去掉了日志的打印，侵入了業務，同時該應用還是用的 log4j 的日志框架，log4j 原生框架是不支持日志異步化的，因此要從根本上業務無侵入的解決因日志而導致的性能問題，需要熟悉 log4j2 的框架原理。

二、原理

2.1?Log4j2 的優勢

1）性能:?Log4j2 使用基于 Lambda 的異步記錄器，顯著提高了日志記錄的速度，減少了日志操作對應用性能的影響。相比之下，Logback 雖然也支持異步記錄，但實現上不如 Log4j2 高效。通過減少對象創建、高效的字符串處理和池化技術，Log4j2 在高并發場景下表現更佳。

2）配置靈活性:?支持多種配置方式，包括 XML、JSON、YAML、properties 文件，甚至編程式配置，提供更大的靈活性。動態重新配置能力，允許在不重啟應用的情況下修改日志配置。

3）插件架構:?Log4j2 采用插件架構，幾乎所有組件（如 Appenders、Layouts、Filters）都是可插拔的，易于擴展和自定義。內置豐富的插件庫，開箱即用，簡化集成過程。

4）內存和資源管理:?更高效的內存管理，減少內存泄漏的風險，尤其是在大量日志輸出時。支持垃圾回收友好的設計，比如基于 Disrupter 的 RingBuffer 等數據結構減少 GC 壓力。

5）可靠性:?強大的故障恢復機制，如重試和備用 Appenders，確保日志能夠被記錄下來，即使主要的日志輸出目的地不可用。

6）先進的特性:

• 支持條件日志記錄（Conditionals），可以根據運行時條件決定是否記錄日志。

• 自動重新加載配置文件變化，無需重啟應用。

• 支持 JMX 監控和管理日志系統狀態。

7）與 SLF4J 的集成:雖然這不是特有優勢，但 Log4j2 提供了與 SLF4J（Simple Logging Facade for Java）的良好集成，使得從其他日志框架遷移更加平滑。

總的來說，Log4j2 的設計更現代化，強調高性能、易用性和靈活性，特別是在大規模分布式系統和高性能應用中表現突出。而 Logback 和 Log4j 1.x 雖有各自的優點，但在這些方面逐漸顯得力不從心。至于 Java Util Logging (JUL)，它是 Java 標準庫的一部分，但功能相對基礎，配置和擴展性不如 Log4j2 和 Logback 靈活。

2.2?Log4j2 的結構

Log4j2 的結構主要包括以下幾個核心組件：

1）Logger:?這是開發者直接使用的接口，用于記錄不同級別的日志信息（如 DEBUG, INFO, ERROR 等）。每個 Logger 都有一個名稱，并且支持繼承性，形成一個名為 Logger Hierarchy 的樹狀結構，根 Logger 的名稱為'root'。

2）LoggerContext:?是日志系統的上下文環境，管理著一組 Logger 實例以及它們的配置。每個應用程序通常只有一個 LoggerContext，但它支持多個上下文以實現更細粒度的控制。

3）Configuration:?每個 LoggerContext 都關聯一個有效的 Configuration，定義了日志的輸出目的地（Appenders）、日志的過濾規則（Filters）、日志的格式化方式（Layouts）等。Configuration 可以通過配置文件（如 XML、JSON、properties）或編程方式動態加載。

4）Appender:?負責將日志事件發送到指定的目標，如控制臺（Console）、文件（File）、數據庫、網絡 Socket 等。

5）Layout:?定義了日志信息的格式化方式，如模式字符串（Pattern String）決定了日期、時間、日志級別、線程名、日志信息等內容的排列和格式。

6）Filter:?可以在日志事件從 Logger 傳遞到 Appender 的過程中進行過濾，根據特定條件決定日志是否被輸出。

7）Lookup:?提供動態值解析機制，如 ${ctx:variable}可以在日志中插入上下文變量的值。

那么，Log4j2 的日志是怎么將日志輸出到文件/數據庫/控制臺等地方的？

2.3?Log4j2 日志輸出流程

關鍵步驟源碼分析：

1）1.1 主要是針對日志級別 Level 和指定的全局 Filter 組件進行過濾

2）ReliabilityStrategy 是 Log4j2 的日志可靠性策略實現，目前主要有以下四種：

• AwaitCompletionReliabilityStrategy:?等待日志接收完成策略。這種策略主要是在應用關閉時，盡可能要等應用日志接收完成后再結束 Appender 的生命周期（這種策略只是說盡可能所有日志等待調用 Appender.append 方法完成，但在異步日志場景下，Appender.append 其實是落了 ringbuffer 或者其他隊列里，實際上未持久化。因此該策略是盡可能保證接收完成而非處理完成）

• AwaitUnconditionallyReliabilityStrategy:?無條件等待策略。這種策略會在 rootLogger 關閉時無條件等待一段時間，具體等待時間可以配置 log4j2.component.properties 文件的 log4j.waitMillisBeforeStopOldConfig 屬性。

• DefaultReliabilityStrategy:?默認策略。該策略不做任何等待。

• LockingReliabilityStrategy:?鎖等待策略。該策略當正在寫入日志時，則會等待；否則即會停止等待。

3）1.2.1.3.1append 操作是將日志寫入到對應的目的地，如 kafka、本地文件、郵件等。這里如果是異步日志，則會將日志追加到異步隊列里，進而提高日志記錄的性能。

4）1.2.1.3.1.1 調用 Layout encode 日志，是根據 log4j2.xml 中配置的 Layout 對日志進行格式化輸出。

那么如果有一些個性化的日志輸出需求，log4j2 能否幫我們實現？

2.4?如何實現日志脫敏

上面提到了 log4j2 的各種組件以及日志輸出流程，log4j2 的強大很大程度上得益于其清晰且高度解耦的架構設計。例如其具有很強的擴展性，log4j2 的很多組件都可以自己定制插件，如：Appender、Filter、Layout 等。那么這里我結合我們實際業務中一個很常見的 case 去分析如何定制一個組件。

首先，作為一家強監管的金融公司，日志脫敏涉及數據保護和隱私安全等問題，非常重要。過去我們很多業務系統在實現業務脫敏時，很容易想到在打日志的入口統一封裝一個格式化方法，造成日志輸出在無形中把異步日志輸出變成了同步輸出（日志脫敏的耗時往往比日志集中持久化到磁盤耗時要高）。

那么如何優雅的實現日志脫敏的功能，既能實現其功能又可以保證日志的性能，是 log4j2 插件化的一個很重要的應用場景。前面我們提到日志輸出流程中會使用 Layout encode 日志，而 PatternConverter 是 Layout 非常重要的組成部分。其通過定義一系列的占位符（如 %d、%m、 %t 等）幫助我們自定義格式輸出日志對象，同時 PatternConverter 支持以高度可定制的插件集成到 Log4j2 框架中，因此我們可以借助其去定制脫敏組件。

話不多說，我們直接上日志脫敏 PatternConverter 插件源碼：

//
// Source code recreated from a .class file by IntelliJ IDEA
// (powered by FernFlower decompiler)
//
import java.util.Arrays;import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.pattern.ConverterKeys;
import org.apache.logging.log4j.core.pattern.LogEventPatternConverter;
import org.apache.logging.log4j.message.FormattedMessage;
import org.apache.logging.log4j.message.Message;
import org.apache.logging.log4j.message.MessageFormatMessage;
import org.apache.logging.log4j.message.ParameterizedMessage;
import org.apache.logging.log4j.message.StringFormattedMessage;
import org.apache.logging.log4j.util.PerformanceSensitive;/*** @author baichun* @version ShieldMessagePatternConverter.java, v 0.1 2024年04月09日 21:13 baichun*/
@Plugin(name = "ShieldPatternConverter",category = "Converter"
)
@ConverterKeys({"shield", "sd", "shieldMessage", "sm"})
@PerformanceSensitive({"allocation"})
public final class ShieldMessagePatternConverter extends LogEventPatternConverter {private final String[] options;private ShieldMessagePatternConverter(String[] options) {super("Shield", "shield");this.options = options == null ? null : (String[])Arrays.copyOf(options, options.length);}//必須要有newInstance方法，log4j2會調用該方法進行初始化public static ShieldMessagePatternConverter newInstance(String[] options) {return new ShieldMessagePatternConverter(options);}@Overridepublic void format(LogEvent logEvent, StringBuilder output) {Message message = logEvent.getMessage();String format = message.getFormat();if (isFormatMessage(message)) {//在這里格式化脫敏日志String msgInfo = ShieldUtils.format(format, message.getParameters());output.append(msgInfo);} else {output.append(message.getFormattedMessage());}}private boolean isFormatMessage(Message message) {return message instanceof ParameterizedMessage || message instanceof StringFormattedMessage|| message instanceof FormattedMessage || message instanceof MessageFormatMessage;}
}

定義好組件后，log4j2 即能夠自動掃描識別到，不需要其他定義和配置。接下來看看如何使用。ConverterKeys 這個注解指定了在 log4j2.xml 中應如何使用該插件。以下是 log4j2.xml 應用示例：

    <RollingFile name="TEST_APPENDER" fileName="test.log"                     filePattern="test.log.%d{yyyy-MM-dd}"                     append="true">            <!-- %sm即為脫敏組件 -->            <PatternLayout pattern="%d %sm%n" charset="UTF-8"/>            <TimeBasedTriggeringPolicy/>            <DefaultRolloverStrategy/>        </RollingFile>

2.5?Log4j2 的異步日志

異步日志原理概述

前面提到了 Log4j2 的高可擴展性，同時 Log4j2 的性能也是極高的，下面是 Log4j2 官方的 benchmark 數據，僅供參考：

Log4j2 之所以性能如此之高，其中一個很重要的原因就是其基于 Disrupter 的環形緩沖區的無鎖化結構 Ringbuffer 設計。Disruptor 是英國外匯交易公司 LMAX 開發的一個高性能隊列，基于 Disruptor 開發的系統單線程能支撐每秒 600 萬訂單。目前，包括 Apache Strom、Log4j2 在內的很多知名項目都應用了 Disruptor 來獲取高性能。關于 Disruptor 的原理，這里不再贅述，大家可以自行查閱：https://lmax-exchange.github.io/disruptor/#_what_is_the_disruptor

Disrupter 組件構成：

Disrupter 性能測試結果

如何使用異步日志

log4j2 開啟異步日志的方法主要有以下兩種方式：

1）全局異步日志

• 通過 JVM 啟動參數來全局啟用異步日志功能。在啟動應用程序時，向 JVM 傳遞以下系統屬性：

?-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

• 在類路徑（classpath）中添加一個名為 log4j2.component.properties 的文件，并包含以下內容（這個文件會在 Log4j2 初始化時被讀取）：

-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

復制代碼

這兩種方式下，所有 Logger 都會自動使用異步處理。

2）混合異步日志

在 log4j2.xml 配置文件中，可以手動指定特定的 Logger 使用異步處理，通過將?<Root>或<Logger>元素替換為<AsyncRoot>或<AsyncLogger>。例如：

<Configuration status='WARN'>
<Appenders>... <!-- your appenders here -->
</Appenders>
<Loggers>
<AsyncRoot level='info' includeLocation='false'>
<AppenderRef ref='yourAppenderName'/>
</AsyncRoot>
<!-- 或者為特定logger配置 -->
<AsyncLogger name='com.example.MyClass' level='debug'>
<AppenderRef ref='yourAppenderName'/>
</AsyncLogger>
</Loggers>
</Configuration>

異步日志的潛在問題及解決方案

• 潛在問題：

1. 日志丟失問題：如果機器發生意外重啟、發布、掉電導致的 jvm 進程停止，停留在隊列的未來得及輸出到目的地的 LogEvent 可能會丟失

2. 日志順序問題：由于日志事件是在不同的線程中異步處理的，因此日志條目可能不會嚴格按照它們產生的順序出現在日志文件中，這對于需要嚴格按時間順序追蹤日志的應用可能是個問題。

3. 其他問題：如增加資源損耗、配置復雜度和調試復雜度等問題

• 解決方案：

1. 對于日志丟失問題：

• 原生 Log4j2 有完整的生命周期管理，并監聽了 jvm 關閉的事件。當 jvm 關閉時，Log4j2 會監聽 Disrupter 隊列中的 RingbufferLogEvent 數量，直到日志打印完（或超時）才釋放關閉 Log4j2，jvm 才得以正常關閉。但是自然災害或者機房掉電等不可抗力因素，無法避免丟失問題。

• 我們基于 Log4j2 定制的 AsyncAbleRollingFileAppender，其中有獨立的 Disrupter，且不在 Log4j2 生命周期管理當中，存在日志丟失風險。可以采用類似方案解決：

try {LoggerContextFactory factory = LogManager.getFactory();if (!(factory instanceof Log4jContextFactory)) {return;}Log4jContextFactory log4jContextFactory = (Log4jContextFactory) factory;ShutdownCallbackRegistry registry = log4jContextFactory.getShutdownCallbackRegistry();if (!(registry instanceof DefaultShutdownCallbackRegistry)) {return;}DefaultShutdownCallbackRegistry defaultShutdownCallbackRegistry = (DefaultShutdownCallbackRegistry) registry;Field hooksField = DefaultShutdownCallbackRegistry.class.getDeclaredField("hooks");hooksField.setAccessible(true);Collection<Cancellable> hooks = (Collection<Cancellable>) hooksField.get(defaultShutdownCallbackRegistry);Collection<Cancellable> newHooks = new CopyOnWriteArrayList<>();//將對Appender的隊列消費監聽和卸載放在首要位置，避免log4j2關閉后再卸載AppendernewHooks.add(new Log4j2Cancellable(() -> {//負責監聽AsyncAbleRollingFileAppender的隊列消費情況，并在消費完成后關閉AsyncAbleRollingFileAppendernew AppenderUnInstaller(register).run();}));newHooks.addAll(hooks);hooksField.set(defaultShutdownCallbackRegistry, newHooks);} catch (NoSuchFieldException e) {// This catch statement is intentionally empty} catch (IllegalAccessException e) {// This catch statement is intentionally empty}

• AsyncAbleRollingFileAppender 使用獨立的 disrupter，且 RingBufferLogEvent 未及時清理對象，容易導致內存泄漏，異步日志場景請慎用。

1. 對于日志順序性問題：

• 異步線程池大小設置為 1，但是會影響日志打印的速度（現在的普遍做法）。

• 延遲打印

三、效果

4 月份的這一問題發生后，我們從原理出發，對理財的核心應用做了升級和優化，整體服務耗時上取得了不錯的性能優化效果。

應用 rpc 耗時：

應用網關耗時：

但與此同時，我們也發現升級后，應用的 fgc 次數更多了，經過 heapdump 分析后，發現 AsyncAbleRollingFileAppender 內部實現的 RingBufferLogEvent 執行后，不會釋放引用的 LogEvent，導致 Disrupter 一直持有已打印的 LogEvent 的引用關系，進而導致了內存泄漏。后來，我們采取主動釋放對象引用（RingBufferLogEvent.setLogEvent(null)）優化的方案，發布以后前后 fgc 對比如下：

GC 優化前：

GC 優化后：

四、建議

日志作為診斷問題、監控系統健康狀況與優化服務效能不可或缺的一環，其重要性不言而喻。熟練掌握并有效利用如 Log4j2 這樣的高性能日志框架以及注意一些打印日志的策略（如動靜分離、合理分割、合理設置日志級別等），對于開發者而言至關重要：

1）動靜分離 ：在一些大日志輸出場景中，即使是異步日志也會給系統帶來性能風險。因此建議合理識別大日志中的動態數據和靜態數據。靜態數據定時輸出，動態數據關聯唯一靜態標識輸出，在降低性能風險的同時又滿足監控分析的需要；

2）合理分割 ：日志文件需要合理分割，并設置合理的保留策略，及時釋放磁盤空間。

3）合理設置日志級別 ：避免日志濫用，尤其是 debug 日志，既有利于日志定位問題的速度，又能提高性能。