利用BLKTRACE分析磁盘IO

http://www.idcat.cn

在Linux系统上,查看磁盘的负载情况,咱们一般使用iostat监控工具,iostat的详细介绍查看另外的培训资料。其中很重要的参数就是await,await表示单个I/O所需的平均时间,但它同时包含了I/O Scheduler所消耗的时间和硬件所消耗的时间,所以不能作为硬件性能的指标。那如何才能分辨一个io从下发到返回整个时间上,是硬件层耗时多还是在io调度上耗时多呢?如何查看io在各个时间段所消耗的时间呢?那么,blktrace在这种场合就能派上用场,因为它能记录I/O所经历的各个步骤,从中可以分析是IO Scheduler慢还是硬件响应慢,以及各个时间段所用时间。

blktrace的原理

一个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能记录I/O所经历的各个步骤,来看一下它记录的数据,包含9个字段,下图标示了其中8个字段的含义,大致的意思是“哪个进程在访问哪个硬盘的哪个扇区,进行什么操作,进行到哪个步骤,时间戳是多少”:

-第一个字段: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表示BarrierOperation

-第八个字段:223490+56,表示的是起始block number 和 number of blocks,即我们常说的Offset 和 Size(扇区??)

-第九个字段: 进程名

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

其中第六个字段非常有用:每一个字母都代表了IO请求所经历的某个阶段。
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处理被磁盘处理完成。

其中最重要的几个阶段如下:

Q – 即将生成IO请求

|
G – IO请求生成

|
I – IO请求进入IO Scheduler队列

|
D – IO请求进入driver

|
C – IO请求执行完毕

根据以上步骤对应的时间戳就可以计算出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才会进行合并。

Q2C – 整个IO请求所消耗的时间(Q2I + I2D + D2C = Q2C),相当于iostat的await。
如果I/O性能慢的话,以上指标有助于进一步定位缓慢发生的地方:
D2C可以作为硬件性能的指标;
I2D可以作为IO Scheduler性能的指标。

blktrace的用法

blktrace centos7安装

yum install blktrace -y

会自动生成blktrace blkparse btt 3个工具,其中,blktrace收集数据,blkparce分析数据,btt汇总数据。

blktrace的用法

使用blktrace需要挂载debugfs:

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

利用blktrace查看实时数据的方法,比如要看的硬盘是sdb:

$ blktrace -d /dev/sdb -o – | blkparse -i –

需要停止的时候,按Ctrl-C。

个人常用方法:

blktrace -d /dev/sdc

生成数据: 应用结束后,手动终止监控,会生成cpu数量的文件

blkparse -i sdc -d sdc.blktrace.bin

分析数据: btt

btt -i sdc.blktrace.bin -A |less

汇总后,部分截图

根据以上步骤对应的时间戳就可以计算出I/O请求在每个阶段所消耗的时间:

Q2G – 生成IO请求所消耗的时间,包括remap和split的时间;

G2I – IO请求进入IO Scheduler所消耗的时间,包括merge的时间;

I2D – IO请求在IO Scheduler中等待的时间;D2C – IO请求在driver和硬件上所消耗的时间;

Q2C – 整个IO请求所消耗的时间(Q2I + I2D + D2C = Q2C),相当于iostat的await。

如果I/O性能慢的话,以上指标有助于进一步定位缓慢发生的地方:

D2C可以作为硬件性能的指标;I2D可以作为IO Scheduler性能的指标。

 

btt 可以生成iops,bw等很多数据

man btt

btt

[ -a               | –seek-absolute ]

[ -A               | –all-data ]

[ -B <output name> | –dump-blocknos=<output name> ]

[ -d <seconds>     | –range-delta=<seconds> ]

[ -D <dev;…>     | –devices=<dev;…> ]

[ -e <exe,…>     | –exes=<exe,…>  ]

[ -h               | –help ]

[ -i <input name>  | –input-file=<input name> ]

[ -I <output name> | –iostat=<output name> ]

[ -l <output name> | –d2c-latencies=<output name> ]

[ -L <freq>        | –periodic-latencies=<freq> ]

[ -m <output name> | –seeks-per-second=<output name> ]

