利用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性能的指標。

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：
$ blkparse -i sdb -d sdb.blktrace.bin
執行btt對sdb.blktrace.bin進行分析：
$ 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，比較二者的差別，而後選擇最適合你應用特色的那個 。