Log4j2打印INFO日志导致线程Block

前言

​ 随着业务的快速增长，日志导致的线程 Block 问题愈发频繁。比如调用后端 RPC 服务超时，导致调用方大量线程 Block；再比如，业务内部输出异常日志导致服务大量线程 Block 等，这些问题严重影响着服务的稳定性。

日志队列满导致线程 Block

​ 通过监控平台查看线程监控指标， Blocked 线程堆栈不难看出这跟日志打印相关，而且是 INFO 级别的日志，遂即登陆机器查看日志是否有异样，发现当时日志量非常大，差不多每两分钟就写满一个500MB 的日志文件。

为什么会 Block 线程

​ 从 Blocked 线程堆栈着手分析，可以看到被阻塞地方有 synchronized 同步调用，再结合上文发现每两分钟写满一个500MB 日志文件的现象，初步怀疑是日志量过大导致了线程阻塞。

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

1. 如果仅仅因为日志量过大就导致线程 Block，那日志框架也太不堪重用了，根本没法在高并发、高吞吐业务场景下使用。

2. 日志配置里明明是输出日志到文件，怎么会输出到 Console PrintStream ？

为什么会输出到 Console

​ 继续沿着线程堆栈调用链路分析，可以看出是 AsyncAppender 调用 append 方法追加日志时发生了错误。

​ AsyncAppender 顾名思义是个异步 Appender，采用异步方式处理日志，在其内部维护了一个 BlockingQueue 队列，每次处理日志时，都先尝试把 Log4jLogEvent事件存入队列中，然后交由后台线程从队列中取出事件并处理（把日志交由 AsyncAppender 所关联的 Appender 处理），但队列长度总是有限的，且队列默认大小是128，如果日志量过大或日志异步线程处理不及时，就很可能导致日志队列被打满。

​ 在本项目的日志配置文件中可以看到，AsyncAppender 设置了 blocking 为 false，且没有配置 error-ref

当日志队列满时，日志框架内部提供了两种处理方式，具体如下：

● 如果 blocking 配置为 true，会选择相应的处理策略，默认是 SYNCHRO-NOUS 策略，可以在 log4j2.component.properties 文件中，通过 log4j2.AsyncQueueFullPolicy 参数配置日志框架提供的其他策略或自定义策略。

○ DISCARD 策略，直接忽略日志。

○ SYNCHRONOUS 策略，当前线程直接发送日志到 Appender。

○ ENQUEUE 策略，强制阻塞入队。

● 如果 blocking 配置为 false，则由 ErrorHandler 和 ErrorAppender 处理失败日志。日志框架提供了默认的 ErrorHandler 实现，即 DefaultErrorHandler，目前暂不支持业务在 XML、JSON 等日志配置文件里自定义 ErrorHandler。日志框架默认不提供 ErrorAppender，业务如有需要可在 XML、JSON 等日志配置文件里自定义 error-ref 配置。

​ 从上述 DefaultErrorHandler 代码中可以看到，真正负责处理日志的是 StatusLogger，继续跟进代码进入 logMessage 方法，方法执行逻辑如下：

● 如果 StatusLogger 内部注册了 StatusListener，则由对应的 StatusListener 负责处理日志。

● 否则由 SimpleLogger 负责处理日志，直接输出日志到 System.err 输出流。

​ DefaultErrorHandler 内部在处理异常日志时增加了条件限制，只有下述两个条件任一满足时才会处理，从而避免大量异常日志导致的性能问题。

● 两条日志处理间隔超过 5min。

● 异常日志数量不超过 3 次。但项目所用日志框架版本的默认实现看起来存在一些不太合理的地方：

● lastException 用于标记上次异常的时间戳，该变量可能被多线程访问，无法保证多线程情况下的线程安全。

● exceptionCount 用于统计异常日志次数，该变量可能被多线程访问，无法保证多线程情况下的线程安全。

​ 所以，在多线程场景下，可能有大量异常日志同时被 DefaultErrorHandler 处理，带来线程安全问题。值得一提的是，该问题在 2.15.0 版本中进行了修复。

​ 从上述 Blocked 线程堆栈来看，是 StatusConsoleListener 负责处理日志，而StatusConsoleListener 是 StatusListener 接 口 的 实 现 类。

StatusConsoleListener 是怎么来的

​ 通常来说，每个项目都会有一个日志配置文件（如 log4j2.xml），该配置对应 Log4j2日志框架中的 Configuration 接口，不同的日志配置文件格式有不同的实现类：

● XmlConfiguration，即 XML 格式日志配置

● JsonConfiguration，即 JSON 格式日志配置

​ 以log4j2.xml 示例配置，Log4j2 在启动时会加载并解析 log4j2.xml 配置文件，由对应的 ConfigurationFactory 创建具体 Configuration 实例。

​ 创建 XmlConfiguration 时， 会 先 创 建 StatusConfiguration， 随 后 在 初 始 化StatusConfiguration 时创建并注册 StatusConsoleListener 到 StatusLogger 的listeners 中，日志配置文件中 标签的属性值通过 XmlConfiguration->StatusConfiguration->StatusConsoleListener 这样的关系链路最终影响StatusConsoleListener 的行为。

​ StatusLogger 采用单例模式实现，它输出日志到 Console（如 System.out 或 System.err），从上文分析可知，在高并发场景下非常容易导致线程 Block。

日志配置文件中的 标签可以配置属性字段，部分字段如下所示：

● status，可选值包括 OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、ALL，该值决定 StatusConsoleListener 级别，默认是 ERROR。

● dest，可选值包括 out、err、标准的 URI 路径，该值决定 StatusConsoleListener 输出流目的地，默认是 System.out。

​ 在本项目的日志配置文件中可以看到并没有设置 Configuration 的 dest 属性值，所以日志直接输出到 System.out

StatusLogger 有什么用

​ StatusLogger 在交由 StatusListener 处理日志前，会判断日志级别，如果级别条件不满足，则忽略此日志，StatusConsoleListener 的日志级别默认是 ERROR。

问题小结

​ 日志量过大导致 AsyncAppender 日志队列被打满，新的日志事件无法入队，进而由 ErrorHandler 处理日志，同时由于 ErrorHandler 存在线程安全问题，导致大量日志输出到了 Console，而 Console 在输出日志到 PrintStream 输出流时，存在synchronized 同步代码块，所以在高并发场景下导致线程 Block。一定要设置 Configuration 的 dest 属性值。