Centos 7下通过blktrace了解io各阶段性能

迷南。 2022-07-11 01:59 333阅读 0赞

# 操作环境 #

Centos 7.0

DELL R720

# 操作步骤 #

## blktrace使用方法 ##

使用blktrace之前需要挂载debugfs

#mount -t debugfs debugfs /sys/kernel/debug

通过blktrace实时收集并显示硬盘操作数据，Ctrl+c退出收集

[root@localhost ~]# blktrace -d /dev/sdb -o - | blkparse -i -
      8,16   2        1     0.000000000 12228  Q  WS 0 + 256 [dd]
      8,16   2        2     0.000004050 12228  G  WS 0 + 256 [dd]
      8,16   2        3     0.000005738 12228  P   N [dd]
      8,16   2        4     0.000008127 12228  I  WS 0 + 256 [dd]
      8,16   2        5     0.000009410 12228  U   N [dd] 1
      8,16   2        6     0.000011178 12228  D  WS 0 + 256 [dd]
      8,16   2        7     0.018092900     0  C  WS 0 + 256 [0]
    .......
    .......
    CPU2 (8,16):
     Reads Queued:           0,        0KiB  Writes Queued:           1,      128KiB
     Read Dispatches:        0,        0KiB  Write Dispatches:        1,      128KiB
     Reads Requeued:         0               Writes Requeued:         0
     Reads Completed:        0,        0KiB  Writes Completed:        1,      128KiB
     Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
     Read depth:             4               Write depth:             1
     PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
     PC Read Disp.:          1,        0KiB  PC Write Disp.:          0,        0KiB
     PC Reads Req.:          0               PC Writes Req.:          0
     PC Reads Compl.:        0               PC Writes Compl.:        0
     IO unplugs:             1               Timer unplugs:           0
    CPU3 (8,16):
     Reads Queued:           1,        4KiB  Writes Queued:           0,        0KiB
     Read Dispatches:        1,        4KiB  Write Dispatches:        0,        0KiB
     Reads Requeued:         0               Writes Requeued:         0
     Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
     Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
     Read depth:             4               Write depth:             1
     PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
     PC Read Disp.:          1,        0KiB  PC Write Disp.:          0,        0KiB
     PC Reads Req.:          0               PC Writes Req.:          0
     PC Reads Compl.:        0               PC Writes Compl.:        0
     IO unplugs:             1               Timer unplugs:           0
    CPU5 (8,16):
     Reads Queued:           8,       32KiB  Writes Queued:           0,        0KiB
     Read Dispatches:        8,       32KiB  Write Dispatches:        0,        0KiB
     Reads Requeued:         0               Writes Requeued:         0
     Reads Completed:        9,       36KiB  Writes Completed:        0,        0KiB
     Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
     Read depth:             4               Write depth:             1
     PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
     PC Read Disp.:          6,        0KiB  PC Write Disp.:          0,        0KiB
     PC Reads Req.:          0               PC Writes Req.:          0
     PC Reads Compl.:        4               PC Writes Compl.:        0
     IO unplugs:             8               Timer unplugs:           0
    
    Total (8,16):
     Reads Queued:           9,       36KiB  Writes Queued:           1,      128KiB
     Read Dispatches:        9,       36KiB  Write Dispatches:        1,      128KiB
     Reads Requeued:         0               Writes Requeued:         0
     Reads Completed:        9,       36KiB  Writes Completed:        1,      128KiB
     Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
     PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
     PC Read Disp.:          8,        0KiB  PC Write Disp.:          0,        0KiB
     PC Reads Req.:          0               PC Writes Req.:          0
     PC Reads Compl.:        4               PC Writes Compl.:        0
     IO unplugs:            10               Timer unplugs:           0
    
    Throughput (R/W): 1,500KiB/s / 5,333KiB/s
    Events (8,16): 98 entries
    Skips: 0 forward (0 -   0.0%)

也可以通过blktrace收集硬盘数据至文件中，而后通过blkparse进行查看

