一、前言
前不久,我们的实时报价服务(下文统称 sirius)出现了偶发接口超时的情况,经过逐层的排查,排除了所有软件类因素,将问题原因定位在硬件层面的RAID卡。
本文主要介绍了问题的发生过程、排查过程、结论,最后会介绍一些通用的性能类问题的排查方法。
PS:由于本文内容的特性,其中包含了大量的监控信息和对监控的分析,阅读时重点关注此类信息,可以帮助你更好的理解内容。
二、sirius 服务简介
sirius 是去哪儿酒店业务中最核心的服务之一,提供主流程中最核心4个的接口:
- L页,List,查询符合条件的酒店列表及每个酒店的最低价
- D页,Detail,在L页中选择一家酒店,查看该酒店的所有报价详情
- B页,Booking,在D页选择一条报价进行预定,填写入住人信息(校验库存、价格、优惠等是否发生变化)
- O页,Order,下单支付(二次校验库存、价格、优惠等信息)
简化后的业务链路图如下:
三、发生过程
- 2024-02-10(大年初一)
- 接到 主站 的反馈,D页即超时率上涨
- 初步排查发现 org.apache.dubbo.remoting.TimeoutException异常增多
- 尝试对服务进行重启,于16:00左右全部重启完成,监控恢复
- 给出初步结论:由于 sirius 运行时间太长(7天)导致的偶发单机GC问题
- 当日监控如图
- 2024-02-17(大年初八)
- 上午11:09,接到 主站 的反馈,D页超时率又开始上涨
- 按照上次的经验,开始操作批量重启,于13:00全部重启完成,超时率有下降,但没有完全恢复
- 之后对于出现 dubbo 超时异常较多的 pod 进行删除重建,于15:35左右,超时率基本恢复;于17:10,超时率完全恢复
- 此时,其实已经可以推翻之前的结论,但当时没有想这么多
- 当日监控如图
- 2024-03-01
- 接到主站反馈,在02-24那一天,D页超时率也出现了同样的上涨现象
- 此时, sirius 离上一次发布只过去了一天,在结合02-17的现象,完全推翻了之前的结论,开始拓宽思路进行排查
- 当日监控如图
四、排查过程
(一)发现问题和宿主相关
初步排查,发现超时的现象并不是所有 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(周五)
从上面的图中可以总结出两个现象:
- 周期规律性
- 在每周六的11:00左右,超时率开始上涨
- 其他非周六时段,则没有任何的周期规律性
- 超时率上涨的情况,有恶化的趋势,体现在两个方面
- 超时率逐渐变高,从 0.05% 到 0.5%,上涨了10倍
- 持续时间越来越长,从2小时 增加到 8小时
直觉上,周期规律性比较关键,也比较重要,就先从它入手;从周期规律性很容易联想到定时任务,于是就有了几个猜测:
- 应用侧
- sirius 没有定时任务
- 退一万步讲,即使有连我们自己都不知道 的 陈年老代码,也不会每次都只出现在特定宿主上
- 基础架构侧(可以理解为基础架构组对全公司所有 Java 类应用所做的增强功能)
- 此猜测过于匪夷所思,几乎不可能,列举出来只是为了逻辑上的严密性
- 同样也解释不了只在特定宿主上出问题的现象
- 宿主侧(操作系统定时任务)
- 联系运维组排查,得到的答案是:所有业务应用的宿主上的 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波形如图:
从图中可以很明显的看出:
- 数量和吞吐的波形极其相似
- 考虑到极端情况下,比如一次读/写 1GB数据时,数量和吞吐的波形肯定是完全不同的
- 但从大数据量的样本统计来看,仍然是相似的
- 使用率 是 read 和 write 的叠加
- 使用率尖刺部分主要来自于 read ,即数量、吞吐监控中蓝色的波形
- 使用率底部的波形来自于 write ,即数量、吞吐监控中橙色的波形(15:00左右有个明显的上涨)
- 使用率较低,最高只有1.15%
而在问题时段,IO波形如图:
从图中同样可以看出:
- 数量和吞吐的波形仍然非常相似
- 使用率明显变高(max从1.15%增加到34%,增长了30倍),使得它的波形和数量、吞吐看起来完全不相关了
- 更准确的来说,是出现了除 read/write 之外的第三种波形,即使用率 = read + write + ?,而且这第三种波形的值相对于 read/write 来说非常大
- 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
- 型号、使用年限等
按照这几个方向,对照查询了 异常宿主 和 正常宿主 相关的信息,发现:
- 使用 lspci | grep RAID 或 lshw -class storage 查看 RAID 卡信息,发现异常宿主都有 RAID 卡,且型号一致,但也有正常宿主是这个 RAID 卡型号
- 使用 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