shhuiw's Technotes

[转载] blktrace 分析 IO

前言

上篇博客介绍了 iostat 的一些输出，这篇介绍 blktrace 这个神器。上一节介绍 iostat 的时候，我们心心念念希望得到块设备处理 io 的 service time，而不是 service time + wait time，因为对于评估一个磁盘或者云磁盘而言，service time 才是衡量磁盘性能的核心指标和直接指标。很不幸 iostat 无法提供这个指标，但是 blktrace 可以。

blktrace 是一柄神器，很多工具都是基于该神器的：ioprof、seekwatcher、iowatcher，这个工具基本可以满足我们的对块设备请求的所有了解。

blktrace 的原理

一个 I/O 请求，从应用层到底层块设备，路径如下图所示：

The Linux Storage Stock Diagram.pnf

从上图可以看出 IO 路径是很复杂的。这么复杂的 IO 路径我们是无法用短短一篇小博文介绍清楚的。我们将 IO 路径简化一下：

Bean Li - Simple IO path.png

  • 一个 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 能够记录下 IO 所经历的各个步骤: Bean Li - blktrace work flow.png

我们一起看下 blktrace 的输出长什么样子： Bean Li - blkparse output.png

    第一个字段：8,0 这个字段是设备号 major device ID 和 minor device ID
    第二个字段：3 表示 CPU
    第三个字段：11 序列号
    第四个字段：0.009507758 Time Stamp 是时间偏移
    第五个字段：PID 本次 IO 对应的进程 ID
    第六个字段：Event，这个字段非常重要，反映了 IO 进行到了那一步
    第七个字段：R 表示 Read， W 是 Write，D 表示 block，B 表示 Barrier Operation
    第八个字段：223490+56，表示的是起始 block number 和 number of blocks，即我们常说的 Offset 和 Size
    第九个字段： 进程名

其中第六个字段非常有用：每一个字母都代表了IO请求所经历的某个阶段。

    Q – 即将生成 IO 请求
    |
    G – IO 请求生成
    |
    I – IO 请求进入 IO Scheduler 队列
    |
    D – IO 请求进入 driver
    |
    C – IO 请求执行完毕

注意，整个 IO 路径，分成很多段，每一段开始的时候，都会有一个时间戳，根据上一段开始的时间和下一段开始的时间，就可以得到 IO 路径各段花费的时间。

注意，我们心心念念的 service time，也就是反应块设备处理能力的指标，就是从 D 到 C 所花费的时间，简称 D2C。

而 iostat 输出中的 await，即整个 IO 从生成请求到IO请求执行完毕，即从 Q 到 C 所花费的时间，我们简称 Q2C。

我们知道 Linux 有 I/O scheduler，调度器的效率如何，I2D 是重要的指标。

注意，这只是 blktrace 输出的一个部分，很明显，我们还能拿到 offset 和 size，根据 offset，我们能拿到某一段时间里，应用程序都访问了整个块设备的那些 block，从而绘制出块设备访问轨迹图。

另外还有 size 和第七个字段（Read or Write），我们可以知道 IO size 的分布直方图。对于本文来讲，我们就是要根据 blktrace 来获取这些信息。

blktrace、blkparse 和 btt

我们接下来简单介绍这些工具的使用，其中这三个命令都是属于 blktrace 这个包的，他们是一家人。

首先通过如下命令，可以查看磁盘上的实时信息：blktrace -d /dev/sdb -o – | blkparse -i – 这个命令会连绵不绝地出现很多输出，当你输入ctrl＋C的时候，会停止。

当然了，你也可以先用如下命令采集信息，待所有信息采集完毕后，统一分析所有采集到的数据。搜集信息的命令如下：blktrace -d /dev/sdb

