天天看點
傳回

利用blktrace分析磁盤I/O

blktrace對于分析block I/O是個非常好的工具，本篇文章記錄了如何使用blktrace。

blktrace原理

blktrace是對通用塊層（block layer）的I/O跟蹤機制，它能抓取詳細的I/O請求（request），發送到使用者空間。

blktrace主要由3部分組成：

核心部分

  • 記錄核心到使用者空間的I/O追蹤資訊的程式
  • 分析、展示I/O追蹤資訊的程式
  • 主要在block layer實作，抓取的資料通過debugfs來傳遞。每個被跟蹤的裝置都有一個在debugfs挂載目錄的檔案。debugfs挂載目錄預設是：/sys/kernel/debug

用官方的一張圖來直覺的展現：

一個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
  • 被I/O Scheduler依照排程政策發送給driver
  • 被driver送出給硬體，經過HBA、電纜（光纖、網線等）、交換機（SAN或網絡）、最後到達儲存設備，裝置完成I/O請求之後再把結果發回。

blktrace使用

  • 安裝blktrace包 
yum
install
blktrace
  • 追蹤指定裝置的I/O 
[root@k8s-slave9 longterm_io]
# blktrace -d /dev/sde
^C=== sde ===
  
CPU  0:                   38 events,        2 KiB data
  
CPU  1:                    1 events,        1 KiB data
  
CPU  2:                  232 events,       11 KiB data
  
CPU  3:                    2 events,        1 KiB data
  
CPU  4:                   41 events,        2 KiB data
  
...
  
Total:                   567 events (dropped 0),       27 KiB data

-d 指定具體的裝置名

上面是抓取一段時間後，Ctrl+C中止的。也可以指定時間：-w

blktrace執行完之後，會生産很多檔案，每個CPU都會有一個檔案，檔案名組成：<裝置名>.blktrace.，如下：

[root@k8s-slave9 longterm_io]
 ls
sde.blktrace.0   sde.blktrace.12  sde.blktrace.16  sde.blktrace.2   sde.blktrace.23  sde.blktrace.27  sde.blktrace.30  sde.blktrace.34  sde.blktrace.38  sde.blktrace.6
...

抓取IO資訊，完成了第一步，我們要分析這些I/O，就需要下面的工具。

blkparse分析資料

  • 解析IO追蹤資訊

    blkparse是一個會把不同CPU的I/O trace檔案合并，并解析、格式化輸出為對使用者可讀友好IO資訊的工具。

    先把上面生成的所有CPU I/O trace檔案合并成一個檔案：

[root@k8s-slave9 longterm_io]
# blkparse -i sde -d sde.blktrace.bin
Input
file
sde.blktrace.0 added
Input
file
sde.blktrace.1 added
Input
file
sde.blktrace.2 added
Input
file
sde.blktrace.3 added
Input
file
sde.blktrace.4 added
...
-----------------------------第一個IO開始
 
8,64  35        1     0.000000000 28378  A   W 470236984 + 40 <- (8,65) 470234936  
8,64  35        2     0.000000670 28378  Q   W 470236984 + 40 [kworker
/u82
:1]  
8,64  35        3     0.000005125 28378  G   W 470236984 + 40 [kworker
/u82
:1]  
8,64  35        4     0.000005443 28378  P   N [kworker
/u82
:1]  
8,64  35        5     0.000009123 28378  I   W 470236984 + 40 [kworker
/u82
:1]  
8,64  35        6     0.000009978 28378  U   N [kworker
/u82
:1] 1  
8,64  35        7     0.000010638 28378  D   W 470236984 + 40 [kworker
/u82
:1]  
8,64  31        1     0.207382887     0  C   W 470236984 + 40 [0]
-----------------------------第一個IO完成
-----------------------------第二個IO開始
 
8,64   2        1    10.239998442  4861  A FWFSM 469242512 + 2 <- (8,65) 469240464 
8,64   2        2    10.239999862  4861  Q FWFSM 469242512 + 2 [kworker
/2
:0H]  
8,64   2        3    10.240004505  4861  G FWFSM 469242512 + 2 [kworker
/2
:0H]  
8,64   2        4    10.240005325  4861  P   N [kworker
/2
:0H]  
8,64   2        5    10.240007109  4861  I FWFSM 469242512 + 2 [kworker
/2
:0H]  
8,64   2        6    10.240008795  4861  U   N [kworker
/2
:0H] 1  
8,64   4        1    10.482792539     0  D WFSM 469242512 + 2 [swapper
/0
]  
8,64   8        1    10.492646670     0  C WFSM 469242512 + 2 [0]
-----------------------------第二個IO完成
...
CPU0 (sde): 
Reads Queued:           1,        8KiB     Writes Queued:           3,      172KiB 
Read Dispatches:        1,        8KiB     Write Dispatches:        3,      172KiB 
Reads Requeued:         0         Writes Requeued:         0 
Reads Completed:        1,        8KiB     Writes Completed:        3,      172KiB
Read Merges:            0,        0KiB     Write Merges:            0,        0KiB
Read depth:             1             Write depth:             4
IO unplugs:             4             Timer unplugs:           0
...
Total (sde): 
Reads Queued:          23,      184KiB     Writes Queued:          41,      652KiB
Read Dispatches:       23,      184KiB     Write Dispatches:       36,      653KiB 
Reads Requeued:         0         Writes Requeued:         0 
Reads Completed:       23,      184KiB     Writes Completed:       53,      653KiB
Read Merges:            0,        0KiB     Write Merges:            5,       91KiB 
IO unplugs:            57             Timer unplugs:           0
Throughput (R
/W
): 0KiB
/s
/ 1KiB
/s
Events (sde): 500 entries
Skips: 0 forward (0 -   0.0%)

