容易忽视的细节：Log4j 配置导致的零点接口严重超时

一、问题发现

我所负责的商城活动系统用于承接公司线上官方商城的营销活动，最近突然收到凌晨0点的服务超时告警。

营销活动类的系统有如下特点：

1. 营销活动一般会0点开始，如红包雨、大额优惠券抢券等。
2. 日常营销活动的机会刷新，如每日任务，每日签到，每日抽奖机会的刷新等。

营销活动的利益刺激会吸引大量真实用户及黑产前来参与活动，所以流量在0点会迎来一波小高峰，也正因如此线上偶现的服务超时告警起初并未引起我的注意。但是接下来的几天，每天的凌晨0点都会收到服务超时告警，这引起了我的警惕，决定一探究竟。

二、问题排查

首先通过公司的应用监控系统查看了0点前后每分钟各接口的P95响应时间。如下图所示，接口响应时间在0点时刻最高达到了8s。继续查看锁定耗时最高的接口为商品列表接口，下面就针对这个接口展开具体的排查。

2.1 排查思路

正式排查之前，先和大家分享下我对接口超时问题的排查思路。下图是一个简化的请求流程。

1. 用户向应用发起请求
2. 应用服务进行逻辑处理
3. 应用服务通过RPC调用下游应用以及进行数据库的读写操作

服务超时可能是应用服务自身慢导致，也可能下游依赖响应慢导致。具体排查思路如下：

3.1.1下游依赖慢服务排查

（1）通过调用链技术定位下游依赖中的慢服务

调用链技术是实现系统可观测性的重要保障，常见的开源方案有ziplin、pinpoint等。完整的调用链可以按时间正序记录每一次下游依赖调用的耗时，如rpc服务调用、sql执行耗时、redis访问耗时等。因此使用调用链技术可以迅速定位到下游依赖的慢服务，如dubbo接口访问超时、慢SQL等。但理想很丰满，现实很骨感。由于调用链路信息的数量过大，想要收集全量的链路信息需要较高的存储成本和计算资源。因此在技术落地时，通常都会采用抽样的策略来收集链路信息。抽样带来的问题是请求链路信息的丢失或不完整。

（2）无调用链时的慢服务排查

如果调用链丢失或不完整，我们就要再结合其它手段进行综合定位了。

下游RPC服务响应超时：如果是用Dubbo框架，在provider响应超时时会打印timeout相关日志；如果公司提供应用监控，还可以查看下游服务P95响应时间综合判断。

慢SQL：MySQL支持设置慢SQL阈值，超过该阈值会记录下慢SQL；像我们常用的数据库连接池Druid也可以通过配置打印慢SQL日志。如果确认请求链路中存在慢SQL可以进一步分析该SQL的执行计划，如果执行计划也没有问题，再去确认在慢SQL产生时mysql主机的系统负载。

下游依赖包含Redis、ES、Mongo等存储服务时，慢服务的排查思路和慢SQL排查相似，在此不再赘述。

2.1.2应用自身问题排查

（1）应用逻辑耗时多

应用逻辑耗时多比较常见，比如大量对象的序列化和反序列化，大量的反射应用等。这类问题的排查通常要从分析源码入手，编码时应该尽量避免。

（2）垃圾回收导致的停顿（stop the world）

垃圾回收会导致应用的停顿，特别是发生Old GC或Full GC时，停顿明显。不过也要看应用选配的垃圾回收器和垃圾回收相关的配合，像CMS垃圾回收器通常可以保证较短的时间停顿，而Parallel Scavenge垃圾回收器则是追求更高的吞吐量，停顿时间会相对长一些。

通过JVM启动参数-XX:+PrintGCDetails，我们可以打印详细的GC日志，借此可以观察到GC的类型、频次和耗时。

（3）线程同步阻塞

线程同步，如果当前持有锁的线程长时间持有锁，排队的线程将一直处于blocked状态，造成服务响应超时。可以通过jstack工具打印线程堆栈，查找是否有处于block状态的线程。当然jstack工具只能采集实时的线程堆栈信息，如果想要查看历史堆栈信息一般需要通过Prometheus进行收集处理。

2.2 排查过程

下面按照这个排查思路进行排查。