注意，这个命令并不是只输出一个文件，它会根据 CPU 的个数上，每一个 CPU 都会输出一个文件，如下所示：

    -rw-r--r-- 1 manu manu  1.3M Jul  6 19:58 sdb.blktrace.0
    -rw-r--r-- 1 manu manu  823K Jul  6 19:58 sdb.blktrace.1
    -rw-r--r-- 1 manu manu  2.8M Jul  6 19:58 sdb.blktrace.10
    -rw-r--r-- 1 manu manu  1.9M Jul  6 19:58 sdb.blktrace.11
    -rw-r--r-- 1 manu manu  474K Jul  6 19:58 sdb.blktrace.12
    -rw-r--r-- 1 manu manu  271K Jul  6 19:58 sdb.blktrace.13
    -rw-r--r-- 1 manu manu  578K Jul  6 19:58 sdb.blktrace.14
    -rw-r--r-- 1 manu manu  375K Jul  6 19:58 sdb.blktrace.15
    -rw-r--r-- 1 manu manu  382K Jul  6 19:58 sdb.blktrace.16
    -rw-r--r-- 1 manu manu  478K Jul  6 19:58 sdb.blktrace.17
    -rw-r--r-- 1 manu manu  839K Jul  6 19:58 sdb.blktrace.18
    -rw-r--r-- 1 manu manu  848K Jul  6 19:58 sdb.blktrace.19
    -rw-r--r-- 1 manu manu  1.6M Jul  6 19:58 sdb.blktrace.2
    -rw-r--r-- 1 manu manu  652K Jul  6 19:58 sdb.blktrace.20
    -rw-r--r-- 1 manu manu  738K Jul  6 19:58 sdb.blktrace.21
    -rw-r--r-- 1 manu manu  594K Jul  6 19:58 sdb.blktrace.22
    -rw-r--r-- 1 manu manu  527K Jul  6 19:58 sdb.blktrace.23
    -rw-r--r-- 1 manu manu 1005K Jul  6 19:58 sdb.blktrace.3
    -rw-r--r-- 1 manu manu  1.2M Jul  6 19:58 sdb.blktrace.4
    -rw-r--r-- 1 manu manu  511K Jul  6 19:58 sdb.blktrace.5
    -rw-r--r-- 1 manu manu  2.3M Jul  6 19:58 sdb.blktrace.6
    -rw-r--r-- 1 manu manu  1.3M Jul  6 19:58 sdb.blktrace.7
    -rw-r--r-- 1 manu manu  2.1M Jul  6 19:58 sdb.blktrace.8
    -rw-r--r-- 1 manu manu  1.1M Jul  6 19:58 sdb.blktrace.9

有了输出，我们可以通过 blkparse -i sdb 来分析采集的数据：

  8,16   7     2147     0.999400390 630169  I   W 447379872 + 8 [kworker/u482:0]
  8,16   7     2148     0.999400653 630169  I   W 447380040 + 8 [kworker/u482:0]
  8,16   7     2149     0.999401057 630169  I   W 447380088 + 16 [kworker/u482:0]
  8,16   7     2150     0.999401364 630169  I   W 447380176 + 8 [kworker/u482:0]
  8,16   7     2151     0.999401521 630169  I   W 453543312 + 8 [kworker/u482:0]
  8,16   7     2152     0.999401843 630169  I   W 453543328 + 8 [kworker/u482:0]
  8,16   7     2153     0.999402195 630169  U   N [kworker/u482:0] 14
  8,16   6     5648     0.999403047 16921  C   W 347875880 + 8 [0]
  8,16   6     5649     0.999406293 16921  D   W 301856632 + 8 [ceph-osd]
  8,16   6     5650     0.999421040 16921  C   W 354834456 + 8 [0]
  8,16   6     5651     0.999423900 16921  D   W 301857280 + 8 [ceph-osd]
  8,16   7     2154     0.999442195 630169  A   W 425409840 + 8 <- (8,22) 131806512
  8,16   7     2155     0.999442601 630169  Q   W 425409840 + 8 [kworker/u482:0]
  8,16   7     2156     0.999444277 630169  G   W 425409840 + 8 [kworker/u482:0]
  8,16   7     2157     0.999445177 630169  P   N [kworker/u482:0]
  8,16   7     2158     0.999446341 630169  I   W 425409840 + 8 [kworker/u482:0]
  8,16   7     2159     0.999446773 630169 UT   N [kworker/u482:0] 1
  8,16   6     5652     0.999452685 16921  C   W 354834520 + 8 [0]
  8,16   6     5653     0.999455613 16921  D   W 301857336 + 8 [ceph-osd]
  8,16   6     5654     0.999470425 16921  C   W 393228176 + 8 [0]
  8,16   6     5655     0.999474127 16921  D   W 411554968 + 8 [ceph-osd]
  8,16   6     5656     0.999488551 16921  C   W 393228560 + 8 [0]
  8,16   6     5657     0.999491549 16921  D   W 411556112 + 8 [ceph-osd]
  8,16   6     5658     0.999594849 16923  C   W 393230152 + 16 [0]
  8,16   6     5659     0.999604038 16923  D   W 432877368 + 8 [ceph-osd]
  8,16   6     5660     0.999610322 16923  C   W 487390128 + 8 [0]
  8,16   6     5661     0.999614654 16923  D   W 432879632 + 8 [ceph-osd]
  8,16   6     5662     0.999628284 16923  C   W 487391344 + 8 [0]
  8,16   6     5663     0.999632014 16923  D   W 432879680 + 8 [ceph-osd]
  8,16   6     5664     0.999646122 16923  C   W 293759504 + 8 [0]

