SpringCloud升級之路2020.0.x版-10.使用Log4j2以及一些核心配置

乾貨滿滿張雜湊發表於2021-08-14
SpringGCCloud

本系列程式碼地址：https://github.com/HashZhang/spring-cloud-scaffold/tree/master/spring-cloud-iiford

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

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

這裡我們給出一個我們日誌配置的模板，供大家參考：

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <Properties>
        <Property name="springAppName">app名稱</Property>
        <Property name="LOG_ROOT">log</Property>
        <Property name="LOG_DATEFORMAT_PATTERN">yyyy-MM-dd HH:mm:ss.SSS</Property>
        <Property name="LOG_EXCEPTION_CONVERSION_WORD">%xwEx</Property>
        <!--對於日誌級別，為了日誌能對齊好看，我們佔 5 個字元-->
        <Property name="LOG_LEVEL_PATTERN">%5p</Property>
        <Property name="logFormat">
            %d{${LOG_DATEFORMAT_PATTERN}} ${LOG_LEVEL_PATTERN} [${springAppName},%X{traceId},%X{spanId}] [${sys:PID}] [%t][%C:%L]: %m%n${sys:LOG_EXCEPTION_CONVERSION_WORD}
        </Property>
    </Properties>
    <appenders>
        <RollingFile name="file" append="true"
                     filePattern="${LOG_ROOT}/app.log-%d{yyyy.MM.dd.HH}"
                     immediateFlush="false">
            <PatternLayout pattern="${logFormat}"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
            <DirectWriteRolloverStrategy maxFiles="72"/>
        </RollingFile>
    </appenders>
    <loggers>
        <!--default logger -->
        <Asyncroot level="info" includeLocation="true">
            <appender-ref ref="file" />
        </Asyncroot>
        <AsyncLogger name="org.mybatis" level="off" additivity="false" includeLocation="false">
            <appender-ref ref="file"/>
        </AsyncLogger>
    </loggers>
</configuration>

對於其中一些重要的配置，我們這裡單獨拿出來分析下。

我們專案的依賴中包含了 spring-cloud-sleuth 這個鏈路追蹤相關的依賴，其核心基於 Opentracing 標準實現。日誌中可以通過列印 Span 的 SpanContext 中的 traceId 以及 spanId，就能通過這些資訊，確定日誌中的一條完整鏈路。spring-cloud-sleuth 是如何將這些資訊放入日誌中的呢？ Log4j2 中有這樣一個抽象，即 org.apache.logging.log4j.ThreadContext，這個其實就是 Java 日誌中 MDC（Mapped Diagnostic Context）的實現，可以理解成是一個執行緒本地的 Map，每個執行緒可以將日誌需要的元素放入這個 ThreadContext 中，這樣這個執行緒在列印日誌的時候，就可以從這個 ThreadContext 中取出放入日誌內容。日誌需要有對應的佔位符，例如下面這個就是將 ThreadContext 中 key 為 traceId 以及 spanId 的值取出輸出：

%X{traceId},%X{spanId}

Spring Cloud 2020.0.x 之後，也就是 spring-cloud-sleuth 3.0.0 之後，放入 ThreadContext 的 key 發生了變化，原來的 traceId 與 spanId 分別是 X-B3-traceId 與 X-B3-spanId，現在改成了更為通用的 traceId 和 spanId。

image

這個主要因為你打日誌的地方不在 spring-cloud-sleuth 管理的範圍內，或者是 Span 提前結束了。這種時候，你可以在確定有 Span 的地方將 Span 快取起來，之後再沒有鏈路追蹤資訊的地方使用這個 Span，例如：

import brave.Tracer;

@Autowire
private Tracer tracer;

//在確定有 span 的地方獲取當前 span 將 span 快取起來
Span span = tracer.currentSpan();

//之後在沒有鏈路追蹤資訊的地方，使用 span 包裹起來
try (Tracer.SpanInScope cleared = tracer.withSpanInScope(span)) {
    //你的業務程式碼
}

設定 includeLocation=false，這樣在日誌中就無法看到日誌屬於的程式碼以及行數了。獲取這個程式碼行數，其實是通過獲取當前呼叫堆疊實現的。Java 9 之前是通過 new 一個 Exception 獲取堆疊，Java 9 之後是通過 StackWalker。兩者其實都有效能問題，在高併發的情況下，會吃掉很多 CPU，得不償失。所以我推薦，在日誌內容中直接體現所在程式碼行數，就不通過這個 includeLocation 獲取當前堆疊從而獲取程式碼行數了。

關閉 immediateFlush，可以減少硬碟 IO，會先寫入記憶體 Buffer（預設是 8 KB），之後在 RingBuffer 目前消費完或者 Buffer 寫滿的時候才會刷盤。這個 Buffer 可以通過系統變數 log4j.encoder.byteBufferSize 改變。

這裡的原理對應原始碼：

AbstractOutputStreamAppender.java

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

那麼對於 Log4j2 Disruptor 非同步日誌來說，什麼時候 LogEvent 是 EndOfBatch 呢？是在消費到的 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++;
        }
    }
}

我們這一節詳細分析了我們微服務框架中日誌相關的各種配置，包括基礎配置，鏈路追蹤實現與配置以及如果沒有鏈路追蹤資訊時候的解決辦法，並且針對一些影響效能的核心配置做了詳細說明。下一節我們將會開始分析針對日誌的 RingBuffer 進行的監控。

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

相關文章