在被線上大量日誌輸出導致效能瓶頸，執行緒Block的坑

原文連結

https://tech.meituan.com/2022/07/29/tips-for-avoiding-log-blocking-threads.html

https://cloud.tencent.com/developer/article/1927375

1. 前言

日誌對程式的重要性不言而喻。它很“大”，我們在專案中經常透過日誌來記錄資訊和排查問題，相關程式碼隨處可見。它也很“小”，作為輔助工具，日誌使用簡單、上手快，我們通常不會花費過多精力耗在日誌上。但看似不起眼的日誌也隱藏著各種各樣的“坑”，如果使用不當，它不僅不能幫助我們，反而還可能降低服務效能，甚至拖垮我們的服務。

日誌導致執行緒Block的問題，相信你或許已經遇到過，對此應該深有體會；或許你還沒遇到過，但不代表沒有問題，只是可能還沒有觸發而已。本文主要介紹美團統一API閘道器服務Shepherd（參見《百億規模API閘道器服務Shepherd的設計與實現》一文）在實踐中所踩過的關於日誌導致執行緒Block的那些“坑”，然後再分享一些避“坑”經驗。

2. 背景

API閘道器服務Shepherd基於Java語言開發，使用業界大名鼎鼎的Apache Log4j2作為主要日誌框架，同時使用美團內部的XMD-Log SDK和Scribe-Log SDK對日誌內容進行處理，日誌處理整體流程如下圖1所示。業務列印日誌時，日誌框架基於Logger配置來決定把日誌交給XMDFile處理還是Scribe處理。其中，XMDFile是XMD-Log內部提供的日誌Appender名稱，負責輸出日誌到本地磁碟，Scribe是Scribe-Log內部提供的日誌Appender名稱，負責上報日誌到遠端日誌中心。

圖1 日誌處理流程示意圖

隨著業務的快速增長，日誌導致的執行緒Block問題愈發頻繁。比如呼叫後端RPC服務超時，導致呼叫方大量執行緒Block；再比如，業務內部輸出異常日誌導致服務大量執行緒Block等，這些問題嚴重影響著服務的穩定性。因此，我們結合專案在過去一段時間暴露出來的各種由於日誌導致的執行緒Block問題，對日誌框架存在的穩定性風險因素進行了徹底的排查和修復，並線上下、線上環境進行全方位驗證。在此過程中，我們總結了一些日誌使用相關的實踐經驗，希望分享給大家。

在進入正文前，首先介紹專案當時的執行環境和日誌相關配置資訊。

• JDK版本

java version "1.8.0_45"
Java(TM) SE Runtime Environment (build 1.8.0_45-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.45-b02, mixed mode)

• 日誌依賴版本

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.7</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.7</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-slf4j-impl</artifactId>
    <version>2.7</version>
</dependency>

• 日誌配置檔案

<?xml version="1.0" encoding="UTF-8"?>
<configuration status="warn">
    <appenders>
        <Console name="Console" target="SYSTEM_OUT" follow="true">
            <PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} %t [%p] %c{1} (%F:%L) %msg%n" />
        </Console>

        <XMDFile name="ShepherdLog" fileName="shepherd.log"/>

        <!--XMDFile非同步磁碟日誌配置示例-->
        <!--預設按天&按512M檔案大小切分日誌，預設最多保留30個日誌檔案。-->
        <!--注意：fileName前會自動增加檔案路徑，只配置檔名即可-->
        <XMDFile name="LocalServiceLog" fileName="request.log"/>

        <Scribe name="LogCenterSync">
            <!-- 在指定日誌名方面，scribeCategory 和 appkey 兩者至少存在一種，且 scribeCategory 高於 appkey。-->
            <!-- <Property name="scribeCategory">data_update_test_lc</Property> -->
            <LcLayout/>
        </Scribe>
        <Async name="LogCenterAsync" blocking="false">
            <AppenderRef ref="LogCenterSync"/>
        </Async>
    </appenders>

    <loggers>
        <AsyncLogger name="com.sankuai.shepherd" level="info" additivity="false">
            <AppenderRef ref="ShepherdLog" level="warn"/>
            <AppenderRef ref="LogCenterAsync" level="info"/>
        </AsyncLogger>

        <root level="info">
            <!--Console日誌是同步、阻塞的，推薦只在本地除錯時使用，線上將該配置去掉-->
            <!--appender-ref ref="Console" /-->
            <appender-ref ref="LocalServiceLog"/>
            <appender-ref ref="LogCenterAsync"/>
        </root>
    </loggers>
</configuration>

3. 踩過的坑

本章節主要記錄專案過去一段時間，我們所遇到的一系列日誌導致的執行緒Block問題，並逐個深入分析問題根因。

3.1 日誌佇列滿導致執行緒Block

3.1.1 問題現場

收到“jvm.thread.blocked.count”告警後立刻透過監控平臺檢視執行緒監控指標，當時的執行緒堆疊如圖2和圖3所示。

圖2 等待鎖的Blocked執行緒堆疊

圖3 持有鎖的Runnable執行緒堆疊

從Blocked執行緒堆疊不難看出這跟日誌列印相關，而且是INFO級別的日誌，遂即登陸機器檢視日誌是否有異樣，發現當時日誌量非常大，差不多每兩分鐘就寫滿一個500MB的日誌檔案。

那大量輸出日誌和執行緒Block之間會有怎樣的關聯呢？接下來本章節將結合如下圖4所示的呼叫鏈路深入分析執行緒Block的根因。

圖4 日誌呼叫鏈路

3.1.2 為什麼會Block執行緒？

從Blocked執行緒堆疊著手分析，檢視PrintStream相關程式碼片段如下圖5所示，可以看到被阻塞地方有synchronized同步呼叫，再結合上文發現每兩分鐘寫滿一個500MB日誌檔案的現象，初步懷疑是日誌量過大導致了執行緒阻塞。

圖5 PringStream程式碼片段

但上述猜測仍有一些值得推敲的地方：

1. 如果僅僅因為日誌量過大就導致執行緒Block，那日誌框架也太不堪重用了，根本沒法在高併發、高吞吐業務場景下使用。
2. 日誌配置裡明明是輸出日誌到檔案，怎麼會輸出到Console PrintStream？

3.1.3 為什麼會輸出到Console？

繼續沿著執行緒堆疊呼叫鏈路分析，可以看出是AsyncAppender呼叫append方法追加日誌時發生了錯誤，相關程式碼片段如下：

// org.apache.logging.log4j.core.appender.AsyncAppender

// 內部維護的阻塞佇列，佇列大小預設是128
private final BlockingQueue<LogEvent> queue;

@Override
public void append(final LogEvent logEvent) {
    if (!isStarted()) {
        throw new IllegalStateException("AsyncAppender " + getName() + " is not active");
    }
    if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose
        logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
    }
    final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);
  	// 日誌事件轉入非同步佇列
    if (!transfer(memento)) {
      	// 執行到這裡說明佇列滿了，入隊失敗，根據是否blocking執行具體策略
        if (blocking) {
          	// 阻塞模式，選取特定的策略來處理，策略可能是 "忽略日誌"、"日誌入隊並阻塞"、"當前執行緒列印日誌"
            // delegate to the event router (which may discard, enqueue and block, or log in current thread)
            final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());
            route.logMessage(this, memento);
        } else {
          	// 非阻塞模式，交由 ErrorHandler 處理失敗日誌
            error("Appender " + getName() + " is unable to write primary appenders. queue is full");
            logToErrorAppenderIfNecessary(false, memento);
        }
    }
}

private boolean transfer(final LogEvent memento) {
    return queue instanceof TransferQueue
        ? ((TransferQueue<LogEvent>) queue).tryTransfer(memento)
        : queue.offer(memento);
}

public void error(final String msg) {
    handler.error(msg);
}

AsyncAppender顧名思義是個非同步Appender，採用非同步方式處理日誌，在其內部維護了一個BlockingQueue佇列，每次處理日誌時，都先嚐試把Log4jLogEvent事件存入佇列中，然後交由後臺執行緒從佇列中取出事件並處理（把日誌交由AsyncAppender所關聯的Appender處理），但佇列長度總是有限的，且佇列預設大小是128，如果日誌量過大或日誌非同步執行緒處理不及時，就很可能導致日誌佇列被打滿。

當日志佇列滿時，日誌框架內部提供了兩種處理方式，具體如下：

• 如果blocking配置為true，會選擇相應的處理策略，預設是SYNCHRONOUS策略，可以在log4j2.component.properties檔案中，透過log4j2.AsyncQueueFullPolicy引數配置日誌框架提供的其他策略或自定義策略。
  • DISCARD策略，直接忽略日誌。
  • SYNCHRONOUS策略，當前執行緒直接傳送日誌到Appender。
  • ENQUEUE策略，強制阻塞入隊。
• 如果blocking配置為false，則由ErrorHandler和ErrorAppender處理失敗日誌。日誌框架提供了預設的ErrorHandler實現，即DefaultErrorHandler，目前暫不支援業務在XML、JSON等日誌配置檔案裡自定義ErrorHandler。日誌框架預設不提供ErrorAppender，業務如有需要可在XML、JSON等日誌配置檔案裡自定義error-ref配置。

在本專案的日誌配置檔案中可以看到，AsyncAppender設定了blocking為false，且沒有配置error-ref，下面具體分析DefaultErrorHandler。

// org.apache.logging.log4j.core.appender.DefaultErrorHandler

private static final Logger LOGGER = StatusLogger.getLogger();

private static final int MAX_EXCEPTIONS = 3;

// 5min 時間間隔
private static final long EXCEPTION_INTERVAL = TimeUnit.MINUTES.toNanos(5);

private int exceptionCount = 0;

private long lastException = System.nanoTime() - EXCEPTION_INTERVAL - 1;

public void error(final String msg) {
    final long current = System.nanoTime();
  	// 當前時間距離上次異常處理時間間隔超過5min 或者異常處理數小於3次
    if (current - lastException > EXCEPTION_INTERVAL || exceptionCount++ < MAX_EXCEPTIONS) {
      	// StatusLogger 負責處理
        LOGGER.error(msg);
    }
    lastException = current;
}