注意，blkparse 仅仅是将 blktrace 输出的信息转化成人可以阅读和理解的输出，但是，信息太多，太杂，人完全没法得到关键信息。 这时候 btt 就横空出世了，这个工具可以将 blktrace 采集回来的数据，进行分析，得到对人更有用的信息。事实上，btt 也是我们的终点。

接下来，我们要利用 blktrace、blkparse 以及 btt 来采集和分析单块磁盘的的性能，最终我会生成一个 pdf 的文档。步骤如下：

    输入： blktrace 采集到的原始数据
    输出： 使用 btt，blkparse 还有自己写的一些 bash 脚本和 python 脚本，
          输出出 pdf 格式的 report
            通过各种工具，生成原始的分析结果，以及绘制对应的 PNG 图片：
                将分析结果以表格和图片的方式，写入 markdown 文本
                将 markdown 文本通过 pandoc 转换成 pdf 文档

获取各阶段的延迟信息

注意，btt 已经可以很自如地生成这部分统计信息，我们可以很容易得到如下的表格： Bean Li - btt output statistic.png

方法如下：

首先 blkparse 可以将对应不同 cpu 的多个文件聚合成一个文件：blkparse -i sdb -d sdb.blktrace.bin

然后 btt 就可以分析这个 sdb.blktrace.bin 了：

==================== All Devices ====================

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

Q2Q               0.000000001   0.000159747   0.025292639       62150
Q2G               0.000000233   0.000001380   0.000056343       52423
G2I               0.000000146   0.000027084   0.005031317       48516
Q2M               0.000000142   0.000000751   0.000021613        9728
I2D               0.000000096   0.001534463   0.022469688       52423
M2D               0.000000647   0.002617691   0.022445412        5821
D2C               0.000046189   0.000779355   0.007860766       62151
Q2C               0.000051089   0.002522832   0.026096657       62151

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

       DEV |       Q2G       G2I       Q2M       I2D       D2C
---------- | --------- --------- --------- --------- ---------
 (  8, 16) |   0.0461%   0.8380%   0.0047%  51.3029%  30.8921%
---------- | --------- --------- --------- --------- ---------
   Overall |   0.0461%   0.8380%   0.0047%  51.3029%  30.8921%

==================== Device Merge Information ====================

       DEV |       #Q       #D   Ratio |   BLKmin   BLKavg   BLKmax    Total
---------- | -------- -------- ------- | -------- -------- -------- --------
 (  8, 16) |    62151    52246     1.2 |        1       20      664  1051700

==================== Device Q2Q Seek Information ====================

       DEV |          NSEEKS            MEAN          MEDIAN | MODE           
---------- | --------------- --------------- --------------- | ---------------
 (  8, 16) |           62151      42079658.0               0 | 0(17159)
---------- | --------------- --------------- --------------- | ---------------
   Overall |          NSEEKS            MEAN          MEDIAN | MODE           
   Average |           62151      42079658.0               0 | 0(17159)

==================== Device D2D Seek Information ====================

       DEV |          NSEEKS            MEAN          MEDIAN | MODE           
---------- | --------------- --------------- --------------- | ---------------
 (  8, 16) |           52246      39892356.2               0 | 0(9249)
---------- | --------------- --------------- --------------- | ---------------
   Overall |          NSEEKS            MEAN          MEDIAN | MODE           
   Average |           52246      39892356.2               0 | 0(9249)

