从接口超时到RAID

一、前言

前不久，我们的实时报价服务（下文统称 sirius）出现了偶发接口超时的情况，经过逐层的排查，排除了所有软件类因素，将问题原因定位在硬件层面的RAID卡。

本文主要介绍了问题的发生过程、排查过程、结论，最后会介绍一些通用的性能类问题的排查方法。

PS：由于本文内容的特性，其中包含了大量的监控信息和对监控的分析，阅读时重点关注此类信息，可以帮助你更好的理解内容。

二、sirius 服务简介

sirius 是去哪儿酒店业务中最核心的服务之一，提供主流程中最核心4个的接口：

1. L页，List，查询符合条件的酒店列表及每个酒店的最低价
2. D页，Detail，在L页中选择一家酒店，查看该酒店的所有报价详情
3. B页，Booking，在D页选择一条报价进行预定，填写入住人信息（校验库存、价格、优惠等是否发生变化）
4. O页，Order，下单支付（二次校验库存、价格、优惠等信息）

简化后的业务链路图如下：

三、发生过程

1. 2024-02-10（大年初一）
2. 接到 主站 的反馈，D页即超时率上涨
3. 初步排查发现 org.apache.dubbo.remoting.TimeoutException异常增多
4. 尝试对服务进行重启，于16:00左右全部重启完成，监控恢复
5. 给出初步结论：由于 sirius 运行时间太长（7天）导致的偶发单机GC问题
6. 当日监控如图
7. 2024-02-17（大年初八）
8. 上午11:09，接到 主站 的反馈，D页超时率又开始上涨
9. 按照上次的经验，开始操作批量重启，于13:00全部重启完成，超时率有下降，但没有完全恢复
10. 之后对于出现 dubbo 超时异常较多的 pod 进行删除重建，于15:35左右，超时率基本恢复；于17:10，超时率完全恢复
11. 此时，其实已经可以推翻之前的结论，但当时没有想这么多
12. 当日监控如图
13. 2024-03-01
14. 接到主站反馈，在02-24那一天，D页超时率也出现了同样的上涨现象
15. 此时， sirius 离上一次发布只过去了一天，在结合02-17的现象，完全推翻了之前的结论，开始拓宽思路进行排查
16. 当日监控如图

四、排查过程

（一）发现问题和宿主相关

初步排查，发现超时的现象并不是所有 sirius 服务共有的，只在个别 pod 上存在。

再对此前几次出问题的 pod 做进一步排查，发现它们当时所在的宿主有重合（用 pod_name/pod_ip + 时间，可以在 k8s 日志中查到当时 pod 所在的宿主）。

至此，我们可以得出阶段性结论：超时问题不是所有 sirius 服务共有的，和宿主机相关，并且定位了几台有嫌疑的宿主机。

（二）发现周期规律性

3次出问题之间间隔都是7天，不太可能是巧合，怀疑问题有周期规律性。

在D页接口超时率的监控中，沿时间线往前回溯，发现在每个周六的同时段，都有同样的现象，最早可以追溯到2023-10-28。

以下是从2023年10月开始，每月最后一个周六的监控图：

2023-10-28（周六）

2023-11-25（周六）

2023-12-30（周六）

2024-01-27（周六）

2024-02-24（周六）

再来看几个非周六的监控图：

2024-02-22（周四）

2024-02-23（周五）

从上面的图中可以总结出两个现象：

1. 周期规律性
2. 在每周六的11:00左右，超时率开始上涨
3. 其他非周六时段，则没有任何的周期规律性
4. 超时率上涨的情况，有恶化的趋势，体现在两个方面
5. 超时率逐渐变高，从 0.05% 到 0.5%，上涨了10倍
6. 持续时间越来越长，从2小时 增加到 8小时

直觉上，周期规律性比较关键，也比较重要，就先从它入手；从周期规律性很容易联想到定时任务，于是就有了几个猜测：

1. 应用侧
2. sirius 没有定时任务
3. 退一万步讲，即使有连我们自己都不知道 的 陈年老代码，也不会每次都只出现在特定宿主上
4. 基础架构侧（可以理解为基础架构组对全公司所有 Java 类应用所做的增强功能）
5. 此猜测过于匪夷所思，几乎不可能，列举出来只是为了逻辑上的严密性
6. 同样也解释不了只在特定宿主上出问题的现象
7. 宿主侧（操作系统定时任务）
8. 联系运维组排查，得到的答案是：所有业务应用的宿主上的 crontab 都是相同的，没有任何一台宿主有特殊的 crontab