[root@localhost ~]# blktrace -d /dev/sdb
    ^C=== sdb ===
      CPU  0:                    1 events,        1 KiB data
      CPU  1:                    0 events,        0 KiB data
      CPU  2:                   14 events,        1 KiB data
      CPU  3:                   12 events,        1 KiB data
      CPU  4:                    0 events,        0 KiB data
      CPU  5:                   85 events,        4 KiB data
      CPU  6:                    0 events,        0 KiB data
      CPU  7:                    0 events,        0 KiB data
      Total:                   112 events (dropped 0),        6 KiB data
    [root@localhost ~]# blkparse -i sdb
    Input file sdb.blktrace.0 added
    Input file sdb.blktrace.2 added
    Input file sdb.blktrace.3 added
    Input file sdb.blktrace.5 added
      8,16   2        1     0.000000000 12243  Q  WS 0 + 256 [dd]
      8,16   2        2     0.000004304 12243  G  WS 0 + 256 [dd]
      8,16   2        3     0.000005577 12243  P   N [dd]
      8,16   2        4     0.000007906 12243  I  WS 0 + 256 [dd]
      8,16   2        5     0.000009096 12243  U   N [dd] 1
      8,16   2        6     0.000011101 12243  D  WS 0 + 256 [dd]
      8,16   2        7     0.015232277     0  C  WS 0 + 256 [0]
    ......
    ......
    CPU2 (sdb):
     Reads Queued:           0,        0KiB  Writes Queued:           1,      128KiB
     Read Dispatches:        0,        0KiB  Write Dispatches:        1,      128KiB
     Reads Requeued:         0               Writes Requeued:         0
     Reads Completed:        0,        0KiB  Writes Completed:        1,      128KiB
     Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
     Read depth:             4               Write depth:             1
     PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
     PC Read Disp.:          1,        0KiB  PC Write Disp.:          0,        0KiB
     PC Reads Req.:          0               PC Writes Req.:          0
     PC Reads Compl.:        0               PC Writes Compl.:        0
     IO unplugs:             1               Timer unplugs:           0
    CPU3 (sdb):
     Reads Queued:           1,        4KiB  Writes Queued:           0,        0KiB
     Read Dispatches:        1,        4KiB  Write Dispatches:        0,        0KiB
     Reads Requeued:         0               Writes Requeued:         0
     Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
     Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
     Read depth:             4               Write depth:             1
     PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
     PC Read Disp.:          1,        0KiB  PC Write Disp.:          0,        0KiB
     PC Reads Req.:          0               PC Writes Req.:          0
     PC Reads Compl.:        0               PC Writes Compl.:        0
     IO unplugs:             1               Timer unplugs:           0
    CPU5 (sdb):
     Reads Queued:           8,       32KiB  Writes Queued:           0,        0KiB
     Read Dispatches:        8,       32KiB  Write Dispatches:        0,        0KiB
     Reads Requeued:         0               Writes Requeued:         0
     Reads Completed:        9,       36KiB  Writes Completed:        0,        0KiB
     Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
     Read depth:             4               Write depth:             1
     PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
     PC Read Disp.:          6,        0KiB  PC Write Disp.:          0,        0KiB
     PC Reads Req.:          0               PC Writes Req.:          0
     PC Reads Compl.:        4               PC Writes Compl.:        0
     IO unplugs:             8               Timer unplugs:           0
    
    Total (sdb):
     Reads Queued:           9,       36KiB  Writes Queued:           1,      128KiB
     Read Dispatches:        9,       36KiB  Write Dispatches:        1,      128KiB
     Reads Requeued:         0               Writes Requeued:         0
     Reads Completed:        9,       36KiB  Writes Completed:        1,      128KiB
     Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
     PC Reads Queued:        0,        0KiB  PC Writes Queued:        0,        0KiB
     PC Read Disp.:          8,        0KiB  PC Write Disp.:          0,        0KiB
     PC Reads Req.:          0               PC Writes Req.:          0
     PC Reads Compl.:        4               PC Writes Compl.:        0
     IO unplugs:            10               Timer unplugs:           0
    
    Throughput (R/W): 1,714KiB/s / 6,095KiB/s
    Events (sdb): 98 entries
    Skips: 0 forward (0 -   0.0%)

通过btt分析blktrace数据

上面可以发现通过blkparse查看的数据量比较大，不利于查看，通过btt可以对blktrace数据进行自动分析

首先将blktrace的报告合并为一

