使用blktrace簡單分析IO效能

2020-06-16 16:44:11

在Linux系統上，如果I/O發生效能問題，有沒有辦法進一步定位故障位置呢？iostat等最常用的工具肯定是指望不上的，【容易被誤讀的iostat】一文中解釋過await表示單個I/O所需的平均時間，但它同時包含了I/O Scheduler所消耗的時間和硬體所消耗的時間，所以不能作為硬體效能的指標，至於iostat的svctm更是一個廢棄的指標，手冊上已經明確說明了的。blktrace在這種場合就能派上用場，因為它能記錄I/O所經歷的各個步驟，從中可以分析是IO Scheduler慢還是硬體響應慢。

blktrace的原理

一個I/O請求進入block layer之後，可能會經歷下面的過程：

Remap: 可能被DM(Device Mapper)或MD(Multiple Device, Software RAID) remap到其它裝置
Split: 可能會因為I/O請求與磁區邊界未對齊、或者size太大而被分拆(split)成多個物理I/O
Merge: 可能會因為與其它I/O請求的物理位置相鄰而合併(merge)成一個I/O
被IO Scheduler依照排程策略傳送給driver
被driver提交給硬體，經過HBA、電纜（光纖、網線等）、交換機（SAN或網路）、最後到達儲存裝置，裝置完成IO請求之後再把結果發回。

blktrace能記錄I/O所經歷的各個步驟，來看一下它記錄的資料，包含9個欄位，下圖示示了其中8個欄位的含義，大致的意思是“哪個進程在存取哪個硬碟的哪個磁區，進行什麼操作，進行到哪個步驟，時間戳是多少”：

第7個欄位在上圖中沒有標出來，它表示操作型別，具體含義是：”R” for Read, “W” for Write, “D” for block, “B” for Barrier operation。

第6個欄位是Event，代表了一個I/O請求所經歷的各個階段，具體含義在blkparse的手冊頁中有解釋，其中最重要的幾個階段如下：

Q – 即將生成IO請求
|
G – IO請求生成
|
I – IO請求進入IO Scheduler佇列
|
D – IO請求進入driver
|
C – IO請求執行完畢

根據以上步驟對應的時間戳就可以計算出I/O請求在每個階段所消耗的時間：

Q2G – 生成IO請求所消耗的時間，包括remap和split的時間；
G2I – IO請求進入IO Scheduler所消耗的時間，包括merge的時間；
I2D – IO請求在IO Scheduler中等待的時間；
D2C – IO請求在driver和硬體上所消耗的時間；
Q2C – 整個IO請求所消耗的時間(Q2I + I2D + D2C = Q2C)，相當於iostat的await。

如果I/O效能慢的話，以上指標有助於進一步定位緩慢發生的地方：
D2C可以作為硬體效能的指標；
I2D可以作為IO Scheduler效能的指標。

blktrace的用法

使用blktrace需要掛載debugfs：
$ mount -t debugfs debugfs /sys/kernel/debug

利用blktrace檢視實時資料的方法，比如要看的硬碟是sdb：
$ blktrace -d /dev/sdb -o – | blkparse -i –
需要停止的時候，按Ctrl-C。

以上命令也可以用下面的指令碼代替：
$ btrace /dev/sdb

利用blktrace把資料記錄在檔案裡，以供事後分析：
$ blktrace -d /dev/sdb
預設的輸出檔名是 sdb.blktrace.<cpu>，每個CPU對應一個檔案。
你也可以用-o引數指定自己的輸出檔名。

利用blkparse命令分析blktrace記錄的資料：
$ blkparse -i sdb