DefaultErrorHandler內部在處理異常日誌時增加了條件限制，只有下述兩個條件任一滿足時才會處理，從而避免大量異常日誌導致的效能問題。

• 兩條日誌處理間隔超過5min。
• 異常日誌數量不超過3次。

但專案所用日誌框架版本的預設實現看起來存在一些不太合理的地方：

• lastException用於標記上次異常的時間戳，該變數可能被多執行緒訪問，無法保證多執行緒情況下的執行緒安全。
• exceptionCount用於統計異常日誌次數，該變數可能被多執行緒訪問，無法保證多執行緒情況下的執行緒安全。

所以，在多執行緒場景下，可能有大量異常日誌同時被DefaultErrorHandler處理，帶來執行緒安全問題。值得一提的是，該問題已有相關Issue: DefaultErrorHandler can not share values across threads反饋給社群，並在2.15.0版本中進行了修復。

從上述DefaultErrorHandler程式碼中可以看到，真正負責處理日誌的是StatusLogger，繼續跟進程式碼進入logMessage方法，方法執行邏輯如下：

• 如果StatusLogger內部註冊了StatusListener，則由對應的StatusListener負責處理日誌。
• 否則由SimpleLogger負責處理日誌，直接輸出日誌到System.err輸出流。

// org.apache.logging.log4j.status.StatusLogger

private static final StatusLogger STATUS_LOGGER = new StatusLogger(StatusLogger.class.getName(),
            ParameterizedNoReferenceMessageFactory.INSTANCE);

// StatusListener
private final Collection<StatusListener> listeners = new CopyOnWriteArrayList<>();

private final SimpleLogger logger;

private StatusLogger(final String name, final MessageFactory messageFactory) {
    super(name, messageFactory);
    this.logger = new SimpleLogger("StatusLogger", Level.ERROR, false, true, false, false, Strings.EMPTY,
            messageFactory, PROPS, System.err);
    this.listenersLevel = Level.toLevel(DEFAULT_STATUS_LEVEL, Level.WARN).intLevel();
}

/**
 * Retrieve the StatusLogger.
 *
 * @return The StatusLogger.
 */
public static StatusLogger getLogger() {
    return STATUS_LOGGER;
}

@Override
public void logMessage(final String fqcn, final Level level, final Marker marker, final Message msg,
        final Throwable t) {
    StackTraceElement element = null;
    if (fqcn != null) {
        element = getStackTraceElement(fqcn, Thread.currentThread().getStackTrace());
    }
    final StatusData data = new StatusData(element, level, msg, t, null);
    msgLock.lock();
    try {
        messages.add(data);
    } finally {
        msgLock.unlock();
    }
  
    if (listeners.size() > 0) {
      	// 如果系統註冊了 listener，由 StatusConsoleListener 處理日誌
        for (final StatusListener listener : listeners) {
            if (data.getLevel().isMoreSpecificThan(listener.getStatusLevel())) {
                listener.log(data);
            }
        }
    } else {
      	// 否則由 SimpleLogger 處理日誌，直接輸出到 System.err
        logger.logMessage(fqcn, level, marker, msg, t);
    }
}

從上述Blocked執行緒堆疊來看，是StatusConsoleListener負責處理日誌，而StatusConsoleListener是StatusListener介面的實現類，那麼StatusConsoleListener是如何被建立的？

3.1.4 StatusConsoleListener是怎麼來的？

通常來說，每個專案都會有一個日誌配置檔案（如log4j2.xml），該配置對應Log4j2日誌框架中的Configuration介面，不同的日誌配置檔案格式有不同的實現類：

• XmlConfiguration，即XML格式日誌配置
• JsonConfiguration，即JSON格式日誌配置
• XMDConfiguration，即美團內部日誌元件XMD-Log定義的日誌配置（XML格式）
• ……

log4j2.xml 示例配置（僅做示例，請勿實際專案中使用該配置）。

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" name="RoutingTest">
  <Properties>
    <Property name="filename">target/rolling1/rollingtest-$${sd:type}.log</Property>
  </Properties>
  <ThresholdFilter level="debug"/>
 
  <Appenders>
    <Console name="STDOUT">
      <PatternLayout pattern="%m%n"/>
      <ThresholdFilter level="debug"/>
    </Console>
    <Routing name="Routing">
      <Routes pattern="$${sd:type}">
        <Route>
          <RollingFile name="Rolling-${sd:type}" fileName="${filename}"
                       filePattern="target/rolling1/test1-${sd:type}.%i.log.gz">
            <PatternLayout>
              <pattern>%d %p %c{1.} [%t] %m%n</pattern>
            </PatternLayout>
            <SizeBasedTriggeringPolicy size="500" />
          </RollingFile>
        </Route>
        <Route ref="STDOUT" key="Audit"/>
      </Routes>
    </Routing>
  </Appenders>
 
  <Loggers>
    <Logger name="EventLogger" level="info" additivity="false">
      <AppenderRef ref="Routing"/>
    </Logger>
 
    <Root level="error">
      <AppenderRef ref="STDOUT"/>
    </Root>
  </Loggers>
</Configuration>

Log4j2在啟動時會載入並解析log4j2.xml配置檔案，由對應的ConfigurationFactory建立具體Configuration例項。

// org.apache.logging.log4j.core.config.xml.XmlConfiguration

public XmlConfiguration(final LoggerContext loggerContext, final ConfigurationSource configSource) {
    super(loggerContext, configSource);
    final File configFile = configSource.getFile();
    byte[] buffer = null;

    try {
        final InputStream configStream = configSource.getInputStream();
        try {
            buffer = toByteArray(configStream);
        } finally {
            Closer.closeSilently(configStream);
        }
        final InputSource source = new InputSource(new ByteArrayInputStream(buffer));
        source.setSystemId(configSource.getLocation());
        final DocumentBuilder documentBuilder = newDocumentBuilder(true);
        Document document;
        try {
          	// 解析 xml 配置檔案
            document = documentBuilder.parse(source);
        } catch (final Exception e) {
            // LOG4J2-1127
            final Throwable throwable = Throwables.getRootCause(e);
            if (throwable instanceof UnsupportedOperationException) {
                LOGGER.warn(
                        "The DocumentBuilder {} does not support an operation: {}."
                        + "Trying again without XInclude...",
                        documentBuilder, e);
                document = newDocumentBuilder(false).parse(source);
            } else {
                throw e;
            }
        }
        rootElement = document.getDocumentElement();
      	// 處理根節點屬性配置，即 <Configuration></Configuration> 節點
        final Map<String, String> attrs = processAttributes(rootNode, rootElement);
      	// 建立 StatusConfiguration
        final StatusConfiguration statusConfig = new StatusConfiguration().withVerboseClasses(VERBOSE_CLASSES)
                .withStatus(getDefaultStatus());
        for (final Map.Entry<String, String> entry : attrs.entrySet()) {
            final String key = entry.getKey();
            final String value = getStrSubstitutor().replace(entry.getValue());
          	// 根據配置檔案中的 status 屬性值，來設定 StatusConfiguration 的 status level
            if ("status".equalsIgnoreCase(key)) {
                statusConfig.withStatus(value);
            // 根據配置檔案中的 dest 屬性值，來設定 StatusConfiguration 的日誌輸出 destination
            } else if ("dest".equalsIgnoreCase(key)) {
                statusConfig.withDestination(value);
            } else if ("shutdownHook".equalsIgnoreCase(key)) {
                isShutdownHookEnabled = !"disable".equalsIgnoreCase(value);
            } else if ("verbose".equalsIgnoreCase(key)) {
                statusConfig.withVerbosity(value);
            } else if ("packages".equalsIgnoreCase(key)) {
                pluginPackages.addAll(Arrays.asList(value.split(Patterns.COMMA_SEPARATOR)));
            } else if ("name".equalsIgnoreCase(key)) {
                setName(value);
            } else if ("strict".equalsIgnoreCase(key)) {
                strict = Boolean.parseBoolean(value);
            } else if ("schema".equalsIgnoreCase(key)) {
                schemaResource = value;
            } else if ("monitorInterval".equalsIgnoreCase(key)) {
                final int intervalSeconds = Integer.parseInt(value);
                if (intervalSeconds > 0) {
                    getWatchManager().setIntervalSeconds(intervalSeconds);
                    if (configFile != null) {
                        final FileWatcher watcher = new ConfiguratonFileWatcher(this, listeners);
                        getWatchManager().watchFile(configFile, watcher);
                    }
                }
            } else if ("advertiser".equalsIgnoreCase(key)) {
                createAdvertiser(value, configSource, buffer, "text/xml");
            }
        }
      
     		// 初始化 StatusConfiguration
        statusConfig.initialize();
    } catch (final SAXException | IOException | ParserConfigurationException e) {
        LOGGER.error("Error parsing " + configSource.getLocation(), e);
    }

    if (getName() == null) {
        setName(configSource.getLocation());
    }
  
  	// 忽略以下內容
}

// org.apache.logging.log4j.core.config.status.StatusConfiguration

private static final PrintStream DEFAULT_STREAM = System.out;
private static final Level DEFAULT_STATUS = Level.ERROR;
private static final Verbosity DEFAULT_VERBOSITY = Verbosity.QUIET;

private final Collection<String> errorMessages = Collections.synchronizedCollection(new LinkedList<String>());
// StatusLogger
private final StatusLogger logger = StatusLogger.getLogger();

private volatile boolean initialized = false;

private PrintStream destination = DEFAULT_STREAM;
private Level status = DEFAULT_STATUS;
private Verbosity verbosity = DEFAULT_VERBOSITY;

public void initialize() {
    if (!this.initialized) {
        if (this.status == Level.OFF) {
            this.initialized = true;
        } else {
            final boolean configured = configureExistingStatusConsoleListener();
            if (!configured) {
              	// 註冊新 StatusConsoleListener
                registerNewStatusConsoleListener();
            }
            migrateSavedLogMessages();
        }
    }
}