[root@localhost ~]# blkparse -i sdb -d sdb.blktrace.btt                                                                                                                                                                                                                       
    Input file sdb.blktrace.0 added
    Input file sdb.blktrace.2 added
    Input file sdb.blktrace.3 added
    Input file sdb.blktrace.5 added
      8,16   2        1     0.000000000 12243  Q  WS 0 + 256 [dd]
      8,16   2        2     0.000004304 12243  G  WS 0 + 256 [dd]
      8,16   2        3     0.000005577 12243  P   N [dd]
      8,16   2        4     0.000007906 12243  I  WS 0 + 256 [dd]
      8,16   2        5     0.000009096 12243  U   N [dd] 1
      8,16   2        6     0.000011101 12243  D  WS 0 + 256 [dd]
      8,16   2        7     0.015232277     0  C  WS 0 + 256 [0]
    ......
    ......

而后通过btt自动分析sdb.blktrace.btt文件

[root@localhost ~]# btt -i sdb.blktrace.btt 
    ==================== All Devices ====================
    
                ALL           MIN           AVG           MAX           N
    --------------- ------------- ------------- ------------- -----------
    
    Q2Q               0.000097608   0.002396168   0.020167415           9
    Q2G               0.000000982   0.000001807   0.000004304          10
    G2I               0.000001246   0.000001827   0.000003602          10
    I2D               0.000001029   0.000001643   0.000003195          10
    D2C               0.000078278   0.001622636   0.015221176          10
    Q2C               0.000081559   0.001627913   0.015232277          10
    
    ==================== Device Overhead ====================
    
           DEV |       Q2G       G2I       Q2M       I2D       D2C
    ---------- | --------- --------- --------- --------- ---------
     (  8, 16) |   0.1110%   0.1122%   0.0000%   0.1009%  99.6758%
    ---------- | --------- --------- --------- --------- ---------
       Overall |   0.1110%   0.1122%   0.0000%   0.1009%  99.6758%

这里分别列出了IO过程中的几个阶段

Q2G

G2I

I2D

D2C

来查看下Q、G、I、D、C分别代表什么含义

The following table shows the various actions which may be output.

<table> 
 <tbody> 
  <tr> 
   <td align="LEFT">Act</td> 
   <td align="LEFT">Description</td> 
  </tr> 
  <tr> 
   <td align="LEFT">A</td> 
   <td align="LEFT">IO was remapped to a different device</td> 
  </tr> 
  <tr> 
   <td align="LEFT">B</td> 
   <td align="LEFT">IO bounced</td> 
  </tr> 
  <tr> 
   <td align="LEFT">C</td> 
   <td align="LEFT">IO completion</td> 
  </tr> 
  <tr> 
   <td align="LEFT">D</td> 
   <td align="LEFT">IO issued to driver</td> 
  </tr> 
  <tr> 
   <td align="LEFT">F</td> 
   <td align="LEFT">IO front merged with request on queue</td> 
  </tr> 
  <tr> 
   <td align="LEFT">G</td> 
   <td align="LEFT">Get request</td> 
  </tr> 
  <tr> 
   <td align="LEFT">I</td> 
   <td align="LEFT">IO inserted onto request queue</td> 
  </tr> 
  <tr> 
   <td align="LEFT">M</td> 
   <td align="LEFT">IO back merged with request on queue</td> 
  </tr> 
  <tr> 
   <td align="LEFT">P</td> 
   <td align="LEFT">Plug request</td> 
  </tr> 
  <tr> 
   <td align="LEFT">Q</td> 
   <td align="LEFT">IO handled by request queue code</td> 
  </tr> 
  <tr> 
   <td align="LEFT">S</td> 
   <td align="LEFT">Sleep request</td> 
  </tr> 
  <tr> 
   <td align="LEFT">T</td> 
   <td align="LEFT">Unplug due to timeout</td> 
  </tr> 
  <tr> 
   <td align="LEFT">U</td> 
   <td align="LEFT">Unplug request</td> 
  </tr> 
  <tr> 
   <td align="LEFT">X</td> 
   <td align="LEFT">Split</td> 
  </tr> 
 </tbody> 
</table>

根据blktrace官网文档

Q：准备发起IO请求

G:：IO请求生成

I：IO请求插入请求队列中

D：IO请求进行硬盘设备

C：IO请求完成

那么对应的

Q2G：生产IO请求耗费的时间

G2I：IO请求进行IO调取所耗费的时间

I2D：IO请求在IO调度中所耗费的时间

D2C：IO请求在硬件设备中耗费的时间

Q2C = Q2G+G2I+I2D+D2C