测试环境准备
- 运行前，通过echo 1 > /proc/sys/vm/drop_caches清理IO cache
- 运行前，通过iostat -x -p {dev} 1确认没有其它IO影响结果
- sysbench参数
<code>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/<code>
其中的变量参数
<code>binlog 异常暴涨分析SYSBENCH_FILE_TOTAL_SIZE=16G SYSBENCH_FILE_NUM=16 SYSBENCH_NUM_THREADS=16 DIRECT= FSYNC=off SYSBENCH_BLOCK_SIZE=4096 SYSBENCH_TIME=60/<code>
附件中的run_sysbench.sh是运行sysbench的脚本，每个实验的输出都附在附件中，样例输出：
现象1
步骤1
1.非Direct I/O模式，测试顺序写
<code>./run_sysbench.sh seqrewr run | tee 1_sysbench_seqrewr/<code>
2.非Direct I/O模式测试随机写
<code>./run_sysbench.sh rndwr run | tee 2_sysbench_rndwr/<code>
3.Direct I/O模式，测试顺序写(seqrewr)
<code>DIRECT=1 ./run_sysbench.sh seqrewr run | tee 3_sysbench_direct_seqrewr/<code>
4.Direct I/O模式，测试随机写(rndwr)
<code>DIRECT=1 ./run_sysbench.sh rndwr run | tee 4_sysbench_direct_rndwr/<code>
结果1
对于磁盘的I/O测试，直觉上顺序写比随机写要快很多。从测试结果可以看到：
- 在Direct I/O模式下，与直觉结果相符
- 在非Direct I/O模式下，随机写比顺序写IOPS快4倍, 吞吐与IOPS成正比。这一点是违反直觉的
对结果的分析将集中在非Direct I/O模式下。
分析1
我们一时间对上述结果没有任何头绪，也不大可能是意外发明了随机写更快的磁盘. 先尝试观察对磁盘的IO压力分布：
<code>iostat -x -p /dev/sdb 1/<code>
观察到在sysbench结束后，顺序写的I/O压力为0，但随机写的I/O压力仍将持续一些时间。随即怀疑sysbench在顺序写时用fsync进行刷盘，并等待刷盘结束。在等待期间没有sysbench不发出新的IO请求，自然IOPS会降低。但sysbench参数中已经设置了--file-fsync-all=off，与现象冲突。
用strace确认这一结论：
<code>strace -e trace=fsync -f ./run_sysbench.sh seqrewr run 2>&1 | tee 5_strace_sysbench_seqrewr/<code>
可以看到显式的fsync调用。
在sysbench源码中可以找到与FILE_OP_TYPE_FSYNC相关的一段代码：
<code> 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++;
}/<code>意味着这个fsync与sysbench参数file-fsync-end相关。解决方案：1. 设置--file-fsync-end=no2. 在测试中sysbench顺序写 写完所有文件的时间--max-time, 避免多出的fsync
之后的测试中, 将置--file-fsync-end=no, 并将--max-time设为30, 避免fsync, 且减少测试时间成本。
插曲1
在分析的过程中，实际过程要比上述描述艰辛一些。
观测工具使用不当带来测试偏差。
用strace确定是否有fsync调用时，最初用的命令是：
<code>strace -f ./run_sysbench.sh seqrewr run 2>&1 | tee 5_strace_sysbench_seqrewr/<code>
由于缺少了-e trace=fsync参数，strace的成本上升，导致sysbench的性能下降，使得写完所有文件的时间>--max-time，就没有发现fsync调用。
这一结果与预期不符，一时陷入僵局。绕了一圈后怀疑和观测工具相关，虽没有定位到是因为观测工具引起的性能下降，但可以尝试用另一个观测工具来校准偏差。在此选定的工具是systemtap。
使用另一观测工具用于校准 — systemtap
Systemtap 提供了极低成本的内核检测能力，类似于Dtrace，详细的介绍请找官方文档。
以检测fsync调用为例演示systemtap的用法：
- 环境准备请找官方文档
- 编辑systemtap脚本 6_systemtap_fsync_summary.stp
<code>!/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]))
}
}/<code>3.编译
<code>stap -v -r $(uname -r) -DMAXSKIPPED=100000 -DSTP_NO_OVERLOAD 6_systemtap_fsync_summary.stp -m 6_systemtap_fsync_summary.ko/<code>
systemtap在观测负荷会显式影响系统性能时，会”跳过”一些观测点，这样不会影响系统性能，可以安全地使用，但会造成结果不准确。-DMAXSKIPPED=100000 -DSTP_NO_OVERLOAD 这两个参数能systemtap尽量”不计成本”地观测，但需要警惕其带来的开销。后续编译中默认会使用这两个参数，但所有结果需要和不使用参数的情况进行对比，来发现并规避其影响。本文不记述对比的过程。
4.使用
<code>staprun -v fsync_summary.ko | tee 6_systemtap_fsync_summary/<code>
输出如下：
<code>pid=34888, fsync=16 times/<code>
可以看到16个fsync调用，与sysbench配置的线程数一致。即证明之前不当使用strace造成了观测结果的偏差。
5.说明systemtap可以一键运行脚本，但我们用了编译+运行两个步骤，原因是systemtap的编译环境配置比较繁复，因此我们将编译环境隔离到了一个容器中，而将编译好的.ko文件放到目标机上运行，目标机只需安装简单的依赖就可以运行。避免环境污染。
复盘1
回头重看现象1的分析过程, 有几点教训：1.其实sysbench的标准输出已经给出了问题原因：
<code>... 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 .../<code>
Calling fsync() at the end of test, Enabled.，藏在一堆数字中信息容易被忽略
2.对观测工具要进行校准
现象2
步骤2
根据现象1的分析，调整sysbench参数：置--file-fsync-end=no，并将--max-time设为30。重新运行非Direct IO模式的顺序写和随机写的测试。
1.测试顺序写
<code>SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh seqrewr run | tee 7_sysbench_seqrewr/<code>
2.测试随机写
<code>SYSBENCH_TIME=30 FIX_FSYNC_END=1 ./run_sysbench.sh rndwr run | tee 8_sysbench_rndwr/<code>
结果2
比之前的结果好一些，但观察仍到两个异常现象：
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
<code>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))
}/<code>运行2.1
1.测试顺序写
<code>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/<code>
2.测试随机写
<code>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/<code>
结果2.1
1.顺序写
2.随机写
可以看到：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
运行2.2
1.测试顺序写
<code>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/<code>
2.测试随机写
<code>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/<code>
结果2.2
- 测试顺序写 (结果经过缩减)
- 测试随机写 (结果经过缩减)rw是读写模式，io_size是设备I/O的大小，count是次数，avg_latency是平均延迟。
可以看到:
- 顺序写的设备I/O的大小集中在大于4k的区域，即在之前经过了合并。随机写的设备I/O的大小几种在4k，即没有经过合并. 符合预期
- 从延迟上没有发现明显的差异
可以得到的结论是：顺序写和随机写的反常的性能差异很大程度来自于文件系统和IO调度。
分析2.3 – 文件系统的缓存命中率
想到问题可能在文件系统，那可能性比较大的是缓存系统的命中率。顺序写的缓存命中率较低，随机写的缓存命中率较高，即几个发往文件系统的随机写请求可能写的是同一个数据块。猜测随机写在文件系统缓存的代价较小，因此性能较好。
下面验证文件系统的缓存命中率。可以参考Brendan Gregg神的cachestat。不过此处由于只需要对比趋势而不需要保证绝对值正确，所以可以简化实现。
systemtap脚本2.3.1
运行2.3.1
1.测试顺序写
<code>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/<code>
2.测试随机写
<code>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/<code>
结果2.3.1
可以看到, 随机写的缓存命中率(1-add_to_page_cache_lru/pagecache_get_page)比顺序写要高。之后的测试，我们增大sysbench文件的总大小到64G，来降低随机写的缓存命中率。
运行2.3.2
1.测试顺序写
<code>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/<code>
2.测试随机写
<code>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/<code>
结果2.3.2
可以看到，随着测试文件增大，随机写的缓存命中率下降，性能也随之下降。写缓存的命中率是随机写和顺序写性能差异的影响因素之一。
分析2.4 – 文件系统的缓存延迟分析
分析2.3的结果是随机写和顺序写的性能差不多，但我们仍可以进一步分析缓存的延时：找一个使用缓存的堆栈，逐层做延迟分析，这是个笨拙但有效的方法。
Systemtap本身提供了大量脚本，其中就有一些成熟的函数入口可以直接借用，而不用自己读Linux源码分析backtrace，比如对于缓存，找到/usr/share/systemtap/tapset/linux/vfs.stp文件，搜一下cache，就可以找到以下入口点：
<code>probe vfs.add_to_page_cache =
kernel.function("add_to_page_cache_locked") !,
kernel.function("add_to_page_cache")
{
...
}/<code>之后可以通过systemtap打印出add_to_page_cache的调用栈 (在3.19内核中, 实际使用了add_to_page_cache_lru，这个需要查看源码才能知道此处的变更)，此处不详述，结果如下：
然后观测这个堆栈中每个函数的延迟，这个过程中需要特别注意如果观测点过多，那么对性能结果会有较大影响，以致影响分析的结论。因此每一次观测后需要对比观测前后的性能差别，如果差异过大，应调整观测手段或减小观测的范围。
在此我们就假设运气很好，一次观测就能命中要害。
systemtap脚本2.4.1
ext4_write_latency.stp
<code>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))
}/<code>运行2.4.1
1.测试顺序写
<code>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/<code>
2.测试随机写
<code>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/<code>
结果2.4.1
可以看到：1. 顺序写与随机写相比，__generic_file_write_iter的开销明显减小，符合常识2. 顺序写与随机写相比，ext4_file_write_iter在其他方面的开销占比明显增加
分析2.4.1
从结果1得到结论：ext4_file_write_iter在其他方面的开销占比明显增加。至于哪个方面的开销增加了，得粗看一下源码(源码已将不重要的部分略去)：
<code>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;
}/<code>源码已将分支内的部分略去，只留下主干。可以看到：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的代价。
<code>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))
}/<code>运行2.4.2
1.测试顺序写
<code>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/<code>
2.测试随机写
<code>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/<code>
结果2.4.2
可以看到，锁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.测试顺序写
<code>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/<code>
2.测试随机写
<code>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/<code>
结果2.4.3
可以看到，在相对公平的测试条件下，顺序写比随机写的性能更好一些。
现象3
在结果2.1中还遗留了一个问题：在研究延迟分布时出现了两个峰。在之前的试验中，如果将一些函数的延迟分布打印出来，也能观察到两个峰。这些函数并不集中在某一个逻辑路径上，比较分散。因此可能是一个共有的机制导致第二个峰的出现，而不是某个逻辑分支导致。
另外可以尝试用systemtap脚本进行分析，但几经尝试，第二个峰的出现并不规律。
偶尔想到这是否由于发生了OS的进程切换而导致的，有了想法就可以快速验证一下。
systemtap脚本3
vfs_write_latency_and_context_switch.ko
<code>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))
}/<code>运行3
<code>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/<code>
结果3
可以看到：I/O延迟的第二峰值和OS进程切换相关。
复盘
现在复盘整个过程：
1.Direct模式的顺序写性能大于随机写，但非Direct模式的顺序写性能小于随机写
* 分析：查找fsync系统调用* 结果：调整sysbench参数--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测试时，如果要对两个场景做性能对比，要关注一下几个维度
- fsync的调用
- 文件系统的缓存命中率
- 文件系统的并发度
- OS上下文切换的频度
这几个维度偏差不大, 才能进行性能对比.
比较顺序写和随机写的性能，要确定比较目的，常识中”顺序写性能优于随机写”的结论，可能适用于设备I/O，但在文件系统上的某些场景下结论并不适用。
注意
所有的测试结果不能用于生产环境，因为测试时间较短，导致一些因素与生产环境不同，比如文件系统缓存是预热状态而并不饱和。得出的结论会有所偏颇，此次试验只是展示一些分析方法。
