http://www.actionsky.com/docs/archives/171
近期在一些简单的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=16GSYSBENCH_FILE_NUM=16SYSBENCH_NUM_THREADS=16DIRECT=FSYNC=offSYSBENCH_BLOCK_SIZE=4096SYSBENCH_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=4096sudo 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 runsysbench 0.4.12: multi-threaded system evaluation benchmarkRunning the test with following options:Number of threads: 16Extra file open flags: 016 files, 1Gb each16Gb total file sizeBlock size 4KbCalling fsync() at the end of test, Enabled.Using synchronous I/O modeDoing sequential rewrite testThreads started!Time limit exceeded, exiting...(last message repeated 15 times)Done.Operations performed: 0 Read, 4194304 Write, 16 Other = 4194320 TotalRead 0b Written 16Gb Total transferred 16Gb (151.62Mb/sec)38815.28 Requests/sec executedTest 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.08msThreads 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相关.
--file-fsync-end=no2. 在测试中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 提供了极低成本的内核检测能力, 类似于Dtrace, 详细的介绍请找官方文档.
以检测fsync调用为例演示systemtap的用法:
1.环境准备请找官方文档
2.编辑systemtap脚本 6_systemtap_fsync_summary.stp!/usr/bin/env stapglobal rprobe syscall.fsync { r[pid()] <<< 1}probe end { foreach ([pid-] in r) { printf ("pid=%d, fsync=%d times\n", 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: 016 files, 1Gb each16Gb total file sizeBlock size 4KbCalling 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栈比较陌生, 可以查看 做初步了解.
由于对”顺序写的效率低于随机写”这一现象没有任何想法, 就先测量一下端到端的延迟分布, 即站在vfs层的角度看延迟分布.
期望是能判断延迟是否平均, 是否由于个别I/O的异常拖慢了整体水平.
还是用到了systemtap脚本, 此处略去编译过程, 直接给出脚本和结果
systemtap脚本2.1
vfs_write_latency.stp
global input_devname="sdb"global io_latencyprobe 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_seqrewr2> 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_rndwr2> 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 | 01152921504606846976 | 12305843009213693952 | 04611686018427387904 | 0WARNING: 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 | 01152921504606846976 | 12305843009213693952 | 04611686018427387904 | 0WARNING: 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 latencyprobe 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\n", 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_seqrewr2> 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_rndwr2> SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run
结果2.2
1.测试顺序写 (结果经过缩减)
rw: 1, io_size: 262144, count: 15056, avg_latency: 1046246rw: 1, io_size: 258048, count: 5, avg_latency: 22840rw: 1, io_size: 253952, count: 17, avg_latency: 7728...rw: 1, io_size: 8192, count: 17, avg_latency: 3035934rw: 96, io_size: 4096, count: 37, avg_latency: 20610rw: 13329, io_size: 4096, count: 6, avg_latency: 13378rw: 1041, io_size: 4096, count: 98, avg_latency: 2165rw: 1, io_size: 4096, count: 6, avg_latency: 1706rw: 97, io_size: 4096, count: 4, avg_latency: 1252rw: 16384, io_size: 4096, count: 2, avg_latency: 14562
2.测试随机写 (结果经过缩减)
rw: 1, io_size: 172032, count: 1, avg_latency: 3689rw: 1, io_size: 163840, count: 1, avg_latency: 3061rw: 1, io_size: 159744, count: 1, avg_latency: 4617...rw: 1, io_size: 8192, count: 46334, avg_latency: 200684rw: 1, io_size: 4096, count: 73103, avg_latency: 173626rw: 0, io_size: 4096, count: 6, avg_latency: 3032rw: 96, io_size: 4096, count: 29, avg_latency: 6783rw: 1041, io_size: 4096, count: 249, avg_latency: 4029rw: 13329, io_size: 4096, count: 9, avg_latency: 25033rw: 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 – 文件系统的缓存命中率
想到问题可能在文件系统, 那可能性比较大的是缓存系统的命中率. 顺序写的缓存命中率较低, 随机写的缓存命中率较高, 即几个发往文件系统的随机写请求可能写的是同一个数据块. 猜测随机写 在文件系统缓存的代价较小, 因此性能较好.
下面验证文件系统的缓存命中率. 可以参考. 不过此处由于只需要对比趋势而不需要保证绝对值正确, 所以可以简化实现.
systemtap脚本2.3.1
global hit_add_to_page_cache_lru, hit_pagecache_get_pageglobal 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\n", @count(hit_add_to_page_cache_lru)) printf ("pagecache_get_page: %d\n", @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_seqrewr2> 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_rndwr2> SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run
结果2.3.1
| 函数命中 | add_to_page_cache_lru | pagecache_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_seqrewr2> 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_rndwr2> SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run
结果2.3.2
| 函数命中 & 性能 | add_to_page_cache_lru | pagecache_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_iterprobe 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_iterprobe 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\n", @avg(latency_ext4_file_write_iter)) printf ("__generic_file_write_iter latency: %d\n", @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_seqrewr2> 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_rndwr2> SYSBENCH_FILE_TOTAL_SIZE=64G SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run
结果2.4.1
| 函数延迟 | __generic_file_write_iter | ext4_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_text4_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_concurrencyprobe 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\n", @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_seqrewr2> 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_rndwr2> 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地址来确认), 也就是说:
- 顺序写的压力集中在写一个文件, 因此在
inode的锁上产生了竞争 - 随机写的压力比较分散, 因此
__generic_file_write_iter的并发度高 - 顺序写的最大并发度为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_latencyglobal fireprobe 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_latencyprobe 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:\n") print (@hist_log(vfs_write_latency)) printf ("switch latency:\n") 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_switch2> 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 | 01073741824 | 0switch 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 | 01073741824 | 0
可以看到: I/O延迟的第二峰值和OS进程切换相关.
复盘
现在复盘整个过程:
- Direct模式的顺序写性能大于随机写, 但非Direct模式的顺序写性能小于随机写.
* 分析: 查找fsync系统调用
--file-fsync-end=no2. 顺序写性能仍小于随机写* 分析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进程切换有关 性能分析经验
- 性能观测工具的准确性需要校准, 要怀疑其正确性.
- 注意其他程序对观测目标的影响
systemtap是强大的观测工具, 其性能开销低, 有许多现成的脚本供参考.- 有一些结论的得出, 比如现象3, 不是依靠于逻辑分析, 而是猜测-验证得来, 这就要求对相关的技术有所了解.
- 之所以现象3不通过逻辑分析, 是因为没有找到恰当的观测手段和分析方法.
IO测试经验
IO测试时, 如果要对两个场景做性能对比, 要关注一下几个维度
1.fsync的调用2. 文件系统的缓存命中率3. 文件系统的并发度4. OS上下文切换的频度 这几个维度偏差不大, 才能进行性能对比.
比较顺序写和随机写的性能, 要确定比较目的, 常识中”顺序写性能优于随机写”的结论, 可能适用于设备I/O, 但在文件系统上的某些场景下结论并不适用.
注意
所有的测试结果不能用于生产环境, 因为测试时间较短, 导致一些因素与生产环境不同, 比如文件系统缓存是预热状态而并不饱和. 得出的结论会有所偏颇, 此次试验只是展示一些分析方法.