一、内容提要

自知是人外有人,天外有天,相信对于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和相关依赖版本信息:

1.JDK:1.8.0_191
2.JSF:1.7.4-HOTFIX-T8
3.SLF4J-API:1.7.25
4.LOG4J-SLF4J-IMPL:2.18.0-jdsec.rc2
5.LOG4J2:2.18.0-jdsec.rc2
6.DISRUPTOR:3.4.2

三、问题点

1.

为何 服务可用率恢复到了一定程度后又掉下来了?
2.

为何 一个服务方的服务出现问题后,其他服务方的服务却也受到了影响?
3.

服务超时控制 为何 没有起作用?
4.

服务端出现问题 为何 需要客户端执行重启操作?

四、排查过程

如果上面的问题解决不了,大概我晚上睡觉的时候一掀开被窝也全是

为何

了,带着这些问题我们便开始了如下排查过程。

第一查

排查客户端机器是否出现由于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の

标签: none

添加新评论