关于日志分析:日志导致线程Block的这些坑你不得不防

研发人员在我的项目开发中不可避免地要应用日志，通过它来记录信息和排查问题。Apache Log4j2 提供了灵便且弱小的日志框架，尽管上手比拟快，但稍有不慎也非常容易踩“坑”。本文介绍了美团对立 API 网关服务 Shepherd 在实践中所踩过的对于日志导致线程 Block 的那些“坑”，以及咱们如何从日志框架源码层面进行剖析和解决问题的过程，并在最初给大家分享一些对于日志避“坑”的实践经验，心愿能给大家带来一些帮忙。

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 名称，负责上报日志到近程日志核心。

随着业务的快速增长，日志导致的线程 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 所示。

从 Blocked 线程堆栈不难看出这跟日志打印相干，而且是 INFO 级别的日志，遂即登陆机器查看日志是否有同样，发现过后日志量十分大，差不多每两分钟就写满一个 500MB 的日志文件。

那大量输入日志和线程 Block 之间会有怎么的关联呢？接下来本章节将联合如下图 4 所示的调用链路深入分析线程 Block 的根因。

3.1.2 为什么会 Block 线程？

从 Blocked 线程堆栈着手剖析，查看 PrintStream 相干代码片段如下图 5 所示，能够看到被阻塞中央有 synchronized 同步调用，再联合上文发现每两分钟写满一个 500MB 日志文件的景象，初步狐疑是日志量过大导致了线程阻塞。

但上述猜想仍有一些值得斟酌的中央：

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 所示。

从 Blocked 线程堆栈不难看出是跟日志打印相干，因为是 ERROR 级别日志，查看具体报错日志，发现有两种业务异样，别离如下图 8 和图 9 所示：

这些业务异样会是导致线程 Block 的幕后首恶吗？接下来本章节将联合如下图 10 所示的调用链路深入分析线程 Block 的根因。

3.2.2 为什么会 Block 线程？

从 Blocked 线程堆栈中能够看出，线程阻塞在类加载流程上，查看 WebAppClassLoader 相干代码片段如下图 11 所示，发现加载类时的确会依据类名来加 synchronized 同步块，因而初步猜想是类加载导致线程 Block。

但上述猜想还有一些值得斟酌的中央：

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 所示的两份业务异样堆栈，咱们能够看到两份堆栈根本类似，且大多数类都是很一般的类，然而惟一不同的中央在于：

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 的外部代理对象指向字节码生成类实例，从而扭转后续反射调用逻辑。

// 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 为什么要解析异样堆栈？

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 所示：

从 Blocked 线程堆栈不难看出是和日志打印相干，因为是 ERROR 级别日志，查看具体报错日志，发现如下图 18 所示的业务异样。

本案例的 Blocked 线程堆栈和上述“AsyncAppender 导致线程 Block”案例一样，那么导致线程 Block 的罪魁祸首会是业务异样吗？接下来本章节将联合下图 19 所示的调用链路深入分析线程 Block 的根因。

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 所示：

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 所示：

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 所示。

从 Blocked 线程堆栈不难看出是和日志打印相干，本案例的业务异样和上述“AsyncAppender 导致线程 Block”的业务异样一样，这里不再反复介绍。

那么，到底是什么起因导致线程 Block 呢？接下来本章节将联合下图 24 所示的调用链路深入分析线程 Block 的根因。

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 解决日志申请。

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 所示，整体步骤如下：

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>

6. 作者简介

志洋、陈超、李敏、凯晖、殷琦等，均来自美团根底技术部 - 利用中间件团队。

7. 招聘信息

美团根底技术部 - 基础架构团队诚招高级、资深技术专家，Base 北京、上海。咱们致力于建设美团全公司对立的高并发高性能分布式基础架构平台，涵盖数据库、分布式监控、服务治理、高性能通信、消息中间件、根底存储、容器化、集群调度等基础架构次要的技术畛域。欢送有趣味的同学投送简历至：edp.itu.zhaopin@meituan.com。

浏览美团技术团队更多技术文章合集

前端 | 算法 | 后端 | 数据 | 平安 | 运维 | iOS | Android | 测试

| 在公众号菜单栏对话框回复【2021 年货】、【2020 年货】、【2019 年货】、【2018 年货】、【2017 年货】等关键词，可查看美团技术团队历年技术文章合集。

| 本文系美团技术团队出品，著作权归属美团。欢送出于分享和交换等非商业目标转载或应用本文内容，敬请注明“内容转载自美团技术团队”。本文未经许可，不得进行商业性转载或者应用。任何商用行为，请发送邮件至 tech@meituan.com 申请受权。