• 用systemtap对sysbench IO测试结果的分析1

     http://www.actionsky.com/docs/archives/171

     2016年5月6日  黄炎

    近期在一些简单的sysbench IO测试中, 遇到了一些不合常识的测试结果. 从结果看, 虽然不是有实际意义的测试结果, 但探索过程中, 利用到了Systemtap进行观测(动态追踪), 可在其他分析中借用.

    测试环境准备

    • 运行前, 通过echo 1 > /proc/sys/vm/drop_caches清理IO cache
    • 运行前, 通过iostat -x -p {dev} 1确认没有其它IO影响结果
    • sysbench参数
    sysbench --test=fileio --num-threads=$SYSBENCH_NUM_THREADS --file-num=$SYSBENCH_FILE_NUM --file-block-size=$SYSBENCH_BLOCK_SIZE --file-total-size=$SYSBENCH_FILE_TOTAL_SIZE --file-test-mode=$1 --file-io-mode=sync --file-extra-flags=$DIRECT --file-fsync-all=$FSYNC --file-fsync-mode=fsync --file-fsync-freq=0 --file-merged-requests=0 --max-time=$SYSBENCH_TIME --max-requests=0

    其中的变量参数

    SYSBENCH_FILE_TOTAL_SIZE=16G
SYSBENCH_FILE_NUM=16
SYSBENCH_NUM_THREADS=16
DIRECT=
FSYNC=off
SYSBENCH_BLOCK_SIZE=4096
SYSBENCH_TIME=60

    附件中的run_sysbench.sh是运行sysbench的脚本, 每个实验的输出都附在附件中, 样例输出:

    huangyan@R820-09:/opt/test-io/sysbench_io_test_1$ ./run_sysbench.sh seqrewr run | tee 1_seqwr
=== check device /dev/sdb
====== device has 0 IO
====== clearing file io cache
=== run sysbench, mode=seqrewr/directIO=/fsync=off/block_size=4096
sudo sysbench --test=fileio --num-threads=16 --file-num=16 --file-block-size=4096 --file-total-size=16G --file-test-mode=seqrewr --file-io-mode=sync --file-extra-flags= --file-fsync-all=off --file-fsync-mode=fsync --file-fsync-freq=0 --file-merged-requests=0 --max-time=60 --max-requests=0 run
sysbench 0.4.12:  multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 16

Extra file open flags: 0
16 files, 1Gb each
16Gb total file size
Block size 4Kb
Calling fsync() at the end of test, Enabled.
Using synchronous I/O mode
Doing sequential rewrite test
Threads started!
Time limit exceeded, exiting...
(last message repeated 15 times)
Done.

Operations performed:  0 Read, 4194304 Write, 16 Other = 4194320 Total
Read 0b  Written 16Gb  Total transferred 16Gb  (151.62Mb/sec)
38815.28 Requests/sec executed

Test execution summary:
    total time:                          108.0581s
    total number of events:              4194304
    total time taken by event execution: 586.2724
    per-request statistics:
         min:                                  0.00ms
         avg:                                  0.14ms
         max:                               1014.09ms
         approx.  95 percentile:               0.08ms