$ blktrace -d /dev/sdb
$ blkparse -i sdb
# 第一個IO開始：
8,16 1 1 0.000000000 18166 Q R 0 + 1 [dd]
8,16 1 0 0.000009827 0 m N cfq18166S /user.slice alloced
8,16 1 2 0.000010451 18166 G R 0 + 1 [dd]
8,16 1 3 0.000011056 18166 P N [dd]
8,16 1 4 0.000012255 18166 I R 0 + 1 [dd]
8,16 1 0 0.000013477 0 m N cfq18166S /user.slice insert_request
8,16 1 0 0.000014526 0 m N cfq18166S /user.slice add_to_rr
8,16 1 5 0.000016643 18166 U N [dd] 1
8,16 1 0 0.000017522 0 m N cfq workload slice:300
8,16 1 0 0.000018880 0 m N cfq18166S /user.slice set_active wl_class:0 wl_type:2
8,16 1 0 0.000020594 0 m N cfq18166S /user.slice fifo= (null)
8,16 1 0 0.000021462 0 m N cfq18166S /user.slice dispatch_insert
8,16 1 0 0.000022898 0 m N cfq18166S /user.slice dispatched a request
8,16 1 0 0.000023786 0 m N cfq18166S /user.slice activate rq, drv=1
8,16 1 6 0.000023977 18166 D R 0 + 1 [dd]
8,16 0 1 0.014270153 0 C R 0 + 1 [0]
# 第一個IO結束。
8,16 0 0 0.014278115 0 m N cfq18166S /user.slice complete rqnoidle 0
8,16 0 0 0.014280044 0 m N cfq18166S /user.slice set_slice=100
8,16 0 0 0.014282217 0 m N cfq18166S /user.slice arm_idle: 8 group_idle: 0
8,16 0 0 0.014282728 0 m N cfq schedule dispatch
# 第二個IO開始：
8,16 1 7 0.014298247 18166 Q R 1 + 1 [dd]
8,16 1 8 0.014300522 18166 G R 1 + 1 [dd]
8,16 1 9 0.014300984 18166 P N [dd]
8,16 1 10 0.014301996 18166 I R 1 + 1 [dd]
8,16 1 0 0.014303864 0 m N cfq18166S /user.slice insert_request
8,16 1 11 0.014304981 18166 U N [dd] 1
8,16 1 0 0.014306368 0 m N cfq18166S /user.slice dispatch_insert
8,16 1 0 0.014307793 0 m N cfq18166S /user.slice dispatched a request
8,16 1 0 0.014308763 0 m N cfq18166S /user.slice activate rq, drv=1
8,16 1 12 0.014308962 18166 D R 1 + 1 [dd]
8,16 0 2 0.014518615 0 C R 1 + 1 [0]
# 第二個IO結束。
8,16 0 0 0.014523548 0 m N cfq18166S /user.slice complete rqnoidle 0
8,16 0 0 0.014525334 0 m N cfq18166S /user.slice arm_idle: 8 group_idle: 0
8,16 0 0 0.014525676 0 m N cfq schedule dispatch
# 第三個IO開始：
8,16 1 13 0.014531022 18166 Q R 2 + 1 [dd]
...

註：
在以上資料中，有一些記錄的event型別是”m”，那是IO Scheduler的排程資訊，對研究IO Scheduler問題有意義：

cfq18166S – cfq是IO Scheduler的名稱，18166是進程號，”S”表示Sync(同步IO)，如果非同步IO則用“A”表示(Async)；
它們的第三列sequence number都是0；
它們表示IO Scheduler內部的關鍵函數，上例中是cfq，程式碼參見block/cfq-iosched.c，以下是各關鍵字所對應的內部函數：
alloced <<< cfq_find_alloc_queue()
insert_request <<< cfq_insert_request()
add_to_rr <<< cfq_add_cfqq_rr()
cfq workload slice:300 <<< choose_wl_class_and_type()
set_active wl_class:0 wl_type:2 <<< __cfq_set_active_queue()
fifo= (null) <<< cfq_check_fifo()
dispatch_insert <<< cfq_dispatch_insert()
dispatched a request <<< cfq_dispatch_requests()
activate rq, drv=1 <<< cfq_activate_request()
complete rqnoidle 0 <<< cfq_completed_request()
set_slice=100 <<< cfq_set_prio_slice()
arm_idle: 8 group_idle: 0 <<< cfq_arm_slice_timer()
cfq schedule dispatch <<< cfq_schedule_dispatch()

利用btt分析blktrace資料

blkparse只是將blktrace資料轉成可以人工閱讀的格式，由於資料量通常很大，人工分析並不輕鬆。btt是對blktrace資料進行自動分析的工具。

btt不能分析實時資料，只能對blktrace儲存的資料檔案進行分析。使用方法：
把原本按CPU分別儲存的檔案合併成一個，合併後的檔名為sdb.blktrace.bin：
$b l k p a r s e - i s d b - d s d b . b l k t r a c e . b i n 执行 b t t 对 s d b . b l k t r a c e . b i n 进行分析：$ btt -i sdb.blktrace.bin

下面是一個btt範例：

...
ALL MIN AVG MAX N
--------------- ------------- ------------- ------------- -----------

Q2Q 0.000138923 0.000154010 0.014298247 94558
Q2G 0.000001154 0.000001661 0.000017313 94559
G2I 0.000000883 0.000001197 0.000012011 94559
I2D 0.000004722 0.000005761 0.000027286 94559
D2C 0.000118840 0.000129201 0.014246176 94558
Q2C 0.000125953 0.000137820 0.014270153 94558

==================== Device Overhead ====================

DEV | Q2G G2I Q2M I2D D2C
---------- | --------- --------- --------- --------- ---------
( 8, 16) | 1.2050% 0.8688% 0.0000% 4.1801% 93.7461%
---------- | --------- --------- --------- --------- ---------
Overall | 1.2050% 0.8688% 0.0000% 4.1801% 93.7461%
...

我們看到93.7461%的時間消耗在D2C，也就是硬體層，這是正常的，我們說過D2C是衡量硬體效能的指標，這裡單個IO平均0.129201毫秒，已經是相當快了，單個IO最慢14.246176 毫秒，不算壞。Q2G和G2I都很小，完全正常。I2D稍微有點大，應該是cfq scheduler的排程策略造成的，你可以試試其它scheduler，比如deadline，比較兩者的差異，然後選擇最適合你應用特點的那個。

使用blktrace簡單分析IO效能

blktrace的原理

blktrace的用法

利用btt分析blktrace資料

熱門文章