容易忽视的细节：Log4j 配置导致的零点接口严重超时
作者：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。
通过堆栈信息可以分析出 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“这个根本原因后，才能给出优雅合理的解决方案。说起来简单，实操起来可能会遇到很多困难，这要求我们有清晰的问题排查思路，有良好的的系统可观测性建设，有扎实的技术基本功和不找到”真凶“永不放弃的决心。
最后希望我的这次问题排查经历能够让你有所收获，有所启发。我也将本文用到的超时问题排查思路整理成了流程图，供大家参考。你有遇到过哪些线上故障呢？你的排查思路是怎样的呢？欢迎留言交流讨论。
版权声明: 本文为 InfoQ 作者【vivo互联网技术】的原创文章。
原文链接:【http://xie.infoq.cn/article/09ee367e48c3d4ead4a888e23】。文章转载请联系作者。
官方公众号：vivo互联网技术，ID：vivoVMIC 2020-07-10 加入
分享 vivo 互联网技术干货与沙龙活动，推荐最新行业动态与热门会议。
评论