Threads fairness:
    events (avg/stddev):           262144.0000/13252.56
    execution time (avg/stddev):   36.6420/0.01

    现象1

    步骤1

    1.非Direct I/O模式, 测试顺序写

    ./run_sysbench.sh seqrewr run | tee 1_sysbench_seqrewr

    2.非Direct I/O模式, 测试随机写

    ./run_sysbench.sh rndwr run | tee 2_sysbench_rndwr

    3.Direct I/O模式, 测试顺序写(seqrewr)

    DIRECT=1 ./run_sysbench.sh seqrewr run | tee 3_sysbench_direct_seqrewr

    4.Direct I/O模式, 测试随机写(rndwr)

    DIRECT=1 ./run_sysbench.sh rndwr run | tee 4_sysbench_direct_rndwr

    结果1

    Direct?顺序写随机写
    – 151.62Mb/s (38815.28 Req/s) 528.77Mb/s (135364.78 Req/s)
    Direct 71.149Mb/s (18214.20 Req/s) 4.212Mb/s (1078.26 Req/s)

    对于磁盘的I/O测试, 直觉上顺序写比随机写要快很多. 从测试结果可以看到:
    1. 在Direct I/O模式下, 与直觉结果相符
    2. 在非Direct I/O模式下, 随机写比顺序写IOPS快4倍, 吞吐与IOPS成正比. 这一点是违反直觉的

    对结果的分析将集中在非Direct I/O模式下.

    分析1

    我们一时间对上述结果没有任何头绪, 也不大可能是意外发明了随机写更快的磁盘. 先尝试观察对磁盘的IO压力分布:

    iostat -x -p /dev/sdb 1

    观察到在sysbench结束后, 顺序写的I/O压力为0, 但随机写的I/O压力仍将持续一些时间.
    随即怀疑sysbench在顺序写时用fsync进行刷盘, 并等待刷盘结束. 在等待期间没有sysbench不发出新的IO请求, 自然IOPS会降低.
    但sysbench参数中已经设置了--file-fsync-all=off, 与现象冲突.

    用strace确认这一结论:

    strace -e trace=fsync -f ./run_sysbench.sh seqrewr run 2>&1 | tee 5_strace_sysbench_seqrewr

    可以看到显式的fsync调用.

    在sysbench源码中可以找到与FILE_OP_TYPE_FSYNC相关的一段代码:

        if (file_fsync_end && file_req->operation == FILE_OP_TYPE_WRITE &&
        fsynced_file2 < num_files)
    {
      file_req->file_id = fsynced_file2;
      file_req->pos = 0;
      file_req->size = 0;
      file_req->operation = FILE_OP_TYPE_FSYNC;
      fsynced_file2++;
    }

    意味着这个fsync与sysbench参数file-fsync-end相关.
    解决方案:
    1. 设置--file-fsync-end=no
    2. 在测试中sysbench顺序写 写完所有文件的时间<--max-time的设置, 写完后进行fsync. 我们可以调大文件大小来延长写完所有文件的时间, 或缩小--max-time 使写完所有文件的时间>--max-time, 避免多出的fsync

    之后的测试中, 将置--file-fsync-end=no, 并将--max-time设为30, 避免fsync, 且减少测试时间成本.

    插曲1

    在分析的过程中, 实际过程要比上述描述艰辛一些.

    观测工具使用不当带来测试偏差

    用strace确定是否有fsync调用时, 最初用的命令是:

    strace -f ./run_sysbench.sh seqrewr run 2>&1 | tee 5_strace_sysbench_seqrewr

    由于缺少了-e trace=fsync参数, strace的成本上升, 导致sysbench的性能下降, 使得 写完所有文件的时间>--max-time, 就没有发现fsync调用.

    这一结果与预期不符, 一时陷入僵局. 绕了一圈后怀疑和观测工具相关, 虽没有定位到是因为观测工具引起的性能下降, 但可以尝试用另一个观测工具来校准偏差. 在此选定的工具是systemtap.

    使用另一观测工具用于校准 — systemtap

    Systemtap 提供了极低成本的内核检测能力, 类似于Dtrace, 详细的介绍请找官方文档.

    以检测fsync调用为例演示systemtap的用法:

    1.环境准备请找官方文档
    2.编辑systemtap脚本 6_systemtap_fsync_summary.stp

    !/usr/bin/env stap
global r
probe syscall.fsync {
        r[pid()] <<< 1
}

