关于线程:容易忽视的细节Log4j-配置导致的零点接口严重超时

作者：vivo 互联网服务器团队 - Jiang Ye

本文具体的记录了一次 0 点接口重大超时的问题排查经验。本文以作者本身视角极具代入感的描述了从问题定位到具体的问题排查过程，并通过根因剖析并最终解决问题。整个过程须要清晰的问题排查思路和丰盛的问题解决教训，也离不开公司弱小的调用链、和全方位的系统监控等基础设施。

我所负责的商城流动零碎用于承接公司线上官网商城的营销流动，最近忽然收到凌晨 0 点的服务超时告警。

营销流动类的零碎有如下特点：

营销流动个别会 0 点开始，如红包雨、大额优惠券抢券等。
日常营销流动的机会刷新，如每日工作，每日签到，每日抽奖机会的刷新等。

营销流动的利益刺激会吸引大量实在用户及黑产前来参加流动，所以流量在 0 点会迎来一波小顶峰，也正因如此线上偶现的服务超时告警起初并未引起我的留神。然而接下来的几天，每天的凌晨 0 点都会收到服务超时告警，这引起了我的警觉，决定一探到底。

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

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

用户向利用发动申请
应用服务进行逻辑解决
应用服务通过 RPC 调用上游利用以及进行数据库的读写操作

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

（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 排查类似，在此不再赘述。

（1）应用逻辑耗时多

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

（2）垃圾回收导致的进展（stop the world）

垃圾回收会导致利用的进展，特地是产生 Old GC 或 Full GC 时，进展显著。不过也要看利用选配的垃圾回收器和垃圾回收相干的配合，像 CMS 垃圾回收器通常能够保障较短的工夫进展，而 Parallel Scavenge 垃圾回收器则是谋求更高的吞吐量，进展工夫会绝对长一些。

通过 JVM 启动参数 -XX:+PrintGCDetails，咱们能够打印具体的 GC 日志，借此能够察看到 GC 的类型、频次和耗时。

（3）线程同步阻塞

线程同步，如果以后持有锁的线程长时间持有锁，排队的线程将始终处于 blocked 状态，造成服务响应超时。能够通过 jstack 工具打印线程堆栈，查找是否有处于 block 状态的线程。当然 jstack 工具只能采集实时的线程堆栈信息，如果想要查看历史堆栈信息个别须要通过 Prometheus 进行收集解决。

上面依照这个排查思路进行排查。

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

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

（2）通过其余伎俩排查上游慢服务

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

（3）慢 SQL 排查

接下来是慢 SQL 的排查，咱们零碎的连接池应用的是阿里开源的 druid，SQL 执行超过 1s 会打印慢 SQL 日志，查看日志核心也没有发现慢 SQL 的形迹。

到当初，能够初步排除因上游依赖慢导致服务超时，咱们持续排查利用本身问题。

（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)
    ...

通过堆栈信息能够剖析出 2 点：

处于 blocked 状态的线程都是日志打印
所有的线程都是被线程名为“catalina-exec-408”阻塞

追踪到这里，慢服务的表层起因就分明了。被线程 catalina-exec-408 阻塞的线程，始终处于 blocked 状态，导致服务响应超时。

表层起因找到当前，咱们一起拨开层层迷雾，寻找假相背地的假相吧！

所有慢服务的线程都是在打印日志的时候被线程 catalina-exec-408 阻塞。那么线程 catalina-exec-408 在做什么呢？

能够发现，在 00:00:18.858 时刻，该线程在打印登录态校验失败的日志，也并无简单的解决逻辑。难道是该线程打印日志慢，阻塞了其余线程吗？带着这个疑难，我开始深刻日志框架的源码寻找答案。

咱们的我的项目应用的日志框架是 slf4j + log4j。依据被阻塞的线程栈信息咱们定位到这段代码如下：

public
void callAppenders(LoggingEvent event) {
  int writes = 0;
 
  for(Category c = this; c != null; c=c.parent) {
    // Protected against simultaneous call to addAppender, removeAppender,...
    // 这是 204 行，加了 sychronized
    synchronized(c) {if(c.aai != null) {writes += c.aai.appendLoopOnAppenders(event);
  }
  if(!c.additive) {break;}
    }
  }
 
  if(writes == 0) {repository.emitNoAppenderWarning(this);
  }
}

能够看到堆栈信息中的 204 行是 synchronized 代码块，对其它线程造成阻塞的这是这块代码。那么 synchronized 代码块外部逻辑是什么呢？为什么要执行很久呢？上面是 synchronized 代码块中的外围逻辑：

public
  int appendLoopOnAppenders(LoggingEvent event) {
    int size = 0;
    Appender appender;
 
    if(appenderList != null) {size = appenderList.size();
      for(int i = 0; i < size; i++) {appender = (Appender) appenderList.elementAt(i);
    appender.doAppend(event);
      }
    }   
    return size;
  }

能够看到，这块逻辑就是将日志写入所有配置的 appender 中。咱们配置的 appender 有两个，一个是 console appender，也就是输入到 catalina.out 文件。还有一个是依照公司日志核心采集要求，以 Json 格局输入的 appender。这里能够做出推断，线程 catalina-exec-408 在将日志输入到 appender 时耗时较多。

我很天然的开始狐疑过后的机器负载，特地是 IO 负载可能会比拟高，通过公司的机器监控，咱们查看了下相干指标：

