近期在一些简单的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\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: 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\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_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\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_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_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_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_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_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\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_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_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_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\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_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地址来确认), 也就是说:
- 顺序写的压力集中在写一个文件, 因此在
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_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:\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_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进程切换相关.
复盘
现在复盘整个过程:
- 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进程切换有关
性能分析经验
- 性能观测工具的准确性需要校准, 要怀疑其正确性.
- 注意其他程序对观测目标的影响
systemtap是强大的观测工具, 其性能开销低, 有许多现成的脚本供参考.- 有一些结论的得出, 比如现象3, 不是依靠于逻辑分析, 而是猜测-验证得来, 这就要求对相关的技术有所了解.
- 之所以现象3不通过逻辑分析, 是因为没有找到恰当的观测手段和分析方法.
IO测试经验
IO测试时, 如果要对两个场景做性能对比, 要关注一下几个维度
1. fsync的调用
2. 文件系统的缓存命中率
3. 文件系统的并发度
4. OS上下文切换的频度
这几个维度偏差不大, 才能进行性能对比.
比较顺序写和随机写的性能, 要确定比较目的, 常识中”顺序写性能优于随机写”的结论, 可能适用于设备I/O, 但在文件系统上的某些场景下结论并不适用.
注意
所有的测试结果不能用于生产环境, 因为测试时间较短, 导致一些因素与生产环境不同, 比如文件系统缓存是预热状态而并不饱和. 得出的结论会有所偏颇, 此次试验只是展示一些分析方法.