2.2.1下游依赖慢服务排查

（1）通过调用链查看下游慢服务

首先到公司的应用监控平台上，筛选出0点前后5min的调用链列表，然后按照链路耗时逆序排列，发现最大接口耗时7399ms。查看调用链详情，发现下游依赖耗时都是ms级别。调用链因为是抽样采集，可能存在链路信息丢失的情况，因此需要其他手段进一步排查下游依赖服务。

（2）通过其他手段排查下游慢服务

接着我查看了0点前后的系统日志，并没有发现dubbo调用超时的情况。然后通过公司的应用监控查看下游应用P95响应时间，如下图，在0点时刻，下游的一些服务响应时长确实会慢一些，最高的达到了1.45s，虽然对上游有一定影响，但不至于影响这么大。

（3）慢SQL排查

接下来是慢SQL的排查，我们系统的连接池使用的是阿里开源的druid，SQL执行超过1s会打印慢SQL日志，查看日志中心也没有发现慢SQL的踪迹。

到现在，可以初步排除因下游依赖慢导致服务超时，我们继续排查应用自身问题。

2.2.2 应用自身问题排查

（1）复杂耗时逻辑排查

首先查看了接口的源码，整体逻辑比较简单，通过dubbo调用下游商品系统获取商品信息，本地再进行商品信息的排序等简单的处理。不存在复杂耗时逻辑问题。

（2）垃圾回收停顿排查

通过公司应用监控查看应用的GC情况，发现0点前后没有发生过full GC，也没有发生过Old GC。垃圾回收停顿的因素也被排除。

（3）线程同步阻塞排查

通过公司应用监控查看是否存在同步阻塞线程，如下图：

看到这里，终于有种天不负有心人的感觉了。从00:00:00开始一直到00:02:00，这两分钟里，出现了较多状态为BLOCKED的线程，超时的接口大概率和这些blocked线程相关。我们只需要进一步分析JVM堆栈信息即可真相大白。

我们随机选取一台比较有代表性的机器查看block堆栈信息，堆栈采集时间是2022-08-02 00:00:20。

// 日志打印操作，被线程catalina-exec-408阻塞
"catalina-exec-99" Id=506 BLOCKED on org.apache.log4j.spi.RootLogger@15f368fa owned by "catalina-exec-408" Id=55204
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    -  blocked on org.apache.log4j.spi.RootLogger@15f368fa
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF(Category.java:391)
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF$accessor$pRDvBPqB(Category.java)
    at org.apache.log4j.Category$auxiliary$JhXHxvpc.call(Unknown Source)
    at com.vivo.internet.trace.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:46)
    at org.apache.log4j.Category.forcedLog(Category.java)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:324)
    ...
// 日志打印操作，被线程catalina-exec-408阻塞
"catalina-exec-440" Id=55236 BLOCKED on org.apache.log4j.spi.RootLogger@15f368fa owned by "catalina-exec-408" Id=55204
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    -  blocked on org.apache.log4j.spi.RootLogger@15f368fa
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF(Category.java:391)
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF$accessor$pRDvBPqB(Category.java)
    at org.apache.log4j.Category$auxiliary$JhXHxvpc.call(Unknown Source)
    at com.vivo.internet.trace.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:46)
    at org.apache.log4j.Category.forcedLog(Category.java)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.slf4j.impl.Log4jLoggerAdapter.warn(Log4jLoggerAdapter.java:444)
    ...
// 日志打印操作，被线程catalina-exec-408阻塞
"catalina-exec-416" Id=55212 BLOCKED on org.apache.log4j.spi.RootLogger@15f368fa owned by "catalina-exec-408" Id=55204
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    -  blocked on org.apache.log4j.spi.RootLogger@15f368fa
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF(Category.java:391)
    at org.apache.log4j.Category.forcedLog$original$mp4HwCYF$accessor$pRDvBPqB(Category.java)
    at org.apache.log4j.Category$auxiliary$JhXHxvpc.call(Unknown Source)
    at com.vivo.internet.trace.agent.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:46)
    at org.apache.log4j.Category.forcedLog(Category.java)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.slf4j.impl.Log4jLoggerAdapter.warn(Log4jLoggerAdapter.java:444)
    ...