Home > Linux, 工具介绍, 调优 > blktrace 深度了解linux系统的IO运作

blktrace 深度了解linux系统的IO运作

February 22nd, 2011

原创文章,转载请注明: 转载自系统技术非业余研究

本文链接地址: blktrace 深度了解linux系统的IO运作

我们在Linux上总是要保存数据的,数据要么保存在文件系统里(如ext3),要么就在裸设备里面。我们在使用这些数据的时候都是通过文件这个抽象来访问的,操作系统会把我们需要的数据给我们,我们通常无需和块设备打交道。

从下图我们可以很清楚的看到:

我们会发现IO是个层次很深的子系统,有很复杂的数据流动线路。

至于操作系统如何去存储和获取这些数据对我们完全是黑盒子的,这通常不是问题。但是如果我们的IO很密集,我们就需要搞清楚IO具体是如何运作的,免的滥用IO和导致设计问题。

这时候你就需要blktrace这样的工具。

blktrace is a block layer IO tracing mechanism which provides detailed information about request queue operations up to user space.

它的作者Jens Axboe, 是内核IO模块的维护者,目前就职于FusionIO, 是个很nice的家伙,同时他还是著名IO评测工具fio的作者。

相关的文档:
users guide: http://pdfedit.petricek.net/bt/file_download.php?file_id=17&type=bug

HP的人写的指南: http://www.gelato.org/pdf/apr2006/gelato_ICE06apr_blktrace_brunelle_hp.pdf

CU上的小伙子写的: http://linux.chinaunix.net/bbs/viewthread.php?tid=1115851&extra=&ordertype=2

目前blktrace在大部分的Linux发行版都支持的,我们可以轻松的安装使用:

$ sudo yum install blktrace 