至此，我们可以得出阶段性结论：周期规律性过于明显，明显到几乎可以判定根因来自 sirius 之外，sirius 是被影响的一方。

（三）发现异常IO使用率波形

对第一步里定位到的有嫌疑的宿主的监控进行分析。

发现在问题时段（每周六11:00至19:00），有三个指标也出现了同样的波动：CPU wait 、磁盘IO使用率、进程 blocked ，如下图：

与D页接口超时率的监控对比，发现：

• 波形具有相似性
• 持续时间一致
• 有相同的周期规律性

不难判断出，这些指标和D页接口超时率之间有强相关性，需要进一步把相关性转变为因果关系。

不妨先假设 IO 波动是结果，因果链为：网络超时 → 超时异常增加 → 异常日志增加 → IO增加 → CPU wait 、进程 blocked 上涨，逻辑上貌似说得通。

从网络超时 + 周期规律性，联想到了网络相关的硬件（如交换机），联系网络组排查，反馈在那个时间段，这些宿主所在的交换机并没有什么异常。

而且，网络波动带来的影响往往是比较大的，不太会是这么轻微的超时率上涨。

继续假设， CPU wait 、磁盘 IO 使用率、进程 blocked 这三个指标中， IO 使用率最有可能是因，其它两个指标则更像是结果。

在宿主监控中，和磁盘 IO 相关的指标有三个：使用率、数量、吞吐，其中数量、吞吐会区分 Read 和 Write ，而使用率不区分。

对这几个指标进一步排查，发现了一个诡异的点：在问题时段，使用率的波形和数量、吞吐的波形不相关了。

正常来讲， IO 使用率 = 读 + 写，所以它的波形和数量、吞吐的波形应该具有相关性。

比如，在正常时段，IO波形如图：

从图中可以很明显的看出：

1. 数量和吞吐的波形极其相似
2. 考虑到极端情况下，比如一次读/写 1GB数据时，数量和吞吐的波形肯定是完全不同的
3. 但从大数据量的样本统计来看，仍然是相似的
4. 使用率 是 read 和 write 的叠加
5. 使用率尖刺部分主要来自于 read ，即数量、吞吐监控中蓝色的波形
6. 使用率底部的波形来自于 write ，即数量、吞吐监控中橙色的波形（15:00左右有个明显的上涨）
7. 使用率较低，最高只有1.15%

而在问题时段，IO波形如图：

从图中同样可以看出：

1. 数量和吞吐的波形仍然非常相似
2. 使用率明显变高（max从1.15%增加到34%，增长了30倍），使得它的波形和数量、吞吐看起来完全不相关了
3. 更准确的来说，是出现了除 read/write 之外的第三种波形，即使用率 = read + write + ?，而且这第三种波形的值相对于 read/write 来说非常大
4. sda、sdb 的使用率都出现了异常波动，如下图

咨询运维同学得知，我们的应用日志都存储在 sdb 中，理论上不会对 sda 产生任何的 IO 。

同时，我们找到了另外一台宿主机 node303，当时（2024-02-24）并没有运行 sirius 服务（从 CPU 监控可以判断出来），也有异常的 IO 使用率波形，如下图：

至此，我们可以得出阶段性结论：证实根因和 sirius 无关，大概率和异常的 IO 使用率波形相关，需要找到异常 IO 的来源。

（四）寻找异常 IO 来源

找到异常宿主列表

既然和异常 IO 使用率波形相关，就可以通过宿主监控来快速锁定有问题的宿主；sirius 共有100个独占宿主，筛选出在周六有异常 IO 使用率波形的，共21台。

因为问题是周期性稳定复现的，刚好第二天就是周六（2024-03-02），决定在问题发生时现场排查。

准备工作

在问题宿主中，选择2台作为对照组

