[[432179]]

本文轉(zhuǎn)載自微信公眾號(hào)「云巔論劍」，作者李光水、毛文安 。轉(zhuǎn)載本文請(qǐng)聯(lián)系云巔論劍公眾號(hào)。

一、引子

話說(shuō)上回青囊協(xié)助曾泰處理完官道的網(wǎng)絡(luò)抖動(dòng)大案之后，接到急報(bào)說(shuō)邗溝發(fā)生鹽船劇烈抖動(dòng)以致傾覆的大案，狄仁杰又帶上青囊火速啟程趕往邗溝。

[[432180]]

二、邗溝現(xiàn)場(chǎng)斷案

此時(shí)大運(yùn)河上一片沉寂，青囊遞給狄仁杰兩片從案發(fā)現(xiàn)場(chǎng)打撈上來(lái)，標(biāo)記有“iostat印記”的鹽船龍骨碎片，沉聲道，“邗溝覆船案，兩年內(nèi)已發(fā)生多次。每到邗溝，大風(fēng)忽起，船只便開(kāi)始抖動(dòng)搖晃;更甚者，船只直接解體。為此，我收集到解體船只的碎片，發(fā)現(xiàn)這船體抖動(dòng)確有玄機(jī)。”運(yùn)河之上押運(yùn)官鹽的船只，遇風(fēng)浪或保持穩(wěn)健前行，或搖晃解體，如能知曉各部件抖動(dòng)之時(shí)間長(zhǎng)短，分析其關(guān)聯(lián)部位，便能揪出幕后真兇。

面對(duì)此龍骨碎片，青囊不禁聯(lián)想到之前處理 IO 問(wèn)題時(shí)的一件奇事，當(dāng)時(shí)系統(tǒng)也是抖得厲害，blktrace 等工具無(wú)法清楚解釋在哪里抖的，后來(lái)便研究了一下 IO 領(lǐng)域的抖動(dòng)問(wèn)題，它表現(xiàn)為在一段時(shí)間內(nèi)，IO 性能無(wú)法始終保持一致，會(huì)突發(fā)性的下跌到不符合我們所預(yù)期的性能范圍。就業(yè)務(wù)影響而言，數(shù)據(jù)存儲(chǔ)效率低下、無(wú)法維持穩(wěn)定的對(duì)外服務(wù)，影響用戶體驗(yàn)。目前看邗溝覆船案，極有可能跟 IO 抖動(dòng)有關(guān)，不禁喜上眉梢。

狄仁杰接過(guò)碎片，仔細(xì)端詳 iostat 中的各指標(biāo)，沉吟片刻道，“磁盤(pán) vda 乃官家所部署的云盤(pán)，號(hào)稱 us 級(jí)別延遲，現(xiàn)在可以看到寫(xiě) iops 最高也不過(guò)十、寫(xiě) IO 最高也不過(guò)百 KB/s，何以在如此低的 IO 負(fù)載情況下，竟有數(shù)十ms的await沖高，著實(shí)令我百思不得其解。”

await 是一個(gè)從時(shí)間維度描述 IO 性能的指標(biāo)，表示為單位時(shí)間內(nèi)每個(gè) IO 請(qǐng)求被處理的平均耗時(shí)，單位為微秒或者毫秒，亦可理解為 IO 的響應(yīng)時(shí)間。這個(gè)指標(biāo)是內(nèi)核 IO 子系統(tǒng) block 層透出來(lái)后經(jīng)過(guò)系統(tǒng)工具 iostat 加工之后的結(jié)果，因此，它既包含了一個(gè) IO 在 IO 軟件棧中處理的時(shí)間，也包含了磁盤(pán)的處理時(shí)間。因此 await 沖高現(xiàn)象是 IO 抖動(dòng)問(wèn)題中比較典型的特征。

“狄閣老莫愁，針對(duì)此類 IO 抖動(dòng)問(wèn)題，鄙人正巧最近研制出一診斷利器——iosdiag，已經(jīng)集成到 sysAK 的工具集，或許可為閣老排憂解難”，青囊笑道。

