从Log4j配置问题入手，解决零点接口严重超时难题

后端

2023-10-02 17:51:50

引言

在当今微服务架构盛行的时代，分布式系统的复杂性和灵活性也给系统运维带来了诸多挑战。本文将详细记录我一次排查零点接口严重超时问题的经历，希望能给各位读者带来一些启发和帮助。

问题

一天深夜，我正准备休息时，突然接到同事的电话，说线上有一个接口在零点时段出现严重超时，导致下游服务无法正常工作。我立刻登录系统监控平台，发现果然如此。接口响应时间在零点前后突然飙升，甚至达到了数秒之久。

问题定位

由于接口在其他时段运行正常，因此我首先怀疑是零点时段的特殊业务导致了超时。我查看了业务日志，发现零点时段确实有一些特殊的业务请求，但这些请求量并不大，不应该导致如此严重的超时。

接着，我查看了系统资源使用情况，发现CPU和内存利用率都很正常，没有明显的异常。这说明问题很可能出在代码层面。

具体问题排查

于是我开始逐行检查代码，寻找可能导致超时的地方。经过一番仔细检查，我终于在Log4j的配置文件中发现了一个问题。

log4j.rootLogger=INFO, file, stdout
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=/var/log/myApp.log
log4j.appender.file.MaxFileSize=10MB
log4j.appender.file.MaxBackupIndex=10

这个配置中，MaxFileSize和MaxBackupIndex这两个参数分别指定了日志文件的最大大小和最大备份数量。当日志文件达到最大大小时，Log4j会自动创建一个新的日志文件，并将旧的日志文件备份。

但是，问题就出在MaxFileSize和MaxBackupIndex这两个参数设置的不合理。MaxFileSize设置为10MB，意味着当日志文件达到10MB时，Log4j就会创建一个新的日志文件。而MaxBackupIndex设置为10，意味着Log4j最多会保存10个日志文件。

这导致了一个问题：当零点时段业务量激增时，日志文件会迅速达到10MB，Log4j就会创建一个新的日志文件。同时，由于MaxBackupIndex设置为10，所以最旧的日志文件会被删除。

这样一来，当系统需要回溯日志时，就会发现最旧的日志文件已经不存在了。这导致系统无法正常分析和定位问题。

根因分析

经过分析，我发现问题的主要原因是Log4j的配置文件中，MaxFileSize和MaxBackupIndex这两个参数设置的不合理。MaxFileSize设置的太小，导致日志文件频繁创建和删除。而MaxBackupIndex设置的太小，导致旧的日志文件无法保存。

这导致了两个问题：

系统无法正常分析和定位问题。
日志文件占用过多磁盘空间。

解决方法

为了解决这个问题，我将MaxFileSize设置为100MB，并将MaxBackupIndex设置为30。这样一来，日志文件可以保存更长时间，而且系统也可以正常分析和定位问题。

log4j.rootLogger=INFO, file, stdout
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=/var/log/myApp.log
log4j.appender.file.MaxFileSize=100MB
log4j.appender.file.MaxBackupIndex=30