• node307，正常运行2个 sirius pod（单个宿主的硬件资源只够运行2个 pod）。
• node308，提前把这个宿主上的2个 pod 摘机，确保在问题时段不会接线上流量，之前的日志会被定期清理掉，所以理论上这台宿主上的 IO 应该非常少。

等到03-02上午11:00 左右，问题出现时，观察如下几个情况：

• 对比307和308上的进程，看是否有差异
• 找出308到底在做什么 IO 操作
• 验证刚筛选出的异常宿主列表是否正确
• 主要是验证一下，是否有出了问题的 pod，但没有在异常宿主列表中
• 搜集 trace，以待进一步分析

我和运维组同学分了两条线并行，我负责业务侧，运维同学负责宿主侧。

现场-应用侧

找到了所有出问题的 pod ，无一例外，它们所在的宿主 和 之前筛选出的异常宿主列表完全一致。

同时搜集了一些 trace ，观察下图中时间轴那一列，发现都是 dubbo 发起调用超时， consumer 发出请求后，过了很久， producer 才接收到。

对 dubbo 超时异常进一步分析，发现原因主要有2种：

第一种， Server 超时，关键字为"Waiting server-side response timeout by scan timer"，在 kibana 中搜索，如图：

整体没有规律，在周六也没有突增，排除。

第二种， Client 超时，关键字为"Sending request timeout in client-side by scan timer"，在kibana中搜索，如图：

图一：7天内的日志

图二：当天10:00至19:00的日志

从图一可以发现 Client 超时在周六有突增，而且图二的波形和D页超时率的波形有相似性，可以得出因果关系：dubbo 调用时 Client 端超时 → D页接口超时。

现场-宿主侧

不出意外，307和308上都出现了异常 IO 使用率的波形，如图：

可以看到，307的使用率比308高很多，波动的持续时间也长很多。

运维组同学反馈307和308上的进程没有差异，308上没有发现高 IO 的进程，无法确认异常 IO 的来源。

至此，我们可以得出阶段性结论：异常 IO 不来自于宿主上的进程，WHAT？？？HOW？？？

（五）寻找宿主差异

大胆假设

既然排除了所有软件类的因素，那么我们的服务除了软件还有什么呢？硬件！

和磁盘 IO 相关的硬件，想到了两个可能：

• 磁盘碎片整理
• 宿主是否有 RAID，RAID 是否有周期性 IO

磁盘碎片方向

经过思考，磁盘碎片一定是和文件相结合，才会产生问题，而文件是操作系统层的概念，和磁盘无关。

也就是说，磁盘自己根本不关心碎片问题；所以即便是整理碎片，也应该由操作系统发起，而非磁盘发起。

而如果是操作系统发起的，一定会有对应的进程，也会在 IO 数量、吞吐的监控中留下痕迹，和我们看到的现象不符。

所以此方向被排除。

RAID 方向

由于自己对 RAID 了解太少，做了一些探索，了解到 RAID 有不同的实现方式：

• 硬件方式，即 RAID 卡
• 软件方式，通常由操作系统提供

并且在 wikipedia - RAID 中发现了关于 RAID 周期性 IO 的相关信息：

大致翻译一下：RAID 控制器（即 RAID 卡）会周期性的读取并检查磁盘阵列中的所有块。

查到这里，心里才有了接近真相的感觉，接下来就是求证了。

求证

既然只是特定宿主有问题，那么可以肯定，异常宿主 和 正常宿主之间，必然存在差异，大概有几个方向：

• 先验证宿主是否有 RAID 卡，如果没有，则此猜测不成立
• 如果有 RAID 卡，它们的型号是否有差别
• 宿主的磁盘是否有差别（ RAID只是个控制器，不具备存储功能，真正的 IO 还是要走磁盘），主要关心如下几种信息：
• 类型：hdd or ssd
• 型号、使用年限等

按照这几个方向，对照查询了 异常宿主 和 正常宿主 相关的信息，发现：

1. 使用 lspci | grep RAID 或 lshw -class storage 查看 RAID 卡信息，发现异常宿主都有 RAID 卡，且型号一致，但也有正常宿主是这个 RAID 卡型号
2. 使用 lsblk -S 查看磁盘信息，发现异常宿主的磁盘型号一致，但是也有正常宿主是这个磁盘型号

