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.
第一句话写错啦。
Yu Feng Reply:
March 1st, 2011 at 11:35 am
谢谢大侠指正！
请问，我想捕捉一个dd 命令的io情况，可以做到吗？
如果可以，怎么做？
我没有捕捉到！
Yu Feng Reply:
March 23rd, 2011 at 11:37 am
当然可以了 blktrace 文件所在的设备
konggonggongzhu Reply:
March 23rd, 2011 at 11:46 am
# 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:
March 23rd, 2011 at 11:48 am
哥们 dd if=/dev/zero of=/mnt/test 应该在加入bs=4096 count=1024这样的
哥们我写了，刚才落下了！
Yu Feng Reply:
March 23rd, 2011 at 11:53 am
再加上oflag=direct 默认是buffer io, 页面是pdflush刷的。
能够监控到后台kjournald 还有 pdflush
可是别的就不行！包括我执行mkfs.ext3 /dev/sda5
是我的监控命令写错了？
Yu Feng Reply:
March 23rd, 2011 at 11:54 am
记得os 默认是buffer的io
谢谢知道！
oflag=direct
你说的这个是write函数的那个标志吗？具体怎么用，请指教！
另外我这边的问题解决了
我把-d参数去掉就好用了
#blktrace /dev/sda5
#blkparse sda5 > a
这样就可以了！
再次感谢！
Yu Feng Reply:
March 23rd, 2011 at 2:12 pm
入门后，可以研究下btt的使用。
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
余大侠，对比测试过as5u3(2.6.18-194.el5 SMP x86_64)下的xfs和ext4性能差别吗。
另外，在io是主要瓶颈的系统中，重点应该关注tps/iops，还是svctime的值呢。
Yu Feng Reply:
September 16th, 2011 at 5:59 pm
5u3我没怎么用过.ext4和xfs在我们的测试场景中，性能比较接近，但是考虑到支持的力度还是ext4靠谱点。io瓶颈主要都是随机读写的瓶颈，吞吐量不是问题，所以通常比较要注意iops
能够通过这个工具，查看到对磁盘的写入，有多少是顺序写，有多少是随机写吗？
Yu Feng Reply:
April 25th, 2012 at 6:27 pm
你自己根据blktrace的数据写个脚本来分析下就可以。
请教个问题： 现在在做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:
March 12th, 2014 at 3:16 pm
不好意思，没遇到这种情况。不过blktrace代码还是比较简单的，打开源码核对下看多盘是怎么运作的。有无可能是数据量太大，内核到userland的数据丢失了？
您好 请问fsync的延时问题是如何使用blktrace来定位的呢
请教个问题 ：当blktrace过大时，在使用blkparse和btt解析时候会不会出现数据丢失呢 同时还发现btt解析出来的.avg文件中的Q2G，G2I，I2D的时间百分比远大于100%，这个是否是blkparse在解析时出问题呢？
余大侠，请教一个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中操作的，并且重新挂载磁盘需要重新分区），感觉跟硬件配置参数或者驱动有关系，但是现在无从下手，不知道该怎么进一步确定问题，还请余大侠出手相助，感谢！
@小z
不好意思，其中问题描述的第一段，不是从U trace action 到 D trace action，而是从 D trace action 到 C trace action，手误写错了