java日志导致线程Block的这些坑，你不得不防
Posted 九师兄
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了java日志导致线程Block的这些坑，你不得不防相关的知识，希望对你有一定的参考价值。
1.概述
- 前言
日志对程序的重要性不言而喻。它很“大”，我们在项目中经常通过日志来记录信息和排查问题，相关代码随处可见。它也很“小”，作为辅助工具，日志使用简单、上手快，我们通常不会花费过多精力耗在日志上。但看似不起眼的日志也隐藏着各种各样的“坑”，如果使用不当，它不仅不能帮助我们，反而还可能降低服务性能，甚至拖垮我们的服务。
日志导致线程Block的问题，相信你或许已经遇到过，对此应该深有体会；或许你还没遇到过，但不代表没有问题，只是可能还没有触发而已。本文主要介绍美团统一API网关服务Shepherd（参见《百亿规模API网关服务Shepherd的设计与实现》一文）在实践中所踩过的关于日志导致线程Block的那些“坑”，然后再分享一些避“坑”经验。
- 背景
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="%dyyyy/MM/dd HH:mm:ss.SSS %t [%p] %c1 (%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>
- 踩过的坑
本章节主要记录项目过去一段时间，我们所遇到的一系列日志导致的线程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日志文件的现象，初步怀疑是日志量过大导致了线程阻塞。
但上述猜测仍有一些值得推敲的地方：
如果仅仅因为日志量过大就导致线程Block，那日志框架也太不堪重用了，根本没法在高并发、高吞吐业务场景下使用。
日志配置里明明是输出日志到文件，怎么会输出到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 %c1. [%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().以上是关于java日志导致线程Block的这些坑，你不得不防的主要内容，如果未能解决你的问题，请参考以下文章