中間那段I/O處理階段說明：

第一列：裝置号 主裝置号，次裝置号

第二列：CPU

第三列：順序号

第五列：時間戳

第六列：PID 程序号

第七列：具體事件

第八列：具體的讀寫操作

W：Write

   R：Read

   S：Sync

   FWF：第一個F是Flush，W還是Write，第二個F是FUA（force unit acess）

   M：Metadata

   D：Discard

   B：Barrier從抓取的I/O來看，所有I2D耗時比較長的都是FWFSM的操作。

第九列：磁盤起始塊+操作的塊的數量

第十列：程序名或具體的指令

通過這些輸出，我們就可以明确看到，每個階段的具體耗時，就可以定位I/O慢在哪個階段，也是需要深入的分析什麼原因導緻的。

  • 具體動作（或事件）的字母代表意義：
  • A remap 對于棧式裝置，進來的I/O将被重新映射到I/O棧中的具體裝置
  • X split 對于做了Raid或進行了device mapper(dm)的裝置，進來的IO可能需要切割，然後發送給不同的裝置
  • Q queued I/O進入block layer，将要被request代碼處理（即将生成IO請求）
  • G get request I/O請求（request）生成，為I/O配置設定一個request 結構體。
  • M back merge 之前已經存在的I/O request的終止block号，和該I/O的起始block号一緻，就會合并。也就是向後合并
  • F front merge 之前已經存在的I/O request的起始block号，和該I/O的終止block号一緻，就會合并。也就是向前合并
  • I inserted I/O請求被插入到I/O scheduler隊列
  • S sleep 沒有可用的request結構體，也就是I/O滿了，隻能等待有request結構體完成釋放
  • P plug 當一個I/O入隊一個空隊列時，Linux會鎖住這個隊列，不處理該I/O，這樣做是為了等待一會，看有沒有新的I/O進來，可以合并

  • U unplug 當隊列中已經有I/O request時，會放開這個隊列，準備向磁盤驅動發送該I/O。

    這個動作的觸發條件是：逾時（plug的時候，會設定逾時時間）；或者是有一些I/O在隊列中（多于1個I/O）

  • D issued I/O将會被傳送給磁盤驅動程式處理
  • C complete I/O處理被磁盤處理完成。

btt分析資料 

blkparse隻是将blktrace資料轉成可以人工閱讀的格式，由于資料量通常很大，人工分析并不輕松。btt是對blktrace資料進行自動分析的工具。
  • 使用btt解析資料，檢視I/O的整體情況 
[root@k8s-slave9 longterm_io]
# btt -i sde.blktrace.bin
==================== All Devices ====================
 
            
ALL           MIN           AVG           MAX           N
--------------- ------------- ------------- ------------- -----------
 
Q2Q               0.000002013   7.354920889  30.208019079          63
Q2G               0.000000889   0.000003898   0.000016826          59
G2I               0.000000591   0.000003383   0.000035937          59
Q2M               0.000000333   0.000001295   0.000002440           5
I2D               0.000000503   0.065649284   0.252996244          59
M2D               0.000003840   0.000011816   0.000017717           5
D2C               0.000128883   0.056202494   0.254664063          64
Q2C               0.000131324   0.116730664   0.262633229          64
 
==================== Device Overhead ====================
 
       
DEV |       Q2G       G2I       Q2M       I2D       D2C
---------- | --------- --------- --------- --------- ---------
 
(  8, 64) |   0.0031%   0.0027%   0.0001%  51.8462%  48.1472%
---------- | --------- --------- --------- --------- ---------
   
Overall |   0.0031%   0.0027%   0.0001%  51.8462%  48.1472%
 
==================== Device Merge Information ====================
 
       
DEV |      
#Q       #D   Ratio |   BLKmin   BLKavg   BLKmax    Total
---------- | -------- -------- ------- | -------- -------- -------- --------
 
(  8, 64) |       64       59     1.1 |        2       28      176     1675
...

第一個表的第一列是具體的I/O階段，第二、三、四列分别是最小耗時、平均耗時、最大耗時（機關：s），第五列是I/O數。

第二個表是對第一個表做了耗時統計，看看整個I/O階段，哪個階段耗時占用最多。

第三個表是進行合并的資訊，但是從内容來看，沒有merge資訊啊。後面有所有I/O中操作的塊數量的最小值、平均值、最大值。

IO處理階段：

