查看原文
其他

风云再续:他抖任他抖,IO诊断在我手

李光水、毛文安 OpenAnolis龙蜥 2022-05-30

编者按青囊,英文名sysAK(system analyse kit),龙蜥社区(OpenAnolis)的一个开源项目,聚集阿里百万服务器的多年运维经验,通过对这些经验进行抽象总结出典型场景,针对不同的运维需求提供了一系列工具,形成统一的产品进行服务。工具集包含了很多强大的底层系统运维能力,这些工具融合到了不同产品的运维平台中,实现高效的自动化运维。本系列文章将青囊拟人化,穿插进狄仁杰判案中,带领大家领略青囊在网络、IO、内存等领域叱咤风云的魅力。

本文作者毛文安(品文)为系统运维SIG负责人、李光水为系统运维SIG核心成员。
相关阅读:
《netinfo:揭开网络抖动面纱的神器

《coredump 瘦身风云》

一、引子

话说上回青囊协助曾泰处理完官道的网络抖动大案之后,接到急报说邗沟发生盐船剧烈抖动以致倾覆的大案,狄仁杰又带上青囊火速启程赶往邗沟。

二、邗沟现场断案

此时大运河上一片沉寂,青囊递给狄仁杰两片从案发现场打捞上来,标记有“iostat印记”的盐船龙骨碎片,沉声道,“邗沟覆船案,两年内已发生多次。每到邗沟,大风忽起,船只便开始抖动摇晃;更甚者,船只直接解体。为此,我收集到解体船只的碎片,发现这船体抖动确有玄机。”运河之上押运官盐的船只,遇风浪或保持稳健前行,或摇晃解体,如能知晓各部件抖动之时间长短,分析其关联部位,便能揪出幕后真凶。

面对此龙骨碎片,青囊不禁联想到之前处理 IO 问题时的一件奇事,当时系统也是抖得厉害,blktrace 等工具无法清楚解释在哪里抖的,后来便研究了一下 IO 领域的抖动问题,它表现为在一段时间内,IO 性能无法始终保持一致,会突发性的下跌到不符合我们所预期的性能范围。就业务影响而言,数据存储效率低下、无法维持稳定的对外服务,影响用户体验。目前看邗沟覆船案,极有可能跟 IO 抖动有关,不禁喜上眉梢。

狄仁杰接过碎片,仔细端详 iostat 中的各指标,沉吟片刻道,“磁盘 vda 乃官家所部署的云盘,号称 us 级别延迟,现在可以看到写 iops 最高也不过十、写 IO 最高也不过百 KB/s,何以在如此低的 IO 负载情况下,竟有数十ms的await冲高,着实令我百思不得其解。”

await 是一个从时间维度描述 IO 性能的指标,表示为单位时间内每个 IO 请求被处理的平均耗时,单位为微秒或者毫秒,亦可理解为 IO 的响应时间。这个指标是内核 IO 子系统 block 层透出来后经过系统工具 iostat 加工之后的结果,因此,它既包含了一个 IO 在 IO 软件栈中处理的时间,也包含了磁盘的处理时间。因此 await 冲高现象是 IO 抖动问题中比较典型的特征。

“狄阁老莫愁,针对此类 IO 抖动问题,鄙人正巧最近研制出一诊断利器——iosdiag,已经集成到 sysAK 的工具集,或许可为阁老排忧解难”,青囊笑道。

众人目光炯炯,恍若流光般向青囊汇聚而去,狄仁杰笑道,“青囊之神技,果真层出不穷,且与我等说来,何为 iosdiag?”

三、 iosdiag 功能介绍

青囊道:

iosdiag,是 sysAK 工具平台中的 IO 存储诊断工具,已具备 IO 时延探测功能、IO HANG 诊断功能两大功能,前者用于分析当前 IO 存储链路中的时延抖动问题并确定抖动边界,后者可检测当前系统中 IO HANG 事件并确定问题边界。

IO 时延,指 IO 在其生命周期内所经历的 IO 各路径上的时间损耗,通常情况下,可以分为 OS 耗时和磁盘耗时,而 OS 内比较受关注的就是 IO 栈了,IO 栈里面又包含复杂的 block、驱动等部分;正所谓每每碰到 IO 抖动问题,必有人抓耳挠腮、暗无天日呐。