果然，从 00:00:00 开始，磁盘 IO 耗费继续彪高，到 1 分钟 20 秒第一波顶峰才完结，在 00:00:20 时刻，IO 耗费达到峰值 99.63%, 靠近 100%。难怪利用输入一条日志都这么难！

到底是谁把 IO 资源耗费光了，耗费到简直骨头都不剩？带着疑难，我进一步通过公司的机器监控查看了主机快照：

发现在 00:00:20 时刻，tomcat 用户在执行脚本 /bin/sh /scripts/cutlog.sh，脚本在执行命令 cp catalina.out catalina.out-2022-08-02-00。IO 耗费达到了 109475612 bytes/s(约 104MB/s)。

事件就要上不着天; 下不着地了，咱们持续掘地三尺。运维同学登陆到机器上，切换到 tomcat 用户，查看定时工作列表（执行 crontab -l），失去后果如下：

00 00 * * * /bin/sh /scripts/cutlog.sh

正是快照中的脚本 /bin/sh /scripts/cutlog.sh，每天 0 点执行。具体的脚本内容如下：

$ cat /scripts/cutlog.sh
#!/bin/bash

files=(xxx)
 
time=$(date +%F-%H)
 
for file in ${files[@]}
do
  dir=$(dirname ${file})
  filename=$(echo "xxx"|awk -F'/' '{print $NF}')
  # 归档 catalina.out 日志并清空 catalina.out 以后文件内容
  cd ${dir} && cp ${filename} ${filename}-${time} && > ${filename}
done

咱们从脚本中找到了高 IO 耗费的首恶，就是这个 copy 命令，目标是将 catalina.out 日志归档并将 catalina.out 日志文件清空。

这个失常的运维脚本必定是比拟耗费 IO 资源的，执行的时长受文件大小影响。运维同学也帮忙看了下归档的日志大小：

[root@xxx:logdir]

# du -sh *

1.4G catalina.out

2.6G catalina.out-2022-08-02-00

归档的文件大小有 2.6 G，依照 104MB/ s 估算，须要耗时 25 秒。也就是 00:00:00 到 00:00:25 期间，业务日志输入都会比拟迟缓，造成大量线程 block，进而导致接口响应超时。

定位到了问题的根因，就能够隔靴搔痒了。有几个计划能够抉择：

耗费 IO 资源的操作就是 catalina.out 日志的归档，如果不写日志到该文件，是能够解决日志打印 IO 期待的问题的。然而像本地调试、压测环境还是比拟依赖 console 日志的，所以就须要依据不同环境来设置不同的 console appender。目前 logback、Log4j2 曾经反对依据 Spring profile 来区别配置，咱们用的 Log4j 还不反对。切换日志底层框架的老本也比拟高，另外晚期的公司中间件与 Log4j 日志框架强耦合，无奈简略切换，所以咱们并没有采纳这个计划。

Log4j 提供了 AsyncAppender 用于反对异步日志打印，异步日志能够解决同步日志打印 IO 期待的问题，不会阻塞业务线程。

异步日志的副作用：

异步日志是在日志打印时，将 event 退出到 buffer 队列中，buffer 的大小默认是 128，反对配置。对于 buffer 满了后有两种解决策略。

（1）阻塞

当属性 blocking 设置为 true 时，应用阻塞策略，默认是 true。即 buffer 满了后，同步期待，此时线程会阻塞，退变成同步日志。

（2）抛弃

如果 blocking 设置为 false，在 buffer 满了当前，会将该条日志抛弃。

最终咱们抉择了计划 2，即配置日志异步打印。buffer 队列大小设置 2048，思考到局部日志失落在业务上是能够承受的，因而就义了小局部可靠性换区更高的程序性能，将 blocking 设置为 false。

这次的问题排查经验，我播种了几点感悟，和大家分享一下：

1）要对线上告警放弃敬畏之心

咱们应该敬畏每一个线上告警，器重每一条谬误日志。现实情况是大多数时候告警只是因为网络抖动，短暂的突发流量等，是能够自行复原的，这就像狼来了的故事一样，让咱们放松了警觉，导致咱们可能会错过真正的问题，给零碎带来重大劫难，给业务带来损失。

2）刨根问底

告警只是表象，咱们须要搞清楚每个告警的外表起因和根本原因。比方这次的接口超时告警，只有剖析出”copy 文件耗尽磁盘 IO，导致日志打印线程 block“这个根本原因后，能力给出优雅正当的解决方案。说起来简略，实操起来可能会遇到很多艰难，这要求咱们有清晰的问题排查思路，有良好的的零碎可观测性建设，有扎实的技术基本功和不找到”真凶“永不放弃的信心。

最初心愿我的这次问题排查经验可能让你有所播种，有所启发。我也将本文用到的超时问题排查思路整顿成了流程图，供大家参考。你有遇到过哪些线上故障呢？你的排查思路是怎么的呢？欢送留言交换探讨。

关于线程:容易忽视的细节Log4j-配置导致的零点接口严重超时

一、问题发现

二、问题排查

2.1 排查思路

2.1.1 上游依赖慢服务排查

2.1.2 利用本身问题排查

2.2 排查过程

2.2.1 上游依赖慢服务排查

2.2.2 利用本身问题排查

三、根因剖析

四、问题解决

4.1 生产环境不打印日志到 console

4.2 配置日志异步打印

4.3 最终计划

4.4 小结