Q2Q： 相鄰兩次進入通用塊層的I/O間隔

Q2G：I/O進入block layer到I/O請求（request）生成的時間

G2I ：I/O請求生成到被插入I/O請求隊列（request queue）的時間

Q2M：I/O進入block層到該I/O被和已存在的I/O請求合并的時間

I2D ：I/O請求進入request queue隊到分發到裝置驅動的時間

M2D：I/O合并成I/O請求到分發到裝置驅動的時間

D2C：I/O分到到裝置驅動到裝置處理完成時間

在上述過程中，Q2M、M2D兩個階段不是必然發生的，隻有可以merge的I/O才會進行合并。

  • 生産不同次元的報告

    檢視所有I/O D2C階段的具體延時： （-l參數将會分析D2C階段延遲，該參數後是具體的輸出檔案名）

[root@k8s-slave9 longterm_io]
# btt -i sde.blktrace.bin -l sde.d2c_latency
==================== All Devices ====================
 
            
ALL           MIN           AVG           MAX           N
--------------- ------------- ------------- ------------- -----------
 
Q2Q               0.000002013   7.354920889  30.208019079          63
Q2G               0.000000889   0.000003898   0.000016826          59
G2I               0.000000591   0.000003383   0.000035937          59
Q2M               0.000000333   0.000001295   0.000002440           5
I2D               0.000000503   0.065649284   0.252996244          59
M2D               0.000003840   0.000011816   0.000017717           5
D2C               0.000128883   0.056202494   0.254664063          64
Q2C               0.000131324   0.116730664   0.262633229          64
...

執行完上面的指令後，會有如下檔案生成：

[root@k8s-slave9 longterm_io]
# ls *.dat
8,64_iops_fp.dat  8,64_mbps_fp.dat  sde.d2c_latency_8,64_d2c.dat  sys_iops_fp.dat  sys_mbps_fp.dat

如上輸出，可以看到：有這段時間的IOPS統計（8,64_iops_fp.dat、sys_iops_fp.dat）、帶寬統計（8,64_mbps_fp.dat、sys_mbps_fp.dat）、延遲統計（sde.d2c_latency_8,64_d2c.dat）

我們看看這些檔案：

每個時間點的I
/O
個數：
[root@k8s-slave9 longterm_io]
# cat sys_iops_fp.dat
0 1
10 1
31 1
40 1
44 1
66 1
70 1
100 5
...
 
每個時間點的帶寬：
[root@k8s-slave9 longterm_io]
# cat sys_mbps_fp.dat
0 0.019531
10 0.000977
31 0.031250
40 0.000977
44 0.003906
66 0.015625
70 0.002441
100 0.048828
...
 
每個時間點的D2C階段延遲：
[root@k8s-slave9 longterm_io]
# cat sde.d2c_latency_8,64_d2c.dat
0.207383 0.207372
10.492647 0.009854
31.439889 0.207854
40.700689 0.009720
44.381372 0.206810
44.381372 0.206810
66.564038 0.004049
70.907380 0.008502
100.047822 0.207767
...

其中，第一列是時間戳，第二列是具體的内容

檢視所有I/O的size、offset等資訊：（-B參數将會輸出具體的block号，包括起始block、終止block）

[root@k8s-slave9 longterm_io]
# btt -i sde.blktrace.bin -B sde.offset
==================== All Devices ====================
 
            
ALL           MIN           AVG           MAX           N
--------------- ------------- ------------- ------------- -----------
 
Q2Q               0.000002013   7.354920889  30.208019079          63
Q2G               0.000000889   0.000003898   0.000016826          59
G2I               0.000000591   0.000003383   0.000035937          59
Q2M               0.000000333   0.000001295   0.000002440           5
I2D               0.000000503   0.065649284   0.252996244          59
M2D               0.000003840   0.000011816   0.000017717           5
D2C               0.000128883   0.056202494   0.254664063          64
Q2C               0.000131324   0.116730664   0.262633229          64
...

上述指令将輸出如下的檔案：

[root@k8s-slave9 longterm_io]
# ls | grep offset
sde.offset_8,64_c.dat
sde.offset_8,64_r.dat
sde.offset_8,64_w.dat
xxx_r.dat：讀操作相關資訊
xxx_w.dat：寫操作相關資訊

xxx_c.dat：所有操作，讀寫都有

我們看看寫操作：

[root@k8s-slave9 longterm_io]
# cat sde.offset_8,64_w.dat
    
0.000010638 470236984 470237024
   
10.482792539 469242512 469242514
   
31.232035019 470237016 470237080
   
40.690968712 469242514 469242516
   
44.174561925 703299792 703299800
   
66.559989117 470237072 470237104
   
70.898878399 469242516 469242521
   
99.840054977 470237096 470237152
  
100.864256898 703277841 703277843
  
...

其中第一列是時間戳，第二列是I/O操作的起始block号，第三列是I/O操作的終止block号。

參考

2d 資料 裝置驅動
上一篇: algorithm_chapter1
下一篇: 記一次shell腳本推背景stopped的問題

繼續閱讀