private boolean configureExistingStatusConsoleListener() {
    boolean configured = false;
    for (final StatusListener statusListener : this.logger.getListeners()) {
        if (statusListener instanceof StatusConsoleListener) {
            final StatusConsoleListener listener = (StatusConsoleListener) statusListener;
          	// StatusConsoleListener 的 level 以 StatusConfiguration 的 status 為準
            listener.setLevel(this.status);
            this.logger.updateListenerLevel(this.status);
            if (this.verbosity == Verbosity.QUIET) {
                listener.setFilters(this.verboseClasses);
            }
            configured = true;
        }
    }
    return configured;
}


private void registerNewStatusConsoleListener() {
  	// 建立 StatusConsoleListener，級別以 StatusConfiguration 為準
  	// 預設 status 是 DEFAULT_STATUS 即 ERROR
  	// 預設 destination 是 DEFAULT_STREAM 即 System.out
    final StatusConsoleListener listener = new StatusConsoleListener(this.status, this.destination);
    if (this.verbosity == Verbosity.QUIET) {
        listener.setFilters(this.verboseClasses);
    }
    this.logger.registerListener(listener);
}

// org.apache.logging.log4j.status.StatusConsoleListener

private Level level = Level.FATAL; // 級別
private String[] filters;
private final PrintStream stream; // 輸出流

public StatusConsoleListener(final Level level, final PrintStream stream) {
    if (stream == null) {
        throw new IllegalArgumentException("You must provide a stream to use for this listener.");
    }
    this.level = level;
    this.stream = stream;
}

以XmlConfiguration為例，分析上述日誌配置解析程式碼片段可以得知，建立XmlConfiguration時，會先建立StatusConfiguration，隨後在初始化StatusConfiguration時建立並註冊StatusConsoleListener到StatusLogger的listeners中，日誌配置檔案中<Configuration>標籤的屬性值透過XmlConfiguration->StatusConfiguration->StatusConsoleListener這樣的關係鏈路最終影響StatusConsoleListener的行為。

日誌配置檔案中的<Configuration>標籤可以配置屬性欄位，部分欄位如下所示：

• status，可選值包括OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、ALL，該值決定StatusConsoleListener級別，預設是ERROR。
• dest，可選值包括out、err、標準的URI路徑，該值決定StatusConsoleListener輸出流目的地，預設是System.out。

在本專案的日誌配置檔案中可以看到並沒有設定Configuration的dest屬性值，所以日誌直接輸出到System.out。

3.1.5 StatusLogger有什麼用？

上文提到StatusConsoleListener是註冊在StatusLogger中，StatusLogger在交由StatusListener處理日誌前，會判斷日誌級別，如果級別條件不滿足，則忽略此日誌，StatusConsoleListener的日誌級別預設是ERROR。

// org.apache.logging.log4j.status.StatusLogger
  
@Override
public void logMessage(final String fqcn, final Level level, final Marker marker, final Message msg,
        final Throwable t) {
    StackTraceElement element = null;
    if (fqcn != null) {
        element = getStackTraceElement(fqcn, Thread.currentThread().getStackTrace());
    }
    final StatusData data = new StatusData(element, level, msg, t, null);
    msgLock.lock();
    try {
        messages.add(data);
    } finally {
        msgLock.unlock();
    }
  
  	// 系統註冊了 listener，由 StatusConsoleListener 處理日誌
    if (listeners.size() > 0) {
        for (final StatusListener listener : listeners) {
          	// 比較當前日誌的 leve 和 listener 的 level
            if (data.getLevel().isMoreSpecificThan(listener.getStatusLevel())) {
                listener.log(data);
            }
        }
    } else {
        logger.logMessage(fqcn, level, marker, msg, t);
    }
}

我們回頭再來看下StatusLogger，StatusLogger採用單例模式實現，它輸出日誌到Console（如System.out或System.err），從上文分析可知，在高併發場景下非常容易導致執行緒Block，那麼它的存在有什麼意義呢？

看官方介紹大意是說，在日誌初始化完成前，也有列印日誌除錯的需求，StatusLogger就是為了解決這個問題而生。

Troubleshooting tip for the impatient:

From log4j-2.9 onward, log4j2 will print all internal logging to the console if system property log4j2.debug is defined (with any or no value).

Prior to log4j-2.9, there are two places where internal logging can be controlled:

• Before a configuration is found, status logger level can be controlled with system property org.apache.logging.log4j.simplelog.StatusLogger.level.
• After a configuration is found, status logger level can be controlled in the configuration file with the “status” attribute, for example: <Configuration status=“trace”>.

Just as it is desirable to be able to diagnose problems in applications, it is frequently necessary to be able to diagnose problems in the logging configuration or in the configured components. Since logging has not been configured, “normal” logging cannot be used during initialization. In addition, normal logging within appenders could create infinite recursion which Log4j will detect and cause the recursive events to be ignored. To accomodate this need, the Log4j 2 API includes a StatusLogger.

3.1.6 問題小結

日誌量過大導致AsyncAppender日誌佇列被打滿，新的日誌事件無法入隊，進而由ErrorHandler處理日誌，同時由於ErrorHandler存線上程安全問題，導致大量日誌輸出到了Console，而Console在輸出日誌到PrintStream輸出流時，存在synchronized同步程式碼塊，所以在高併發場景下導致執行緒Block。

3.2 AsyncAppender導致執行緒Block

3.2.1 問題現場

收到“jvm.thread.blocked.count”告警後立刻透過監控平臺檢視執行緒監控指標，當時的執行緒堆疊如下圖6和圖7所示。

圖6 等待鎖的Blocked執行緒堆疊

圖7 持有鎖的Runnable執行緒堆疊

從Blocked執行緒堆疊不難看出是跟日誌列印相關，由於是ERROR級別日誌，檢視具體報錯日誌，發現有兩種業務異常，分別如下圖8和圖9所示：

圖8 業務異常堆疊一

圖9 業務異常堆疊二

這些業務異常會是導致執行緒Block的幕後元兇嗎？接下來本章節將結合如下圖10所示的呼叫鏈路深入分析執行緒Block的根因。

圖10 日誌呼叫鏈路

3.2.2 為什麼會Block執行緒？

從Blocked執行緒堆疊中可以看出，執行緒阻塞在類載入流程上，檢視WebAppClassLoader相關程式碼片段如下圖11所示，發現載入類時確實會根據類名來加synchronized同步塊，因此初步猜測是類載入導致執行緒Block。

圖11 WebAppClassLoader

但上述猜測還有一些值得推敲的地方：

1. 專案程式碼裡只是普通地輸出一條ERROR日誌而已，為何會觸發類載入？
2. 通常情況下類載入幾乎不會觸發執行緒Block，不然一個專案要載入成千上萬個類，如果因為載入類就導致Block，那專案就沒法正常執行了。

3.2.3 為什麼會觸發類載入？

繼續從Blocked執行緒堆疊著手分析，檢視堆疊中的ThrowableProxy相關程式碼，發現其建構函式會遍歷整個異常堆疊中的所有堆疊元素，最終獲取所有堆疊元素類所在的JAR名稱和版本資訊。具體流程如下：

1. 首先獲取堆疊元素的類名稱。
2. 再透過loadClass的方式獲取對應的Class物件。
3. 進一步獲取該類所在的JAR資訊，從CodeSource中獲取JAR名稱，從Package中獲取JAR版本。

// org.apache.logging.log4j.core.impl.ThrowableProxy
  
private ThrowableProxy(final Throwable throwable, final Set<Throwable> visited) {
    this.throwable = throwable;
    this.name = throwable.getClass().getName();
    this.message = throwable.getMessage();
    this.localizedMessage = throwable.getLocalizedMessage();
    final Map<String, CacheEntry> map = new HashMap<>();
    final Stack<Class<?>> stack = ReflectionUtil.getCurrentStackTrace();
  	// 獲取堆疊擴充套件資訊
    this.extendedStackTrace = this.toExtendedStackTrace(stack, map, null, throwable.getStackTrace());
    final Throwable throwableCause = throwable.getCause();
    final Set<Throwable> causeVisited = new HashSet<>(1);
    this.causeProxy = throwableCause == null ? null : new ThrowableProxy(throwable, stack, map, throwableCause,
        visited, causeVisited);
    this.suppressedProxies = this.toSuppressedProxies(throwable, visited);
}

ExtendedStackTraceElement[] toExtendedStackTrace(final Stack<Class<?>> stack, final Map<String, CacheEntry> map,
                                                 final StackTraceElement[] rootTrace,
                                                 final StackTraceElement[] stackTrace) {
    int stackLength;
    if (rootTrace != null) {
        int rootIndex = rootTrace.length - 1;
        int stackIndex = stackTrace.length - 1;
        while (rootIndex >= 0 && stackIndex >= 0 && rootTrace[rootIndex].equals(stackTrace[stackIndex])) {
            --rootIndex;
            --stackIndex;
        }
        this.commonElementCount = stackTrace.length - 1 - stackIndex;
        stackLength = stackIndex + 1;
    } else {
        this.commonElementCount = 0;
        stackLength = stackTrace.length;
    }
    final ExtendedStackTraceElement[] extStackTrace = new ExtendedStackTraceElement[stackLength];
    Class<?> clazz = stack.isEmpty() ? null : stack.peek();
    ClassLoader lastLoader = null;
    for (int i = stackLength - 1; i >= 0; --i) {
      	// 遍歷 StackTraceElement
        final StackTraceElement stackTraceElement = stackTrace[i];
      	// 獲取堆疊元素對應的類名稱
        final String className = stackTraceElement.getClassName();
        // The stack returned from getCurrentStack may be missing entries for java.lang.reflect.Method.invoke()
        // and its implementation. The Throwable might also contain stack entries that are no longer
        // present as those methods have returned.
        ExtendedClassInfo extClassInfo;
        if (clazz != null && className.equals(clazz.getName())) {
            final CacheEntry entry = this.toCacheEntry(stackTraceElement, clazz, true);
            extClassInfo = entry.element;
            lastLoader = entry.loader;
            stack.pop();
            clazz = stack.isEmpty() ? null : stack.peek();
        } else {
          	// 對載入過的 className 進行快取，避免重複載入
            final CacheEntry cacheEntry = map.get(className);
            if (cacheEntry != null) {
                final CacheEntry entry = cacheEntry;
                extClassInfo = entry.element;
                if (entry.loader != null) {
                    lastLoader = entry.loader;
                }
            } else {
              	// 透過載入類來獲取類的擴充套件資訊，如 location 和 version 等
                final CacheEntry entry = this.toCacheEntry(stackTraceElement,
                    // 獲取 Class 物件
                    this.loadClass(lastLoader, className), false);
                extClassInfo = entry.element;
                map.put(stackTraceElement.toString(), entry);
                if (entry.loader != null) {
                    lastLoader = entry.loader;
                }
            }
        }
        extStackTrace[i] = new ExtendedStackTraceElement(stackTraceElement, extClassInfo);
    }
    return extStackTrace;
}