这一步里，我们从反面确定了只要不是这个 RAID 卡和磁盘型号的宿主，都没有出问题；也就是说，这两个型号的组合是出问题的必要条件，但还不够充分。

至此，我们可以得出阶段性结论：异常 IO 大概率来自 RAID 卡，且和宿主的 RAID 卡型号、磁盘型号有关。

（六）运维组给的结论

周期性的 RAID 巡检计划

LSI MegaRAID xxxxxx 型号的RAID卡有定期巡检功能，默认开启；出厂默认配置的触发时间点为 格林威治时间 每周六凌晨3点（即北京时间每周六 上午11点），如下：

----------------------------------------------- Ctrl_Prop Value ----------------------------------------------- CC Operation Mode Concurrent # CC = Consistency Check CC Execution Delay 168 # 循环周期：168小时 = 1周 CC Next Starttime 03/09/2024, 03:00:00 # 下次执行时间 CC Current State Stopped CC Number of iterations 97 CC Number of VD completed 2 CC Excluded VDs None -----------------------------------------------

关于磁盘、 RAID 卡型号的问题

我们所有的宿主都有 RAID 卡，但不同的宿主对应的情况不同，运维组同学给出的结论为特定场景下才会出问题：

• RAID 卡型号为 LSI MegaRAID xxxxxx
• 磁盘为 ssd 且为 raid1
• 运行1年以上

此型号的 RAID 卡有什么问题？

以下是 RAID供应商给出的解释：

LSI阵列卡默认会开启PR（Patrol Read巡检读取）和CC（Consistency Check一致性检查）功能，当阵列卡在执行PR或者CC时，如果串口同时存在频繁的I2C信息打印，此时会增加阵列卡的繁忙程度，导致硬盘时延增大。对于一些IO时延要求较高的场景（如分布式存储），会对业务造成影响。

94/95系列阵列卡固件（MR7.20及之前版本）对于I2C信息打印的处理机制是以中断方式向串口输出。由于串口打印日志的效率很低，当日志打印任务增加，同时执行PR或CC任务时，会增加阵列卡的繁忙程度，从而造成硬盘的IO延时增大。94/95锡类阵列卡升级阵列卡固件版本至MR7.21或之后的版本，新版本固件将I2C信息打印从串口转移到RAM中，提升了阵列卡对日志写入效率，从而解决了此问题。

但当前9361阵列卡的最新固件版本描述中未见解决此问题的说明，所以为了避免影响业务，当前只能是关闭PR，CC来保证业务的正常运行。

简单翻译一下：固件的实现存在性能问题，无法解决，只能升级固件或关闭巡检。

至此，根因已经明确了，但我们还有一个问题没有解释清楚：IO 高是怎么导致超时的？

（七）异常 IO 是怎么导致超时的？

sirius 的日志都是异步的，正常来讲，不会阻塞请求。

带着疑问研究了 logback 相关的配置，发现 logback 的异步日志，在队列满时，默认是会阻塞请求的，如下：

进一步想，既然根源在于 IO 高，那么所有的 IO 类操作都会被影响到，比如应用的 logback 日志、 tomcat 的 access 日志、甚至于我们在宿主上执行的 IO 类命令（tail、grep......）。

带着这个想法，在2024-03-02现场的 tomcat access 日志中找到了证据。

以下为某个有异常的pod上11:36:43和11:39:04两个时间点前后的日志：

