[转载] 使用 blktrace 统计磁盘块 IO 访问频率

如果我们想知道,在一段时间内,那一个磁盘块被读写的频率最高,怎么办?我问这个问题是看到 taobao kernel wiki 上面有这么一段话,看了我十分心痒:

    通过对 blktrace 的输出结果进行分析,我们可以对特定时间段内发生的
    读、写操作的磁盘块进行 I/O 频次统计。结合通过将磁盘块 I/O 频度统计和
    page cache 命中率统计相结合,就可以比较有效的判断服务器节点的 cache
    使用效率。通过这套工具,CDN 系统修正了一个固态硬盘上 cache 管理的缺陷,
    显著提高了I/O性能(详细信息)

淘宝大神给了一个 shell 脚本解决这个问题,但是我守着代码,不知道怎么用。就研究了下 blktrace 和大神的代码。

常常听淘宝的霸爷,提起 blktrace。 iostat,iotop 这些的工具也是统计磁盘 IO 的,也非常有用,但是和 blktrace 比,信息过于 summarized,而 blktrace 跟踪了发生在块设备层的很多事件,简直就是整个块设备层事件的回放。

blktrace 能够 trace 那些事件呢? Bean_lee - blktrace events.png

上面这个胶片来自 HP 的介绍 blktrace 的胶片,介绍的非常好,是参考文献中一篇。

这些事件都会被 blktrace 捕捉到。由于这些事件要和 kernel 代码中 block device 的 work flow 一一对应,目前我的功力尚不足,所以我就不一一介绍这些事件了。

blktrace 输出的东西,不是文本,是一些特殊的格式,要想可读,需要 blkparse 解析 blktrace 的输出。

我们看下blktrace和blkparse合作方式

    blktrace -d /dev/sda -o - |blkparse -i - -o blkparse.out

这是一个比较典型的使用:blktrace -d 表示 monitor 哪个设备,-o -表示讲输出吐出到标准输出。blkparse -i - 表示从标准输入获取信息,-o 表示讲解析的内容记录在 blkparse.out

我们看下输出长的什么样子: BlockIO/Bean_lee - blkparse output.png

这个胶片非常好的介绍了各个字段的含义。主次设备号,CPU ID,sequence num,time stamp PID ,起始扇区号,进程名字比较好理解,比较难理解的是$6,$7。$6 中的 GPQMDC,一堆字母,代表什么含义?$7的WR 又代表什么含义呢?

一个一个来,对于$6,表示的是 event,官方手册给了事件对应表: Bean_lee - blktrace events mask.png

那么$7是干嘛的呢?基本上是 R 和 W,也会出现 B 和 S。R 表示是 read 操作,W 表示 write 操作,B 是 barrier operation,S 是 synchronous operation

看到这个 blkparse 的输出,我们发现这些更像是 raw data,需要我们挖掘背后的信息。btt 这个工具就是一个分析输出得到更高层信息的 tool,他不是我们本文的重点,我们不提他。

回到开篇的问题,如何知道 which 磁盘扇区被读写的次数最多?有了 blkparse 的输出,我们完全可以做到这个统计:淘宝的 Coly 大神的 shell 脚本已经帮我们作了这个事情。

    root@manu-hacks:~/code/shell/blkstrace_calculator# cat cal.sh
    #!/bin/bash

    TMP_DIR=".blktrace_cal"

    # extend the blktrace log to "blockid R/W"
    extend()
    {
        awk -v max=$2 -v mod=$3 '{
            if ( NR%max==mod && $6 == "D" && (index($7, "R") || index($7, "W")) ) {
                for(i=0; i<$10; i++) {
                    print $8+i" "substr($7, 1, 1);
                }
            }
        }' $1 | sort -k1 -nr > $TMP_DIR/.tmp.$1.$3
        touch $TMP_DIR/$3.ok
    }

    usage()
    {
        echo "Usage: $1 input_log [parallel_num]"
        exit
    }

    rm -rf $TMP_DIR
    mkdir $TMP_DIR

    if [ "$1" == "" ]; then
        usage $0
    fi

    # does input_log exists?
    if [ ! -f $1 ]; then
        echo "($1) not exists"
        exit
    fi

    parallel=$2

    if [ "$2" == "" ]; then
        parallel=4
    fi

    echo "[input: $1]"

    max=`expr $parallel - 1`
    files=""
    filename=`basename $1`

    echo "[run $parallel process]"

    for i in `seq 0 $max`
    do
        extend $filename $parallel $i &
        files=$files" $TMP_DIR/.tmp.$filename.$i"
    done
    echo "processing...."

    nr=0
    # awk will finish if all *.ok created.
    while [ $nr -ne "$parallel" ]
    do
        nr=`find $TMP_DIR -maxdepth 1 -name "*.ok"|wc -l`
        echo -n "."
        sleep 1
    done

    echo ""
    echo "merge sort"
    sort -m -k1 -nr $files | uniq -c | sort -k1 -nr > tmp
    total=`awk '{sum+=$1} END{print sum}' tmp`
    awk -v sum=$total '{
        print $0"\t"$1*1000/sum;
    }' tmp > result

    echo "sort finish."

    rm -rf $TMP_DIR