/**
 * Construct the CacheEntry from the Class's information.
 *
 * @param stackTraceElement The stack trace element
 * @param callerClass       The Class.
 * @param exact             True if the class was obtained via Reflection.getCallerClass.
 * @return The CacheEntry.
 */
private CacheEntry toCacheEntry(final StackTraceElement stackTraceElement, final Class<?> callerClass,
                                final boolean exact) {
    String location = "?";
    String version = "?";
    ClassLoader lastLoader = null;
    if (callerClass != null) {
        try {
            // 獲取 jar 檔案資訊
            final CodeSource source = callerClass.getProtectionDomain().getCodeSource();
            if (source != null) {
                final URL locationURL = source.getLocation();
                if (locationURL != null) {
                    final String str = locationURL.toString().replace('\\', '/');
                    int index = str.lastIndexOf("/");
                    if (index >= 0 && index == str.length() - 1) {
                        index = str.lastIndexOf("/", index - 1);
                        location = str.substring(index + 1);
                    } else {
                        location = str.substring(index + 1);
                    }
                }
            }
        } catch (final Exception ex) {
            // Ignore the exception.
        }
    		// 獲取類所在 jar 版本資訊
        final Package pkg = callerClass.getPackage();
        if (pkg != null) {
            final String ver = pkg.getImplementationVersion();
            if (ver != null) {
                version = ver;
            }
        }
        lastLoader = callerClass.getClassLoader();
    }
    return new CacheEntry(new ExtendedClassInfo(exact, location, version), lastLoader);
}

從上述程式碼中可以看到，ThrowableProxy#toExtendedStackTrace方法透過Map<string, cacheentry="">快取當前堆疊元素類對應的CacheEntry，來避免重複解析CacheEntry，但是由於Map快取put操作使用的key來自於StackTraceElement.toString方法，而get操作使用的key卻來自於StackTraceElement.getClassName方法，即使對於同一個StackTraceElement而言，其toString和getClassName方法對應的返回結果也不一樣，所以此map形同虛設。

// java.lang.StackTraceElement
  
public String getClassName() {
    return declaringClass;
}

public String toString() {
    return getClassName() + "." + methodName +
        (isNativeMethod() ? "(Native Method)" :
         (fileName != null && lineNumber >= 0 ?
          "(" + fileName + ":" + lineNumber + ")" :
          (fileName != null ?  "("+fileName+")" : "(Unknown Source)")));
}

該問題已有相關Issue: fix the CacheEntry map in ThrowableProxy#toExtendedStackTrace to be put and gotten with same key反饋給社群，並在2.11.1版本中修復了該問題。雖然透過讓get/put方法使用同一個key來修復快取的有效性問題，但由於ThrowableProxy對每個Throwable都會建立一個全新的Map，而不是使用全域性Map，因此其快取也僅僅對單個Throwable生效，作用範圍非常有限，食之無味，棄之可惜。

言歸正傳，通常情況下一個類載入器對於一個類只會載入一次，類載入器內部儲存有類快取，無需重複載入，但目前的現象卻是由於類載入而導致執行緒大量Block，因此必然是有些類載入不了，且不斷重複嘗試載入，那到底是什麼類無法載入呢？

3.2.4 到底什麼類載入不了？

要找到具體是什麼類無法載入，歸根結底還是要分析業務異常的具體堆疊。

圖12 業務異常堆疊一

圖13 業務異常堆疊二

對比如圖12和圖13所示的兩份業務異常堆疊，我們可以看到兩份堆疊基本相似，且大多數類都是很普通的類，但是唯一不同的地方在於：

1. sun.reflect.NativeMethodAccessorImpl（參見圖12）。
2. sun.reflect.GeneratedMethodAccessor261（參見圖13）。

從字面資訊中不難猜測出這與反射呼叫相關，但問題是這兩份堆疊對應的其實是同一份業務程式碼，為什麼會產生兩份不同的異常堆疊？

查閱相關資料得知，這與JVM反射呼叫相關，JVM對反射呼叫分兩種情況：

1. 預設使用native方法進行反射操作。
2. 一定條件下會生成位元組碼進行反射操作，即生成sun.reflect.GeneratedMethodAccessor<N>類，它是一個反射呼叫方法的包裝類，代理不同的方法，類字尾序號遞增。

JVM反射呼叫的主要流程是獲取MethodAccessor，並由MethodAccessor執行invoke呼叫，相關程式碼如下：

// java.lang.reflect.Method  

@CallerSensitive
public Object invoke(Object obj, Object... args)
    throws IllegalAccessException, IllegalArgumentException,
       InvocationTargetException
{
    if (!override) {
        if (!Reflection.quickCheckMemberAccess(clazz, modifiers)) {
            Class<?> caller = Reflection.getCallerClass();
            checkAccess(caller, clazz, obj, modifiers);
        }
    }

    MethodAccessor ma = methodAccessor;             // read volatile
    if (ma == null) {
    		// 獲取 MethodAccessor
        ma = acquireMethodAccessor();
    }
    // 透過 MethodAccessor 呼叫
    return ma.invoke(obj, args);
}

private MethodAccessor acquireMethodAccessor() {
    MethodAccessor tmp = null;
    if (root != null) tmp = root.getMethodAccessor();
    if (tmp != null) {
        methodAccessor = tmp;
    } else {
        // 透過 ReflectionFactory 建立 MethodAccessor
        tmp = reflectionFactory.newMethodAccessor(this);
        setMethodAccessor(tmp);
    }

    return tmp;
}

當noInflation為false（預設為false）或者反射方法所在類是VM匿名類（類名中包括斜槓“/”）的情況下，ReflectionFactory會返回一個MethodAccessor代理類，即DelegatingMethodAccessorImpl。

// sun.reflect.ReflectionFactory

