朱亮亮

Stay Hungry, Stay Foolish.

0%

一次 Log4j2 引起线上服务 CPU 占用过高问题排查

某天运维反馈某个线上集群多个节点夜间 0 点左右 CPU 被打满,0-4 点 prometheus 的监控数据都没有采集到,在 4 点左右自动恢复。机器整体整体的负载如下:

故障现象

这个集群上部署了多个服务,我们的服务作为一个中间件提供 rpc 调用。观察我们服务的监控,发现在 0 点左右 cpu 使用率和 jvm 线程数都暴涨。

image-20211120100814518

故障分析

我们首先怀疑可能是 0 点左右服务请求暴增,导致 rpc 线程变多,但大盘监控显示 0 点附近的流量和平时一样,都是下降的趋势。因为是 0 点触发的暴增,开始也怀疑是 0 点附近有定时任务导致,但该服务上并没有部署定时任务。

后面怀疑与日志压缩有关。之前为了方便定位问题,把所有请求的入参和返回都打印到日志里面了,导致日志量非常大,因此配置了日志文件满 4g 就压缩的策略。而此次发现,在服务器 CPU 打满的时候,正好存在 0 点滚动日志压缩和日志满 4g 压缩。进一步观察日志发现,在 01 和 03 节点上,两种情况的日志压缩在 0 点撞上了,此时CPU 和线程使用情况都暴增,而 02 节点 0 点的日志切分在 00:01 分就完成了。那么,为什么出现这个问题呢?

问题一:Log4j2 的这两种日志压缩任务为什么会同时执行呢?

Log4j2 的核心配置如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
<RollingFile name="xx" fileName="${LOG_HOME}/${LOG_FOLDER}/${LOG_FOLDER}.log"
filePattern="${LOG_HOME}/${LOG_FOLDER}/${LOG_FOLDER}.%d{yyyy-MM-dd}-%i.zip">
<!--需要打印出INFO的日志,这里必须设置级别高的-->
<ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
<PatternLayout>
<Pattern>${pattern}</Pattern>
</PatternLayout>

<Policies>
<TimeBasedTriggeringPolicy interval="1" modulate="true"/>
<SizeBasedTriggeringPolicy size="4096 MB"/>
</Policies>
<!-- max=1标识一小时内最多产生1个日志文件 -->
<DefaultRolloverStrategy compressionLevel="9" max="25">
<!-- 对于指定的路径下的指定后缀的文件,只保留 7 天的日志文件,那么最多会有 7 天 * 10个日志文件 -->
<!-- 4096 + 7 * 25 * 4096 / 12 = 62g 左右-->
<Delete basePath="${LOG_HOME}/${LOG_FOLDER}" maxDepth="2">
<IfFileName glob="*.zip"/>
<IfLastModified age="7d"/>
</Delete>
</DefaultRolloverStrategy>

</RollingFile>

其中日志策略配置了两种 Trigger

TimeBasedTriggeringPolicy :interval 为 1,并且 filePattern 精确到天,表示按天切割日志,当日期与日志文件日期不一致时,触发日志切割。

SizeBasedTriggeringPolicy :size 为 4096MB,表示当日志文件大小达到 4G 时,触发日志切割。

两种策略组合使用,任何一个策略符合条件是都会开始触发日志切割。

再来看 01节点(01 和 03 现象差不多,选择 01 观察) 上临界点日志的情况,主要是两个日志文件:

1
2
3
4
5
6
7
8
9
10
11
#xxx.2021-11-18-24.zip,最后压缩完毕时间是 Nov 19 03:34
#第一行
20211118-223834.476 [INFO] request = xxx
#最后一行
20211118-235925.430 [INFO] request = xxx

#xxx.2021-11-18-25.zip,最后压缩完毕时间是 Nov 19 03:39
#第一行
20211118-235925.430 [INFO] request = xxx
#最后一行
20211118-235959.999 [INFO] request = xxx