$ sudo  blktrace /dev/sda5 -o - | blkparse -i -    

  8,5    2        1     0.000000000     0  C   W 40247824 + 8 [0]
  0,0    2        2     0.000040884  4271  A   W 31105920 + 8 <- (8,3) 132600
  8,5    2        3     0.000041214  4271  Q   W 31105920 + 8 [(null)]
  8,5    2        4     0.000045947  4271  G   W 31105920 + 8 [(null)]
  8,5    2        5     0.000046707  4271  P   N [(null)]
  8,5    2        6     0.000047073  4271  I   W 31105920 + 8 [(null)]
  0,0    2        7     0.000048282  4271  A   W 31105928 + 8 <- (8,3) 132608
  8,5    2        8     0.000048357  4271  Q   W 31105928 + 8 [(null)]
  8,5    2        9     0.000049137  4271  M   W 31105928 + 8 [(null)]
  0,0    2       10     0.000050167  4271  A   W 31105936 + 8 <- (8,3) 132616
  8,5    2       11     0.000050241  4271  Q   W 31105936 + 8 [(null)]
  8,5    2       12     0.000050417  4271  M   W 31105936 + 8 [(null)]
  0,0    2       13     0.000050984  4271  A   W 31105944 + 8 <- (8,3) 132624
  8,5    2       14     0.000051047  4271  Q   W 31105944 + 8 [(null)]
  8,5    2       15     0.000051258  4271  M   W 31105944 + 8 [(null)]
  8,5    2       16     0.000051829  4271  U   N [(null)] 1
  8,5    2       17     0.000052699  4271  D   W 31105920 + 32 [(null)]
  8,5    2       18     0.000108292     0  C   W 31105920 + 32 [0]
  0,0    2       19     0.000127791  4271  A   W 31105952 + 8 <- (8,3) 132632
  8,5    2       20     0.000128001  4271  Q   W 31105952 + 8 [(null)]
  8,5    2       21     0.000128874  4271  G   W 31105952 + 8 [(null)]
  8,5    2       22     0.000129373  4271  P   N [(null)]
  8,5    2       23     0.000129706  4271  I   W 31105952 + 8 [(null)]
  8,5    2       24     0.000130551  4271  U   N [(null)] 1
  8,5    2       25     0.000131330  4271  D   W 31105952 + 8 [(null)]
  8,5    2       26     0.000172705     0  C   W 31105952 + 8 [0]
  0,0   13        1 1266874889.709337223  4271  A   W 40247824 + 8 <- (8,3) 9274504
  8,5   13        2 1266874889.709338011  4271  Q   W 40247824 + 8 [kjournald]
  8,5   13        3 1266874889.709343974  4271  G   W 40247824 + 8 [kjournald]
  8,5   13        4 1266874889.709346653  4271  P   N [kjournald]
  8,5   13        5 1266874889.709347728  4271  I   W 40247824 + 8 [kjournald]
  8,5   13        6 1266874889.709350795  4271  U   N [kjournald] 1
  8,5   13        7 1266874889.709355396  4271  D   W 40247824 + 8 [kjournald]
  0,0   21        1     0.504685570  4267  A   W 92640335 + 8 <- (8,6) 234392
  8,5   21        2     0.504686212  4267  Q   W 92640335 + 8 [kjournald]
  8,5   21        3     0.504690614  4267  G   W 92640335 + 8 [kjournald]
  8,5   21        4     0.504691826  4267  P   N [kjournald]
  8,5   21        5     0.504692896  4267  I   W 92640335 + 8 [kjournald]
  0,0   21        6     0.504694268  4267  A   W 92640343 + 8 <- (8,6) 234400
  8,5   21        7     0.504694448  4267  Q   W 92640343 + 8 [kjournald]
  8,5   21        8     0.504695115  4267  M   W 92640343 + 8 [kjournald]
  0,0   21        9     0.504696227  4267  A   W 92640351 + 8 <- (8,6) 234408
  8,5   21       10     0.504696357  4267  Q   W 92640351 + 8 [kjournald]
  8,5   21       11     0.504696615  4267  M   W 92640351 + 8 [kjournald]
  0,0   21       12     0.504697422  4267  A   W 92640359 + 8 <- (8,6) 234416
  8,5   21       13     0.504697565  4267  Q   W 92640359 + 8 [kjournald]
  8,5   21       14     0.504697787  4267  M   W 92640359 + 8 [kjournald]
  0,0   21       15     0.504698549  4267  A   W 92640367 + 8 <- (8,6) 234424
  8,5   21       16     0.504698677  4267  Q   W 92640367 + 8 [kjournald]
  8,5   21       17     0.504698939  4267  M   W 92640367 + 8 [kjournald]
  8,5   21       18     0.504699954  4267  U   N [kjournald] 1
  8,5   21       19     0.504704050  4267  D   W 92640335 + 40 [kjournald]
  8,5    2       27     0.504810390     0  C   W 92640335 + 40 [0]
  0,0    2       28     0.504842324  4267  A   W 92640375 + 8 <- (8,6) 234432
  8,5    2       29     0.504842594  4267  Q   W 92640375 + 8 [kjournald]
  8,5    2       30     0.504844133  4267  G   W 92640375 + 8 [kjournald]
  8,5    2       31     0.504845233  4267  P   N [kjournald]
  8,5    2       32     0.504845703  4267  I   W 92640375 + 8 [kjournald]
  8,5    2       33     0.504846958  4267  U   N [kjournald] 1
  8,5    2       34     0.504848547  4267  D   W 92640375 + 8 [kjournald]
  8,5    2       35     0.504879109     0  C   W 92640375 + 8 [0]
CPU2 (8,5):
 Reads Queued:           0,        0KiB  Writes Queued:           6,       24KiB
 Read Dispatches:        0,        0KiB  Write Dispatches:        3,       24KiB
 Reads Requeued:         0               Writes Requeued:         0
 Reads Completed:        0,        0KiB  Writes Completed:        5,       48KiB
 Read Merges:            0,        0KiB  Write Merges:            3,       12KiB
 Read depth:             0               Write depth:             2
 IO unplugs:             3               Timer unplugs:           0
CPU13 (8,5):
 Reads Queued:           0,        0KiB  Writes Queued:           1,        4KiB
 Read Dispatches:        0,        0KiB  Write Dispatches:        1,        4KiB
 Reads Requeued:         0               Writes Requeued:         0
 Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB  Write Merges:            0,        0KiB
 Read depth:             0               Write depth:             2
 IO unplugs:             1               Timer unplugs:           0