注意： D2C 和 Q2C，一个是表征块设备性能的关键指标，另一个是客户发起请求到收到响应的时间，我们可以看出，D2C 平均在0.000779355 秒，即0.7毫秒 Q2C 平均在0.002522832 秒，即2.5毫秒，无论是 service time 还是客户感知到的 await time，都是非常短的，表现非常不俗。但是 D2C 花费的时间只占整个 Q2C 的 30%， 51% 以上的时间花费在 I2D。

下面我们看下 D2C 和 Q2C 随着时间的分布情况： Bean Li - sdb D2C latency.png Bean Li - sdb D2C latency.png

绘制图片需要的信息可以通过如下指令得到：

    btt -i sdb.blktrace.bin -l sdb.d2c_latency
    btt -i sdb.blktrace.bin -q sdb.q2c_latency

IOPS 和 MBPS

从 btt 出发，我们分析出来采样时间内，整个块设备的 IOPS： Bean Li - sdb IOPS.png Bean Li - sdb MBPS.png

获取方法如下：

    blkparse -i sdb -d sdb.blktrace.bin
    btt -i sdb.blktrace.bin -q sdb.q2c_latency

注意，这一步之后，我们会得到如下文件：

    sdb.q2c_latency_8,16_q2c,dat
    sys_iops_fp.dat
    sys_mbps_fp.dat
    8,16_iops_fp.dat
    8,17_mbps_fp.dat

注意，如果我们 blktrace -d sdb，只关注 sdb 的时候，我们可以通过sys_iops_fp.dat 和 sys_mbps_fp.dat 获取对应的 IOPS 和 MBPS 信息：

    # cat sys_iops_fp.dat 
    0 3453
    1 4859
    2 7765
    3 6807
    4 4804
    5 4345
    6 2501
    7 10291
    8 2767
    9 4654

IO Size Historgram

我们很关心，在采样的时间内，IO size 的分布情况，因为这个可以得到，过去的时间里，我们是大 IO 居多还是小 IO 居多： Bean Li - IO size.png

步骤如下：

    blkparse -i sdb -d sub.blktrace.bin
    btt -i sdb.blktrace.bin -B sdb.offset

这个步骤之后会生成三个文件：

    sdb.offset_8,16_r.dat
    sdb.offset_8,16_w.dat
    sdb.offset_8,16_c.dat

其中 r 表示读操作的 offset 和 size 信息，w 表示写操作的 offset 和 size 信息，c 表示读＋写。

其输出格式如下：

 cat sdb.offset_8,16_w.dat
    0.000006500 74196632 74196656
    0.000194981 74196656 74196680
    0.000423532 21923304 21923336
    0.000597505 60868864 60868912
    0.001046757 20481496 20481520
    0.001137646 20481520 20481544
    0.002203609 21923336 21923360
    0.002288944 60868912 60868936
    0.002329903 21923360 21923384
    0.002895619 60868936 60868960
    0.004535853 20481544 20481576
    0.004841878 74196680 74196704
    0.004888624 60868960 60869008
    0.004991469 74196704 74196744
    0.005799109 74196744 74196800
    0.005880756 74196800 74196856
    0.007083202 74196856 74196880
    0.007172808 74196880 74196952
    0.007969956 60869008 60869040
    0.008297881 74196952 74196976
    0.008540390 74196976 74197000
    0.009995244 60869040 60869072
    0.010516189 74197000 74197032
    0.011409120 60869072 60869096
    0.011554233 60869096 60869120
    0.011996171 74197032 74197104
    ....
    9.908351667 74389976 74390000
    9.909115545 74390000 74390024
    9.909160991 74390024 74390048
    9.909688260 20665552 20665600
    9.909987699 61083560 61083584
    9.910271958 61083584 61083608
    9.911689305 20665600 20665624
    9.911785890 20665624 20665648
    9.917379146 20665648 20665672
    9.917471753 20665672 20665696
    9.928170104 74390048 74390072
    9.928249913 74390072 74390096

注意，第一个字段是时间，第二个字段是开始扇区即 offset，第三个字段为结束扇区。不难根据第二个字段和第三个字段算出来 size。当然了单位为扇区。

访问轨迹图

注意上小节，可以拿到不同时间里，访问磁盘的位置以及访问扇区的个数，如果不考虑访问扇区的个数，我们可以得到一张访问轨迹 2D 图： Bean Li - sdb offset.png

如果把访问扇区的个数作为第三个维度，可以得到一张三维图 Bean Li - sdb block access.png