线程 Block汇总分析

线程 Block汇总分析

问题总结

日志异步处理流程示意如图 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的现象。

对症下药

​ 搞清楚了日志导致线程 Block 的原因后，问题也就不难解决，解决方案主要从日志事件“入队前”、“入队时”和“出队后”三方面展开

入队前避免线程 Block

​ 结合之前分析的“AsyncAppender 导致线程 Block”、“Lambda 表达式导致线程Block”和“AsyncLoggerConfig 导致线程 Block”案例，日志事件入队前避免线程 Block 的解决方案可从如下几方面考虑：

1. 日志事件入队前避免触发异常堆栈类解析、加载操作。

2. 禁用 JVM 反射调用优化。

3. 升级 JDK 版本修复 Lambda 类 Bug。

方案结论

1. 自定义 Appender 实现，创建日志事件快照时避免触发异常堆栈类解析、加载，美团内部 Scribe-Log 提供的 AsyncScribeAppender 即是如此。

2. 日志配置文件中不使用 AsyncLogger标签，可以使用 Logger标签来代替

分析方案可行性：

1. 日志事件入队前避免触发异常堆栈类解析、加载操作

2. 禁用 JVM 反射调用优化。

​ 调大 inflationThreshold（其类型为 int）值到 int 最大值，如此，虽然一定范围内（反射调用次数不超过 int 最大值时）避免了类加载 Block 问题，但损失了反射调用性能，顾此失彼，且无法根治。

3. 升级 JDK 版本修复 Lambda 类 Bug

​ 升级 JDK 版本的确可以解决 Lambda 表达式问题，但并不能彻底解决线程 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。

2. Appender 使用自定义的 ErrorHandler 实现处理日志

​ 自定义 ErrorHandler，Appender 内设置 handler 为自定义 ErrorHandler 实例即可，但该方式仅适用于通过 Log4j2 API 方式创建的 Logger，不支持日志配置文件的使用方式。由于大多数用户都使用配置文件方式，所以该方案使用场景有限，不过可以期待后续日志框架支持配置文件自定义 ErrorHandler.

3. 关闭 StatusConfigListener 日志输出

● 配置文件中设置 Configuration 的 status 属性值为 off，则不会创建 StatusConfigListener，但此时 StatusLogger 会调用 SimpleLogger 来输出日志到System.err，仍不解决问题。

● 配置文件中设置 Configuration 的 status 属性值为 fatal，则只有 fatal 级别的日志才会输出，普通的 error 日志直接忽略，但 fatal 条件过于严苛，可能会忽略一些重要的 error 日志

出队后避免线程 Block

​ 日志事件出队后会按照用户配置的输出样式，对日志内容进行格式化转换，此时仍然可能触发解析、加载异常堆栈类。因此，日志出队后避免线程 Block 的根本解决方法是在异常格式化转换时避免解析、加载异常堆栈类.

方案结论：

​ 显式配置日志输出样式 %ex 来代替默认的 %xEx，避免对日志内容格式化时解析、加载异常堆栈类。

分析方案可行性：

1. %ex，仅输出异常信息，不获取扩展信息（jar 文件名称和版本信息）

​ 对应的格式转化类是 ThrowablePatternConverter，在 format 方法内部并没有获取ThrowableProxy 对象，所以不会触发解析、加载异常堆栈类。

2. %xEx，不仅输出异常信息，同时获取扩展信息。

​ 对应的格式转化类是 ExtendedThrowablePatternConverter，在 format 方法内部获取了 ThrowableProxy 对象，此时一定会触发解析、加载异常堆栈类。

最佳实践

关于日志配置的最佳实践，供大家参考：

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>