给你一颗“定心丸”——记一次由线上事故引发的Log4j2日志异步打印优化分析

一、内容提要

自知是人外有人，天外有天，相信对于Log4j2的异步日志打印早有老师或者同学已是熟稔于心，优化配置更是信手拈来，为了防止我在这里啰里八嗦的班门弄斧，我先将谜底在此公布：
log4j2.asyncQueueFullPolicy=Discard & log4j2.discardThreshold=ERROR
，这两个Log4j2配置在强依赖的RPC服务方系统或中间件系统出现问题且业务流量巨大时，对系统的快速止血和影响范围的控制有奇效。
要问为什么如此配置，是否还有高手？请见下文分晓。

二、现场还原

在2023年12月15日这“普通”的一天午后14点25分，我们收到了来自UMP的报警，接口服务可用率直接从100%干到了0.72%（该服务会直接影响到订单接单的相关流程，对客户体验有着重大影响）。我们顺藤摸瓜，并配合其他的服务监控定位到是强依赖系统出现了故障，导致其服务高度不可用，因此赶紧联系相关系统同事进行问题排查和处理。

大概14:33左右，服务端系统同事反馈已经机器扩容完成，由以下截图可见，确实在14:32左右服务可用率开始有抬头趋势，但是至此问题却并未终结，在14:36服务可用率开始急转直下（错误日志内容除了服务响应超时，服务端线程池满等异常以外，同时还收到了无服务的异常以及其他不相关服务调用的超时异常）。服务端系统同事反馈新扩容机器仅有极少数流量流入，如此“意外之喜”是我们没想到的，其后续排查和问题定位的过程分析也是该文成文的主要原因。最终我们通过操作客户端机器重启，服务得以完全恢复。

图2-1 服务端系统问题初现

图2-2 客户端服务监控可用率再次骤降

图2-3 客户端服务监控TP指标

系统JDK和相关依赖版本信息：

三、问题点

四、排查过程

如果上面的问题解决不了，大概我晚上睡觉的时候一掀开被窝也全是
“
为何
”
了，带着这些问题我们便开始了如下排查过程。

第一查

排查客户端机器是否出现由于GC导致的STW（stop the world）

由以下截图可见Young GC次数确有所升高（猜测应该有较多大对象产生），Full GC并未触发；堆内存，非堆内存的使用率处于正常水平；CPU使用率有所飙高且线程数略有增加，但是尚处于正常可接受范围内，目前看来问题时间段内机器的JVM指标并不能提供太多的定位线索。

图4-1-1 客户端服务器Young GC和Full GC情况

图4-1-2 客户端服务器堆内存和非堆内存情况

图4-1-3 客户端服务器CPU使用率和线程数情况

第二查

排查客户端机器磁盘情况，看是否存在日志阻塞的情况

通过以下截图可见，磁盘使用率，磁盘繁忙，磁盘写速度等磁盘指标看起来也尚属正常，由此暂时推断该问题与日志的相关性并不大。

注：这对我们后来问题排查的方向造成了误导，将罪魁祸首给很快排除掉了，其实再仔细看一下磁盘使用率的截图，在相对较短的时间内磁盘使用率却有了明显的增长，这是出现了“精英怪”呀，不过即便如此，目前也仅仅是猜测，并无充足的证据来支持定罪，接下来的排查才是重量级
）

图4-2-1 客户端服务器磁盘使用率情况

图4-2-2 客户端服务器磁盘繁忙情况

图4-2-3 客户端服务器磁盘写速度情况

第三查

查看问题时间段内客户端机器的内存状况（jmaq -dump）

通过
JSF-CLI-WORKER
关键字我们可以定位到JSF客户端线程状态，通过以下截图可以看出，JSF客户端线程虽然在执行不同的服务处理流程，但是都在执行WARN/ERROR日志打印的时候卡在了enqueue环节。

图4-3-1 JSF客户端线程状态1

图4-3-2 JSF客户端线程状态2

下面让我们来分析一下源码，具体看一下enqueue到底干了什么？

// enqueue源码分析
// 代码位置org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor#enqueue 363
private void enqueue(final LogEvent logEvent, final AsyncLoggerConfig asyncLoggerConfig) {
        // synchronizeEnqueueWhenQueueFull() 是与另外一个要和大家分享的开关配置（AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull）有关，该配置用于指定当日志异步打印使用的RingBuffer满了以后，将多个日志线程的队列写入操作通过锁（queueFullEnqueueLock）调整为同步
        if (synchronizeEnqueueWhenQueueFull()) {
            // 同步锁：private final Object queueFullEnqueueLock = new Object();
            synchronized (queueFullEnqueueLock) {
                disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
            }
        } else {
            disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
        }
    }

由上述源码我们不妨大胆的假设一下：
JSF的客户端线程由于日志打印被阻塞而导致功能出现异常。
那么顺着这个思路，我们就顺藤摸瓜，看看RingBuffer里面到底存了啥。聚光灯呢？往这打！

当我们找到RingBuffer的时候，不禁倒吸一口凉气，这小小RingBuffer居然有1.61GB之巨，让我们更近一步到RingBuffer的entries里面看看，到底是什么样的压力让RingBufferの