作者：vivo 互联网服务器团队- Jiang Ye
本文具体的记录了一次0点接口重大超时的问题排查经验。本文以作者本身视角极具代入感的描述了从问题定位到具体的问题排查过程，并通过根因剖析并最终解决问题。整个过程须要清晰的问题排查思路和丰盛的问题解决教训，也离不开公司弱小的调用链、和全方位的系统监控等基础设施。
一、问题发现
我所负责的商城流动零碎用于承接公司线上官网商城的营销流动，最近忽然收到凌晨0点的服务超时告警。
营销流动类的零碎有如下特点：
- 营销流动个别会0点开始，如红包雨、大额优惠券抢券等。
- 日常营销流动的机会刷新，如每日工作，每日签到，每日抽奖机会的刷新等。
营销流动的利益刺激会吸引大量实在用户及黑产前来参加流动，所以流量在0点会迎来一波小顶峰，也正因如此线上偶现的服务超时告警起初并未引起我的留神。然而接下来的几天，每天的凌晨0点都会收到服务超时告警，这引起了我的警觉，决定一探到底。
二、问题排查
首先通过公司的利用监控零碎查看了0点前后每分钟各接口的P95响应工夫。如下图所示，接口响应工夫在0点时刻最高达到了8s。持续查看锁定耗时最高的接口为商品列表接口，上面就针对这个接口开展具体的排查。
2.1 排查思路
正式排查之前，先和大家分享下我对接口超时问题的排查思路。下图是一个简化的申请流程。
- 用户向利用发动申请
- 应用服务进行逻辑解决
- 应用服务通过RPC调用上游利用以及进行数据库的读写操作
服务超时可能是应用服务本身慢导致，也可能上游依赖响应慢导致。具体排查思路如下：
2.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) ...通过堆栈信息能够剖析出2点：
- 处于blocked状态的线程都是日志打印
- 所有的线程都是被线程名为“catalina-exec-408”阻塞
追踪到这里，慢服务的表层起因就分明了。被线程catalina-exec-408阻塞的线程，始终处于blocked状态，导致服务响应超时。
三、根因剖析
表层起因找到当前，咱们一起拨开层层迷雾，寻找假相背地的假相吧！
所有慢服务的线程都是在打印日志的时候被线程catalina-exec-408阻塞。那么线程catalina-exec-408在做什么呢？
能够发现，在00:00:18.858时刻，该线程在打印登录态校验失败的日志，也并无简单的解决逻辑。难道是该线程打印日志慢，阻塞了其余线程吗？带着这个疑难，我开始深刻日志框架的源码寻找答案。
咱们的我的项目应用的日志框架是slf4j + log4j。依据被阻塞的线程栈信息咱们定位到这段代码如下：
publicvoid 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/bashfiles=( 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，进而导致接口响应超时。
四、问题解决
定位到了问题的根因，就能够隔靴搔痒了。有几个计划能够抉择：
4.1 生产环境不打印日志到console
耗费 IO资源的操作就是catalina.out日志的归档，如果不写日志到该文件，是能够解决日志打印IO期待的问题的。然而像本地调试、压测环境还是比拟依赖console日志的，所以就须要依据不同环境来设置不同的console appender。目前logback、Log4j2曾经反对依据Spring profile来区别配置，咱们用的Log4j还不反对。切换日志底层框架的老本也比拟高，另外晚期的公司中间件与Log4j日志框架强耦合，无奈简略切换，所以咱们并没有采纳这个计划。
4.2 配置日志异步打印
Log4j提供了AsyncAppender用于反对异步日志打印，异步日志能够解决同步日志打印IO期待的问题，不会阻塞业务线程。
异步日志的副作用：
异步日志是在日志打印时，将event退出到buffer队列中，buffer的大小默认是128，反对配置。对于buffer满了后有两种解决策略。
（1）阻塞
当属性blocking设置为true时，应用阻塞策略，默认是true。即buffer满了后，同步期待，此时线程会阻塞，退变成同步日志。
（2）抛弃
如果blocking设置为false，在buffer满了当前，会将该条日志抛弃。
4.3 最终计划
最终咱们抉择了计划2，即配置日志异步打印。buffer队列大小设置2048，思考到局部日志失落在业务上是能够承受的，因而就义了小局部可靠性换区更高的程序性能，将blocking设置为false。
4.4 小结
这次的问题排查经验，我播种了几点感悟，和大家分享一下：
1）要对线上告警放弃敬畏之心
咱们应该敬畏每一个线上告警，器重每一条谬误日志。现实情况是大多数时候告警只是因为网络抖动，短暂的突发流量等，是能够自行复原的，这就像狼来了的故事一样，让咱们放松了警觉，导致咱们可能会错过真正的问题，给零碎带来重大劫难，给业务带来损失。
2）刨根问底
告警只是表象，咱们须要搞清楚每个告警的外表起因和根本原因。比方这次的接口超时告警，只有剖析出”copy文件耗尽磁盘IO，导致日志打印线程block“这个根本原因后，能力给出优雅正当的解决方案。说起来简略，实操起来可能会遇到很多艰难，这要求咱们有清晰的问题排查思路，有良好的的零碎可观测性建设，有扎实的技术基本功和不找到”真凶“永不放弃的信心。
最初心愿我的这次问题排查经验可能让你有所播种，有所启发。我也将本文用到的超时问题排查思路整顿成了流程图，供大家参考。你有遇到过哪些线上故障呢？你的排查思路是怎么的呢？欢送留言交换探讨。