[ -M <dev map>     | –dev-maps=<dev map>

[ -o <output name> | –output-file=<output name> ]

[ -p <output name> | –per-io-dump=<output name> ]

[ -P <output name> | –per-io-trees=<output name> ]

[ -q <output name> | –q2c-latencies=<output name> ]

[ -Q <output name> | –active-queue-depth=<output name> ]

[ -r               | –no-remaps ]

[ -s <output name> | –seeks=<output name> ]

[ -S <interval>    | –iostat-interval=<interval> ]

[ -t <sec>         | –time-start=<sec> ]

[ -T <sec>         | –time-end=<sec> ]

[ -u <output name> | –unplug-hist=<output name> ]

[ -v               | –verbose ]

[ -V               | –version ]

[ -X               | –easy-parse-avgs ]

[ -z <output name> | –q2d-latencies=<output name> ]

[ -Z               | –do-active ]

测试

1、4k direct=1

通过fio对本地磁盘sdc挂载点进行4K小文件顺序写测试,期间监控磁盘信息。完成fio测试后,手动终止监控程序,然后进行数据分析。并与iostat的数据进行对比分析。

fio 开启测试

[root@node1 samba-test]# fio -filename=./4k_file -direct=1 -iodepth=1 -thread -rw=write -ioengine=libaio -bs=4k -size=3G -numjobs=4  -times=300 -group_reporting -name=mytest2

mytest2: (g=0): rw=write, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=1

fio-2.2.5

Starting 4 threads

注意:

1、direct=1即o_direct直写io。不会经过系统缓存,即没有合并

2、numjobs=4 bs=4k  对应iostat即队列深度为4.

3、bs=4k 对应iostat扇区数为8

 

[root@node1 ~]# blktrace -d /dev/sdc   开启监控磁盘sdc

 

iostat监控

FIO运行结束后,终止blktrace进程

收集数据

[root@node1 fioblk]# blktrace -d /dev/sdc

^C=== sdc ===

CPU  0:              5504242 events,   258012 KiB data

CPU  1:              5693967 events,   266905 KiB data

Total:              11198209 events (dropped 0),   524917 KiB data

[root@node1 fioblk]# ll

total 524920

-rw-r–r– 1 root root 264203656 Apr 27 14:08 sdc.blktrace.0

-rw-r–r– 1 root root 273310432 Apr 27 14:08 sdc.blktrace.1

[root@node1 fioblk]#

会看到生成文件数以当前cpu个数命名。

 

生成数据

blkparse -i sdc -d sdc.blktrace.bin

会将所有数据汇总到文件sdc.blktrace.bin里面。期间我截图了如下,代表3个io的过程。对比上面介绍。

WS表示同步写

 

分析数据

生成所有数据,后面介绍针对性的数据。

[root@node1 fioblk]# btt -i sdc.blktrace.bin -A |less

Q2G – 生成IO请求所消耗的时间,包括remap和split的时间;本例0.009ms

G2I – IO请求进入IO Scheduler所消耗的时间,包括merge的时间;0.001ms

I2D – IO请求在IO Scheduler中等待的时间;0.0009ms

D2C – IO请求在driver和硬件上所消耗的时间;0.7ms

因此:

Q2C – 整个IO请求所消耗的时间(Q2I + I2D + D2C = Q2C),相当于iostat的await。 几乎0.78ms与iostat wait值一致。在io scheduler上几乎没有消耗任何时间。

生成iops 和bw每秒值

btt -i sdc.blktrace.bin -q sdc.q2c_latencytotal

-rw-r–r– 1 root root      2759 Apr 27 14:45 8,32_iops_fp.dat

-rw-r–r– 1 root root      4340 Apr 27 14:45 8,32_mbps_fp.dat

-rw-r–r– 1 root root 264203656 Apr 27 14:08 sdc.blktrace.0

-rw-r–r– 1 root root 273310432 Apr 27 14:08 sdc.blktrace.1

-rw-r–r– 1 root root 537514088 Apr 27 14:16 sdc.blktrace.bin

-rw-r–r– 1 root root  30244692 Apr 27 14:45 sdc.q2c_latency_8,32_q2c.dat

-rw-r–r– 1 root root      2759 Apr 27 14:45 sys_iops_fp.dat

-rw-r–r– 1 root root      4340 Apr 27 14:45 sys_mbps_fp.dat

 

生成io大小分布

btt -i sdc.blktrace.bin -B sdc.offset

[root@node1 fioblk]# ll

total 1183168

-rw-r–r– 1 root root      2759 Apr 27 14:57 8,32_iops_fp.dat

-rw-r–r– 1 root root      4340 Apr 27 14:57 8,32_mbps_fp.dat

-rw-r–r– 1 root root 264203656 Apr 27 14:08 sdc.blktrace.0

-rw-r–r– 1 root root 273310432 Apr 27 14:08 sdc.blktrace.1

-rw-r–r– 1 root root 537514088 Apr 27 14:16 sdc.blktrace.bin

-rw-r–r– 1 root root  53125272 Apr 27 14:57 sdc.offset_8,32_c.dat

-rw-r–r– 1 root root  53125272 Apr 27 14:57 sdc.offset_8,32_w.dat

本例只有write,所有生成了_w _c   写是w  读是r  c是w+c 本例c和w一样大。查看文件内容

0.000002716 52608272 52608280

0.000129844 52608000 52608008

0.000324497 52607688 52607696

0.000927928 52606144 52606152

0.001015187 52608280 52608288

0.001449302 52608008 52608016

第一行为时间,第二个为其实扇区大小,第3行为每个io结束扇区大小。可以算出每个io为8个扇区大小,既4k 与测试实际相符合。

2、1M direct=1

fio运行

[root@node1 samba-test]# fio -filename=./1m_file -direct=1 -iodepth=1 -thread -rw=write -ioengine=libaio -bs=1M -size=3G -numjobs=4  -times=300 -group_reporting -name=mytest2

mytest2: (g=0): rw=write, bs=1M-1M/1M-1M/1M-1M, ioengine=libaio, iodepth=1

fio-2.2.5

Starting 4 threads

mytest2: Laying out IO file(s) (1 file(s) / 3072MB)

注意:

1、bs=1M ,sdc块设备最大单次io大小为512,因此会分为2个io写入,numjobs=4,因此队列深度为2*4 = 8

[root@node1 1m]# cat /sys/block/sdc/queue/max_sectors_kb

512

[root@node1 ~]# cat /sys/block/sdc/queue/nr_requests

128   磁盘最大队列深度。

2、bs=1M  最大io数为512kb,除以512byte扇区大小为操作扇区数1024

与iostat一致。

 

 

blktrace取值

[root@node1 1m]# blktrace -d /dev/sdc

 

iostat取值

fio运行完成后,生成数据,并分析数据

 

生成数据

[root@node1 1m]# blkparse -i sdc -d sdc.blktrace.bin

可以看到Q-C一个完整的io路径。右边起始扇区+1024个扇区数。与实际相符合。

分析数据

[root@node1 1m]# btt -i sdc.blktrace.bin -A | less

Q2G – 生成IO请求所消耗的时间,包括remap和split的时间;

本例0.7ms 因为有块分为2部分。1m分为2个512kb io,单个512kb io 到扇区后得与扇区对齐等等

G2I – IO请求进入IO Scheduler所消耗的时间,包括merge的时间;

0.009ms  没有进行合并 绕过缓存了。

I2D – IO请求在IO Scheduler中等待的时间;

2.8ms

D2C – IO请求在driver和硬件上所消耗的时间;

34.5 ms

因此:

Q2C – 整个IO请求所消耗的时间(Q2I + I2D + D2C = Q2C),相当于iostat的await。 为38.1ms与iostat wait值几乎一致。在io scheduler上几乎没有消耗任何时间。时间花费在driver硬件层。

 

生成iops 和bw每秒值

btt -i sdc.blktrace.bin -q sdc.q2c_latency

[root@node1 1m]# ll

total 14508

-rw-r–r– 1 root root     913 Apr 27 15:40 8,32_iops_fp.dat

-rw-r–r– 1 root root    1731 Apr 27 15:40 8,32_mbps_fp.dat

-rw-r–r– 1 root root 3295528 Apr 27 15:20 sdc.blktrace.0

-rw-r–r– 1 root root 3894704 Apr 27 15:20 sdc.blktrace.1

-rw-r–r– 1 root root 7190232 Apr 27 15:28 sdc.blktrace.bin

-rw-r–r– 1 root root  452027 Apr 27 15:40 sdc.q2c_latency_8,32_q2c.dat

-rw-r–r– 1 root root     913 Apr 27 15:40 sys_iops_fp.dat

-rw-r–r– 1 root root    1731 Apr 27 15:40 sys_mbps_fp.dat

生成io大小分布

btt -i sdc.blktrace.bin -B sdc.offset

[root@node1 1m]# ll

total 16148

-rw-r–r– 1 root root     913 Apr 27 15:44 8,32_iops_fp.dat

-rw-r–r– 1 root root    1731 Apr 27 15:44 8,32_mbps_fp.dat

-rw-r–r– 1 root root 3295528 Apr 27 15:20 sdc.blktrace.0

-rw-r–r– 1 root root 3894704 Apr 27 15:20 sdc.blktrace.1

-rw-r–r– 1 root root 7190232 Apr 27 15:28 sdc.blktrace.bin

-rw-r–r– 1 root root  835954 Apr 27 15:44 sdc.offset_8,32_c.dat

-rw-r–r– 1 root root  835954 Apr 27 15:44 sdc.offset_8,32_w.dat

-rw-r–r– 1 root root  452027 Apr 27 15:40 sdc.q2c_latency_8,32_q2c.dat

-rw-r–r– 1 root root     913 Apr 27 15:44 sys_iops_fp.dat

-rw-r–r– 1 root root    1731 Apr 27 15:44 sys_mbps_fp.dat

 

只有写,即_w 与_c一致。查看_w文件sdc.offset_8,32_w.dat

127.845942908 65054784 65055808

127.846185883 65055808 65056832

127.952831800 65056832 65057856

127.953065986 65057856 65058880

127.955207647 65058880 65059904

第一行为时间,第二个为其实扇区大小,第3行为每个io结束扇区大小。可以算出每个io为1024个扇区大小,既1M 与测试实际相符合。

3、4k direct=0

[root@node1 samba-test]# fio -filename=./4k_file_direct0  -direct=0 -iodepth=1 -thread -rw=write -ioengine=libaio -bs=4k -size=3G -numjobs=4  -times=300 -group_reporting -name=mytest2

mytest2: (g=0): rw=write, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=1

fio-2.2.5

Starting 4 threads

mytest2: Laying out IO file(s) (1 file(s) / 3072MB)

 

direct=0后 启动io buffer

iostat监控

blktrace监控数据

生成数据

[root@node1 1m]# blkparse -i sdc -d sdc.blktrace.bin

 

4k对象大小,在io路径变成1024 既最大512kb字节,很明显进行IO合并,大部分io动作都是Q G I来回循环,即生成io请求到io请求队列,就返回继续申请新的io到队列,整体由内核kworker进行io任务的调度,在内存swapper中完成io写入。W表示异步写。

 

 

分析数据

[root@node1 1m]# btt -i sdc.blktrace.bin -A | less

Q2G – 生成IO请求所消耗的时间,包括remap和split的时间;

本例5.6ms

G2I – IO请求进入IO Scheduler所消耗的时间,包括merge的时间;

0.009ms  没有进行合并。

I2D – IO请求在IO Scheduler中等待的时间;

635 ms

D2C – IO请求在driver和硬件上所消耗的时间;

188 ms

Q2C – 整个IO请求所消耗的时间(Q2I + I2D + D2C = Q2C),相当于iostat的await。 为828.6ms与iostat wait值几乎一致。在io scheduler上消耗太多时间。在driver硬件层耗时相对少一些,但是也很大了达到188ms。

其中M2D io合并时间平均4.5s.

生成io大小分布

btt -i sdc.blktrace.bin -B sdc.offset

 

93.463618386 74670904 74671928

93.463870465 74671928 74672952

93.464140190 74672952 74673976

93.464445965 74673976 74675000

93.464740898 74675000 74676024

93.465027976 74676024 74677048

93.465313376 74677048 74678072

同样的是以1024个扇区为最小io。