眾人目光炯炯，恍若流光般向青囊匯聚而去，狄仁杰笑道，“青囊之神技，果真層出不窮，且與我等說(shuō)來(lái)，何為 iosdiag?”

三、 iosdiag 功能介紹

青囊道：

iosdiag，是 sysAK 工具平臺(tái)中的 IO 存儲(chǔ)診斷工具，已具備 IO 時(shí)延探測(cè)功能、IO HANG 診斷功能兩大功能，前者用于分析當(dāng)前 IO 存儲(chǔ)鏈路中的時(shí)延抖動(dòng)問(wèn)題并確定抖動(dòng)邊界，后者可檢測(cè)當(dāng)前系統(tǒng)中 IO HANG 事件并確定問(wèn)題邊界。

IO 時(shí)延，指 IO 在其生命周期內(nèi)所經(jīng)歷的 IO 各路徑上的時(shí)間損耗，通常情況下，可以分為 OS 耗時(shí)和磁盤(pán)耗時(shí)，而 OS 內(nèi)比較受關(guān)注的就是 IO 棧了，IO 棧里面又包含復(fù)雜的 block、驅(qū)動(dòng)等部分;正所謂每每碰到 IO 抖動(dòng)問(wèn)題，必有人抓耳撓腮、暗無(wú)天日吶。

iosdiag 中的 iolatency工具，實(shí)現(xiàn)了 IO 時(shí)延探測(cè)功能，最喜隱匿于內(nèi)核 IO 棧之中，竟能眼觀六路，耳聽(tīng)八方，以迅雷不及掩耳之勢(shì)，將各 IO 在生命周期之內(nèi)，不同關(guān)鍵路徑上的時(shí)間戳信息盡收于乾坤寶袋之中;而后又基于此，計(jì)算 IO 路徑上的所有時(shí)延數(shù)據(jù)，來(lái)確認(rèn) IO 耗時(shí)最大的路徑(磁盤(pán)耗時(shí)或者軟件內(nèi)耗時(shí))，可謂神通廣大，法力無(wú)邊。

且 iosdiag latency 已經(jīng)成功定位到多起線上 IO 抖動(dòng)問(wèn)題，目前具備如下特色：

• 支持捕獲 IO 延遲超過(guò)指定耗時(shí)的 IO
• 支持獲取 IO 各路徑延遲信息，準(zhǔn)確定界磁盤(pán)、OS 耗時(shí)(包含 block、驅(qū)動(dòng)、磁盤(pán)、IO 結(jié)束耗時(shí))問(wèn)題
• 信息格式化輸出，更直觀，具備完整單個(gè) IO 信息、所有 IO 統(tǒng)計(jì)信息、進(jìn)程級(jí)IO 耗時(shí)分析，能夠直接了當(dāng)?shù)闹滥睦锍隽藛?wèn)題

“甚好!知我者，真乃青囊也，此迷局當(dāng)以 iosdiag latency 破之”，邊聽(tīng)青囊介紹，狄仁杰一臉愁容漸漸消散，滿面春風(fēng)取而代之，如今已是柳暗花明，既有 iosdiag latency 利器在手，何不上去診斷一把。

四、iosdiag 抖動(dòng)問(wèn)題破解

狄仁杰早已迫不及待，讓青囊運(yùn)行了 sysak iosdiag latency，開(kāi)始了激動(dòng)人心的 IO 抖動(dòng)診斷之旅。

[root@VM20200727-16 /root] 
#sysak iosdiag latency -b 10 -t 10 