public MethodAccessor newMethodAccessor(Method method) {
  	// 透過啟動引數獲取並解析 noInflation 和 inflationThreshold 值
  	// noInflation 預設為 false
  	// inflationThreshold 預設為15
    checkInitted();

    if (noInflation && !ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {
        return new MethodAccessorGenerator().
            generateMethod(method.getDeclaringClass(),
                           method.getName(),
                           method.getParameterTypes(),
                           method.getReturnType(),
                           method.getExceptionTypes(),
                           method.getModifiers());
    } else {
        NativeMethodAccessorImpl acc =
            new NativeMethodAccessorImpl(method);
        DelegatingMethodAccessorImpl res =
            new DelegatingMethodAccessorImpl(acc);
        acc.setParent(res);
      
      	// 返回代理 DelegatingMethodAccessorImpl
        return res;
    }
}

private static void checkInitted() {
    if (initted) return;
    AccessController.doPrivileged(
        new PrivilegedAction<Void>() {
            public Void run() {
                // Tests to ensure the system properties table is fully
                // initialized. This is needed because reflection code is
                // called very early in the initialization process (before
                // command-line arguments have been parsed and therefore
                // these user-settable properties installed.) We assume that
                // if System.out is non-null then the System class has been
                // fully initialized and that the bulk of the startup code
                // has been run.

                if (System.out == null) {
                    // java.lang.System not yet fully initialized
                    return null;
                }

                String val = System.getProperty("sun.reflect.noInflation");
                if (val != null && val.equals("true")) {
                    noInflation = true;
                }

                val = System.getProperty("sun.reflect.inflationThreshold");
                if (val != null) {
                    try {
                        inflationThreshold = Integer.parseInt(val);
                    } catch (NumberFormatException e) {
                        throw new RuntimeException("Unable to parse property sun.reflect.inflationThreshold", e);
                    }
                }

                initted = true;
                return null;
            }
        });
}

預設情況下DelegatingMethodAccessorImpl代理了NativeMethodAccessorImpl，但是隨著反射呼叫次數的增加，當一個方法被反射呼叫的次數超過一定的閥值時（inflationThreshold，預設值是15），NativeMethodAccessorImpl會透過位元組碼生成技術，自動生成MethodAccessorImpl實現類，並修改DelegatingMethodAccessorImpl的內部代理物件指向位元組碼生成類例項，從而改變後續反射呼叫邏輯。

圖14 MethodAccessor關係圖

// sun.reflect.DelegatingMethodAccessorImpl

class DelegatingMethodAccessorImpl extends MethodAccessorImpl {
  	// 內部代理 MethodAccessorImpl
    private MethodAccessorImpl delegate;

    DelegatingMethodAccessorImpl(MethodAccessorImpl delegate) {
        setDelegate(delegate);
    }

    public Object invoke(Object obj, Object[] args)
        throws IllegalArgumentException, InvocationTargetException
    {
        return delegate.invoke(obj, args);
    }

    void setDelegate(MethodAccessorImpl delegate) {
        this.delegate = delegate;
    }
}

// sun.reflect.NativeMethodAccessorImpl

class NativeMethodAccessorImpl extends MethodAccessorImpl {
    private final Method method;
    private DelegatingMethodAccessorImpl parent;
    private int numInvocations;

    NativeMethodAccessorImpl(Method method) {
        this.method = method;
    }

    public Object invoke(Object obj, Object[] args)
        throws IllegalArgumentException, InvocationTargetException
    {
        // We can't inflate methods belonging to vm-anonymous classes because
        // that kind of class can't be referred to by name, hence can't be
        // found from the generated bytecode.
      
      	// 每次呼叫時 numInvocations 都會自增加1，如果超過閾值（預設是15次），就會修改父類的代理物件，從而改變呼叫鏈路
        if (++numInvocations > ReflectionFactory.inflationThreshold()
                && !ReflectUtil.isVMAnonymousClass(method.getDeclaringClass())) {
            MethodAccessorImpl acc = (MethodAccessorImpl)
              	// 動態生成位元組碼，最佳化反射呼叫速度
                new MethodAccessorGenerator().
                    generateMethod(method.getDeclaringClass(),
                                   method.getName(),
                                   method.getParameterTypes(),
                                   method.getReturnType(),
                                   method.getExceptionTypes(),
                                   method.getModifiers());
          	// 修改父代理類的代理物件
            parent.setDelegate(acc);
        }

        return invoke0(method, obj, args);
    }

    void setParent(DelegatingMethodAccessorImpl parent) {
        this.parent = parent;
    }

    private static native Object invoke0(Method m, Object obj, Object[] args);
}

從MethodAccessorGenerator#generateName方法可以看到，位元組碼生成的類名稱規則是sun.reflect.GeneratedConstructorAccessor<N>，其中N是從0開始的遞增數字，且生成類是由DelegatingClassLoader類載入器定義，所以其他類載入器無法載入該類，也就無法生成類快取資料，從而導致每次載入類時都需要遍歷JarFile，極大地降低了類查詢速度，且類載入過程是synchronized同步呼叫，在高併發情況下會更加惡化，從而導致執行緒Block。

// sun.reflect.MethodAccessorGenerator

public MethodAccessor generateMethod(Class<?> declaringClass,
                                     String   name,
                                     Class<?>[] parameterTypes,
                                     Class<?>   returnType,
                                     Class<?>[] checkedExceptions,
                                     int modifiers)
{
    return (MethodAccessor) generate(declaringClass,
                                     name,
                                     parameterTypes,
                                     returnType,
                                     checkedExceptions,
                                     modifiers,
                                     false,
                                     false,
                                     null);
}

private MagicAccessorImpl generate(final Class<?> declaringClass,
                                   String name,
                                   Class<?>[] parameterTypes,
                                   Class<?>   returnType,
                                   Class<?>[] checkedExceptions,
                                   int modifiers,
                                   boolean isConstructor,
                                   boolean forSerialization,
                                   Class<?> serializationTargetClass)
{
  
	  final String generatedName = generateName(isConstructor, forSerialization);

    // 忽略以上程式碼

    return AccessController.doPrivileged(
        new PrivilegedAction<MagicAccessorImpl>() {
            public MagicAccessorImpl run() {
                    try {
                    return (MagicAccessorImpl)
                    ClassDefiner.defineClass
                            (generatedName,
                             bytes,
                             0,
                             bytes.length,
                             declaringClass.getClassLoader()).newInstance();
                    } catch (InstantiationException | IllegalAccessException e) {
                        throw new InternalError(e);
                    }
                }
            });
}

// 生成反射類名，看到了熟悉的 sun.reflect.GeneratedConstructorAccessor<N>
private static synchronized String generateName(boolean isConstructor, boolean forSerialization)
{
    if (isConstructor) {
        if (forSerialization) {
            int num = ++serializationConstructorSymnum;
            return "sun/reflect/GeneratedSerializationConstructorAccessor" + num;
        } else {
            int num = ++constructorSymnum;
            return "sun/reflect/GeneratedConstructorAccessor" + num;
        }
    } else {
        int num = ++methodSymnum;
        return "sun/reflect/GeneratedMethodAccessor" + num;
    }
}

// sun.reflect.ClassDefiner
  
static Class<?> defineClass(String name, byte[] bytes, int off, int len,
                            final ClassLoader parentClassLoader)
{
    ClassLoader newLoader = AccessController.doPrivileged(
        new PrivilegedAction<ClassLoader>() {
            public ClassLoader run() {
                    return new DelegatingClassLoader(parentClassLoader);
                }
            });
  	// 透過 DelegatingClassLoader 類載入器定義生成類
    return unsafe.defineClass(name, bytes, off, len, newLoader, null);
}

那麼，JVM反射呼叫為什麼要做這麼做？

其實這是JVM對反射呼叫的一種最佳化手段，在sun.reflect.ReflectionFactory的文件註釋裡對此做了解釋，這是一種“Inflation”機制，載入位元組碼的呼叫方式在第一次呼叫時會比Native呼叫的速度要慢3~4倍，但是在後續呼叫時會比Native呼叫速度快20多倍。為了避免反射呼叫影響應用的啟動速度，所以在反射呼叫的前幾次透過Native方式呼叫，當超過一定呼叫次數後使用位元組碼方式呼叫，提升反射呼叫效能。

“Inflation” mechanism. Loading bytecodes to implement Method.invoke() and Constructor.newInstance() currently costs 3-4x more than an invocation via native code for the first invocation (though subsequent invocations have been benchmarked to be over 20x faster). Unfortunately this cost increases startup time for certain applications that use reflection intensively (but only once per class) to bootstrap themselves. To avoid this penalty we reuse the existing JVM entry points for the first few invocations of Methods and Constructors and then switch to the bytecode-based implementations.

至此，總算理清了類載入導致執行緒Block的直接原因，但這並非根因，業務程式碼中普普通通地列印一條ERROR日誌，為何會導致解析、載入異常堆疊類？

3.2.5 為什麼要解析異常堆疊？

圖15 AsyncAppender處理日誌流程

AsyncAppender處理日誌簡要流程如上圖15所示，在其內部維護一個BlockingQueue佇列和一個AsyncThread執行緒，處理日誌時先把日誌轉換成Log4jLogEvent快照然後入隊，同時AsyncThread執行緒負責從佇列裡獲取元素來非同步處理日誌事件。

// org.apache.logging.log4j.core.appender.AsyncAppender

@Override
public void append(final LogEvent logEvent) {
    if (!isStarted()) {
        throw new IllegalStateException("AsyncAppender " + getName() + " is not active");
    }
    if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose
        logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
    }
  	// 建立 日誌資料快照
    final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);
  	// 放入 BlockingQueue 中
    if (!transfer(memento)) {
        if (blocking) {
            // delegate to the event router (which may discard, enqueue and block, or log in current thread)
            final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());
            route.logMessage(this, memento);
        } else {
            error("Appender " + getName() + " is unable to write primary appenders. queue is full");
            logToErrorAppenderIfNecessary(false, memento);
        }
    }
}

AsyncAppender在生成LogEvent的快照Log4jLogEvent時，會先對LogEvent序列化處理統一轉換為LogEventProxy，此時不同型別的LogEvent的處理情況稍有差異：

• Log4jLogEvent型別，先執行Log4jLogEvent#getThrownProxy方法，觸發建立ThrowableProxy例項。
• MutableLogEvent型別，先建立LogEventProxy例項，在建構函式內執行MutableLogEvent#getThrownProxy方法，觸發建立ThrowableProxy例項。

綜上，不管LogEvent的實際型別是MutableLogEvent還是Log4jLogEvent，最終都會觸發建立ThrowableProxy例項，並在ThrowableProxy建構函式內觸發瞭解析、載入異常堆疊類。

// org.apache.logging.log4j.core.impl.Log4jLogEvent

// 生成Log4jLogEvent快照
public static Log4jLogEvent createMemento(final LogEvent event, final boolean includeLocation) {
    // TODO implement Log4jLogEvent.createMemento()
    return deserialize(serialize(event, includeLocation));
}

public static Serializable serialize(final LogEvent event, final boolean includeLocation) {
    if (event instanceof Log4jLogEvent) {
      	// 確保 ThrowableProxy 已完成初始化
        event.getThrownProxy(); // ensure ThrowableProxy is initialized
      	// 建立 LogEventProxy
        return new LogEventProxy((Log4jLogEvent) event, includeLocation);
    }
  	// 建立 LogEventProxy
    return new LogEventProxy(event, includeLocation);
}

@Override
public ThrowableProxy getThrownProxy() {
    if (thrownProxy == null && thrown != null) {
        thrownProxy = new ThrowableProxy(thrown);
    }
    return thrownProxy;
}

public LogEventProxy(final LogEvent event, final boolean includeLocation) {
    this.loggerFQCN = event.getLoggerFqcn();
    this.marker = event.getMarker();
    this.level = event.getLevel();
    this.loggerName = event.getLoggerName();

    final Message msg = event.getMessage();
    this.message = msg instanceof ReusableMessage
            ? memento((ReusableMessage) msg)
            : msg;
    this.timeMillis = event.getTimeMillis();
    this.thrown = event.getThrown();
  	// 建立 ThrownProxy 例項
    this.thrownProxy = event.getThrownProxy();
    this.contextData = memento(event.getContextData());
    this.contextStack = event.getContextStack();
    this.source = includeLocation ? event.getSource() : null;
    this.threadId = event.getThreadId();
    this.threadName = event.getThreadName();
    this.threadPriority = event.getThreadPriority();
    this.isLocationRequired = includeLocation;
    this.isEndOfBatch = event.isEndOfBatch();
    this.nanoTime = event.getNanoTime();
}

// org.apache.logging.log4j.core.impl.MutableLogEvent

@Override
public ThrowableProxy getThrownProxy() {
    if (thrownProxy == null && thrown != null) {
      	// 構造 ThrowableProxy 時列印異常堆疊
        thrownProxy = new ThrowableProxy(thrown);
    }
    return thrownProxy;
}

3.2.6 問題小結

Log4j2列印異常日誌時，AsyncAppender會先建立日誌事件快照，並進一步觸發解析、載入異常堆疊類。JVM透過生成位元組碼的方式最佳化反射呼叫效能，但該動態生成的類無法被WebAppClassLoader類載入器載入，因此當大量包含反射呼叫的異常堆疊被輸出到日誌時，會頻繁地觸發類載入，由於類載入過程是synchronized同步加鎖的，且每次載入都需要讀取檔案，速度較慢，從而導致執行緒Block。

