風(fēng)云再續(xù)：他抖任他抖，IO診斷在我手
本文轉(zhuǎn)載自微信公眾號「云巔論劍」，作者李光水、毛文安 。轉(zhuǎn)載本文請聯(lián)系云巔論劍公眾號。
一、引子
話說上回青囊協(xié)助曾泰處理完官道的網(wǎng)絡(luò)抖動大案之后，接到急報說邗溝發(fā)生鹽船劇烈抖動以致傾覆的大案，狄仁杰又帶上青囊火速啟程趕往邗溝。
二、邗溝現(xiàn)場斷案
此時大運河上一片沉寂，青囊遞給狄仁杰兩片從案發(fā)現(xiàn)場打撈上來，標(biāo)記有“iostat印記”的鹽船龍骨碎片，沉聲道，“邗溝覆船案，兩年內(nèi)已發(fā)生多次。每到邗溝，大風(fēng)忽起，船只便開始抖動搖晃;更甚者，船只直接解體。為此，我收集到解體船只的碎片，發(fā)現(xiàn)這船體抖動確有玄機(jī)。”運河之上押運官鹽的船只，遇風(fēng)浪或保持穩(wěn)健前行，或搖晃解體，如能知曉各部件抖動之時間長短，分析其關(guān)聯(lián)部位，便能揪出幕后真兇。
面對此龍骨碎片，青囊不禁聯(lián)想到之前處理 IO 問題時的一件奇事，當(dāng)時系統(tǒng)也是抖得厲害，blktrace 等工具無法清楚解釋在哪里抖的，后來便研究了一下 IO 領(lǐng)域的抖動問題，它表現(xiàn)為在一段時間內(nèi)，IO 性能無法始終保持一致，會突發(fā)性的下跌到不符合我們所預(yù)期的性能范圍。就業(yè)務(wù)影響而言，數(shù)據(jù)存儲效率低下、無法維持穩(wěn)定的對外服務(wù)，影響用戶體驗。目前看邗溝覆船案，極有可能跟 IO 抖動有關(guān)，不禁喜上眉梢。
狄仁杰接過碎片，仔細(xì)端詳 iostat 中的各指標(biāo)，沉吟片刻道，“磁盤 vda 乃官家所部署的云盤，號稱 us 級別延遲，現(xiàn)在可以看到寫 iops 最高也不過十、寫 IO 最高也不過百 KB/s，何以在如此低的 IO 負(fù)載情況下，竟有數(shù)十ms的await沖高，著實令我百思不得其解。”
await 是一個從時間維度描述 IO 性能的指標(biāo)，表示為單位時間內(nèi)每個 IO 請求被處理的平均耗時，單位為微秒或者毫秒，亦可理解為 IO 的響應(yīng)時間。這個指標(biāo)是內(nèi)核 IO 子系統(tǒng) block 層透出來后經(jīng)過系統(tǒng)工具 iostat 加工之后的結(jié)果，因此，它既包含了一個 IO 在 IO 軟件棧中處理的時間，也包含了磁盤的處理時間。因此 await 沖高現(xiàn)象是 IO 抖動問題中比較典型的特征。
“狄閣老莫愁，針對此類 IO 抖動問題，鄙人正巧最近研制出一診斷利器——iosdiag，已經(jīng)集成到 sysAK 的工具集，或許可為閣老排憂解難”，青囊笑道。
眾人目光炯炯，恍若流光般向青囊匯聚而去，狄仁杰笑道，“青囊之神技，果真層出不窮，且與我等說來，何為 iosdiag?”
三、 iosdiag 功能介紹
青囊道：
iosdiag，是 sysAK 工具平臺中的 IO 存儲診斷工具，已具備 IO 時延探測功能、IO HANG 診斷功能兩大功能，前者用于分析當(dāng)前 IO 存儲鏈路中的時延抖動問題并確定抖動邊界，后者可檢測當(dāng)前系統(tǒng)中 IO HANG 事件并確定問題邊界。
IO 時延，指 IO 在其生命周期內(nèi)所經(jīng)歷的 IO 各路徑上的時間損耗，通常情況下，可以分為 OS 耗時和磁盤耗時，而 OS 內(nèi)比較受關(guān)注的就是 IO 棧了，IO 棧里面又包含復(fù)雜的 block、驅(qū)動等部分;正所謂每每碰到 IO 抖動問題，必有人抓耳撓腮、暗無天日吶。
iosdiag 中的 iolatency工具，實現(xiàn)了 IO 時延探測功能，最喜隱匿于內(nèi)核 IO 棧之中，竟能眼觀六路，耳聽八方，以迅雷不及掩耳之勢，將各 IO 在生命周期之內(nèi)，不同關(guān)鍵路徑上的時間戳信息盡收于乾坤寶袋之中;而后又基于此，計算 IO 路徑上的所有時延數(shù)據(jù)，來確認(rèn) IO 耗時最大的路徑(磁盤耗時或者軟件內(nèi)耗時)，可謂神通廣大，法力無邊。
且 iosdiag latency 已經(jīng)成功定位到多起線上 IO 抖動問題，目前具備如下特色：
- 支持捕獲 IO 延遲超過指定耗時的 IO
- 支持獲取 IO 各路徑延遲信息，準(zhǔn)確定界磁盤、OS 耗時(包含 block、驅(qū)動、磁盤、IO 結(jié)束耗時)問題
- 信息格式化輸出，更直觀，具備完整單個 IO 信息、所有 IO 統(tǒng)計信息、進(jìn)程級IO 耗時分析，能夠直接了當(dāng)?shù)闹滥睦锍隽藛栴}
“甚好!知我者，真乃青囊也，此迷局當(dāng)以 iosdiag latency 破之”，邊聽青囊介紹，狄仁杰一臉愁容漸漸消散，滿面春風(fēng)取而代之，如今已是柳暗花明，既有 iosdiag latency 利器在手，何不上去診斷一把。
四、iosdiag 抖動問題破解
狄仁杰早已迫不及待，讓青囊運行了 sysak iosdiag latency，開始了激動人心的 IO 抖動診斷之旅。
- [root@VM20200727-16 /root]
- #sysak iosdiag latency -b 10 -t 10
以上命令表示，sysak iosdiag latency 將在系統(tǒng)中運行 10 秒，并收集系統(tǒng)中該時間段內(nèi)延遲超過 10ms 的 IO，隨后退出診斷，屆時，IO 在各路徑上的延遲將無所遁形。時間 1 秒 1 秒過去，眾人滿懷期待，當(dāng)看到 iosdiag 診斷結(jié)束之后，狄仁杰隨即打開了診斷日志文件，果然大有玄機(jī)，而后眾人發(fā)現(xiàn)，總共收集到 9 個IO，其中 flush/fua io 有 6 個，而經(jīng)過統(tǒng)計主要 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 果真神器也!”，狄仁杰忍不住贊嘆，朝青囊豎起了大拇指。
“只是現(xiàn)下已知 os(block) 耗時嚴(yán)重，可否進(jìn)一步獲悉耗時原因?”
“當(dāng)然可以，狄閣老且看，診斷結(jié)果中不僅包含延遲分布統(tǒng)計信息，同時還包含延遲最大的 IO，我們可以將此 IO 展開來看，或可發(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 請求(op: FWFS)，總耗時 51.7ms，而 block 層耗時竟有 51.4ms，實在是不正常。正如我們對 block 層 flush 實現(xiàn)機(jī)制的理解，flush/fua 請求在真正寫入數(shù)據(jù)前后，要執(zhí)行多次 flush 請求，不僅要求串行執(zhí)行，而且還需要 workqueue 的介入，繁瑣至極。由此可見，有兩種可能性導(dǎo)致此 IO 耗時長：workqueue 調(diào)度慢或者磁盤本身就慢。”
聽完青囊的分析，狄仁杰面露喜色，認(rèn)為已經(jīng)離真相不遠(yuǎn)，追問，“不知是否還有信息可以查看進(jìn)一步原因?”
“狄閣老此前是否留意到除了 os(block)路徑耗時嚴(yán)重之外，還有 disk 路徑也占據(jù)了 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":[...]
- }
- }
至此眾人發(fā)現(xiàn)，正常的寫 IO，在磁盤側(cè)的延遲竟然達(dá)到 32.4ms，同時此 IO 也是通過 workqueue 下發(fā)，但 block 側(cè)的消耗也僅 43us，由此可見沒有 workqueue 調(diào)度慢問題，是磁盤有問題。
自打?qū)⒋疟P升級之后，線上穩(wěn)定運行數(shù)月，未見await沖高問題，而沉寂了許久的大運河也重現(xiàn)往日喧囂，官家鹽船南來北往，淮北百姓終于又能吃上官鹽了。
五、后記
一個月后，破案捷報傳到洛陽，武則天讀完奏折驚嘆不已，“邗溝覆船已發(fā)多次，各家工具齊上，尚不能破，獨狄懷英竟以青囊之 iosdiag 神器，不日便告功成，真乃神乎其技矣。只是這青囊，為何許人也?”
這時忽有內(nèi)史答曰，“青囊，英文名 sysAK，是龍蜥社區(qū)(OpenAnolis)的一個開源項目，里面有諸多工具神技”
武則天驚呼，“sysAK，真乃神技也!”
而此時遠(yuǎn)隔千里之外的大運河邊，楊柳依依，狄仁杰正依依不舍送別青囊，“這些日子多虧有你解決各類疑難雜癥，你那諸多神技，也令我大開眼界，我實在不舍你離去”。
“這些時日承蒙閣老厚愛，奈何要務(wù)在身，不便久留。日后若閣老再有需要，哪怕遠(yuǎn)在天邊，青囊必定肝腦涂地，為閣老解憂。”