# 第一列为响应时间，第二列为时间点 117 [02/Mar/2024:11:36:36 91 [02/Mar/2024:11:36:36 4055 [02/Mar/2024:11:36:43 5716 [02/Mar/2024:11:36:43 5654 [02/Mar/2024:11:36:43 3419 [02/Mar/2024:11:36:43 5727 [02/Mar/2024:11:36:43 5361 [02/Mar/2024:11:36:43 6769 [02/Mar/2024:11:36:43 6222 [02/Mar/2024:11:36:43 1932 [02/Mar/2024:11:36:43 6808 [02/Mar/2024:11:36:43 3705 [02/Mar/2024:11:36:43 6818 [02/Mar/2024:11:36:43 6388 [02/Mar/2024:11:36:43 5713 [02/Mar/2024:11:36:43 2609 [02/Mar/2024:11:36:43 2614 [02/Mar/2024:11:36:43 1989 [02/Mar/2024:11:36:43 6154 [02/Mar/2024:11:36:43 4531 [02/Mar/2024:11:36:43 5211 [02/Mar/2024:11:36:43 4753 [02/Mar/2024:11:36:43 6432 [02/Mar/2024:11:36:43 6420 [02/Mar/2024:11:36:43 223 [02/Mar/2024:11:36:43 2271 [02/Mar/2024:11:36:43 6602 [02/Mar/2024:11:36:43 ... ... ... 339 [02/Mar/2024:11:38:57 155 [02/Mar/2024:11:38:57 154 [02/Mar/2024:11:38:57 3831 [02/Mar/2024:11:39:00 4856 [02/Mar/2024:11:39:04 4002 [02/Mar/2024:11:39:04 5740 [02/Mar/2024:11:39:04 4285 [02/Mar/2024:11:39:04 5803 [02/Mar/2024:11:39:04 3684 [02/Mar/2024:11:39:04 5898 [02/Mar/2024:11:39:04 4751 [02/Mar/2024:11:39:04 7672 [02/Mar/2024:11:39:04 5940 [02/Mar/2024:11:39:04 5698 [02/Mar/2024:11:39:04 4992 [02/Mar/2024:11:39:04 3852 [02/Mar/2024:11:39:01 5318 [02/Mar/2024:11:39:04 5926 [02/Mar/2024:11:39:04 5969 [02/Mar/2024:11:39:04 4388 [02/Mar/2024:11:39:04 5717 [02/Mar/2024:11:39:04 4819 [02/Mar/2024:11:39:04 7307 [02/Mar/2024:11:39:04 5896 [02/Mar/2024:11:39:04 5442 [02/Mar/2024:11:39:04 5815 [02/Mar/2024:11:39:04

可以发现，在11:36:36~11:36:43之间、11:38:57~11:39:04之间，几乎没有任何的日志。

这是因为有大量的请求一直被阻塞，直到这两个时间点才返回，响应时间最高甚至超过7秒。

而在这两个时刻，此 pod 所在宿主的 IO 使用率都出现了非常高的尖刺，超过80%。

至此，完整的因果链已经很清晰了：宿主做 RAID 一致性检测 → 宿主 IOPS 下降 → 应用的日志队列堆积 → 记日志产生等待 → 各种异步请求(dubbo/redis)超时 → sirius 接口超时

而为什么对 dubbo 请求影响最大呢，是因为 sirius 开启了 dubbo-access 日志，且日志中记录了请求和响应的详细信息，非常大，且不允许丢弃。

2024-03-09，我们进行了一次验证，在降级了 logback 配置之后，在异常宿主上，没有再出现超时的问题。

五、结论

（一）问题的触发条件

• 硬件侧
• 特定型号的 RAID 卡 + 开启了 RAID 巡检计划
• ssd 磁盘 + raid1 + 长使用年限
• 软件侧
• 应用的磁盘 IO 量大：这种情况下， IO 使用率会明显增加，巡检的持续时间也会明显的延长，从3小时增加到8小时
• 应用对响应时间比较敏感：只有对响应时间敏感，问题才有可能被发现

而 sirius 服务的部分宿主刚好满足以上所有条件。

（二）问题的影响范围

目前只发现了 sirius 一个被影响方，影响也很小。

但理论上只要满足条件，就会被影响到；对应的现象是每周六上午11点开始，某些指标开始有轻微的波动，持续3到8小时，之后自愈。

（三）损失评估

虽然持续时间很长，从2023-10至2024-03，将近半年，但影响太小，未达到故障标准。

考虑到接口超时的现象有逐渐恶化的趋势，属于及时止损，避免了更大的负面影响。

（四）解决方案

• 运维侧
• 在全司范围内，关闭该型号RAID卡的所有巡检计划（PR、CC）
• 业务侧
• 减少非必要的日志记录

六、其他问题

（一）2024-02-10，sirius 全部重启完之后，超时率为什么恢复了？

巧合，而且时间过去太久，已经无法追溯当时操作的精确时间点了。

（二）问题为什么从2023-10才开始暴露出来？

sirius 在2023-10切换成了独享型 大规格pod的部署模式。

