[[432179]]

本文轉載自微信公眾號「云巔論劍」，作者李光水、毛文安 。轉載本文請聯系云巔論劍公眾號。

一、引子

話說上回青囊協助曾泰處理完官道的網絡抖動大案之后，接到急報說邗溝發生鹽船劇烈抖動以致傾覆的大案，狄仁杰又帶上青囊火速啟程趕往邗溝。

[[432180]]

二、邗溝現場斷案

此時大運河上一片沉寂，青囊遞給狄仁杰兩片從案發現場打撈上來，標記有“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，真乃神技也!”

而此時遠隔千里之外的大運河邊，楊柳依依，狄仁杰正依依不舍送別青囊，“這些日子多虧有你解決各類疑難雜癥，你那諸多神技，也令我大開眼界，我實在不舍你離去”。

“這些時日承蒙閣老厚愛，奈何要務在身，不便久留。日后若閣老再有需要，哪怕遠在天邊，青囊必定肝腦涂地，為閣老解憂。”