iosdiag 中的 iolatency工具,实现了 IO 时延探测功能,最喜隐匿于内核 IO 栈之中,竟能眼观六路,耳听八方,以迅雷不及掩耳之势,将各 IO 在生命周期之内,不同关键路径上的时间戳信息尽收于乾坤宝袋之中;而后又基于此,计算 IO 路径上的所有时延数据,来确认 IO 耗时最大的路径(磁盘耗时或者软件内耗时),可谓神通广大,法力无边。

且 iosdiag latency 已经成功定位到多起线上 IO 抖动问题,目前具备如下特色:
  • 支持捕获 IO 延迟超过指定耗时的 IO

  • 支持获取 IO 各路径延迟信息,准确定界磁盘、OS 耗时(包含 block、驱动、磁盘、IO 结束耗时)问题

  •  信息格式化输出,更直观,具备完整单个 IO 信息、所有 IO 统计信息、进程级IO 耗时分析,能够直接了当的知道哪里出了问题

“甚好!知我者,真乃青囊也,此迷局当以 iosdiag latency 破之”,边听青囊介绍,狄仁杰一脸愁容渐渐消散,满面春风取而代之,如今已是柳暗花明,既有 iosdiag latency 利器在手,何不上去诊断一把。

四、iosdiag 抖动问题破解

狄仁杰早已迫不及待,让青囊运行了 sysak iosdiag latency,开始了激动人心的 IO 抖动诊断之旅。

[root@VM20200727-16 /root]#sysak iosdiag latency -b 10 -t 10
以上命令表示,sysak iosdiag latency 将在系统中运行 10 秒,并收集系统中该时间段内延迟超过 10ms 的 IO,随后退出诊断,届时,IO 在各路径上的延迟将无所遁形。时间 1 秒 1 秒过去,众人满怀期待,当看到 iosdiag 诊断结束之后,狄仁杰随即打开了诊断日志文件,果然大有玄机,而后众人发现,总共收集到 9 个IO,其中 flush/fua io 有 6 个,而经过统计主要 IO 耗时竟然集中在 OS 的 block 中(最大耗时 51.4ms)
... "diskname":"vda", "total_ios": 9, "flush/fua":6 "delays":[ ... { "component":"os(block)", "percent":"58.988%", "max":51442, "min":14, "avg":20686 }, { "component":"os(driver)", "percent":"0.034%", "max":22, "min":4, "avg":12 }, { "component":"disk", "percent":"40.966%", "max":51291, "min":250, "avg":14366 }, { "component":"os(complete)", "percent":"0.009%", "max":7, "min":2, "avg":3 } ] ...
“iosdiag 果真神器也!”,狄仁杰忍不住赞叹,朝青囊竖起了大拇指。

“只是现下已知 os(block) 耗时严重,可否进一步获悉耗时原因?”

“当然可以,狄阁老且看,诊断结果中不仅包含延迟分布统计信息,同时还包含延迟最大的 IO,我们可以将此 IO 展开来看,或可发现其中玄机”,青囊笑答曰。

"abnormal_seq":{ "summary":{ "check_time":"Thu Oct 14 11:21:36 2021", "event":"slow io", "component":"os(block)", "delay":"51442 us", "total_delay":"51738 us", "cpu":0, "comm":"jbd2/vda1-8 -> kworker/4:1H", "pid":"358 -> 352", "diskname":"vda", "op":"FWFS", "sector":59159840, "data_len":4096 }, "detail":{...} }

“此 IO 为 jbd2 线程发起的 flush/fua 请求(op: FWFS),总耗时 51.7ms,而 block 层耗时竟有 51.4ms,实在是不正常。正如我们对 block 层 flush 实现机制的理解,flush/fua 请求在真正写入数据前后,要执行多次 flush 请求,不仅要求串行执行,而且还需要 workqueue 的介入,繁琐至极。由此可见,有两种可能性导致此 IO 耗时长:workqueue 调度慢或者磁盘本身就慢。”

听完青囊的分析,狄仁杰面露喜色,认为已经离真相不远,追问,“不知是否还有信息可以查看进一步原因?”

“狄阁老此前是否留意到除了 os(block)路径耗时严重之外,还有 disk 路径也占据了 40% 的的耗时?由此,我料问题必定由磁盘引起,我们可再找一个捕获到的写 IO 请求展开来看”,青囊似乎早已了然于胸,淡然从诊断日志文件中随意取出一个写 IO 信息。