3.3 Lambda表示式導致執行緒Block

3.3.1 問題現場

收到“jvm.thread.blocked.count”告警後，立刻透過監控平臺檢視執行緒監控指標，當時的執行緒堆疊如下圖16和圖17所示：

圖16 等待鎖的Blocked執行緒堆疊

圖17 持有鎖的Runnable執行緒堆疊

從Blocked執行緒堆疊不難看出是和日誌列印相關，由於是ERROR級別日誌，檢視具體報錯日誌，發現如下圖18所示的業務異常。

圖18 業務異常堆疊

本案例的Blocked執行緒堆疊和上述“AsyncAppender導致執行緒Block”案例一樣，那麼導致執行緒Block的罪魁禍首會是業務異常嗎？接下來本章節將結合下圖19所示的呼叫鏈路深入分析執行緒Block的根因。

圖19 日誌呼叫鏈路

3.3.2 為什麼會Block執行緒？

從Blocked執行緒堆疊中可以看出，執行緒阻塞在類載入上，該執行緒堆疊和上述“AsyncAppender導致執行緒Block”案例相似，這裡不再重複分析。

3.3.3 為什麼會觸發類載入？

原因和上述“AsyncAppender導致執行緒Block”案例相似，這裡不再重複分析。

3.3.4 到底什麼類載入不了？

上述“AsyncAppender導致執行緒Block”案例中，類載入器無法載入由JVM針對反射呼叫最佳化所生成的位元組碼類，本案例是否也是該原因導致，還待進一步具體分析。

要找到具體是什麼類無法載入，歸根結底還是要分析業務異常的具體堆疊。從業務堆疊中可以明顯看出來，沒有任何堆疊元素和JVM反射呼叫相關，因此排除JVM反射呼叫原因，但如下的特殊堆疊資訊引起了注意：

com.sankuai.shepherd.core.process.ProcessHandlerFactory$$Lambda$35/1331430278

從堆疊的關鍵字$$Lambda$大致能猜測出這是程式碼裡使用了Lambda表示式的緣故，檢視程式碼確實相關部分使用了Lambda表示式，經過斷點除錯，證實的確無法載入該類。那麼，這樣的類是怎麼來的？

查閱相關資料得知，Lambda表示式區別於匿名內部類實現，在構建時不會生成class檔案，而是在執行時透過invokeDynamic指令動態呼叫，Lambda表示式的內容會被封裝在一個靜態方法內，JVM透過ASM位元組碼技術來動態生成呼叫類，也就是$$Lambda$這種形式的類，生成類示例如下圖20所示：

圖20 Lambda生成類示例

Lambda表示式的實現原理不是本文重點內容，在此不做過多介紹。專案程式碼中使用Lambda表示式是再普通不過的事情，但是關於此類的案例卻並不多見，實在令人難以置信。繼續查閱Lambda表示式相關文件，發現異常堆疊類名包含$$Lambda$這樣的關鍵字，其實是JDK的一個Bug，相關Issue可參考:

• NoClassDefFound error in transforming lambdas
• JVMTI RedefineClasses doesn’t handle anonymous classes properly

值得一提的是，該Bug在JDK9版本已經修復，實際測試中發現，在JDK8的高版本如8U171等已修復該Bug，異常堆疊中不會有類似$$Lambda$的堆疊資訊，示例如下圖21所示：

圖21 JDK8U171版本下Lambda異常堆疊示例

3.3.5 為什麼要解析異常堆疊？

原因和上述“AsyncAppender導致執行緒Block”案例相似，不再重複分析。

3.3.6 問題小結

Log4j2列印異常日誌時，AsyncAppender會先建立日誌事件快照，並進一步觸發解析、載入異常堆疊類。JDK 8低版本中使用Lambda表示式所生成的異常堆疊類無法被WebAppClassLoader類載入器載入，因此，當大量包含Lambda表示式呼叫的異常堆疊被輸出到日誌時，會頻繁地觸發類載入，由於類載入過程是synchronized同步加鎖的，且每次載入都需要讀取檔案，速度較慢，從而導致了執行緒Block。

3.4 AsyncLoggerConfig導致執行緒Block

3.4.1 問題現場

收到“jvm.thread.blocked.count”告警後立刻透過監控平臺檢視執行緒監控指標，當時的執行緒堆疊如下圖22和圖23所示。

圖22 等待鎖的Blocked執行緒堆疊

圖23 持有鎖的Runnable執行緒堆疊

從Blocked執行緒堆疊不難看出是和日誌列印相關，本案例的業務異常和上述“AsyncAppender導致執行緒Block”的業務異常一樣，這裡不再重複介紹。

那麼，到底是什麼原因導致執行緒Block呢？接下來本章節將結合下圖24所示的呼叫鏈路深入分析執行緒Block的根因。

圖24 日誌呼叫鏈路

3.4.2 為什麼會Block執行緒？

原因和上述“AsyncAppender導致執行緒Block”案例相似，這裡不再重複分析。

3.4.3 為什麼會觸發類載入？

原因和上述“AsyncAppender導致執行緒Block”案例相似，這裡不再重複分析。

3.4.4 到底是什麼類載入不了？

原因和上述“AsyncAppender導致執行緒Block”案例相似，這裡不再重複分析。

3.4.5 為什麼要解析異常堆疊？

在開始分析原因之前，先理清楚Log4j2關於日誌的幾個重要概念：

• <Logger>，日誌配置標籤，用於XML日誌配置檔案中，對應Log4j2框架中的LoggerConfig類，同步分發日誌事件到對應Appender。
• <AsyncLogger>，日誌配置標籤，用於XML日誌配置檔案中，對應Log4j2框架中的AsyncLoggerConfig類，內部使用Disruptor佇列非同步分發日誌事件到對應Appender。
• Logger，同步日誌類，用於建立同步日誌例項，同步呼叫ReliabilityStrategy處理日誌。
• AsyncLogger，非同步日誌類，用於建立非同步日誌例項，內部使用Disruptor佇列實現非同步呼叫ReliabilityStrategy處理日誌。

總的來說，<Logger>標籤和Logger類是完全不同的兩個概念，<AsyncLogger>標籤和AsyncLogger類也是完全不同的兩個概念，不可混淆。

由於專案並未配置Log4jContextSelector引數，所以使用的是同步Logger，即透過LoggerFactory.getLogger方法獲取的是Logger類例項而不是AsyncLogger類例項，同時由於專案的log4j2.xml配置檔案裡配置了<AsyncLogger>標籤，所以其底層是Logger和AsyncLoggerConfig組合。

AsyncLoggerConfig處理日誌事件簡要流程如下圖25所示，內部使用Disruptor佇列，在生成佇列元素時，由translator來負責填充元素欄位，並把填充後的元素放入RingBuffer中，於此同時，獨立的非同步執行緒從RingBuffer中消費事件，並呼叫配置在該AsyncLoggerConfig上的Appender處理日誌請求。

圖25 AsyncLoggerConfig處理流程

AsyncLoggerConfig提供了帶有Disruptor佇列實現的代理類即AsyncLoggerConfigDisruptor，在日誌事件進入RingBuffer時，由於專案使用的是ReusableLogEventFactory，所以由MUTABLE_TRANSLATOR負責初始化日誌事件，在此過程中會呼叫getThrownProxy方法建立ThrowableProxy例項，進而在ThrowableProxy建構函式內部觸發解析、載入異常堆疊類。

// org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$EventTranslatorTwoArg

/**
 * Object responsible for passing on data to a RingBuffer event with a MutableLogEvent.
 */
private static final EventTranslatorTwoArg<Log4jEventWrapper, LogEvent, AsyncLoggerConfig> MUTABLE_TRANSLATOR =
        new EventTranslatorTwoArg<Log4jEventWrapper, LogEvent, AsyncLoggerConfig>() {

    @Override
    public void translateTo(final Log4jEventWrapper ringBufferElement, final long sequence,
            final LogEvent logEvent, final AsyncLoggerConfig loggerConfig) {
      	// 初始化 Disruptor RingBuffer 日誌元素欄位
        ((MutableLogEvent) ringBufferElement.event).initFrom(logEvent);
        ringBufferElement.loggerConfig = loggerConfig;
    }
};

// org.apache.logging.log4j.core.impl.MutableLogEvent

public void initFrom(final LogEvent event) {
    this.loggerFqcn = event.getLoggerFqcn();
    this.marker = event.getMarker();
    this.level = event.getLevel();
    this.loggerName = event.getLoggerName();
    this.timeMillis = event.getTimeMillis();
    this.thrown = event.getThrown();
  	// 觸發建立 ThrowableProxy 例項
    this.thrownProxy = event.getThrownProxy();

    // NOTE: this ringbuffer event SHOULD NOT keep a reference to the specified
    // thread-local MutableLogEvent's context data, because then two threads would call
    // ReadOnlyStringMap.clear() on the same shared instance, resulting in data corruption.
    this.contextData.putAll(event.getContextData());

    this.contextStack = event.getContextStack();
    this.source = event.isIncludeLocation() ? event.getSource() : null;
    this.threadId = event.getThreadId();
    this.threadName = event.getThreadName();
    this.threadPriority = event.getThreadPriority();
    this.endOfBatch = event.isEndOfBatch();
    this.includeLocation = event.isIncludeLocation();
    this.nanoTime = event.getNanoTime();
    setMessage(event.getMessage());
}

@Override
public ThrowableProxy getThrownProxy() {
    if (thrownProxy == null && thrown != null) {
      	// 構造 ThrowableProxy 時列印異常堆疊
        thrownProxy = new ThrowableProxy(thrown);
    }
    return thrownProxy;
}

3.4.6 問題小結

Log4j2列印異常日誌時，AsyncLoggerConfig會初始化Disruptor RingBuffer日誌元素欄位，並進一步觸發解析、載入異常堆疊類。JVM透過生成位元組碼的方式最佳化反射呼叫效能，但該動態生成的類無法被WebAppClassLoader類載入器載入，因此當大量包含反射呼叫的異常堆疊被輸出到日誌時，會頻繁地觸發類載入，由於類載入過程是synchronized同步加鎖的，且每次載入都需要讀取檔案，速度較慢，從而導致執行緒Block。