在这之前，sirius 有超过600个 pod，和全司所有业务共用一个很大的宿主池，所以 sirius 的 IO 压力被分散了，而且大部分其他业务的 IO 压力远没有 sirius 大，所以问题没有暴露出来。

而切换之后，sirius 缩减到200个 pod，使用固定的一批宿主池（100台），所以 sirius 的所有 IO 压力都要由这100台宿主承担，问题才得以暴露出来。

（三）RAID 巡检期间，为什么只有 IO 使用率有异常波形，次数和吞吐量没有？

只有通过系统调用发起的 IO，才会被记录到磁盘 IO 相关的监控中；RAID 巡检的相关指令是由 RAID 卡直接下发给磁盘，不经过操作系统。

IO 使用率其实也没有记录 RAID 巡检所带来的 IO，但这个指标是从耗时的维度来衡量的，巡检时，磁盘繁忙，导致对 IO 系统调用的处理能力下降，导致耗时升高。

所以是 RAID 巡检影响了 IO 系统调用的耗时。

（四）超时现象逐渐恶化的趋势是怎么来的？

不知道，但有几个猜测：

• 和磁盘数据量有关
• 和磁盘碎片化程度有关（ssd 同样也有碎片问题，只是对性能的影响远没有 hdd 那么严重；而且 ssd 的寿命是根据擦除次数来的，所以在 ssd 上开启碎片整理，只会加速损耗 ssd 的寿命）

七、通用的性能类问题排查方法

本部分内容是大多基于个人的理解和经验，难免有主观和局限的地方，大家如有不同的看法，欢迎交流探讨！

（一）方法层面

• 找规律：在异常情况中寻找规律或共性
• 变化规律
• 相关性规律
• 周期性规律
• ......
• 作对照
• 排查问题时，大脑里应该始终绷着的一根弦
• 从差异点入手，可以大幅提高排查问题的效率
• 用一切手段复现问题
• 大胆假设，小心求证

（二）技术层面

• 计算机领域内，和性能相关的，无外乎四类：CPU、内存、磁盘、网络
• 绝大部分的性能问题，根因都可以归到其中的一类
• 这四类所带来的影响都不是点的问题，而是面的问题，找到了影响面，也就找到了问题的所在
• 根据实际情况建立猜疑链
• 应用 → 中间件 → ...... → 操作系统 → 硬件 → 物理世界
• 不断向下，不跳步、不遗漏
• 平时多拓宽知识面
• 让自己在关键时刻能问出正确的问题，再利用 搜索引擎 + AI 找到答案
• 当前的技术环境下，问出正确的问题 比 知道答案 要重要的多得多
• 推荐阅读《性能之巅》，书中包含了非常全面的方法论和工具集，如果你想成为性能专家，这一本不容错过

（三）道的层面

• 信念感
• 99.99%的性能问题都是有原因的
• 不要轻易的归结为”网络波动“或”性能不稳定“之类的借口；我们每一次归为这些借口，就错过了一次突破自我的机会
• 敢于质疑”权威“
• 质疑要有事实基础 和 合理性
• 质疑的事情要有能力证明 或 证伪
• 对巧合的警惕：巧合的背后往往有深层次的原因
• 良好的心态
• 性能专家不是速成的，需要从相对简单的问题入手，建立正反馈，培养自信心
• 很多问题，想要查出来，确实需要一些运气成分；所以实在查不出来的时候，也请不要气馁
• 做事不设边界，回归到解决问题本身

八、参考资料

• logback异步日志：https://logback.qos.ch/manual/appenders.html#AsyncAppender
• RAID 周期性巡检：https://en.wikipedia.org/wiki/RAID#Integrity
• MegaRAID芯片支持的巡检功能：https://techdocs.broadcom.com/us/en/storage-and-ethernet-connectivity/enterprise-storage-solutions/storcli-12gbs-megaraid-tri-mode/1-0/v11869215/v11673749/v11673787/v11675132.html
• SSD磁盘碎片：https://en.wikipedia.org/wiki/Solid-state_drive#Hard_disk_drives，搜索fragmentation

作者:李成亚

来源-微信公众号:Qunar技术沙龙

出处:https://mp.weixin.qq.com/s/riHDAecplHoSxV8_Kz-u_Q