{ "summary":{ "check_time":"Thu Oct 14 11:21:36 2021", "event":"slow io", "component":"disk", "delay":"32465 us", "total_delay":"32520 us", "cpu":0, "comm":"jbd2/vda1-8 -> kworker/0:1H", "pid":"358 -> 357", "diskname":"vda", "op":"WS", "sector":59159848, "data_len":98304 }, "detail":{ "delays":[ {...}, { "component":"block", "delay":43 }, { "component":"driver", "delay":8 }, { "component":"disk", "delay":32465 }, { "component":"complete", "delay":4 } ], "points":[...] }}

至此众人发现,正常的写 IO,在磁盘侧的延迟竟然达到 32.4ms,同时此 IO 也是通过 workqueue 下发,但 block 侧的消耗也仅 43us,由此可见没有 workqueue 调度慢问题,是磁盘有问题。

自打将磁盘升级之后,线上稳定运行数月,未见await冲高问题,而沉寂了许久的大运河也重现往日喧嚣,官家盐船南来北往,淮北百姓终于又能吃上官盐了。

五、后记

一个月后,破案捷报传到洛阳,武则天读完奏折惊叹不已,“邗沟覆船已发多次,各家工具齐上,尚不能破,独狄怀英竟以青囊之 iosdiag 神器,不日便告功成,真乃神乎其技矣。只是这青囊,为何许人也?”

这时忽有内史答曰,“青囊,英文名 sysAK,是龙蜥社区(OpenAnolis)的一个开源项目,里面有诸多工具神技”

武则天惊呼,“sysAK,真乃神技也!”

而此时远隔千里之外的大运河边,杨柳依依,狄仁杰正依依不舍送别青囊,“这些日子多亏有你解决各类疑难杂症,你那诸多神技,也令我大开眼界,我实在不舍你离去”。

“这些时日承蒙阁老厚爱,奈何要务在身,不便久留。日后若阁老再有需要,哪怕远在天边,青囊必定肝脑涂地,为阁老解忧。”

加入系统运维 SIG组:

系统运维SIG致力于打造一个集主机管理、配置部署、监控报警、异常诊断、安全审计等一系列功能的自动化运维平台。

欢迎更多开发者加入系统运维 SIG:

网址:https://openanolis.cn/sig/sysom

邮件列表:sysom@lists.openanolis.cn

—— 完 ——

加入龙蜥社群

加入微信群:添加社区助理-龙蜥社区小龙(微信:openanolis_assis),备注【龙蜥】拉你入群;加入钉钉群:扫描下方钉钉群二维码。欢迎开发者/用户加入龙蜥社区(OpenAnolis)交流,共同推进龙蜥社区的发展,一起打造一个活跃的、健康的开源操作系统生态!

关于龙蜥社区

龙蜥社区(OpenAnolis)是由企事业单位、高等院校、科研单位、非营利性组织、个人等按照自愿、平等、开源、协作的基础上组成的非盈利性开源社区。龙蜥社区成立于 2020 年 9 月,旨在构建一个开源、中立、开放的Linux上游发行版社区及创新平台。

短期目标是开发龙蜥操作系统(Anolis OS)作为 CentOS 替代版,重新构建一个兼容国际 Linux 主流厂商发行版。中长期目标是探索打造一个面向未来的操作系统,建立统一的开源操作系统生态,孵化创新开源项目,繁荣开源生态。

龙蜥OS 8.4已发布,支持 x86_64 、ARM64、LoongArch 架构,完善适配 Intel、飞腾、海光、兆芯、鲲鹏、龙芯等芯片,并提供全栈国密支持。

欢迎下载:

https://openanolis.cn/download

加入我们,一起打造面向未来的开源操作系统!

https://openanolis.cn

往期精彩推荐
1.杭州西软加入龙蜥社区,应用软件兼容适配已完成
2.龙蜥操作系统(Anolis OS)荣获“中国开源云联盟年度优秀开源项目”奖!

3.龙蜥社区10月运营委员会会议顺利召开

4.海尔智能加入龙蜥社区,推动软硬件应用生态繁荣发展

5.云栖回顾|龙蜥论坛圆桌环节都有哪些精彩观点?

您可能也对以下帖子感兴趣

文章有问题?点此查看未经处理的缓存