利用blktrace分析IO性能
在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性能的指標。
附上event速查表：
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
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
|
$ 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：
$ blkparse -i sdb -d sdb.blktrace.bin
執行btt對sdb.blktrace.bin進行分析：
$ btt -i sdb.blktrace.bin
下面是一個btt實例：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
|
...
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數據自制分析工具
blktrace在block layer采集了每一個I/O的數據，可以用於完成一些非常深入的分析任務，以下是一個利用它分析應用系統的I/O模式的例子：
剖析生產系統的I/O模式
轉載自：http://linuxperf.com/?cat=11