利用blktrace分析磁盘I/O

Posted 2022-11-09 ygtff

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了利用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 <dev> 指定具体的设备名

上面是抓取一段时间后，Ctrl+C中止的。也可以指定时间：-w <seconds>
blktrace执行完之后，会生产很多文件，每个CPU都会有一个文件，文件名组成：<设备名>.blktrace.<CPU id>，如下：

[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号。

参考

https://www.mimuw.edu.pl/~lichota/09-10/Optymalizacja-open-source/Materialy/10%20-%20Dysk/gelato_ICE06apr_blktrace_brunelle_hp.pdf

http://fibrevillage.com/storage/539-blktrace-and-btt-example-to-debug-and-tune-disk-i-o-on-linux

以上是关于利用blktrace分析磁盘I/O的主要内容，如果未能解决你的问题，请参考以下文章

通过blktrace, debugfs分析磁盘IO

不同的是在分析 blktrace 时队列深度、磁盘偏移量、iops、吞吐量的数据

blktrace分析IO

磁盘I/O性能优化的几个思路

利用Oracle分区表来减少磁盘I/O冲突

用于测量磁盘 i/o 等的 Linux 工具