给你一颗“定心丸”——记一次由线上事故引发的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和相关依赖版本信息：

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使用率和线程数情况

第二查

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

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

注：这对我们后来问题排查的方向造成了误导&#