4. 避坑指南

本章節主要對上述案例中導致執行緒Block的原因進行彙總分析，並給出相應的解決方案。

4.1 問題總結

圖26 日誌非同步處理流程

日誌非同步處理流程示意如圖26所示，整體步驟如下：

1. 業務執行緒組裝日誌事件物件，如建立日誌快照或者初始化日誌欄位等。
2. 日誌事件物件入隊，如BlockingQueue佇列或Disruptor RingBuffer佇列等。
3. 日誌非同步執行緒從佇列獲取日誌事件物件，並輸出至目的地，如本地磁碟檔案或遠端日誌中心等。

對應地，Log4j2導致執行緒Block的主要潛在風險點如下：

1. 如上圖示號①所示，日誌事件物件在入隊前，組裝日誌事件時觸發了異常堆疊類解析、載入，從而引發執行緒Block。
2. 如上圖示號②所示，日誌事件物件在入隊時，由於佇列滿，無法入隊，從而引發執行緒Block。
3. 如上圖示號③所示，日誌事件物件在出隊後，對日誌內容進行格式化處理時觸發了異常堆疊類解析、載入，從而引發執行緒 Block。

從上述分析不難看出：

1. 標號①和②處如果發生執行緒Block，那麼會直接影響業務執行緒池內的所有執行緒。
2. 標號③出如果發生執行緒Block，那麼會影響日誌非同步執行緒，該執行緒通常為單執行緒。

標號①和②處發生執行緒Block的影響範圍遠比標號③更大，因此核心是要避免日誌事件在入隊操作完成前觸發執行緒Block。其實日誌非同步執行緒通常是單執行緒，因此對於單個Appender來說，不會出現Block現象，至多會導致非同步執行緒處理速度變慢而已，但如果存在多個非同步Appender，那麼多個日誌非同步執行緒仍然會出現彼此Block的現象。

4.2 對症下藥

搞清楚了日誌導致執行緒Block的原因後，問題也就不難解決，解決方案主要從日誌事件“入隊前”、“入隊時”和“出隊後”三方面展開。

4.2.1 入隊前避免執行緒Block

結合上文分析的“AsyncAppender導致執行緒Block”、“Lambda表示式導致執行緒Block”和“AsyncLoggerConfig導致執行緒Block”案例，日誌事件入隊前避免執行緒Block的解決方案可從如下幾方面考慮：

1. 日誌事件入隊前避免觸發異常堆疊類解析、載入操作。
2. 禁用JVM反射呼叫最佳化。
3. 升級JDK版本修復Lambda類Bug。

先說方案結論：

1. 自定義Appender實現，建立日誌事件快照時避免觸發異常堆疊類解析、載入，美團內部Scribe-Log提供的AsyncScribeAppender即是如此。
2. 日誌配置檔案中不使用<AsyncLogger>標籤，可以使用<Logger>標籤來代替。

下面具體分析方案可行性：

1. 日誌事件入隊前避免觸發異常堆疊類解析、載入操作

如果在日誌事件入隊前，能避免異常堆疊類解析、載入操作，則可從根本上解決該問題，但在Log4j2的2.17.1版本中AsyncAppender和AsyncLoggerConfig仍存在該問題，此時：

• 對於AsyncAppender場景來說，可以透過自定義Appender實現，在生成日誌事件快照時避免觸發解析、載入異常堆疊類，並在配置檔案中使用自定義的Appender代替Log4j2提供的AsyncAppender。自定義AsyncScribeAppender相關程式碼片段如下。

// org.apache.logging.log4j.scribe.appender.AsyncScribeAppender

@Override
public void append(final LogEvent logEvent) {
    // ... 以上部分忽略 ...
    Log4jLogEvent.Builder builder = new Log4jLogEvent.Builder(event);
    builder.setIncludeLocation(includeLocation);
    // 建立日誌快照，避免解析、載入異常堆疊類
    final Log4jLogEvent memento = builder.build();
    // ... 以下部分忽略 ...
}

• 對於AsyncLoggerConfig場景來說，可以考慮使用非ReusableLogEventFactory型別的LogEventFactory來規避該問題，除此之外也可以考慮換用LoggerConfig來避免該問題。

2. 禁用JVM反射呼叫最佳化

調大inflationThreshold（其型別為 int）值到int最大值，如此，雖然一定範圍內（反射呼叫次數不超過int最大值時）避免了類載入Block問題，但損失了反射呼叫效能，顧此失彼，且無法根治。另外，對於非反射類問題仍然無法解決，如上文所述的Lambda表示式問題等。

3. 升級JDK版本修復Lambda類Bug

升級JDK版本的確可以解決Lambda表示式問題，但並不能徹底解決執行緒Block問題，如上文所述的反射呼叫等。

4.2.2 入隊時避免執行緒Block

結合上文分析的“日誌佇列滿導致執行緒Block”案例，日誌事件入隊時避免執行緒Block的解決方案可從如下幾方面考慮：

1. 日誌佇列滿時，Appender忽略該日誌。
2. Appender使用自定義的ErrorHandler實現處理日誌。
3. 關閉StatusConfigListener日誌輸出。

先說方案結論：自定義Appender實現，日誌事件入隊失敗時忽略錯誤日誌，美團內部Scribe-Log提供的AsyncScribeAppender即是如此。

下面具體分析方案可行性：

1. 日誌佇列滿時Appender忽略該日誌

日誌佇列滿，某種程度上說明日誌執行緒的處理能力不足，在現有機器資源不變的情況下需要做一定取捨，如果日誌不是特別重要通常可丟棄該日誌，此時：

• 對於AsyncAppender在blocking場景來說，可以透過配置log4j2.AsyncQueueFullPolicy=Discard來使用DISCARD策略忽略日誌。
• 對於AsyncAppender在非blocking場景來說，可以透過自定義Appender實現，在日誌事件入隊失敗後直接忽略錯誤日誌，並在配置檔案中使用自定義的Appender代替Log4j2提供的AsyncAppender。自定義AsyncScribeAppender相關程式碼片段如下。

// org.apache.logging.log4j.scribe.appender.AsyncScribeAppender

@Override
public void append(final LogEvent logEvent) {
		// ... 以上部分忽略 ...
    if (!transfer(memento)) {
        if (blocking) {
            // delegate to the event router (which may discard, enqueue and block, or log in current thread)
            final EventRouteAsyncScribe route = asyncScribeQueueFullPolicy.getRoute(processingThread.getId(), memento.getLevel());
            route.logMessage(this, memento);
        } else {
          	// 自定義printDebugInfo引數，控制是否輸出error資訊，預設為false
            if (printDebugInfo) {
                error("Appender " + getName() + " is unable to write primary appenders. queue is full");
            }
            logToErrorAppenderIfNecessary(false, memento);
        }
    }
		// ... 以下部分忽略 ...
}

2. Appender使用自定義的ErrorHandler實現處理日誌

自定義ErrorHandler，Appender內設定handler為自定義ErrorHandler例項即可，但該方式僅適用於透過Log4j2 API方式建立的Logger，不支援日誌配置檔案的使用方式。由於大多數使用者都使用配置檔案方式，所以該方案使用場景有限，不過可以期待後續日誌框架支援配置檔案自定義ErrorHandler，已有相關Issue: ErrorHandlers on Appenders cannot be configured反饋給社群。

3. 關閉StatusConfigListener日誌輸出

• 配置檔案中設定Configuration的status屬性值為off，則不會建立StatusConfigListener，但此時StatusLogger會呼叫SimpleLogger來輸出日誌到System.err，仍不解決問題。
• 配置檔案中設定Configuration的status屬性值為fatal，則只有fatal級別的日誌才會輸出，普通的error日誌直接忽略，但fatal條件過於嚴苛，可能會忽略一些重要的error日誌。

4.2.3 出隊後避免執行緒Block

日誌事件出隊後會按照使用者配置的輸出樣式，對日誌內容進行格式化轉換，此時仍然可能觸發解析、載入異常堆疊類。因此，日誌出隊後避免執行緒Block的根本解決方法是在異常格式化轉換時避免解析、載入異常堆疊類。

先說方案結論：顯式配置日誌輸出樣式%ex來代替預設的%xEx，避免對日誌內容格式化時解析、載入異常堆疊類。

下面透過分析日誌內容格式化處理流程來介紹解決方案。以PatternLayout為例，日誌內容格式化轉換流程鏈路為：Layout->PatternFormatter->LogEventPatternConverter。其中LogEventPatternConverter是個抽象類，有兩個處理異常的格式化轉換具體實現類，分別是ThrowablePatternConverter和ExtendedThrowablePatternConverter。

// org.apache.logging.log4j.core.layout.PatternLayout

// 將 LogEvent 轉換為可以輸出的 String
@Override
public String toSerializable(final LogEvent event) {
  	// 由 PatternSerializer 對日誌事件格式化處理
    return eventSerializer.toSerializable(event);
}

// org.apache.logging.log4j.core.layout.PatternLayout.PatternSerializer

@Override
public String toSerializable(final LogEvent event) {
    final StringBuilder sb = getStringBuilder();
    try {
        return toSerializable(event, sb).toString();
    } finally {
        trimToMaxSize(sb);
    }
}

@Override
public StringBuilder toSerializable(final LogEvent event, final StringBuilder buffer) {
    final int len = formatters.length;
    for (int i = 0; i < len; i++) {
    		// 由 PatternFormatter 對日誌事件格式化處理
        formatters[i].format(event, buffer);
    }
    if (replace != null) { // creates temporary objects
        String str = buffer.toString();
        str = replace.format(str);
        buffer.setLength(0);
        buffer.append(str);
    }
    return buffer;
}

// org.apache.logging.log4j.core.pattern.PatternFormatter

public void format(final LogEvent event, final StringBuilder buf) {
    if (skipFormattingInfo) {
      	// 由 LogEventPatternConverter 對日誌事件進行格式化處理
        converter.format(event, buf);
    } else {
        formatWithInfo(event, buf);
    }
}

