Linux blktrace跟踪块设备后使用fio回放过程

Linux blktrace跟踪块设备后使用fio回放过程

注：部分操作参考博文 Linux下Fio和Blktrace模拟块设备的访问模式 http://blog.yufeng.info/archives/1112

前提条件

内核需要支持：CONFIG_BLK_DEV_IO_TRACE=y，否则blktrace无法使用。

busybox支持：losetup、mke2fs

其他：blktrace、blkparse、fio

操作过程

先生成一个临时镜像文件，用作测试：

dd if=/dev/zero of=./mj.ext4 bs=1M count=100

镜像文件关联到loop设备上：

./busybox losetup /dev/loop0 ./mj.ext4
./busybox losetup -a

当前结果如下：

[mj@mj fio+blktrace] # ./busybox losetup -a
/dev/loop0: 0 ./mj.ext4

接着格式化镜像文件：

mke2fs /dev/loop0

挂载loop设备到临时目录：

mount /dev/loop0 /tmp/

接着用blktrace跟踪/dev/loop0：

mount -t debugfs nodeg /sys/kernel/debug/
./blktrace /dev/loop0

在另一个终端，拷贝一些数据到/tmp目录：

cp /bin/* /tmp

Ctrl+C 停止 blktrace 后, blktrace 解析数据：

./blkparse loop0 -d loop0.log

接着就可以用fio对过程进行回放了：

./fio --name=replay --filename=/dev/loop0 --thread --read_iolog=loop0.log

结果(1)如下：

replay: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
fio-3.23
Starting 1 thread
Jobs: 1 (f=1): [M(1)][70.0%][r=2KiB/s][r=2 IOPS][eta 00m:03s]
replay: (groupid=0, jobs=1): err= 0: pid=1112: Thu Jan  1 04:26:59 1970
  read: IOPS=3, BW=3817B/s (3817B/s)(27.0KiB/7242msec)
    clat (usec): min=33, max=129, avg=57.72, stdev=32.13
     lat (usec): min=34, max=133, avg=59.49, stdev=33.14
    clat percentiles (usec):
     |  1.00th=[   34],  5.00th=[   34], 10.00th=[   34], 20.00th=[   36],
     | 30.00th=[   37], 40.00th=[   38], 50.00th=[   45], 60.00th=[   49],
     | 70.00th=[   50], 80.00th=[  100], 90.00th=[  118], 95.00th=[  122],
     | 99.00th=[  130], 99.50th=[  130], 99.90th=[  130], 99.95th=[  130],
     | 99.99th=[  130]
   bw (  KiB/s): min=    2, max=   36, per=100.00%, avg= 9.00, stdev=13.31, samples=6
   iops        : min=    2, max=   36, avg= 9.00, stdev=13.31, samples=6
  write: IOPS=700, BW=13.0MiB/s (14.6MB/s)(101MiB/7242msec); 0 zone resets
    clat (usec): min=47, max=1689, avg=145.36, stdev=266.43
     lat (usec): min=48, max=1712, avg=148.09, stdev=270.99
    clat percentiles (usec):
     |  1.00th=[   48],  5.00th=[   48], 10.00th=[   49], 20.00th=[   49],
     | 30.00th=[   49], 40.00th=[   50], 50.00th=[   53], 60.00th=[   57],
     | 70.00th=[   58], 80.00th=[   96], 90.00th=[  375], 95.00th=[  693],
     | 99.00th=[ 1254], 99.50th=[ 1287], 99.90th=[ 1369], 99.95th=[ 1434],
     | 99.99th=[ 1696]
   bw (  KiB/s): min=28930, max=70645, per=100.00%, avg=55607.33, stdev=23165.64, samples=3
   iops        : min=  738, max= 4554, avg=2334.67, stdev=1982.74, samples=3
  lat (usec)   : 50=39.51%, 100=41.22%, 250=8.51%, 500=1.69%, 750=4.35%
  lat (usec)   : 1000=0.53%
  lat (msec)   : 2=4.20%
  cpu          : usr=0.41%, sys=3.31%, ctx=5480, majf=0, minf=0
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=27,5073,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=17

Run status group 0 (all jobs):
   READ: bw=3817B/s (3817B/s), 3817B/s-3817B/s (3817B/s-3817B/s), io=27.0KiB (27.6kB), run=7242-7242msec
  WRITE: bw=13.0MiB/s (14.6MB/s), 13.0MiB/s-13.0MiB/s (14.6MB/s-14.6MB/s), io=101MiB (106MB), run=7242-7242msec

Disk stats (read/write):
  loop0: ios=27/5449, merge=0/0, ticks=0/920, in_queue=920, util=7.50%

结果(2)如下：

replay: (g=0): rw=read, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
fio-3.23
Starting 1 thread
Jobs: 1 (f=1): [M(1)][87.5%][r=2KiB/s,w=16.1MiB/s][r=2,w=2077 IOPS][eta 00m:01s]
replay: (groupid=0, jobs=1): err= 0: pid=1116: Thu Jan  1 04:27:39 1970
  read: IOPS=3, BW=3942B/s (3942B/s)(27.0KiB/7013msec)
    clat (nsec): min=16100, max=89940, avg=37762.96, stdev=16015.51
     lat (nsec): min=16620, max=92260, avg=38608.89, stdev=16590.94
    clat percentiles (nsec):
     |  1.00th=[16064],  5.00th=[17280], 10.00th=[18304], 20.00th=[30336],
     | 30.00th=[31104], 40.00th=[31872], 50.00th=[32384], 60.00th=[36096],
     | 70.00th=[36608], 80.00th=[38656], 90.00th=[60160], 95.00th=[69120],
     | 99.00th=[89600], 99.50th=[89600], 99.90th=[89600], 99.95th=[89600],
     | 99.99th=[89600]
   bw (  KiB/s): min=    2, max=   36, per=100.00%, avg= 9.00, stdev=13.31, samples=6
   iops        : min=    2, max=   36, avg= 9.00, stdev=13.31, samples=6
  write: IOPS=723, BW=14.4MiB/s (15.1MB/s)(101MiB/7013msec); 0 zone resets
    clat (usec): min=19, max=9320, avg=88.46, stdev=210.29
     lat (usec): min=20, max=9328, avg=90.01, stdev=212.42
    clat percentiles (usec):
     |  1.00th=[   20],  5.00th=[   21], 10.00th=[   21], 20.00th=[   21],
     | 30.00th=[   24], 40.00th=[   37], 50.00th=[   48], 60.00th=[   49],
     | 70.00th=[   51], 80.00th=[   56], 90.00th=[  210], 95.00th=[  457],
     | 99.00th=[ 1172], 99.50th=[ 1221], 99.90th=[ 1287], 99.95th=[ 1319],
     | 99.99th=[ 9372]
   bw (  KiB/s): min=28615, max=109277, per=100.00%, avg=68651.33, stdev=40334.23, samples=3
   iops        : min= 1440, max= 4846, avg=3379.33, stdev=1751.50, samples=3
  lat (usec)   : 20=1.55%, 50=65.67%, 100=19.25%, 250=6.59%, 500=4.16%
  lat (usec)   : 750=1.51%, 1000=0.18%
  lat (msec)   : 2=1.08%, 10=0.02%
  cpu          : usr=1.00%, sys=2.28%, ctx=5571, majf=0, minf=0
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=27,5073,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=17

Run status group 0 (all jobs):
   READ: bw=3942B/s (3942B/s), 3942B/s-3942B/s (3942B/s-3942B/s), io=27.0KiB (27.6kB), run=7013-7013msec
  WRITE: bw=14.4MiB/s (15.1MB/s), 14.4MiB/s-14.4MiB/s (15.1MB/s-15.1MB/s), io=101MiB (106MB), run=7013-7013msec

Disk stats (read/write):
  loop0: ios=27/5225, merge=0/0, ticks=0/480, in_queue=480, util=4.46%

两次结果不一样的，为什么说是对整个过程进行回放呢？

=101MiB (106MB), run=7013-7013msec

Disk stats (read/write):
loop0: ios=27/5225, merge=0/0, ticks=0/480, in_queue=480, util=4.46%

两次结果不一样的，为什么说是对整个过程进行回放呢？

经历过回放后，/dev/loop0里面的数据已经被破坏了，文件系统已经损坏，所以在尝试时要注意。