以上命令表示，sysak iosdiag latency 將在系統(tǒng)中運(yùn)行 10 秒，并收集系統(tǒng)中該時(shí)間段內(nèi)延遲超過(guò) 10ms 的 IO，隨后退出診斷，屆時(shí)，IO 在各路徑上的延遲將無(wú)所遁形。時(shí)間 1 秒 1 秒過(guò)去，眾人滿懷期待，當(dāng)看到 iosdiag 診斷結(jié)束之后，狄仁杰隨即打開(kāi)了診斷日志文件，果然大有玄機(jī)，而后眾人發(fā)現(xiàn)，總共收集到 9 個(gè)IO，其中 flush/fua io 有 6 個(gè)，而經(jīng)過(guò)統(tǒng)計(jì)主要 IO 耗時(shí)竟然集中在 OS 的 block 中(最大耗時(shí) 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 果真神器也!”，狄仁杰忍不住贊嘆，朝青囊豎起了大拇指。

“只是現(xiàn)下已知 os(block) 耗時(shí)嚴(yán)重，可否進(jìn)一步獲悉耗時(shí)原因?”

“當(dāng)然可以，狄閣老且看，診斷結(jié)果中不僅包含延遲分布統(tǒng)計(jì)信息，同時(shí)還包含延遲最大的 IO，我們可以將此 IO 展開(kāi)來(lái)看，或可發(fā)現(xiàn)其中玄機(jī)”，青囊笑答曰。

"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 線程發(fā)起的 flush/fua 請(qǐng)求(op: FWFS)，總耗時(shí) 51.7ms，而 block 層耗時(shí)竟有 51.4ms，實(shí)在是不正常。正如我們對(duì) block 層 flush 實(shí)現(xiàn)機(jī)制的理解，flush/fua 請(qǐng)求在真正寫(xiě)入數(shù)據(jù)前后，要執(zhí)行多次 flush 請(qǐng)求，不僅要求串行執(zhí)行，而且還需要 workqueue 的介入，繁瑣至極。由此可見(jiàn)，有兩種可能性導(dǎo)致此 IO 耗時(shí)長(zhǎng)：workqueue 調(diào)度慢或者磁盤(pán)本身就慢。”

聽(tīng)完青囊的分析，狄仁杰面露喜色，認(rèn)為已經(jīng)離真相不遠(yuǎn)，追問(wèn)，“不知是否還有信息可以查看進(jìn)一步原因?”

“狄閣老此前是否留意到除了 os(block)路徑耗時(shí)嚴(yán)重之外，還有 disk 路徑也占據(jù)了 40% 的的耗時(shí)?由此，我料問(wèn)題必定由磁盤(pán)引起，我們可再找一個(gè)捕獲到的寫(xiě) IO 請(qǐng)求展開(kāi)來(lái)看”，青囊似乎早已了然于胸，淡然從診斷日志文件中隨意取出一個(gè)寫(xiě) 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":[...] 
    } 
} 

至此眾人發(fā)現(xiàn)，正常的寫(xiě) IO，在磁盤(pán)側(cè)的延遲竟然達(dá)到 32.4ms，同時(shí)此 IO 也是通過(guò) workqueue 下發(fā)，但 block 側(cè)的消耗也僅 43us，由此可見(jiàn)沒(méi)有 workqueue 調(diào)度慢問(wèn)題，是磁盤(pán)有問(wèn)題。

自打?qū)⒋疟P(pán)升級(jí)之后，線上穩(wěn)定運(yùn)行數(shù)月，未見(jiàn)await沖高問(wèn)題，而沉寂了許久的大運(yùn)河也重現(xiàn)往日喧囂，官家鹽船南來(lái)北往，淮北百姓終于又能吃上官鹽了。

五、后記

一個(gè)月后，破案捷報(bào)傳到洛陽(yáng)，武則天讀完奏折驚嘆不已，“邗溝覆船已發(fā)多次，各家工具齊上，尚不能破，獨(dú)狄懷英竟以青囊之 iosdiag 神器，不日便告功成，真乃神乎其技矣。只是這青囊，為何許人也?”

這時(shí)忽有內(nèi)史答曰，“青囊，英文名 sysAK，是龍蜥社區(qū)(OpenAnolis)的一個(gè)開(kāi)源項(xiàng)目，里面有諸多工具神技”

武則天驚呼，“sysAK，真乃神技也!”

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

“這些時(shí)日承蒙閣老厚愛(ài)，奈何要?jiǎng)?wù)在身，不便久留。日后若閣老再有需要，哪怕遠(yuǎn)在天邊，青囊必定肝腦涂地，為閣老解憂。”