这段代码是 Coly 大神的代码,我无意抄袭前辈,只是晚辈拿来欣赏学习,光荣属于淘宝的 Coly 前辈。

先说 parallel,这个是为了充分利用 CPU 资源,让多个 CPU 一起来执行 extend。NR%max==mod 将一个文件按照行分开,由多个进程分别处理之。不多讲。

extend的含义也比较简单:

      8,0 0 909 19.618798623 6475 Q W 20397704 + 8 [evince-thumbnai]
      8,0 0 910 19.618803866 6475 G W 20397704 + 8 [evince-thumbnai]

20397704是起始扇区,+ 8表示的连续8个扇区都在本次事件之内,也就是说20397704/20397705/20397706.. 都是本次事件涉及的扇区。

OK,我们看下 cal.sh 的使用及输出:

    ../blkstrace_calculator/cal.sh blkparse.out 4

当前目录下生成了 tmp 和 result 文件:

    root@manu-hacks:~/code/shell/blktrace# head result
         39 454375583 W    0.228744
         39 454375582 W    0.228744
         39 454375581 W    0.228744
         39 454375580 W    0.228744
         39 454375579 W    0.228744
         39 454375578 W    0.228744
         39 454375577 W    0.228744
         39 454375576 W    0.228744
         27 264753359 W    0.158361
         27 264753358 W    0.158361

我们可以看到,扇区号为 454375583 被访问的次数为 39 次,占总访问的千分之 0.228744

那这个扇区属于拿个文件呢?debugfs 就可以来帮忙了。我们以访问 27 次的 264753359 扇区为例。扇区是 512 字节,我的文件系统 ext4 的块大小是 4K,所以根据扇区可以定位的块号,debugfs 根据块号,可以定位到 inode,再根据 inode,就可定位到 filename

    root@manu-hacks:~/code/shell/blktrace# echo 264753359/8 |bc
    33094169

    root@manu-hacks:~/code/shell/blktrace# debugfs -R "icheck 33094169" /dev/sda1
    debugfs 1.42 (29-Nov-2011)
    Block    Inode number
    33094169    14290766

    root@manu-hacks:~/code/shell/blktrace# debugfs -R "ncheck 14290766" /dev/sda1
    debugfs 1.42 (29-Nov-2011)
    Inode    Pathname
    14290766    /home/manu/.pki/nssdb/key4.db

我们发现,这个文件被读写的次数最多。谁干的? lsof 来帮忙?

    root@manu-hacks:~/code/shell/blktrace# lsof /home/manu/.pki/nssdb/key4.db
    lsof: WARNING: can't stat() fuse.gvfs-fuse-daemon file system /home/manu/.gvfs
    Output information may be incomplete.
    COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
    chromium- 5717 manu 57u REG 8,1 11264 14290766 /home/manu/.pki/nssdb/key4.db
    chromium- 5902 manu 7u REG 8,1 11264 14290766 /home/manu/.pki/nssdb/key4.db
    chromium- 5906 manu 7u REG 8,1 11264 14290766 /home/manu/.pki/nssdb/key4.db

我们用 Coly 大神的脚本和 blktrace/blkparse 就解决了磁盘块 IO 访问频率的统计。如果有个别的 block 被频繁的读取,表示 cache 的替换效率不高

参考文献