實戰：Java web應用性能分析之【異步日志：性能優化的金鑰匙】

概敘

實戰：Java web應用性能分析之【Arthas性能分析trace監控后端性能】-CSDN博客

在優化方面，可以采取以下步驟：

?性能分析工具?：使用Arthas或Async Profiler進行實時診斷，定位耗時的方法調用。這可以幫助精確找到瓶頸所在，而不是僅依靠日志推測?。
?優化JSON處理?：檢查請求體和響應體的數據大小，優化DTO結構，移除不必要的字段。同時，可以切換為更高效的序列化庫，比如替換默認的Jackson為Fastjson，或者調整Jackson的配置以提升性能?。
?連接池預熱?：在應用啟動時主動初始化數據庫連接，避免首次請求時建立連接的耗時。這在之前的回答中已經提供了MyBatis的預熱方法，用戶可以參考實施?。
?JVM預熱?：通過模擬請求觸發JIT編譯。
?緩存預熱?：啟動時加載高頻數據到緩存。
?懶加載優化?：將部分初始化移到啟動階段。
?異步日志記錄?：確保日志記錄是異步的，避免同步寫日志阻塞請求處理。使用Logback或Log4j2的異步Appender配置，將日志寫入隊列后由后臺線程處理?。
?事務優化?：檢查Service方法的事務配置，確保@Transactional注解的范圍合理，避免在事務中包含非數據庫操作。對于只讀操作，可以設置readOnly=true以提升性能?。
?精簡攔截器邏輯?：審查所有Filter和Interceptor的實現，移除不必要的操作，特別是避免在Filter中進行復雜的計算或同步IO操作。確保這些組件的邏輯盡可能高效?。

關鍵優化點總結

?緩存預熱?：啟動時主動加載高頻數據，避免首次查詢穿透數據庫。
?連接池預熱?：初始化時建立最小空閑連接，減少首次SQL延遲。
?JVM預熱?：通過模擬請求觸發JIT編譯，加速熱點方法。
?批量操作?：合并單次插入為批量操作，減少事務開銷。
?DTO轉換優化?：用MapStruct生成編譯期代碼，替代反射拷貝。

本文主要介紹了Log4j2框架的核心原理、實踐應用以及一些實用的小Tips，力圖揭示Log4j2這一強大日志記錄工具在現代分布式服務架構運維中的關鍵作用。

一、背景

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

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

后來，我們去掉了這兩行日志后緊急發布，事實證明我們的思路是對的。

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

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

二、原理

2.1 Log4j2的優勢

性能:?Log4j2使用基于Lambda的異步記錄器，顯著提高了日志記錄的速度，減少了日志操作對應用性能的影響。相比之下，Logback雖然也支持異步記錄，但實現上不如Log4j2高效。通過減少對象創建、高效的字符串處理和池化技術，Log4j2在高并發場景下表現更佳。
配置靈活性:?支持多種配置方式，包括XML、JSON、YAML、properties文件，甚至編程式配置，提供更大的靈活性。動態重新配置能力，允許在不重啟應用的情況下修改日志配置。
插件架構:?Log4j2采用插件架構，幾乎所有組件（如Appenders、Layouts、Filters）都是可插拔的，易于擴展和自定義。內置豐富的插件庫，開箱即用，簡化集成過程。
內存和資源管理:?更高效的內存管理，減少內存泄漏的風險，尤其是在大量日志輸出時。支持垃圾回收友好的設計，比如基于Disrupter的RingBuffer等數據結構減少GC壓力。
可靠性:?強大的故障恢復機制，如重試和備用Appenders，確保日志能夠被記錄下來，即使主要的日志輸出目的地不可用。
先進的特性:

- 支持條件日志記錄（Conditionals），可以根據運行時條件決定是否記錄日志。
- 自動重新加載配置文件變化，無需重啟應用。
- 支持JMX監控和管理日志系統狀態。

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

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

2.2 Log4j2的結構

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

Logger:?這是開發者直接使用的接口，用于記錄不同級別的日志信息（如DEBUG, INFO, ERROR等）。每個Logger都有一個名稱，并且支持繼承性，形成一個名為Logger Hierarchy的樹狀結構，根Logger的名稱為"root"。
LoggerContext:?是日志系統的上下文環境，管理著一組Logger實例以及它們的配置。每個應用程序通常只有一個LoggerContext，但它支持多個上下文以實現更細粒度的控制。
Configuration:?每個LoggerContext都關聯一個有效的Configuration，定義了日志的輸出目的地（Appenders）、日志的過濾規則（Filters）、日志的格式化方式（Layouts）等。Configuration可以通過配置文件（如XML、JSON、properties）或編程方式動態加載。
Appender:?負責將日志事件發送到指定的目標，如控制臺（Console）、文件（File）、數據庫、網絡Socket等。
Layout:?定義了日志信息的格式化方式，如模式字符串（Pattern String）決定了日期、時間、日志級別、線程名、日志信息等內容的排列和格式。
Filter:?可以在日志事件從Logger傳遞到Appender的過程中進行過濾，根據特定條件決定日志是否被輸出。
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:?鎖等待策略。該策略當正在寫入日志時，則會等待；否則即會停止等待。

1.2.1.3.1append操作是將日志寫入到對應的目的地，如kafka、本地文件、郵件等。這里如果是異步日志，則會將日志追加到異步隊列里，進而提高日志記錄的性能。
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);    }    @Override    public 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的異步日志

2.5.1 異步日志原理概述

前面提到了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性能測試結果

2.5.2 如何使用異步日志

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

全局異步日志

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

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

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

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

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

混合異步日志
在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>

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

潛在問題：

日志丟失問題：如果機器發生意外重啟、發布、掉電導致的jvm進程停止，停留在隊列的未來得及輸出到目的地的LogEvent可能會丟失
日志順序問題：由于日志事件是在不同的線程中異步處理的，因此日志條目可能不會嚴格按照它們產生的順序出現在日志文件中，這對于需要嚴格按時間順序追蹤日志的應用可能是個問題。
其他問題：如增加資源損耗、配置復雜度和調試復雜度等問題

解決方案：

對于日志丟失問題：

原生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關閉后再卸載Appender            newHooks.add(new Log4j2Cancellable(() -> {               //負責監聽AsyncAbleRollingFileAppender的隊列消費情況，并在消費完成后關閉AsyncAbleRollingFileAppender                new 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，但是會影響日志打印的速度（現在的普遍做法）。
延遲打印

三、效果

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

應用rpc耗時：

應用網關耗時：

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

GC優化前：

GC優化后：

四、建議

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

動靜分離：在一些大日志輸出場景中，即使是異步日志也會給系統帶來性能風險。因此建議合理識別大日志中的動態數據和靜態數據。靜態數據定時輸出，動態數據關聯唯一靜態標識輸出，在降低性能風險的同時又滿足監控分析的需要；
合理分割：日志文件需要合理分割，并設置合理的保留策略，及時釋放磁盤空間。
合理設置日志級別：避免日志濫用，尤其是debug日志，既有利于日志定位問題的速度，又能提高性能。