# Linux 核心設計: Block I/O(3): Block I/O 追蹤工具
## 前言
當前 Linux kernel 採用的 Block I/O 框架是採用 [Multi-Queue Block IO Queueing Mechanism (blk-mq)](https://docs.kernel.org/block/blk-mq.html)。
如上圖所見。上層的 I/O library 或檔案系統所請求的 I/O 操作會以 `struct bio` 形式來描述，交付給 Block Layer。Block Layer 再將 `struct bio` 整合成一個 `struct request`(可能與現有的 `struct request` 合併，或者為其建立新的 `struct request`)，交付給底層的 device driver。每個 device driver 有各自對應所需處理的 `request_queue` 可以接受這些 `struct request`。
由此可知，I/O 的完成將經歷多個步驟。檔案系統、I/O scheduler、在裝置中處理的時間等，都可能是造成 I/O 延遲的原因。因此，對於 I/O 造成之延遲的分析，如果要探究瓶頸所在，勢必需要能夠拆解出每個階段所耗費時間的工具。這就是 Linux 中 [blk tracer](https://docs.kernel.org/trace/ftrace.html#the-tracers) 引入的目的。藉由此工具，我們可以蒐集 Block I/O 的相關資訊。不過 blk tracer 的直接輸出可能不易解讀。更為普遍的使用方式是透過 [blktrace](https://git.kernel.dk/cgit/blktrace/) 來控制 blk tracer，然後再由 `blkparse` 來將輸出格式化成可讀的資訊。
## `blktrace` + `blkparse`
下表中依序列出了一個 I/O 操作所可能經歷的事件之代號與對應函式名稱。
| Id | Function | Description |
|:--- |:-------------------- |:---------------------------------------------- |
| Q | block_bio_queue | 新的 `bio` 被加入到 Block Layer 的 queue 中 |
| B | block_bio_bounce | `bio` 被複製到 bounced buffer(因為 DMA 的限制) |
| X | block_split | 一個 `bio` 被拆分成兩個 `bio` |
| M | block_bio_backmerge | `bio` 被 I/O scheduler back-merge 到 queue 中的 `request` |
| F | block_bio_frontmerge | `bio` 被 I/O scheduler front-merge 到 queue 中的 `request` |
| G | block_getrq | 獲取一個 free `request` 結構以處理 `bio` |
| P | block_plug | `bio` 被禁止分派到 `request_queue` |
| I | block_rq_insert | `request` 被加入到 `request_queue` |
| U | block_unplug | `bio` 被允許分派到 `request_queue` |
| A | block_rq_remap | `request` 被 remap 到不同裝置 |
| D | block_rq_issue | 向 device driver 發出待處理的 `request` |
| C | block_rq_complete | `request` 完成 |
執行 `blktrace` + `blkparse`，我們將能採樣每個 block I/O 事件的進行與執行時間。
```
$ sudo blktrace -d /dev/nvme1n1p2 -o blktrace_out
$ blkparse -i blktrace_out -o - -d blktrace.bin
```
如果毋須保留 `blktrace` 的輸出，可以直接將結果 pipe 給 `blkparse`。具體的使用範例如下所示:
```
$ sudo blktrace -d /dev/nvme1n1p2 -o - | blkparse -i -
259,1 10 1 0.000000000 978 A WS 6142404488 + 8 <- (259,3) 6141353864
259,3 10 2 0.000001905 978 Q WS 6142404488 + 8 [NetworkManager]
259,3 10 3 0.000011710 978 G WS 6142404488 + 8 [NetworkManager]
259,3 10 4 0.000012731 978 P N [NetworkManager]
259,3 10 5 0.000017918 978 D WS 6142404488 + 8 [NetworkManager]
259,3 10 6 1.375993973 0 C WS 6142404488 + 8 [0]
259,1 2 1 1.376345034 498 A WSM 3999900032 + 8 <- (259,3) 3998849408
259,3 2 2 1.376347119 498 Q WSM 3999900032 + 8 [jbd2/nvme1n1p2-]
259,3 2 3 1.376354175 498 G WSM 3999900032 + 8 [jbd2/nvme1n1p2-]
...
```
`blktrace` 的每行輸出是固定的格式。以上方的最後一行輸出為範例，從中我們能得知的資訊是:
* `259,3`: 進行此 I/O 操作的裝置之 major ID 為 259 且 minor ID 為 3
* 第一個 `2` 表示在 CPU2 上運行
* 第二個 `3` 表示這個 I/O 操作的序號(Sequence number)
* `1.376354175` 是完成這個操作所發生在時間軸上的時間(秒)
* `498` 是 PID
* `G` 及對應上表中的單字代號
* `WSM` 表示對應 RWBS，參考 [`fill_rwbs`](https://elixir.bootlin.com/linux/v6.15.1/source/kernel/trace/blktrace.c#L1142)
* R: `BLK_TC_READ`
* W: `BLK_TC_WRITE`
* D: `BLK_TC_DISCARD`
* M: `BLK_TC_META`
* N: `BLK_TN_MESSAGE`
* `3999900032 + 8`: 表示 starting block 在 `3999900032`，且操作的長度是 8 個 sectors
* `[jbd2/nvme1n1p2-]` 是 process 名稱
## btt
雖然 `blktrace` 可以蒐集每一次 I/O 操作的各階段資訊，但繁雜的資訊可能使人無從下手。想取得更方便分析的統計數據，我們可以使用內建的 `btt` 來彙整。
```
$ sudo blktrace -d /dev/nvme1n1p2 -o - | blkparse -i - -d blktrace.bin
$ btt -i blktrace.bin
```
一個 I/O 的完成可大致分成三個階段，`btt` 對各個階段的耗時進行統計:
1. I/O 進入 Block I/O 層，插入或合併到 `request_queue`，成為一個新的 request
* Q2I: 插入 I/O，這又可以分解為兩個組成：
* Q2G: 從 `bio` 發生到取得 `request` 的時間，表示 I/O scheduler 的相關效率
* G2I: 從 `request` 被建立到加入 `request_queue` 的時間
* Q2M: 從 `bio` 發生到 merge 至 `request` 的時間，表示 I/O scheduler 的相關效率
2. I/O 從 `request_queue` 到進入底層驅動程式
* I2D: 新的 `request` 在 `request_queue` 的等待時間
* M2D: I/O 被 merge 至 `request` 後，在 `request_queue` 的等待時間
3. I/O 進入驅動程序，到完成後返回到 Block I/O 層
* D2C: Device driver 從收到 `request` 到處理完畢的時間
`btt` 另外也統計兩個時間段:
* Q2Q: 兩個新的 `bio` 發生的時間間隔，表示 I/O 進行的頻繁程度
* Q2C: I/O 完整生命週期的長度。即從新的 I/O 請求產生到完成所需要的時間
### Basic Output
```
==================== All Devices ====================
ALL MIN AVG MAX N
--------------- ------------- ------------- ------------- -----------
Q2Q 0.000001027 0.000067603 0.001175166 39
Q2G 0.000000495 0.000002482 0.000007205 6
G2I 0.000329385 0.000550971 0.000863522 3
Q2M 0.000000307 0.000000445 0.000002261 34
I2D 0.000002023 0.000002617 0.000003670 3
M2D 0.000002563 0.000015287 0.000032745 34
D2C 0.000019841 0.000048032 0.000374409 40
Q2C 0.000025326 0.000104925 0.001089623 40
```
上表中可以看到各個階段包含最小、最大、平均時間與發生的次數的資訊。`N` 欄表示的是各階段發生的次數。
當追蹤 device mapper device 時，我們也會分解這些 I/O 的 Q2A 和 Q2C 時間。
```
==================== Device Overhead ====================
DEV | Q2G G2I Q2M I2D D2C
---------- | --------- --------- --------- --------- ---------
(259, 3) | 0.3549% 39.3831% 0.3604% 0.1870% 45.7770%
---------- | --------- --------- --------- --------- ---------
Overall | 0.3549% 39.3831% 0.3604% 0.1870% 45.7770%
```
利用上面的數據，可以大致了解 I/O 在哪些階段花了最多的時間。
```
==================== Device Merge Information ====================
DEV | #Q #D Ratio | BLKmin BLKavg BLKmax Total
---------- | -------- -------- ------- | -------- -------- -------- --------
(259, 3) | 40 6 6.7 | 8 112 160 672
```
I/O 進行的一個關鍵的衡量指標是了解 Block I/O 層在發送到底層驅動程式前，對 `request` 的合併。如上表，展示了傳入 I/O 的數量 (`#Q`)、最終發出的 `request` 數量 (`#D`) 以及其中比率。此外也展示了產生的最小、平均值和最大 I/O block 數，例如這裡顯示平均的 I/O 是 112 個 block，因此 6 * 112 總共 672 個 block 被進行。
```
==================== Device Q2Q Seek Information ====================
DEV | NSEEKS MEAN MEDIAN | MODE
---------- | --------------- --------------- --------------- | ---------------
(259, 3) | 40 99998169.2 0 | 0(39)
---------- | --------------- --------------- --------------- | ---------------
Overall | NSEEKS MEAN MEDIAN | MODE
Average | 40 99998169.2 0 | 0(39)
```
```
==================== Device D2D Seek Information ====================
DEV | NSEEKS MEAN MEDIAN | MODE
---------- | --------------- --------------- --------------- | ---------------
(259, 3) | 6 666654461.3 0 | 0(5)
---------- | --------------- --------------- --------------- | ---------------
Overall | NSEEKS MEAN MEDIAN | MODE
Average | 6 666654461.3 0 | 0(5)
```
這裡顯示的統計數據是連續 I/O queue 與 I/O sumbit 之間 sector 距離的變化。
其中 `NSEEKS` 表示 seek (提交給底層驅動程式的 I/O)數量，`MEAN` 指 I/O 之間的平均距離。此外也統計了 seek 的中位數(`MEDIAN`)以及眾數(`MODE`, 包含值以及括號中的計數)。
當 `MEDIAN` 為 0，代表向前與向後的 seek 之數量趨於相等。而 `MODE` 中的計數與 NSEEKS 總數的筆值越大，則表示 I/O 越來自於相鄰的 sector，意味著底層處理這些 I/O 的效率能更好。
```
==================== Plug Information ====================
DEV | # Plugs # Timer Us | % Time Q Plugged
---------- | ---------- ---------- | ----------------
(259, 3) | 1( 0) | 94.935708781%
DEV | IOs/Unp IOs/Unp(to)
---------- | ---------- ----------
(259, 3) | 0.0 0.0
(259, 1) | 0.0 0.0
```
在運行期間，`request_queue` 可能會被阻塞(plugged)，此時 `request` 無法被交付到底層的驅動程式。上表的上半部分展示了 `request_queue` 處於這種狀態的頻率。
`request_queue` unplugged 會有兩個原因:
1. kernel 中某個子系統明確發出的 unplugged 請求。
2. 如果 `request_queue` 的 plug 時間超過了某個時間限制，會定期 unplug。
換言之，子系統 unplug 的總數等於 plug 總次數減去定期 unplug 的次數。
下半部分則展示了當 unplug 發生時，`request_queue` 中的平均 I/O 數量。右半部分特別獨立出因 timeout 而 unplug 時的數據。
```
==================== Active Requests At Q Information ====================
DEV | Avg Reqs @ Q
---------- | -------------
(259, 3) | 0.8
```
分析 Block I/O Scheduler 時，一個重要的考慮點是了解 Scheduler 需要處理的 request 數量。這裡提供的數據顯示了處理傳入的 request 時，Scheduler 平均保留了多少個。
```
==================== I/O Active Period Information ====================
DEV | # Live Avg. Act Avg. !Act % Live
---------- | ---------- ------------- ------------- ------
(259, 3) | 6 0.000148146 0.000491539 26.56
(259, 1) | 0 0.000000000 0.000000000 0.00
---------- | ---------- ------------- ------------- ------
Total Sys | 6 0.000148146 0.000491539 26.56
```
這節的數據展示了每個裝置的 "I/O activity": 意指底層裝置驅動程式和裝置有至少一個 I/O 需要處理的時間段。
* `# Live`: 發生 active 時間段的總次數
* `Avg. Act`: 每個 active period 的平均時長
* `Avg. !Act`: 每個 non-active period 的平均時長
* `% Live`: 驅動程式/裝置處於 active 的總時間比例
```
# Total System
# Total System : q activity
0.000161592 0.0
0.000161592 0.4
0.002798116 0.4
0.002798116 0.0
# Total System : c activity
0.000241946 0.5
0.000241946 0.9
0.000241946 0.9
0.000241946 0.5
18446744073.709518433 0.5
18446744073.709518433 0.9
18446744073.709518433 0.9
18446744073.709518433 0.5
# Per device
# 259,3 : q activity
0.000161592 1.0
0.000161592 1.4
0.002798116 1.4
0.002798116 1.0
# 259,3 : c activity
0.000241946 1.5
0.000241946 1.9
0.000241946 1.9
0.000241946 1.5
18446744073.709518433 1.5
18446744073.709518433 1.9
18446744073.709518433 1.9
18446744073.709518433 1.5
# Per process
# blktrace : q activity
# blktrace : c activity
0.000241946 2.5
0.000241946 2.9
0.000241946 2.9
0.000241946 2.5
# jbd2 : q activity
0.000161592 3.0
0.000161592 3.4
0.002798116 3.4
0.002798116 3.0
# jbd2 : c activity
# kernel : q activity
# kernel : c activity
0.000013446 4.5
0.000013446 4.9
0.000132848 4.9
0.000132848 4.5
18446744073.709518433 4.5
18446744073.709518433 4.9
18446744073.709518433 4.9
18446744073.709518433 4.5
```
最後的部分展示了系統/裝置/程序觀察到的 "Activity"，以易於 xmgrace6 繪圖工具處理的格式紀錄。
資訊被拆分成多個 data points，包含兩行資料。第一行是代表時間的 X 軸值（以秒為單位），第二行則是代表是否有 activity 的 Y 軸值。Y 軸僅會存在兩種數值: 代表沒有 activity 的低值以及有 activity 的高值。之所以每個觀察角度的 Y 軸數值有不同，是為了在繪圖時避免重疊，以利於觀察。
以上表的 "Total System : q activity" 為例，該輸出代表在 0.000161592 開始出現 activity，並於 0.002798116 時 activity 歸為零。
### Detail Data
在使用 btt 時如果加上 `-A` 選項，可以得到更多額外的資訊。
```
==================== Per Process ====================
Q2C MIN AVG MAX N
--------------- ------------- ------------- ------------- -----------
jbd2 0.000032966 0.000138166 0.001372781 30
kworker 0.004075599 0.004075599 0.004075599 1
```
包含區分 Process 的分析。會顯示各個 process 在 Block I/O 的不同階段的耗時(不僅只有 Q2C，上表僅擷取部分示範)。
必須留意的是，顯示的 process 可能與原始請求 I/O 的 process 無關。例如，如果某個應用程式正在執行 Buffer I/O，那麼實際提交的 I/O 很可能來自管理 page buffer 的 daemon(例如 pdflush 或 kjournald)。
```
==================== Per Device ====================
Q2Q MIN AVG MAX N
--------------- ------------- ------------- ------------- -----------
(259, 3) 0.000000808 0.022403921 0.669235380 30
```
也有區分 Device 在各階段耗時的分析。
```
==================== Q2D Histogram ====================
DEV | <.005 <.010 <.025 <.050 <.075 <.100 <.250 <.500 < 1.0 >=1.0
--------- | ===== ===== ===== ===== ===== ===== ===== ===== ===== =====·
(259, 3) | 100.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0·
========== | ===== ===== ===== ===== ===== ===== ===== ===== ===== =====·
AVG | 100.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0·
```
另外還有 Q2D 時間分佈的直方圖。
## Plot
```
btt -i blktrace.bin -z q2d_latency
btt -i blktrace.bin -l d2c_latency
btt -i blktrace.bin -q q2c_latency
```
## iowatcher
透過 `iowatcher` 我們可以將 I/O 的資訊視覺化出來，這可以讓 I/O 的分析更一眼明瞭。
```
$ iowatcher -t blktrace.bin -o result.svg
```
## iosnoop
[perf-tools/iosnoop](https://github.com/brendangregg/perf-tools/blob/master/iosnoop)
## Reference
* [blktrace分析IO](https://bean-li.github.io/blktrace-to-report/)
* [分析IO的工具 ioprof](https://bean-li.github.io/ioprof/)
* [Linux Block Driver - 5](https://oliveryang.net/2016/10/linux-block-driver-basic-5/)
* [btt User Guide](https://allstar.jhuapl.edu/repo/p1/amd64/blktrace/doc/btt.pdf)
Sign in with Wallet
Connect another wallet