CPU21 (8,5):
 Reads Queued:           0,        0KiB  Writes Queued:           5,       20KiB
 Read Dispatches:        0,        0KiB  Write Dispatches:        1,       20KiB
 Reads Requeued:         0               Writes Requeued:         0
 Reads Completed:        0,        0KiB  Writes Completed:        0,        0KiB
 Read Merges:            0,        0KiB  Write Merges:            4,       16KiB
 Read depth:             0               Write depth:             2
 IO unplugs:             1               Timer unplugs:           0

Total (8,5):
 Reads Queued:           0,        0KiB  Writes Queued:          12,       48KiB
 Read Dispatches:        0,        0KiB  Write Dispatches:        5,       48KiB
 Reads Requeued:         0               Writes Requeued:         0
 Reads Completed:        0,        0KiB  Writes Completed:        5,       48KiB
 Read Merges:            0,        0KiB  Write Merges:            7,       28KiB
 IO unplugs:             5               Timer unplugs:           0

Throughput (R/W): 0KiB/s / 95KiB/s
Events (8,5): 61 entries
Skips: 0 forward (0 -   0.0%)

利用这些信息我们可以很清楚的知道我们IO设备在做什么,花了多少时间,透过它了解我们系统的运作。如何解读这些信息我们可以看手册有详细的解释:
$ man blkparse

同时如果你觉得这些信息太原始,类似btt, seekwatcher这样的工具在blktrace的信息的基础上更深入的挖掘了系统的行为,使用起来也更简单。

我们在实际工作的过程中用blktrace定位了很多问题,比如fsync的延时问题和IO调度器的问题,确实是很实用的一个工具。

祝大家玩的开心。

