一、问题发现
我所负责的商城活动系统用于承接公司线上官方商城的营销活动，最近突然收到凌晨0点的服务超时告警。
营销活动类的系统有如下特点：
- 营销活动一般会0点开始，如红包雨、大额优惠券抢券等。
- 日常营销活动的机会刷新，如每日任务，每日签到，每日抽奖机会的刷新等。
营销活动的利益刺激会吸引大量真实用户及黑产前来参与活动，所以流量在0点会迎来一波小高峰，也正因如此线上偶现的服务超时告警起初并未引起我的注意。但是接下来的几天，每天的凌晨0点都会收到服务超时告警，这引起了我的警惕，决定一探究竟。
二、问题排查
首先通过公司的应用监控系统查看了0点前后每分钟各接口的P95响应时间。如下图所示，接口响应时间在0点时刻最高达到了8s。继续查看锁定耗时最高的接口为商品列表接口，下面就针对这个接口展开具体的排查。
2.1 排查思路
正式排查之前，先和大家分享下我对接口超时问题的排查思路。下图是一个简化的请求流程。
- 用户向应用发起请求
- 应用服务进行逻辑处理
- 应用服务通过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。
通过堆栈信息可以分析出2点：
- 处于blocked状态的线程都是日志打印
- 所有的线程都是被线程名为“catalina-exec-408”阻塞
追踪到这里，慢服务的表层原因就清楚了。被线程catalina-exec-408阻塞的线程，一直处于blocked状态，导致服务响应超时。
三、根因分析
表层原因找到以后，我们一起拨开层层迷雾，寻找真相背后的真相吧！
所有慢服务的线程都是在打印日志的时候被线程catalina-exec-408阻塞。那么线程catalina-exec-408在做什么呢？
可以发现，在00:00:18.858时刻，该线程在打印登录态校验失败的日志，也并无复杂的处理逻辑。难道是该线程打印日志慢，阻塞了其他线程吗？带着这个疑问，我开始深入日志框架的源码寻找答案。
我们的项目使用的日志框架是slf4j + log4j。根据被阻塞的线程栈信息我们定位到这段代码如下：
可以看到堆栈信息中的204行是synchronized代码块，对其它线程造成阻塞的这是这块代码。那么synchronized代码块内部逻辑是什么呢？为什么要执行很久呢？下面是synchronized代码块中的核心逻辑：
可以看到，这块逻辑就是将日志写入所有配置的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），得到结果如下：
正是快照中的脚本/bin/sh /scripts/cutlog.sh，每天0点执行。具体的脚本内容如下：
我们从脚本中找到了高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“这个根本原因后，才能给出优雅合理的解决方案。说起来简单，实操起来可能会遇到很多困难，这要求我们有清晰的问题排查思路，有良好的的系统可观测性建设，有扎实的技术基本功和不找到”真凶“永不放弃的决心。
最后希望我的这次问题排查经历能够让你有所收获，有所启发。我也将本文用到的超时问题排查思路整理成了流程图，供大家参考。你有遇到过哪些线上故障呢？你的排查思路是怎样的呢？欢迎留言交流讨论。
