风云再续：他抖任他抖，IO诊断在我手

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

相关阅读：

一、引子

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

二、邗沟现场断案

此时大运河上一片沉寂，青囊递给狄仁杰两片从案发现场打捞上来，标记有“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，真乃神技也！”

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

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

往期精彩推荐