private void formatWithInfo(final LogEvent event, final StringBuilder buf) {
    final int startField = buf.length();
  	// 由 LogEventPatternConverter 對日誌事件進行格式化處理
    converter.format(event, buf);
    field.format(startField, buf);
}

// org.apache.logging.log4j.core.pattern.LogEventPatternConverter

public abstract class LogEventPatternConverter extends AbstractPatternConverter {

    /**
     * 將日誌事件 LogEvent 轉換為 String
     * Formats an event into a string buffer.
     *
     * @param event      event to format, may not be null.
     * @param toAppendTo string buffer to which the formatted event will be appended.  May not be null.
     */
    public abstract void format(final LogEvent event, final StringBuilder toAppendTo);

}

日誌框架對異常進行格式化轉換時，有如下兩個配置項可參考，預設配置是%xEx。

1. %ex，僅輸出異常資訊，不獲取擴充套件資訊（jar檔名稱和版本資訊）

對應的格式轉化類是ThrowablePatternConverter，在format方法內部並沒有獲取ThrowableProxy物件，所以不會觸發解析、載入異常堆疊類。

// org.apache.logging.log4j.core.pattern.ThrowablePatternConverter

@Plugin(name = "ThrowablePatternConverter", category = PatternConverter.CATEGORY)
@ConverterKeys({ "ex", "throwable", "exception" })
public class ThrowablePatternConverter extends LogEventPatternConverter {

    /**
     * {@inheritDoc}
     */
    @Override
    public void format(final LogEvent event, final StringBuilder buffer) {
        final Throwable t = event.getThrown();

        if (isSubShortOption()) {
            formatSubShortOption(t, getSuffix(event), buffer);
        }
        else if (t != null && options.anyLines()) {
            formatOption(t, getSuffix(event), buffer);
        }
    }

    private boolean isSubShortOption() {
        return ThrowableFormatOptions.MESSAGE.equalsIgnoreCase(rawOption) ||
                ThrowableFormatOptions.LOCALIZED_MESSAGE.equalsIgnoreCase(rawOption) ||
                ThrowableFormatOptions.FILE_NAME.equalsIgnoreCase(rawOption) ||
                ThrowableFormatOptions.LINE_NUMBER.equalsIgnoreCase(rawOption) ||
                ThrowableFormatOptions.METHOD_NAME.equalsIgnoreCase(rawOption) ||
                ThrowableFormatOptions.CLASS_NAME.equalsIgnoreCase(rawOption);
    }

    private void formatSubShortOption(final Throwable t, final String suffix, final StringBuilder buffer) {
        StackTraceElement[] trace;
        StackTraceElement throwingMethod = null;
        int len;

        if (t != null) {
            trace = t.getStackTrace();
            if (trace !=null && trace.length > 0) {
                throwingMethod = trace[0];
            }
        }

        if (t != null && throwingMethod != null) {
            String toAppend = Strings.EMPTY;

            if (ThrowableFormatOptions.CLASS_NAME.equalsIgnoreCase(rawOption)) {
                toAppend = throwingMethod.getClassName();
            }
            else if (ThrowableFormatOptions.METHOD_NAME.equalsIgnoreCase(rawOption)) {
                toAppend = throwingMethod.getMethodName();
            }
            else if (ThrowableFormatOptions.LINE_NUMBER.equalsIgnoreCase(rawOption)) {
                toAppend = String.valueOf(throwingMethod.getLineNumber());
            }
            else if (ThrowableFormatOptions.MESSAGE.equalsIgnoreCase(rawOption)) {
                toAppend = t.getMessage();
            }
            else if (ThrowableFormatOptions.LOCALIZED_MESSAGE.equalsIgnoreCase(rawOption)) {
                toAppend = t.getLocalizedMessage();
            }
            else if (ThrowableFormatOptions.FILE_NAME.equalsIgnoreCase(rawOption)) {
                toAppend = throwingMethod.getFileName();
            }

            len = buffer.length();
            if (len > 0 && !Character.isWhitespace(buffer.charAt(len - 1))) {
                buffer.append(' ');
            }
            buffer.append(toAppend);

            if (Strings.isNotBlank(suffix)) {
                buffer.append(' ');
                buffer.append(suffix);
            }
        }
    }

    private void formatOption(final Throwable throwable, final String suffix, final StringBuilder buffer) {
        final StringWriter w = new StringWriter();

        throwable.printStackTrace(new PrintWriter(w));
        final int len = buffer.length();
        if (len > 0 && !Character.isWhitespace(buffer.charAt(len - 1))) {
            buffer.append(' ');
        }
        if (!options.allLines() || !Strings.LINE_SEPARATOR.equals(options.getSeparator()) || Strings.isNotBlank(suffix)) {
            final StringBuilder sb = new StringBuilder();
            final String[] array = w.toString().split(Strings.LINE_SEPARATOR);
            final int limit = options.minLines(array.length) - 1;
            final boolean suffixNotBlank = Strings.isNotBlank(suffix);
            for (int i = 0; i <= limit; ++i) {
                sb.append(array[i]);
                if (suffixNotBlank) {
                    sb.append(' ');
                    sb.append(suffix);
                }
                if (i < limit) {
                    sb.append(options.getSeparator());
                }
            }
            buffer.append(sb.toString());

        } else {
            buffer.append(w.toString());
        }
    }

    /**
     * This converter obviously handles throwables.
     *
     * @return true.
     */
    @Override
    public boolean handlesThrowable() {
        return true;
    }

    protected String getSuffix(final LogEvent event) {
        //noinspection ForLoopReplaceableByForEach
        final StringBuilder toAppendTo = new StringBuilder();
        for (int i = 0, size = formatters.size(); i <  size; i++) {
            formatters.get(i).format(event, toAppendTo);
        }
        return toAppendTo.toString();
    }

    public ThrowableFormatOptions getOptions() {
        return options;
    }
}

2. %xEx，不僅輸出異常資訊，同時獲取擴充套件資訊

對應的格式轉化類是ExtendedThrowablePatternConverter，在format方法內部獲取了ThrowableProxy物件，此時一定會觸發解析、載入異常堆疊類。

// org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter

@Plugin(name = "ExtendedThrowablePatternConverter", category = PatternConverter.CATEGORY)
@ConverterKeys({ "xEx", "xThrowable", "xException" })
public final class ExtendedThrowablePatternConverter extends ThrowablePatternConverter {

    /**
     * {@inheritDoc}
     */
    @Override
    public void format(final LogEvent event, final StringBuilder toAppendTo) {
      	// 獲取 ThrowableProxy 物件，觸發解析、載入異常堆疊類
        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 String extStackTrace = proxy.getExtendedStackTraceAsString(options.getIgnorePackages(),
                    options.getTextRenderer(), getSuffix(event), options.getSeparator());
            final int len = toAppendTo.length();
            if (len > 0 && !Character.isWhitespace(toAppendTo.charAt(len - 1))) {
                toAppendTo.append(' ');
            }
            toAppendTo.append(extStackTrace);
        }
    }

}

5. 最佳實踐

本章節主要結合專案在日誌使用方面的一系列踩坑經歷和實踐經驗，總結了一份關於日誌配置的最佳實踐，供大家參考。

1. 建議日誌配置檔案中對所有Appender的PatternLayout都增加%ex配置，因為如果沒有顯式配置%ex，則異常格式化輸出的預設配置是%xEx，此時會列印異常的擴充套件資訊（JAR名稱和版本），可能導致業務執行緒Block。
2. 不建議日誌配置檔案中使用AsyncAppender，建議自定義Appender實現，因為AsyncAppender是日誌框架預設提供的，目前最新版本中仍然存在日誌事件入隊前就觸發載入異常堆疊類的問題，可能導致業務執行緒Block。
3. 不建議生產環境使用ConsoleAppender，因為輸出日誌到Console時有synchronized同步操作，高併發場景下非常容易導致業務執行緒Block。
4. 不建議在配置檔案中使用<AsyncLogger>標籤，因為日誌事件元素在入隊前就會觸發載入異常堆疊類，可能導致業務執行緒Block。如果希望使用Log4j2提供的非同步日誌AsyncLogger，建議配置Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector引數，開啟非同步日誌。

下面提供一份log4j2.xml配置示例：

<configuration status="warn">
    <appenders>
        <Console name="Console" target="SYSTEM_OUT" follow="true">
            <PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} %t [%p] %c{1} (%F:%L) %msg%n %ex" />
        </Console>

        <XMDFile name="ShepherdLog" fileName="shepherd.log">
          	<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} %t [%p] %c{1} (%F:%L) %msg%n %ex" />
	      </XMDFile>

        <!--XMDFile非同步磁碟日誌配置示例-->
        <!--預設按天&按512M檔案大小切分日誌，預設最多保留30個日誌檔案。-->
        <!--注意：fileName前會自動增加檔案路徑，只配置檔名即可-->
        <XMDFile name="LocalServiceLog" fileName="request.log">
	          <PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} %t [%p] %c{1} (%F:%L) %msg%n %ex" />
	      </XMDFile>
  			
      	<!-- 使用自定義的AsyncScribeAppender代替原有的AsycncAppender -->
        <AsyncScribe name="LogCenterAsync" blocking="false">
            <!-- 在指定日誌名方面，scribeCategory 和 appkey 兩者至少存在一種，且 scribeCategory 高於 appkey。-->
            <!-- <Property name="scribeCategory">data_update_test_lc</Property> -->
           <LcLayout/>
        </AsyncScribe>
    </appenders>

    <loggers>
        <logger name="com.sankuai.shepherd" level="info" additivity="false">
            <AppenderRef ref="ShepherdLog" level="warn"/>
            <AppenderRef ref="LogCenterAsync" level="info"/>
        </logger>

        <root level="info">
            <!--Console日誌是同步、阻塞的，推薦只在本地除錯時使用，線上將該配置去掉-->
            <!--appender-ref ref="Console" /-->
            <appender-ref ref="LocalServiceLog"/>
            <appender-ref ref="LogCenterAsync"/>
        </root>
    </loggers>
</configuration>