probe end {
        foreach ([pid-] in r) {
                printf ("pid=%d, fsync=%d times
", pid, @count(r[pid]))
        }
}

    3.编译

    stap -v -r $(uname -r) -DMAXSKIPPED=100000 -DSTP_NO_OVERLOAD 6_systemtap_fsync_summary.stp -m 6_systemtap_fsync_summary.ko

    systemtap在观测负荷会显式影响系统性能时, 会”跳过”一些观测点, 这样不会影响系统性能, 可以安全地使用, 但会造成结果不准确. -DMAXSKIPPED=100000 -DSTP_NO_OVERLOAD 这两个参数能systemtap尽量”不计成本”地观测, 但需要警惕其带来的开销. 后续编译中默认会使用这两个参数, 但所有结果需要和不使用参数的情况进行对比, 来发现并规避其影响. 本文不记述对比的过程.

    4.使用

    staprun -v fsync_summary.ko | tee 6_systemtap_fsync_summary

    输出如下:

    pid=34888, fsync=16 times

    可以看到16个fsync调用, 与sysbench配置的线程数一致. 即证明之前不当使用strace造成了观测结果的偏差.

    5.说明
    systemtap可以一键运行脚本, 但我们用了编译+运行两个步骤, 原因是systemtap的编译环境配置比较繁复, 因此我们将编译环境隔离到了一个容器中, 而将编译好的.ko文件放到目标机上运行, 目标机只需安装简单的依赖就可以运行. 避免环境污染.

    复盘1

    回头重看现象1的分析过程, 有几点教训:
    1.其实sysbench的标准输出已经给出了问题原因:

    ...
Extra file open flags: 0
16 files, 1Gb each
16Gb total file size
Block size 4Kb
Calling fsync() at the end of test, Enabled.
Using synchronous I/O mode
...

    Calling fsync() at the end of test, Enabled., 藏在一堆数字中信息容易被忽略

    2.对观测工具要进行校准

    现象2

    步骤2

    根据现象1的分析, 调整sysbench参数: 置--file-fsync-end=no, 并将--max-time设为30. 重新运行非Direct IO模式的顺序写和随机写的测试.

    1.测试顺序写

    SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run | tee 7_sysbench_seqrewr

    2.测试随机写

    SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run | tee 8_sysbench_rndwr

    结果2

    顺序写随机写
    503.05Mb/s (128779.82 Req/s) 833.43Mb/s (213357.78 Req/s)

    比之前的结果好一些, 但观察仍到两个异常现象:
    1. 现象2的随机写效率高于现象1. 猜测是因为缩短了--max-time, 导致文件系统缓存仍然在预热过程中, 不需等待回刷. 之后的分析中将略过这一点, 并不影响分析结果.
    2. 顺序写的效率仍然低于随机写. 对这个现象完全没有想法.

    分析2.1 – 端到端的延迟分布

    如果对Linux I/O栈比较陌生, 可以查看Linux Storage Stack Diagram 做初步了解.

    由于对”顺序写的效率低于随机写”这一现象没有任何想法, 就先测量一下端到端的延迟分布, 即站在vfs层的角度看延迟分布.

    期望是能判断延迟是否平均, 是否由于个别I/O的异常拖慢了整体水平.

    还是用到了systemtap脚本, 此处略去编译过程, 直接给出脚本和结果

    systemtap脚本2.1

    vfs_write_latency.stp

    global input_devname="sdb"
global io_latency

probe vfs.write.return {
        if (bytes_to_write > 0 && input_devname == devname) {
                time = gettimeofday_ns() - @entry(gettimeofday_ns())
                io_latency <<< time
        }
}

probe end {
        print (@hist_log(io_latency))
}

    运行2.1

    1.测试顺序写

    1> staprun -v vfs_write_latency.ko 2>&1 | tee 9_systemtap_vfs_write_latency_seqrewr
2> SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run

    2.测试随机写

    1> staprun -v vfs_write_latency.ko 2>&1 | tee 10_systemtap_vfs_write_latency_rndwr
2> SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run

    结果2.1

    1.顺序写

                  value |-------------------------------------------------- count
                512 |                                                        0
               1024 |                                                        0
               2048 |                                                     5797
               4096 |@@@@@@@@@@@@@@@                                    285267
               8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@               656853
              16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  903046
              32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   870665
              65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           736454
             131072 |@@@@@@@@@@@@                                       230028
             262144 |@                                                   32081
             524288 |                                                      916
            1048576 |                                                      121
            2097152 |                                                       94
            4194304 |                                                       37
            8388608 |                                                       13
           16777216 |                                                     3490
           33554432 |                                                     1027
           67108864 |                                                      114
          134217728 |                                                       20
          268435456 |                                                       30
          536870912 |                                                       16
         1073741824 |                                                        0
         2147483648 |                                                        0
                    ~
 288230376151711744 |                                                        0
 576460752303423488 |                                                        0
1152921504606846976 |                                                        1
2305843009213693952 |                                                        0
4611686018427387904 |                                                        0

WARNING: Number of errors: 0, skipped probes: 1

    2.随机写

                  value |-------------------------------------------------- count
                512 |                                                         0
               1024 |                                                         0
               2048 |                                                      4247
               4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     1153800
               8192 |@@@@@@@@@@@@@@@@@@@@                                517586
              16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  1242648
              32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          1043353
              65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@              949123
             131072 |@@@@@@@@@@@@@@@@                                    414590
             262144 |@@                                                   57399
             524288 |                                                      1026
            1048576 |                                                         0
            2097152 |                                                        17
            4194304 |                                                        32
            8388608 |                                                       289
           16777216 |                                                       168
           33554432 |                                                        12
           67108864 |                                                        16
          134217728 |                                                        16
          268435456 |                                                         0
          536870912 |                                                         0
         1073741824 |                                                        16
         2147483648 |                                                         0
         4294967296 |                                                         0
                    ~
 288230376151711744 |                                                         0
 576460752303423488 |                                                         0
1152921504606846976 |                                                         1
2305843009213693952 |                                                         0
4611686018427387904 |                                                         0

WARNING: Number of errors: 0, skipped probes: 1

    可以看到:
    1. 存在skipped probes. systemtap认为有一个观测点影响太大, 因此跳过.
    2. 存在一个非常离谱的异常点: 1152921504606846976ns, 以至对平均值产生了很大影响. 这可能是由于skipped probes引起的. 之后的分析将这个异常点去掉.
    3. 存在两段峰值: 2048~524288ns, 2097152~1073741824ns. 第二段的命中次数远低于第一段, 但延迟占有一定比例. 由于一时没有头绪, 先忽略这一现象, 留待之后解决.
    4. 随机写比顺序写的低延迟段(4096ns附近)的分布要多一些.

    目前为止没有进展. 下一步试试研究设备层的I/O请求特征, 期望是设备层的I/O请求特征正常, 从而确认问题出在文件系统和IO调度上.

    分析2.2 – 设备层的I/O请求特征

    systemtap脚本2.2

    global input_devname="sdb"
global latency

probe ioblock.request.return {
        if (devname == input_devname && size > 0) {
                latency[rw, size] <<< gettimeofday_ns() - @entry(gettimeofday_ns())
        }
}

probe end {
        foreach ([rw, size-] in latency) {
                printf ("rw: %d, io_size: %d, count: %d, avg_latency: %d
", rw, size, @count(latency[rw, size]), @avg(latency[rw, size]))
        }
}

    运行2.2

    1.测试顺序写

    1> staprun -v ioblock_request_summary.ko 2>&1 | tee 11_systemtap_ioblock_write_latency_seqrewr
2> SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run

    2.测试随机写

    1> staprun -v ioblock_request_summary.ko 2>&1 | tee 12_systemtap_ioblock_write_latency_rndwr
2> SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run

    结果2.2

    1.测试顺序写 (结果经过缩减)

    rw: 1, io_size: 262144, count: 15056, avg_latency: 1046246
rw: 1, io_size: 258048, count: 5, avg_latency: 22840
rw: 1, io_size: 253952, count: 17, avg_latency: 7728
...

rw: 1, io_size: 8192, count: 17, avg_latency: 3035934
rw: 96, io_size: 4096, count: 37, avg_latency: 20610
rw: 13329, io_size: 4096, count: 6, avg_latency: 13378
rw: 1041, io_size: 4096, count: 98, avg_latency: 2165
rw: 1, io_size: 4096, count: 6, avg_latency: 1706
rw: 97, io_size: 4096, count: 4, avg_latency: 1252
rw: 16384, io_size: 4096, count: 2, avg_latency: 14562

    2.测试随机写 (结果经过缩减)

    rw: 1, io_size: 172032, count: 1, avg_latency: 3689
rw: 1, io_size: 163840, count: 1, avg_latency: 3061
rw: 1, io_size: 159744, count: 1, avg_latency: 4617
...

rw: 1, io_size: 8192, count: 46334, avg_latency: 200684
rw: 1, io_size: 4096, count: 73103, avg_latency: 173626
rw: 0, io_size: 4096, count: 6, avg_latency: 3032
rw: 96, io_size: 4096, count: 29, avg_latency: 6783
rw: 1041, io_size: 4096, count: 249, avg_latency: 4029
rw: 13329, io_size: 4096, count: 9, avg_latency: 25033
rw: 97, io_size: 4096, count: 129, avg_latency: 183751

    rw是读写模式, io_size是设备I/O的大小, count是次数, avg_latency是平均延迟.

    可以看到:
    1. 顺序写的设备I/O的大小集中在大于4k的区域, 即在之前经过了合并. 随机写的设备I/O的大小几种在4k, 即没有经过合并. 符合预期.
    2. 从延迟上没有发现明显的差异.

    可以得到的结论是: 顺序写和随机写的反常的性能差异 很大程度来自于 文件系统和IO调度.

    分析2.3 – 文件系统的缓存命中率

    想到问题可能在文件系统, 那可能性比较大的是缓存系统的命中率. 顺序写的缓存命中率较低, 随机写的缓存命中率较高, 即几个发往文件系统的随机写请求可能写的是同一个数据块. 猜测随机写 在文件系统缓存的代价较小, 因此性能较好.

    下面验证文件系统的缓存命中率. 可以参考Brendan Gregg神的cachestat. 不过此处由于只需要对比趋势而不需要保证绝对值正确, 所以可以简化实现.

    systemtap脚本2.3.1

    global hit_add_to_page_cache_lru, hit_pagecache_get_page
global input_devname="sdb"

probe kernel.function("add_to_page_cache_lru") {
        dev = $mapping->host->i_sb->s_dev
        devname = __find_bdevname(dev, $mapping->host->i_sb->s_bdev)
        if (devname == input_devname) {
                hit_add_to_page_cache_lru <<< 1
        }
}

probe kernel.function("pagecache_get_page") {
        if (@defined($mapping->host->i_sb->s_dev)) {
                dev = $mapping->host->i_sb->s_dev
                devname = __find_bdevname(dev, $mapping->host->i_sb->s_bdev)
                if (devname == input_devname) {
                        hit_pagecache_get_page <<< 1
                }
        }
}

probe end {
        printf ("add_to_page_cache_lru: %d
", @count(hit_add_to_page_cache_lru))
        printf ("pagecache_get_page: %d
", @count(hit_pagecache_get_page))
}

    运行2.3.1

    1.测试顺序写

    1> staprun -v io_cache_hit_ratio.ko 2>&1 | tee 13_systemtap_io_cache_hit_ratio_seqrewr
2> SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run

    2.测试随机写

    1> staprun -v io_cache_hit_ratio.ko 2>&1 | tee 14_systemtap_io_cache_hit_ratio_rndwr
2> SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run

    结果2.3.1

    函数命中add_to_page_cache_lrupagecache_get_page
    顺序写 3619661 3620106
    随机写 3145851 5923712

    可以看到, 随机写的缓存命中率(1-add_to_page_cache_lru/pagecache_get_page)比顺序写要高. 之后的测试, 我们增大sysbench文件的总大小到64G, 来降低随机写的缓存命中率.

    运行2.3.2

    1.测试顺序写

    1> staprun -v io_cache_hit_ratio.ko 2>&1 | tee 15_systemtap_io_cache_hit_ratio_64G_seqrewr
2> SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run

    2.测试随机写

    1> staprun -v io_cache_hit_ratio.ko 2>&1 | tee 16_systemtap_io_cache_hit_ratio_64G_rndwr
2> SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run

    结果2.3.2

    函数命中 & 性能add_to_page_cache_lrupagecache_get_page性能
    顺序写 3767180 3767439 473.11Mb/s (121116.60 Req/s)
    随机写 3054193 3404711 438.59Mb/s (112279.94 Req/s)

    可以看到, 随着测试文件增大, 随机写的缓存命中率下降, 性能也随之下降. 写缓存的命中率是随机写和顺序写性能差异的影响因素之一.

    分析2.4 – 文件系统的缓存延迟分析

    分析2.3的结果是随机写和顺序写的性能差不多, 但我们仍可以进一步分析缓存的延时: 找一个使用缓存的堆栈, 逐层做延迟分析, 这是个笨拙但有效的方法.

    Systemtap本身提供了大量脚本, 其中就有一些成熟的函数入口可以直接借用, 而不用自己读Linux源码分析backtrace, 比如对于缓存, 找到/usr/share/systemtap/tapset/linux/vfs.stp文件, 搜一下cache, 就可以找到以下入口点:

    probe vfs.add_to_page_cache =
        kernel.function("add_to_page_cache_locked") !,
        kernel.function("add_to_page_cache")
{
...
}

    之后可以通过systemtap打印出add_to_page_cache的调用栈 (在3.19内核中, 实际使用了add_to_page_cache_lru, 这个需要查看源码才能知道此处的变更), 此处不详述, 结果如下:

     0xffffffff8117bac0 : add_to_page_cache_lru+0x0/0x80 [kernel]
 0xffffffff8117bc80 : pagecache_get_page+0x140/0x1a0 [kernel]
 0xffffffff8117bd0d : grab_cache_page_write_begin+0x2d/0x50 [kernel]
 0xffffffff81280299 : ext4_da_write_begin+0x99/0x300 [kernel]
 0xffffffff8117adbf : generic_perform_write+0xbf/0x1b0 [kernel]
 0xffffffff8117d0d0 : __generic_file_write_iter+0x1e0/0x390 [kernel]
 0xffffffff812759f9 : ext4_file_write_iter+0x109/0x400 [kernel]
 0xffffffff811f4c41 : new_sync_write+0x81/0xb0 [kernel]
 0xffffffff811f5417 : vfs_write+0xb7/0x1f0 [kernel]
 0xffffffff811f61b2 : sys_pwrite64+0x72/0xb0 [kernel]

    然后观测这个堆栈中每个函数的延迟, 这个过程中需要特别注意如果观测点过多, 那么对性能结果会有较大影响, 以致影响分析的结论. 因此每一次观测后需要对比观测前后的性能差别, 如果差异过大, 应调整观测手段或减小观测的范围.

    在此我们就假设运气很好, 一次观测就能命中要害.

    systemtap脚本2.4.1

    ext4_write_latency.stp

    global input_devname="sdb"

global latency_ext4_file_write_iter
probe kernel.function("ext4_file_write_iter").return {
        dev = __file_dev($iocb->ki_filp)
        devname = __find_bdevname(dev, __file_bdev($iocb->ki_filp))
        if (devname == input_devname) {
                latency_ext4_file_write_iter <<< gettimeofday_ns()-@entry(gettimeofday_ns())
        }
}

global latency___generic_file_write_iter
probe kernel.function("__generic_file_write_iter").return {
        dev = __file_dev($iocb->ki_filp)
        devname = __find_bdevname(dev, __file_bdev($iocb->ki_filp))
        if (devname == input_devname) {
                latency___generic_file_write_iter <<< gettimeofday_ns()-@entry(gettimeofday_ns())
        }
}

probe end {
        printf ("ext4_file_write_iter latency: %d
", @avg(latency_ext4_file_write_iter))
        printf ("__generic_file_write_iter latency: %d
", @avg(latency___generic_file_write_iter))
}

    运行2.4.1

    1.测试顺序写

    1> staprun -v ext4_write_latency.ko 2>&1 | tee 17_systemtap_ext4_write_latency_seqrewr
2> SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run

    2.测试随机写

    1> staprun -v ext4_write_latency.ko 2>&1 | tee 18_systemtap_ext4_write_latency_rndwr
2> SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run

    结果2.4.1

    函数延迟__generic_file_write_iterext4_file_write_iter__generic_file_write_iter占比
    顺序写 7481ns 148707ns 5.03%
    随机写 33791ns 132551ns 25.49%

    可以看到:
    1. 顺序写与随机写相比, __generic_file_write_iter的开销明显减小, 符合常识
    2. 顺序写与随机写相比, ext4_file_write_iter在其他方面的开销占比明显增加

    分析2.4.1

    从结果1得到结论: ext4_file_write_iter在其他方面的开销占比明显增加. 至于哪个方面的开销增加了, 得粗看一下源码(源码已将不重要的部分略去):


    static ssize_t
ext4_file_write_iter(struct kiocb *iocb, struct iov_iter *from)
{
       ...

        /*
         * Unaligned direct AIO must be serialized; see comment above
         * In the case of O_APPEND, assume that we must always serialize
         */
        if (o_direct && ...) {
            ...
        }

        mutex_lock(&inode->i_mutex);
        if (file->f_flags & O_APPEND) ...;

        /*
         * If we have encountered a bitmap-format file, the size limit
         * is smaller than s_maxbytes, which is for extent-mapped files.
         */
        if (!(ext4_test_inode_flag(inode, EXT4_INODE_EXTENTS))) {
                ...
        }

        ...
        if (o_direct) {
                ...
        }

        ret = __generic_file_write_iter(iocb, from);
        mutex_unlock(&inode->i_mutex);

        if (ret > 0) {
                ...
        }
        if (o_direct) ...;

errout:
        if (aio_mutex) ...;
        return ret;
}

    源码已将分支内的部分略去, 只留下主干. 可以看到:
    1. 代码特别处理了一些情况(比如, Direct I/O, append模式等)
    2. 主干上的操作主要是__generic_file_write_iter和锁inode->i_mutex

    因此可以怀疑锁inode->i_mutex的代价是否过高.

    systemtap脚本2.4.2

    脚本generic_file_write_iter_concurrency.stp用于观测__generic_file_write_iter的并行度, 以此来估算锁inode->i_mutex的代价.

    global input_devname="sdb"

global concurrency, max_concurrency
probe kernel.function("__generic_file_write_iter") {
        dev = __file_dev($iocb->ki_filp)
        devname = __find_bdevname(dev,
                                  __file_bdev($iocb->ki_filp))
        if (devname == input_devname) {
                concurrency += 1
                max_concurrency <<< concurrency
        }
}

probe kernel.function("__generic_file_write_iter").return {
        dev = __file_dev($iocb->ki_filp)
        devname = __find_bdevname(dev,
                                  __file_bdev($iocb->ki_filp))
        if (devname == input_devname) {
                concurrency -= 1
        }
}

probe end {
        printf ("concurrency=%d
", @max(max_concurrency))
}

    运行2.4.2

    1.测试顺序写

    1> staprun -v generic_file_write_iter_concurrency.ko 2>&1 | tee 19_systemtap_generic_file_write_iter_concurrency_seqrewr
2> SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run

    2.测试随机写

    1> staprun -v generic_file_write_iter_concurrency.ko 2>&1 | tee 20_systemtap_generic_file_write_iter_concurrency_rndwr
2> SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run

    结果2.4.2

    –并发度
    顺序写 2
    随机写 14

    可以看到, 锁inode->i_mutex限制了__generic_file_write_iter的并发度. 由常识得知, 一个文件一般对应一个inode结构 (也可以通过systemtap打印inode地址来确认), 也就是说:

    1. 顺序写的压力集中在写一个文件, 因此在inode的锁上产生了竞争
    2. 随机写的压力比较分散, 因此__generic_file_write_iter的并发度高
    3. 顺序写的最大并发度为2, 而不是1, 可能是发生在已写满某一文件并要写下一个文件的瞬间

    之后, 我们将调整sysbench并发数为1, 来拉平顺序写和随机写的__generic_file_write_iter并发度, 创造公平的测试环境.

    步骤2.4.3

    根据现象2的分析, 本次的测试将调整sysbench并发数为1. 此处也可以随手验证一下现象2中的generic_file_write_iter的并发度, 在两种情况下都相等, 在此不详述.

    1.测试顺序写

    SYSBENCH_NUM_THREADS=1 SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run | tee 21_sysbench_1thread_seqrewr

    2.测试随机写

    SYSBENCH_NUM_THREADS=1 SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run | tee 22_sysbench_1thread_rndwr

    结果2.4.3

    –性能
    顺序写 523.46Mb/s (134006.71 Req/s)
    随机写 410.77Mb/s (105156.10 Req/s)

    可以看到, 在相对公平的测试条件下, 顺序写比随机写的性能更好一些.

    现象3

    在结果2.1中还遗留了一个问题: 在研究延迟分布时出现了两个峰. 在之前的试验中, 如果将一些函数的延迟分布打印出来, 也能观察到两个峰. 这些函数并不集中在某一个逻辑路径上, 比较分散. 因此可能是一个共有的机制导致第二个峰的出现, 而不是某个逻辑分支导致.

    另外可以尝试用systemtap脚本进行分析, 但几经尝试, 第二个峰的出现并不规律.

    偶尔想到这是否由于发生了OS的进程切换而导致的, 有了想法就可以快速验证一下

    systemtap脚本3

    vfs_write_latency_and_context_switch.ko

    global input_devname="sdb"
global vfs_write_latency

global fire
probe vfs.write {
        if (bytes_to_write > 0 && input_devname == devname) {
                fire[tid()] = 1
        }
}

probe vfs.write.return {
        if (fire[tid()] == 1) {
                delete fire[tid()]
                vfs_write_latency <<< gettimeofday_ns() - @entry(gettimeofday_ns())
        }
}

global t_switchout, switch_latency
probe scheduler.ctxswitch {
        if (fire[prev_tid] == 1) {
                t_switchout[prev_tid] = gettimeofday_ns()
        }
        if (fire[next_tid] == 1) {
                switch_latency <<< gettimeofday_ns() - t_switchout[next_tid]
        }
}

probe end {
        printf ("vfs write latency:
")
        print (@hist_log(vfs_write_latency))
        printf ("switch latency:
")
        print (@hist_log(switch_latency))
}

    运行3

    1> staprun -v vfs_write_latency_and_context_switch.ko 2>&1 | tee 23_systemtap_vfs_write_latency_and_context_switch
2> SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run

    结果3

    vfs write latency:
     value |-------------------------------------------------- count
       512 |                                                         0
      1024 |                                                         0
      2048 |@@@@@@@@@@@@@@                                      839729
      4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  2983472
      8192 |                                                     54172
     16384 |                                                     10870
     32768 |                                                       434
     65536 |                                                        35
    131072 |                                                         4
    262144 |                                                        40
    524288 |                                                         0
   1048576 |                                                         0
   2097152 |                                                       102
   4194304 |                                                       974
   8388608 |                                                        88
  16777216 |                                                         0
  33554432 |                                                         1
  67108864 |                                                         1
 134217728 |                                                         5
 268435456 |                                                         1
 536870912 |                                                         0
1073741824 |                                                         0

switch latency:
     value |-------------------------------------------------- count
       256 |                                                     0
       512 |                                                     0
      1024 |                                                     1
      2048 |                                                     8
      4096 |@                                                   25
      8192 |                                                    11
     16384 |                                                     5
     32768 |                                                     1
     65536 |                                                     0
    131072 |                                                     0
           ~
    524288 |                                                     0
   1048576 |                                                     0
   2097152 |@@@@@                                              116
   4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   964
   8388608 |@@@@                                                84
  16777216 |                                                     0
  33554432 |                                                     1
  67108864 |                                                     1
 134217728 |                                                     5
 268435456 |                                                     1
 536870912 |                                                     0
1073741824 |                                                     0

    可以看到: I/O延迟的第二峰值和OS进程切换相关.

    复盘

    现在复盘整个过程:

    1. Direct模式的顺序写性能大于随机写, 但非Direct模式的顺序写性能小于随机写.

    * 分析: 查找fsync系统调用
    * 结果: 调整sysbench参数--file-fsync-end=no
    2. 顺序写性能仍小于随机写
    * 分析2.1: 是否有部分异常I/O延迟拖慢了平均值
    * 结果2.1: 没有进展. 延迟存在两个峰
    * 分析2.2: 设备层的I/O请求特征
    * 结果2.2: 设备层的I/O请求特征无异常, 确定问题来自文件系统或IO调度
    * 分析2.3: 文件系统的缓存命中率
    * 结果2.3: 缓存命中率影响了性能, 通过调大测试文件大小可降低命中率差异, 顺序写性能大于随机写
    * 分析2.4: 文件系统的缓存延迟分析,
    * 结果2.4: Ext4的锁inode->i_mutex的影响, 顺序写受到的影响高于随机写
    3. 对延迟分布的第二个峰与OS进程切换有关

    性能分析经验

    1. 性能观测工具的准确性需要校准, 要怀疑其正确性.
    2. 注意其他程序对观测目标的影响
    3. systemtap 是强大的观测工具, 其性能开销低, 有许多现成的脚本供参考.
    4. 有一些结论的得出, 比如现象3, 不是依靠于逻辑分析, 而是猜测-验证得来, 这就要求对相关的技术有所了解.
    5. 之所以现象3不通过逻辑分析, 是因为没有找到恰当的观测手段和分析方法.

    IO测试经验

    IO测试时, 如果要对两个场景做性能对比, 要关注一下几个维度
    1. fsync的调用
    2. 文件系统的缓存命中率
    3. 文件系统的并发度
    4. OS上下文切换的频度

    这几个维度偏差不大, 才能进行性能对比.

    比较顺序写和随机写的性能, 要确定比较目的, 常识中”顺序写性能优于随机写”的结论, 可能适用于设备I/O, 但在文件系统上的某些场景下结论并不适用.

    注意

    所有的测试结果不能用于生产环境, 因为测试时间较短, 导致一些因素与生产环境不同, 比如文件系统缓存是预热状态而并不饱和. 得出的结论会有所偏颇, 此次试验只是展示一些分析方法.
  • 相关阅读:
    常用DOS命令
    uCGUI窗口重绘代码分析
    STM32的FSMC总线驱动ili9341，掉电重启无法正常显示的问题
    再次编译 arm toolchains
    GDB和GDB Server
    QT Creator 环境使用 remote debug 调试 arm 程序
    [转]一个简洁的 systemd 操作指南
    用 bottle.py 写了个简单的升级包上传
    批量 ping 测试脚本(IP 扫描)
    float 对整形的取余运算
  • 原文地址：https://www.cnblogs.com/zengkefu/p/5679307.html
Copyright © 2020-2023  润新知