Post Footer automatically generated by wp-posturl plugin for wordpress.

  1. March 1st, 2011 at 09:33 | #1

    第一句话写错啦。

    Yu Feng Reply:

    谢谢大侠指正!

  2. konggonggongzhu
    March 23rd, 2011 at 11:29 | #2

    请问,我想捕捉一个dd 命令的io情况,可以做到吗?
    如果可以,怎么做?
    我没有捕捉到!

    Yu Feng Reply:

    当然可以了 blktrace 文件所在的设备

    konggonggongzhu Reply:

    # mount -t debugfs debugfs /sys/kernel/debug/
    #mount /dev/sda5 /mnt

    一个窗口监控
    #blktrace -d /dev/sda5 -o test
    一个窗口进行如下操作
    #dd if=/dev/zero of=/mnt/test

    然后使用blkparse分析
    blkparse -d bp.bin test.blktrace.*

    结果我怎么都看不到dd这个命令的io情况

    Yu Feng Reply:

    哥们 dd if=/dev/zero of=/mnt/test 应该在加入bs=4096 count=1024这样的

  3. konggonggongzhu
    March 23rd, 2011 at 11:50 | #3

    哥们我写了,刚才落下了!

    Yu Feng Reply:

    再加上oflag=direct 默认是buffer io, 页面是pdflush刷的。

  4. konggonggongzhu
    March 23rd, 2011 at 11:52 | #4

    能够监控到后台kjournald 还有 pdflush
    可是别的就不行!包括我执行mkfs.ext3 /dev/sda5

    是我的监控命令写错了?

    Yu Feng Reply:

    记得os 默认是buffer的io

  5. konggonggongzhu
    March 23rd, 2011 at 12:02 | #5

    谢谢知道!
    oflag=direct
    你说的这个是write函数的那个标志吗?具体怎么用,请指教!
    另外我这边的问题解决了
    我把-d参数去掉就好用了
    #blktrace /dev/sda5
    #blkparse sda5 > a
    这样就可以了!
    再次感谢!

    Yu Feng Reply:

    入门后,可以研究下btt的使用。

  6. May 4th, 2011 at 16:23 | #6

    Accurate blktrace: ablktrace

    ABSTRACT
    The blktrace is low-overhead, configurable kernel component that
    generates events for specific operations performed on I/O entering
    or leaving the block layer. The events generated by kernel
    blktrace are get intercepted by a user level application also named
    blktrace. This user-land blktrace displays the block trace output
    from the kernel. (I will call these components kernel blktrace and
    user blktrace respectively.)
    However, current blktrace have a serious technical limitation. The
    log information that kernel blktrace generate indicates the PID
    and application name as following example:
    8,0 0 132 3.1700847 14403 C W 24165559 + 8 [pdflush]
    The problem is process ID and name information might not be the
    correct process responsible for that operation. It is mostly because
    the Linux kernel writes dirty pages asynchronously and the
    pdflush is the ultimate process that flushes dirty pages to the disk.
    The main goal of this project is enhancing the blktrace to show
    accurate process information in its event logs.
    Keywords
    Blktrace, Page cache, Dirty page, IO Scheduler

  7. September 16th, 2011 at 17:54 | #7

    余大侠,对比测试过as5u3(2.6.18-194.el5 SMP x86_64)下的xfs和ext4性能差别吗。
    另外,在io是主要瓶颈的系统中,重点应该关注tps/iops,还是svctime的值呢。

    Yu Feng Reply:

    5u3我没怎么用过.ext4和xfs在我们的测试场景中,性能比较接近,但是考虑到支持的力度还是ext4靠谱点。io瓶颈主要都是随机读写的瓶颈,吞吐量不是问题,所以通常比较要注意iops

  8. April 24th, 2012 at 23:36 | #8

    能够通过这个工具,查看到对磁盘的写入,有多少是顺序写,有多少是随机写吗?

    Yu Feng Reply:

    你自己根据blktrace的数据写个脚本来分析下就可以。

  9. liubing
    March 12th, 2014 at 11:36 | #9

    请教个问题: 现在在做raid的io优化,想使用blktrace跟踪底层设备(约16-24个磁盘)的io merge情况。看到blktrace有-I参数可以同时跟踪多个设备,但实际使用中发现很多时候只能trace部分磁盘(有时候也能跟到全部部磁盘),大牛遇到过这种情况吗,是不是某些参数我设置的有问题?谢谢!
    附:
    blktrace: blktrace-1.0.1-6.el6.x86_64
    系统: centos 6.5

    Yu Feng Reply:

    不好意思,没遇到这种情况。不过blktrace代码还是比较简单的,打开源码核对下看多盘是怎么运作的。有无可能是数据量太大,内核到userland的数据丢失了?

  10. nanana
    July 10th, 2014 at 14:10 | #10

    您好 请问fsync的延时问题是如何使用blktrace来定位的呢

  11. nanana
    August 20th, 2014 at 16:39 | #11

    请教个问题 :当blktrace过大时,在使用blkparse和btt解析时候会不会出现数据丢失呢 同时还发现btt解析出来的.avg文件中的Q2G,G2I,I2D的时间百分比远大于100%,这个是否是blkparse在解析时出问题呢?

  12. 小z
    August 6th, 2015 at 15:42 | #12

    余大侠,请教一个blktrace查出来的磁盘问题的解决方式,感谢!
    背景如下:最近遇到一台服务器磁盘性能很差的问题,最终经过在RAID上将问题磁盘重新挂载解决了性能问题,特意留了一个盘做问题分析使用,最后经过定位,通过blktrace看到的具体表现是从“U”trace action到“D”trace action耗时是正常的磁盘耗时100倍,也就是数据写入磁盘时性能严重下降导致。
    其中一组问题磁盘和正常磁盘的对比结果为:正常磁盘(D trace action触发时间0.000021446,C trace action触发时间0.000089317)耗时0.000067871秒,异常磁盘(D trace action触发时间0.000013808,C trace action触发时间0.007814277)耗时0.007800469秒,明显是磁盘驱动数据写入耗时导致。(测试使用的两块磁盘在测试时没有任何其他用户进程使用测试磁盘)

    背景描述如上,问题在于最终确认问题之后,搞不明白的是为什么通过RAID上重新挂载一次磁盘就解决这个问题了,而且通过格式化磁盘或者重新挂载磁盘或者重启机器等,磁盘都是还是一样的性能差,只有通过RAID重新挂载一次磁盘就完全恢复了(RAID重新挂载磁盘实在BIOS中操作的,并且重新挂载磁盘需要重新分区),感觉跟硬件配置参数或者驱动有关系,但是现在无从下手,不知道该怎么进一步确定问题,还请余大侠出手相助,感谢!

  13. 小z
    August 6th, 2015 at 15:46 | #13

    @小z
    不好意思,其中问题描述的第一段,不是从U trace action 到 D trace action,而是从 D trace action 到 C trace action,手误写错了

Comments are closed.