一次鞭辟入里的 Log4j2 日志输出阻塞问题的定位
问题现象
线上某个应用的某个实例突然出现某些次请求服务响应极慢的情况，有几次请求超过 60s 才返回，并且通过日志发现，服务线程并没有做什么很重的操作。这种情况断断续续持续了半小时左右。
核心问题定位
由于半小时后，服务实例恢复正常，并且出现请求极慢的次数并不太多，没有能及时打印出现问题的时候线程堆栈采集相关信息。但是，我们有自己的法宝，JFR（关于 JFR，请参考我的另一系列JFR全解）。
JFR 非常适合用来事后复盘定位问题，并且配置得当的话，性能损耗极小，并且不像 APM 系统一样需要额外的采集以及需要统一的服务进程进行整合展现。我们随用随取即可，但是 JFR 面向的是单进程的问题定位，找到问题进程，定位跨进程业务问题链路追踪还是需要 APM 系统的。
我们通过如下命令采集对应时间段的 JFR：
jcmd 进程pid JFR.dump begin=2021-07-04T17:30:00.000Z end=2021-07-04T18:30:00.000Z
我们选择的时间跨度比出问题的时间跨度大一些，这样保证底层问题出现的时候也被采集写入这个 dump 文件。
对于历史某些请求响应慢，我一般按照如下流程去看：
- 是否有 STW（Stop-the-world，参考我的另一篇文章：JVM相关 - SafePoint 与 Stop The World 全解）:
- 是否有 GC 导致的长时间 STW
- 是否有其他原因导致进程所有线程进入 safepoint 导致 STW
- 是否 IO 花了太长时间，例如调用其他微服务，访问各种存储（硬盘，数据库，缓存等等）
- 是否在某些锁上面阻塞太长时间？
- 是否 CPU 占用过高，哪些线程导致的？
接下来我们来详细分析，首先是 GC，从下图看，并没有能严重影响线程 STW 很长时间的：
然后查看 safepoint 相关，发现也没有什么影响：
接着，我们查看 IO 相关的事件，也并没有发现业务相关的阻塞读：
然后，我们查看是否在某些锁上面阻塞太长时间，终于发现异常：
通过堆栈，我们发现是** log4j2 打印日志卡住了**。
问题分析
1. Java Monitor Blocked 的 Monitor Address 对于同一个对象也是会改变的
首先，对于 Java Monitor Blocked 这个事件，我们可以通过 Monitor Address 来判断是否是同一个锁。例如这里我们发现这些线程都是阻塞在 FFFF 4C09 3188 这个地址的对象，这个地址是基于对象在 Java 堆中的相对地址得出的。
但是对于同一个对象，这个地址并不会是不变的，在每次 GC 扫描整理到这个对象对象的时候，如果有回收内存，一般这个地址就会改变。由于我们使用的是 G1，所以并不是每次 GC 都会扫描到这个对象，但是如果地址发生改变，一定是因为发生了 GC
2. log4j2 异步日志原理简介
在我们的应用配置中，采用的日志框架是 log4j2，采用的配置是异步日志配置。这里简单说一下 Log4j2 异步日志的原理：Log4j2 异步日志基于高性能数据结构 Disruptor，Disruptor 是一个环形 buffer，做了很多性能优化（具体原理可以参考我的另一系列：高并发数据结构（disruptor）），Log4j2 对此的应用如下所示：
简单来说，多线程通过 log4j2 的门面类 org.apache.logging.log4j.Logger 进行日志输出，被封装成为一个 org.apache.logging.log4j.core.LogEvent，放入到 Disruptor 的环形 buffer 中。在消费端有一个单线程消费这些 LogEvent 写入对应的 Appender，我们这里只有一个 Appender，其配置是：
<RollingFile name="file" append="true" filePattern="./app.log-%d{yyyy.MM.dd.HH}"> <PatternLayout pattern="${logFormat}"/> <Policies> <TimeBasedTriggeringPolicy interval="1" modulate="true"/> </Policies> <DirectWriteRolloverStrategy maxFiles="72"/> </RollingFile>
异步日志 logger 配置为（配置 includeLocation 为 false，避免每次打印日志需要获取调用堆栈的性能损耗）：
<Asyncroot level="info" includeLocation="false"> <appender-ref ref="file"/> </Asyncroot>
log4j component 额外配置为：
log4j2.component.properties:
# 当没有日志的时候，消费线程通过 Block 等待日志事件到来，这样 CPU 占用最少 AsyncLoggerConfig.WaitStrategy=Block
3. log4j2 disruptor 的 RingBuffer 的大小
既然是一个环形 Buffer，它的容量是有限的，我们这里没有修改它的大小，走的是默认配置，查看其源码：
AsyncLoggerConfigDisruptor.java
public synchronized void start() { //省略其他代码 ringBufferSize = DisruptorUtil.calculateRingBufferSize("AsyncLoggerConfig.RingBufferSize"); disruptor = new Disruptor<>(factory, ringBufferSize, threadFactory, ProducerType.MULTI, waitStrategy); }
private static final int RINGBUFFER_MIN_SIZE = 128; private static final int RINGBUFFER_DEFAULT_SIZE = 256 * 1024; private static final int RINGBUFFER_NO_GC_DEFAULT_SIZE = 4 * 1024; static int calculateRingBufferSize(final String propertyName) { //是否启用了 ThreadLocal，如果是则为 4 kB，不是则为 256 kB int ringBufferSize = Constants.ENABLE_THREADLOCALS ? RINGBUFFER_NO_GC_DEFAULT_SIZE : RINGBUFFER_DEFAULT_SIZE; //读取系统变量，以及 log4j2.component.properties 文件获取 propertyName(这里是 AsyncLoggerConfig.RingBufferSize) 这个配置 final String userPreferredRBSize = PropertiesUtil.getProperties().getStringProperty(propertyName, String.valueOf(ringBufferSize)); try { int size = Integer.parseInt(userPreferredRBSize); //如果小于 128 字节则按照 128 字节设置 if (size < RINGBUFFER_MIN_SIZE) { size = RINGBUFFER_MIN_SIZE; LOGGER.warn("Invalid RingBufferSize {}, using minimum size {}.", userPreferredRBSize, RINGBUFFER_MIN_SIZE); } ringBufferSize = size; } catch (final Exception ex) { LOGGER.warn("Invalid RingBufferSize {}, using default size {}.", userPreferredRBSize, ringBufferSize); } //取最近的 2 的 n 次方，因为对于 2 的 n 次方取余等于对于 2^n-1 取与运算，这样更快 return Integers.ceilingNextPowerOfTwo(ringBufferSize); }
如果启用了 ThreadLocal 这种方式生成 LogEvent，每次不新生成的 LogEvent 用之前的，用 ThreadLocal 存储的，这样避免了创建新的 LogEvent。但是考虑下面这种情况：
logger.info("{}", someObj);
这样会造成强引用，导致如果线程没有新的日志，这个 someObj 一直不能回收。所以针对 Web 应用，log4j2 默认是不启用 ThreadLocal 的 方式生成 LogEvent：
public static final boolean IS_WEB_APP = PropertiesUtil.getProperties().getBooleanProperty( "log4j2.is.webapp", isClassAvailable("javax.servlet.Servlet")); public static final boolean ENABLE_THREADLOCALS = !IS_WEB_APP && PropertiesUtil.getProperties().getBooleanProperty( "log4j2.enable.threadlocals", true);
由此，可以看出，我们的 RingBuffer 的大小为 256 kB。