从日志中可以看出,在 2021-11-18-23:59:25 时,日志文件达到 4G,触发 SizeBasedTriggeringPolicy,Log4j2 开始切割并压缩日志,后面的日志写到 xxx.2021-11-18-25.log 中。紧接着,时间到达 19 日 0 点,触发 TimeBasedTriggeringPolicy,Log4j2再次开始切割并压缩日志。由于 xxx.2021-11-18-24.log 的日志(4G 大小)还在压缩中,因此此时存在两个压缩任务,并且直到 19 日 3 点 39 左右才全部压缩完毕。

我们可以再看看 02 这个正常的节点是否有类似的情况。

1
2
3
4
5
6
7
8
9
10
11
#xxx.2021-11-18-24.zip,最后压缩完毕时间是 Nov 18 22:41
#第一行
20211118-214715.495 [INFO] request = xxx
#最后一行
20211118-223925.050 [INFO] request = xxx

#xxx.2021-11-18-25.zip,最后压缩完毕时间是 Nov 19 00:01
#第一行
20211118-223925.050 [INFO] request = xxx
#最后一行
20211118-235959.999 [INFO] request = xxx

从日志切割并压缩的时间线上看,当只有一个日志切割和压缩任务时,Log4j2 只需要 1 分钟左右就能完成;而当同时存在两个压缩任务时,足足花了 3 个多小时才完成,尽管其中一个压缩任务的日志文件非常小。

问题二:多个日志切割和压缩任务为什么会导致 CPU 使用率和线程数暴增?

Log4j2 日志的写入都会调用 RollingFileAppender 的 append 方法,如下:

1
2
3
4
5
@Override
public void append(final LogEvent event) {
getManager().checkRollover(event);
super.append(event);
}

其中 checkRollover 方法如下:

1
2
3
4
5
public synchronized void checkRollover(final LogEvent event) {
if (triggeringPolicy.isTriggeringEvent(event)) {
rollover();
}
}

这里发现这个方法使用了 synchronized 修饰,会产生线程竞争。进一步查看 rollover 触发日志切割:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
public synchronized void rollover() {
if (!hasOutputStream()) {
return;
}
if (rollover(rolloverStrategy)) {
try {
size = 0;
initialTime = System.currentTimeMillis();
createFileAfterRollover();
} catch (final IOException e) {
logError("Failed to create file after rollover", e);
}
}
}

同样使用了 synchronized 修饰,也就是同一时刻只会有一个线程来进行日志切割操作。结合上文 0 点和满 4G 大小的日志切割分析,首先执行的是满 4G 的日志文件切割,0 点的日志切割则需要等待。此外,执行日志切割的时候,还会获取一个信号量,只有在执行成功之后才会释放信号量。

1
2
3
4
5
6
7
8
9
10
11
12
13
private boolean rollover(final RolloverStrategy strategy) {

boolean releaseRequired = false;
try {
// Block until the asynchronous operation is completed.
semaphore.acquire();
releaseRequired = true;
} catch (final InterruptedException e) {
logError("Thread interrupted while attempting to check rollover", e);
return false;
}
……
}

可以发现,当 Log4j2 正在进行日志切割时,其它线程写日志的请求会阻塞住。这时会有大量的线程处于等待中,导致线程数暴增,而线程数的暴增也会导致 CPU 使用率暴增。

解决方案

那么在写入日志时,有什么办法能够提高日志的写入性能而不必等待日志切割呢?答案是有的,Log4j2 中引入了新的异步写入日志的方案:AsyncLogger。

使用异步日志写入,首先要引入 disruptor 依赖

1
2
3
4
5
<dependency>
<groupId>com.lmax</groupId>
<artifactId>disruptor</artifactId>
<version>3.4.2</version>
</dependency>

然后修改 log4j2.xml 配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
<Configuration status="warn" name="MyApp" packages="">
<Appenders>
<File name="MyFile" fileName="logs/app.log">
<PatternLayout>
<Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
</PatternLayout>
</File>
<Async name="Async">
<AppenderRef ref="MyFile"/>
</Async>
</Appenders>
<Loggers>
<Root level="error">
<AppenderRef ref="Async"/>
</Root>
</Loggers>
</Configuration>