2、Blktrace IO 跟踪
很多时候，业务系统生产上线之前，都需要对存储性能有一个充分的评估。我们常用的方式是使用 Fio 进行压测，使用 iostat 实时监控块设备的数据，可以对存储性能有一个较为全面的评估。但是对于一些 IO 延迟敏感的业务系统来说，可能会引起 IO 超时，从而引发一系列的问题。
iostat 监控数据中的 await 参数是指 IO 在队列中的时间 + 服务 IO 请求的时间，只能得到一个整体 IO 延时。
如果想深入了解 IO 生成时间，IO 调度时间， IO 在驱动和硬盘服务时间等，就需要使用 blktrace 工具。
2.1、blktrace 原理
一个 I/O 请求，从应用层到底层块设备，路径如下图所示：
从上图可以看出 IO 路径是很复杂的，我们将 IO 路径简化一下：
一个 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 的输出长什么样子：
说明：下面的输出格式是默认的输出格式("%D %2c %8s %5T.%9t %5p %2a %3d")，请查看 man blkparse，也可以自定义格式。
- 第一个字段：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 请求所经历的某个阶段，请参考 man blkparse 准确了解各个阶段。
- A：remap 对于栈式设备，进来的 I/O 将被重新映射到 I/O 栈中的具体设备。
- X：split 对于做了 Raid 或进行了 device mapper(dm) 的设备，进来的 I/O 可能需要切割，然后发送给不同的设备。
- Q：queued I/O 进入 block layer，将要被 request 代码处理（即将生成 I/O 请求）。
- 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 处理被磁盘处理完成。
这些 Event 中常见的出现顺序如下：
Q – 准备队列位置给 I/O，请求未生成
|
G – I/O 请求生成，struct request container 已分配
|
I – I/O 请求进入 I/O Scheduler 队列
|
D – I/O 请求进入 Driver
|
C – I/O 请求执行完毕由于每个 Event 都有出现的时间戳，根据这个时间戳就可以计算出 I/O 请求在每个阶段所消耗的时间，比如从 Q 事件到 C 事件的时间叫 Q2C，那么常见阶段称呼如下：
Q------------>G----------------->I----------------------------------->D----------------------------------->C
|-Q time(Q2G)-|-Insert time(G2I)-|------schduler wait time(I2D)-------|--------driver,disk time(D2C)-------|
|------------------------------- await time in iostat output(Q2C) -----------------------------------------|- Q2G：生成 I/O 请求所消耗的时间，包括 remap 和 split 的时间；
- G2I：I/O 请求进入 I/O Scheduler 所消耗的时间，包括 merge 的时间；
- I2D：I/O 请求在 I/O Scheduler 中等待的时间，可以作为 I/O Scheduler 性能的指标；
- D2C：I/O 请求在 Driver 和硬件上所消耗的时间，可以作为硬件性能的指标；
- Q2C：整个 I/O 请求所消耗的时间(Q2I + G2I + I2D + D2C = Q2C)，相当于 iostat 的 await。
- Q2Q：2 个 I/O 请求的间隔时间。
2.2、blktrace 应用
blktrace 只能采集信息，得到的结果不是很直观，需要配套的 blkparse 和 btt 两个工具计算和展示。
说明：根据 blktrace man 文档介绍，blktrace 命令执行时，会一直处于运行状态，实时监控 IO 活动。如果 blktrace 监控的磁盘没有 IO 活动，那么 blktrace 获取不到任何信息，Ctrl+c 结束命令也得不到任何数据。因此在使用 blktrace 命令时，要保证监控的硬盘有 IO 活动，测试的时候可以使用 fio 制造 IO 活动。
首先通过如下命令，可以查看磁盘上的实时信息：
# blktrace -d /dev/sde -o - | blkparse -i -当然了，你也可以先用如下命令采集信息，待所有信息采集完毕后，统一分析所有采集到的数据。搜集信息的命令如下：
# blktrace -d /dev/sde注意，这个命令并不是只输出一个文件，他会根据 CPU 的个数，每一个 CPU 都会输出一个文件，如下所示：
sde.blktrace.0 sde.blktrace.20 sde.blktrace.32 sde.blktrace.44 sde.blktrace.56
sde.blktrace.1 sde.blktrace.21 sde.blktrace.33 sde.blktrace.45 sde.blktrace.57
sde.blktrace.10 sde.blktrace.22 sde.blktrace.34 sde.blktrace.46 sde.blktrace.58
sde.blktrace.11 sde.blktrace.23 sde.blktrace.35 sde.blktrace.47 sde.blktrace.59
sde.blktrace.12 sde.blktrace.24 sde.blktrace.36 sde.blktrace.48 sde.blktrace.6
sde.blktrace.13 sde.blktrace.25 sde.blktrace.37 sde.blktrace.49 sde.blktrace.60
sde.blktrace.14 sde.blktrace.26 sde.blktrace.38 sde.blktrace.5 sde.blktrace.61
sde.blktrace.15 sde.blktrace.27 sde.blktrace.39 sde.blktrace.50 sde.blktrace.62
sde.blktrace.16 sde.blktrace.28 sde.blktrace.4 sde.blktrace.51 sde.blktrace.63
sde.blktrace.17 sde.blktrace.29 sde.blktrace.40 sde.blktrace.52 sde.blktrace.7
sde.blktrace.18 sde.blktrace.3 sde.blktrace.41 sde.blktrace.53 sde.blktrace.8
sde.blktrace.19 sde.blktrace.30 sde.blktrace.42 sde.blktrace.54 sde.blktrace.9
sde.blktrace.2 sde.blktrace.31 sde.blktrace.43 sde.blktrace.55有了输出，我们可以通过 blkparse -i sde 来分析采集的数据：
......
8,64 15 2612 1.772002740 49062 G WS 19456 + 32 [fio]
8,64 15 2613 1.772003000 49062 P N [fio]
8,64 3 3087 1.772003940 49065 Q WS 19488 + 32 [fio]
8,64 15 2614 1.772004080 49062 I WS 19456 + 32 [fio]
8,64 15 2615 1.772004960 49062 U N [fio] 1
8,64 52 3368 1.772006140 49047 Q WS 19808 + 32 [fio]
8,64 3 3088 1.772006260 49065 M WS 19488 + 32 [fio]
8,64 52 3369 1.772008000 49047 M WS 19808 + 32 [fio]
8,64 15 2616 1.772012340 49062 Q WS 19488 + 32 [fio]
8,64 3 3089^C
CPU0 (sde):
Reads Queued: 130, 2,080KiB Writes Queued: 116, 1,856KiB
Read Dispatches: 19, 2,224KiB Write Dispatches: 3, 672KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 14, 1,440KiB Writes Completed: 4, 768KiB
Read Merges: 103, 1,648KiB Write Merges: 102, 1,632KiB
Read depth: 33 Write depth: 27
IO unplugs: 41 Timer unplugs: 0
CPU1 (sde):
Reads Queued: 620, 9,920KiB Writes Queued: 628, 10,048KiB
Read Dispatches: 94, 10,016KiB Write Dispatches: 21, 3,600KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 83, 11,568KiB Writes Completed: 46, 8,992KiB
Read Merges: 504, 8,064KiB Write Merges: 538, 8,608KiB
Read depth: 33 Write depth: 27
IO unplugs: 206 Timer unplugs: 0
CPU2 (sde):
Reads Queued: 592, 9,472KiB Writes Queued: 575, 9,200KiB
Read Dispatches: 109, 12,496KiB Write Dispatches: 35, 6,784KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 87, 8,352KiB Writes Completed: 56, 12,576KiB
Read Merges: 451, 7,216KiB Write Merges: 473, 7,568KiB
Read depth: 33 Write depth: 27
IO unplugs: 243 Timer unplugs: 0
......注意，blkparse 仅仅是将 blktrace 输出的信息转化成人可以阅读和理解的输出，但是，信息太多，太杂，人完全没法得到关键信息。
这时候 btt 就出现了，这个工具可以将 blktrace 采集回来的数据，进行分析，得到对人更有用的信息。
2.2.1、数据分析
-
首先需要使用 blkparse 将 blktrace 采集到的多个文件合并为一个，如下：
# blkparse -i sde -d sde.blktrace.bin # ll sde.blktrace.bin -rw-r--r-- 1 root root 31572600 Jul 5 15:58 sde.blktrace.bin如果想输出文本格式，可以使用 -o 选项。
-
然后使用 btt 分析 sde.blktrace.bin，如下：
# btt -i sde.blktrace.bin ==================== All Devices ==================== ALL MIN AVG MAX N --------------- ------------- ------------- ------------- ----------- Q2Q 0.000000001 0.000086776 0.104272500 116524 Q2G 0.000000080 0.004796667 0.118014600 41237 G2I 0.000000020 0.000004078 0.000332080 41208 Q2M 0.000000560 0.004417939 0.118061860 193543 I2D 0.000000380 0.007650022 0.116317640 42869 M2D 0.000001020 0.010226954 0.116307800 110534 D2C 0.000000420 0.008968065 0.021607380 84473 Q2C 0.000000001 0.018545012 0.123586100 116525 ==================== Device Overhead ==================== DEV | Q2G G2I Q2M I2D D2C ---------- | --------- --------- --------- --------- --------- ( 8, 64) | 9.1534% 0.0078% 39.5686% 15.1761% 35.0567% ---------- | --------- --------- --------- --------- --------- Overall | 9.1534% 0.0078% 39.5686% 15.1761% 35.0567% ==================== Device Merge Information ==================== DEV | #Q #D Ratio | BLKmin BLKavg BLKmax Total ---------- | -------- -------- ------- | -------- -------- -------- -------- ( 8, 64) | 116525 28517 4.1 | 16 263 512 7518848 ==================== Device Q2Q Seek Information ==================== DEV | NSEEKS MEAN MEDIAN | MODE ---------- | --------------- --------------- --------------- | --------------- ( 8, 64) | 116525 66337.2 0 | 0(39668) ---------- | --------------- --------------- --------------- | --------------- Overall | NSEEKS MEAN MEDIAN | MODE Average | 116525 66337.2 0 | 0(39668) ==================== Device D2D Seek Information ==================== DEV | NSEEKS MEAN MEDIAN | MODE ---------- | --------------- --------------- --------------- | --------------- ( 8, 64) | 28517 264363.5 0 | 0(15889) ---------- | --------------- --------------- --------------- | --------------- Overall | NSEEKS MEAN MEDIAN | MODE Average | 28517 264363.5 0 | 0(15889) ==================== Plug Information ==================== DEV | # Plugs # Timer Us | % Time Q Plugged ---------- | ---------- ---------- | ---------------- ( 8, 64) | 38218( 0) | 1.347335520% DEV | IOs/Unp IOs/Unp(to) ---------- | ---------- ---------- ( 8, 64) | 1.0 0.0 ---------- | ---------- ---------- Overall | IOs/Unp IOs/Unp(to) Average | 1.0 0.0 ==================== Active Requests At Q Information ==================== DEV | Avg Reqs @ Q ---------- | ------------- ( 8, 64) | 0.5 ==================== I/O Active Period Information ==================== DEV | # Live Avg. Act Avg. !Act % Live ---------- | ---------- ------------- ------------- ------ ( 8, 64) | 128 0.077715422 0.001312728 98.35 ---------- | ---------- ------------- ------------- ------ Total Sys | 128 0.077715422 0.001312728 98.35 ......重点关注 D2C 和 Q2C，D2C 表示块设备性能的关键指标，Q2C 是客户发起请求到收到响应的时间，我们可以看出，D2C 平均在 8968065ns；Q2C 平均在 18545012ns。
另外，Q2M 占比 39%，D2C 占比 35%，所以这两个阶段消耗了 Q2C 的大部分时间。
2.2.2、脚本分析
#!/bin/bash
if [ $# -ne 1 ]; then
echo "Usage: $0 <block_device_name>"
exit
fi
if [ ! -b $1 ]; then
echo "could not find block device $1"
exit
fi
duration=30
echo "running blktrace for $duration seconds to collect data..."
timeout $duration blktrace -d $1 >/dev/null 2>&1
DEVNAME=`basename $1`
echo "parsing blktrace data..."
blkparse -i $DEVNAME |sort -g -k8 -k10 -k4 |awk '
BEGIN {
total_read=0;
total_write=0;
maxwait_read=0;
maxwait_write=0;
}
{
if ($6=="Q") {
queue_ts=$4;
block=$8;
nblock=$10;
rw=$7;
};
if ($6=="C" && $8==block && $10==nblock && $7==rw) {
await=$4-queue_ts;
if (rw=="R") {
if (await>maxwait_read) maxwait_read=await;
total_read++;
read_count_block[nblock]++;
if (await>0.001) read_count1++;
if (await>0.01) read_count10++;
if (await>0.02) read_count20++;
if (await>0.03) read_count30++;
}
if (rw=="WS" || rw=="W") {
if (await>maxwait_write) maxwait_write=await;
total_write++;
write_count_block[nblock]++;
if (await>0.001) write_count1++;
if (await>0.01) write_count10++;
if (await>0.02) write_count20++;
if (await>0.03) write_count30++;
}
}
} END {
printf("========\nsummary:\n========\n");
printf("total number of reads: %d\n", total_read);
printf("total number of writes: %d\n", total_write);
printf("slowest read : %.6f second\n", maxwait_read);
printf("slowest write: %.6f second\n", maxwait_write);
printf("reads\n> 1ms: %d\n>10ms: %d\n>20ms: %d\n>30ms: %d\n", read_count1, read_count10, read_count20, read_count30);
printf("writes\n> 1ms: %d\n>10ms: %d\n>20ms: %d\n>30ms: %d\n", write_count1, write_count10, write_count20, write_count30);
printf("\nblock size:%16s\n","Read Count");
for (i in read_count_block)
printf("%10d:%16d\n", i, read_count_block[i]);
printf("\nblock size:%16s\n","Write Count");
for (i in write_count_block)
printf("%10d:%16d\n", i, write_count_block[i]);
}'该脚本来自 http://linuxperf.com/?p=227 ，其中的写条件我修改了一下，否则采集不到写数据。因为 fio 指定 -direct=1 时，写变成了 WS，而不是 W。
提示：根据经验，可以使用 blkparse -i sde -o sde.blktrace.txt 输出 text 文本，里面可以清晰地看出哪个命令执行时间很长，特别是 IO 性能很差的时候，要找出哪个命令卡住了，非常有效。
