1. 背景
在 Linux Block Driver - 1 中，我们实现了一个最简块设备驱动 Sampleblk。这个只有 200 多行源码的块设备驱动利用内存创建了标准的 Linux 磁盘。我们在基于 Linux 4.6.0 内核的环境下，加载该驱动，并在其上创建了 Ext4 文件系统。
本文将继续之前的实验，围绕 Sampleblk 探究 Linux 块设备驱动的运作机制。除非特别指明，本文中所有 Linux 内核源码引用都基于 4.6.0。其它内核版本可能会有较大差异。
2. 准备
首先，在阅读本文前，请按照 Linux Block Driver - 1中的步骤准备好实验环境。确保可以做到如下步骤，
- 编译和加载 Sampleblk Day1 驱动
- 用 Ext4 格式化 /dev/sampleblk1
- mount 文件系统到 /mnt
其次，为了继续后续实验，还需做如下准备工作。
安装 fio 测试软件。
fio 是目前非常流行的 IO 子系统测试工具。作者 Jens Axboe 是 Linux IO 子系统的 maintainer，目前就职于 Facebook。互联网上 FIO 安装和使用的文章很多，这里就不在赘述。不过最值得细读的还是 fio HOWTO。
安装 blktrace 工具。
也是 Jens Axboe 开发的 IO 子系统追踪和性能调优工具。发行版有安装包。关于该工具的使用可以参考 blktrace man page。
安装 Linux Perf 工具。
Perf 是 Linux 源码树自带工具，运行时动态追踪，性能分析的利器。也可以从发行版找到安装包。网上的 Perf 使用介绍很多。Perf Wiki 非常值得一看。下载 perf-tools 脚本。
perf-tools 脚本 是 Brendan Gregg 写的基于 ftrace 和 perf 的工具脚本。全部由 bash 和 awk 写成，无需安装，非常简单易用。Ftrace: The hidden light switch 这篇文章是 Brendan Gregg 给 LWN 的投稿，推荐阅读。
3. 实验与分析
3.1 文件顺序写测试
如一般 Linux 测试工具支持命令行参数外，fio 也支持 job file 的方式定义测试参数。本次实验中使用的 fs_seq_write_sync_001 job file 内容如下，
; -- start job file --
[global] ; global shared parameters
filename=/mnt/test ; location of file in file system
rw=write ; sequential write only, no read
ioengine=sync ; synchronized, write(2) system call
bs=,4k ; fio iounit size, write=4k, read and trim are default(4k)
iodepth=1 ; how many in-flight io unit
size=2M ; total size of file io in one job
loops=1000000 ; number of iterations of one job
[job1] ; job1 specific parameters
[job2] ; job2 specific parameters
; -- end job file --
本次实验将在 /dev/sampleblk1 上 mount 的 Ext4 文件系统上进行顺序 IO 写测试。其中 fio 将启动两个测试进程，同时对 /mnt/test 文件进行写操作。
$ sudo fio ./fs_seq_write_sync_001
job1: (g=0): rw=write, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
job2: (g=0): rw=write, bs=4K-4K/4K-4K/4K-4K, ioengine=sync, iodepth=1
fio-2.1.10
Starting 2 processes
^Cbs: 2 (f=2): [WW] [58.1% done] [0KB/2208MB/0KB /s] [0/565K/0 iops] [eta 13m:27s]
...[snipped]...
fio: terminating on signal 2
job1: (groupid=0, jobs=1): err= 0: pid=22977: Thu Jul 21 22:10:28 2016
write: io=1134.8GB, bw=1038.2MB/s, iops=265983, runt=1118309msec
clat (usec): min=0, max=66777, avg= 1.63, stdev=21.57
lat (usec): min=0, max=66777, avg= 1.68, stdev=21.89
clat percentiles (usec):
| 1.00th=[ 0], 5.00th=[ 1], 10.00th=[ 1], 20.00th=[ 1],
| 30.00th=[ 1], 40.00th=[ 1], 50.00th=[ 2], 60.00th=[ 2],
| 70.00th=[ 2], 80.00th=[ 2], 90.00th=[ 2], 95.00th=[ 3],
| 99.00th=[ 4], 99.50th=[ 7], 99.90th=[ 18], 99.95th=[ 25],
| 99.99th=[ 111]
lat (usec) : 2=49.79%, 4=49.08%, 10=0.71%, 20=0.34%, 50=0.06%
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
lat (msec) : 100=0.01%
cpu : usr=8.44%, sys=69.65%, ctx=1935732, majf=0, minf=9
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued : total=r=0/w=297451591/d=0, short=r=0/w=0/d=0
latency : target=0, window=0, percentile=100.00%, depth=1
job2: (groupid=0, jobs=1): err= 0: pid=22978: Thu Jul 21 22:10:28 2016
write: io=1137.4GB, bw=1041.5MB/s, iops=266597, runt=1118309msec
clat (usec): min=0, max=62132, avg= 1.63, stdev=21.35
lat (usec): min=0, max=62132, avg= 1.68, stdev=21.82
...[snipped]...
Run status group 0 (all jobs):
WRITE: io=2271.2GB, aggrb=2080.5MB/s, minb=1038.2MB/s, maxb=1041.5MB/s, mint=1118309msec, maxt=1118309msec
Disk stats (read/write):
sda: ios=0/4243062, merge=0/88, ticks=0/1233576, in_queue=1232723, util=37.65%
从 fio 的输出中可以看到 fio 启动了两个 job，并且按照 job file 规定的设置开始做文件系统写测试。在测试进行到 58.1% 的时候，我们中断程序，得到了上述的输出。从输出中我们得出如下结论，
- 两个线程总共的写的吞吐量为 2080.5MB/s，在磁盘上的 IPOS 是 4243062。
- 每个线程的平均完成延迟 (clat) 为 1.63us，方差是 21.57。
- 每个线程的平均总延迟 (lat) 为 1.68us，方差是 21.89。
- 磁盘 IO merge 很少，磁盘的利用率也只有 37.65%。
- 线程所在处理器的时间大部分在内核态：69.65%，用户态时间只有 8.44% 。
3.2 文件 IO Pattern 分析
3.2.1 使用 strace
首先，我们可以先了解一下 fio 测试在系统调用层面看的 IO pattern 是如何的。Linux 的 strace 工具是跟踪应用使用系统调用的常用工具。
在 fio 运行过程中，我们获得 fio 其中一个 job 的 pid 之后，运行了如下的 strace 命令，
$ sudo strace -ttt -T -e trace=desc -C -o ~/strace_fio_fs_seq_write_sync_001.log -p 94302
strace man page 给出了命令的详细用法，这里只对本小节里用到的各个选项做简单的说明，
-ttt打印出每个系统调用发生的起始时间戳。-T则给出了每个系统调用的开销。-e trace=desc只记录文件描述符相关系统调用。这样可过滤掉无关信息，因为本实验是文件顺序写测试。-C则在strace退出前可以给出被跟踪进程的系统调用在strace运行期间使用比例和次数的总结。-o则指定把strace的跟踪结果输出到文件中去。
3.2.2 分析 strace 日志
根据 strace 的跟踪日志，我们可对本次 fio 测试的 IO pattern 做一个简单的分析。详细日志信息请访问这里，下面只给出其中的关键部分，
1466326568.892873 open("/mnt/test", O_RDWR|O_CREAT, 0600) = 3 <0.000013>
1466326568.892904 fadvise64(3, 0, 2097152, POSIX_FADV_DONTNEED) = 0 <0.000813>
1466326568.893731 fadvise64(3, 0, 2097152, POSIX_FADV_SEQUENTIAL) = 0 <0.000004>
1466326568.893744 write(3, " 26035 32037 30035 34037 "..., 4096) = 4096 <0.000020>
[...snipped (512 write system calls)...]
1466326568.901551 write(3, " p27 32037 30033 34037 "..., 4096) = 4096 <0.000006>
1466326568.901566 close(3) = 0 <0.000008>
[...snipped (many iterations of open, fadvise64, write, close)...]
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
72.55 0.192610 2 84992 write
27.04 0.071788 216 332 fadvise64
0.28 0.000732 4 166 open
0.13 0.000355 2 166 close
------ ----------- ----------- --------- --------- ----------------
100.00 0.265485 85656 total
根据 strace 日志，我们就可以轻松分析这个 fio 测试的 IO Pattern 是如何的了，
首先调用
open在 Ext4 上以读写方式打开 /mnt/test 文件，若不存在则创建一个。因为 fio job file 指定了文件名，filename=/mnt/test
调用
fadvise64，使用POSIX_FADV_DONTNEED把 /mnt/test 在 page cache 里的数据 flush 到磁盘。fio 做文件 IO 前，清除 /mnt/test 文件的 page cache，可以让测试避免受到 page cache 影响。
调用
fadvise64，使用POSIX_FADV_SEQUENTIAL提示内核应用要对 /mnt/test 做顺序 IO 操作。这是因为 fio job file 定义了 rw=write，因此这是顺序写测试。
调用
write对 /mnt/test 写入 4K 大小的数据。一共 write 512 次，共 2M 数据。这是因为 fio job file 定义了 ioengine=sync，bs=,4k，size=2M。
最后，调用
close完成一次 /mnt/test 顺序写测试。重复上述过程，反复迭代。fio job file 定义了 loops=1000000
另外，根据 strace 日志的系统调用时间和调用次数的总结，我们可以得出如下结论，
- 系统调用
open，write和close的开销非常小，只有几微秒。 - 测试中
write调用次数最多，虽然单次write只有几微妙，但积累总时间最高。 - 测试中
fadvise64调用次数比write少，但POSIX_FADV_DONTNEED带来的 flush page cache 的操作可以达到几百微秒。
3.2.3 使用 SystemTap
使用 strace 虽然可以拿到单次系统调用读写的字节数，但对大量的 IO 请求来说，不经过额外的脚本处理，很难得到一个总体的认识和分析。但是，我们可以通过编写 SystemTap 脚本来对这个测试的 IO 请求大小做一个宏观的统计，并且使用直方图来直观的呈现这个测试的文件 IO 尺寸分布。
启动 fio 测试后，只需要运行如下命令，即可收集到指定 PID 的文件 IO 的统计信息，
$ sudo ./fiohist.stp 94302
starting probe
^C
IO Summary:
read read write write
name open read KB tot B avg write KB tot B avg
fio 7917 0 0 0 3698312 14793248 4096
Write I/O size (bytes):
process name: fio
value |-------------------------------------------------- count
1024 | 0
2048 | 0
4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3698312
8192 | 0
16384 | 0
可以看到，直方图和统计数据显示，整个跟踪数据收集期间都是 4K 字节的 write 写操作，而没有任何读操作。而且，在此期间，没有任何 read IO 操作。同时，由于 write 系统调用参数并不提供文件内的偏移量，所以我们无法得知文件的写操作是否是随机还是顺序的。
但是，如果是文件的随机读写 IO，应该可以在 strace 时观测到 lseek + read 或 write 调用。这也从侧面可以推测测试是顺序写 IO。此外，pread 和 pwrite 系统调用提供了文件内的偏移量，有这个偏移量的数据，即可根据时间轴画出 IO 文件内偏移的 Heatmap。
通过该图，即可直观地判断是否是随机还是顺序 IO 了。
本例中的 SystemTap 脚本 fiohist.stp 是作者个人为分析本测试所编写。详细代码请参考文中给出的源码链接。此外，在 Linux Perf Tools Tips 这篇文章里收录了关于在自编译内核上运行 SystemTap 脚本的一些常见问题。
3.2.4 延迟统计
fio 的测试结果已经提供了详尽的 IO 延迟数据。因为 fs_seq_write_sync_001 文件定义的是文件 buffer IO，并且是同步写模式。因此，fio 报告的延迟数据就是在文件 IO 层面上的，我们不需要使用其它的工具了。
查看 fio 源码，可以发现，它记录了一次 IO 流程的三个时间，
起始时间 (io_u->start_time) >>>>>> 触发时间 (io_u->issue_time) >>>>>> 完成时间 (icd->time)
其具体含义分别如下，
起始时间
在文件打开的状态下，是读写入文件的缓冲区准备好后的时间。源代码定义：io_u->start_time。
触发时间
同步 IO 时，是读写系统调用发起前的时间。异步 IO 时，是 IO 请求成功放入请求队列后 (td->io_ops->queue) 返回的时间。源代码定义：io_u->issue_time。
完成时间
是 IO 完成时的时间。源代码定义：icd->time。
而在 fio 输出里，则存在三种类型的延迟数据，分别为如下含义，
slat (submission latency)
即 IO 提交延迟。其确切含义是 IO 准备好到 IO 真正开始的时间 (即 io_u->issue_time － io_u->start_time)。需要注意的是，在同步 (SYNC) IO 模式下，slat 并不计算，这是因为同步 IO 的这两个时间非常接近，没有计算意义。
clat (completion latency)
即 IO 完成延迟。其确切含义是 IO 真正开始到 IO 返回的时间 (即 icd->time - io_u->issue_time)。
lat (latency)
即 IO 总延迟，其确切含义是 IO 准备好到 IO 返回的总时间 （即 icd->time - io_u->issue_time)。
有了以上概念，再解读下面的数据就很简单了。
例如，本测试里完成延迟 clat (completion latency) 的结果如下，其中包含了均值 (avg) 和方差 (stdev)，
clat (usec): min=0, max=66777, avg= 1.63, stdev=21.57
而总延迟 lat (latency) 结果如下，
lat (usec): min=0, max=66777, avg= 1.68, stdev=21.89
其中，clat percentiles 给出了各种 IO 完成延迟的百分比分布，
clat percentiles (usec):
| 1.00th=[ 0], 5.00th=[ 1], 10.00th=[ 1], 20.00th=[ 1],
| 30.00th=[ 1], 40.00th=[ 1], 50.00th=[ 2], 60.00th=[ 2],
| 70.00th=[ 2], 80.00th=[ 2], 90.00th=[ 2], 95.00th=[ 3],
| 99.00th=[ 4], 99.50th=[ 7], 99.90th=[ 18], 99.95th=[ 25],
| 99.99th=[ 111]
而总 IO 延迟的百分比分布也包括在输出了，
lat (usec) : 2=49.79%, 4=49.08%, 10=0.71%, 20=0.34%, 50=0.06%
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
lat (msec) : 100=0.01%
3.3 On CPU Time 分析
运行 fio 测试期间，我们可以利用 Linux perf， 对系统做 ON CPU Time 分析。这样可以进一步获取如下信息，
在测试中，软件栈的哪一部分消耗了主要的 CPU 资源。可以帮助我们确定 CPU 时间优化的主要方向。
通过查看消耗 CPU 资源的软件调用栈，了解函数调用关系。
利用可视化工具，如 Flamgraph，对 Profiling 的大量数据做直观的呈现。方便进一步分析和定位问题。
3.3.1 使用 perf
首先，当 fio 测试进入稳定状态，运行 perf record 命令，
# perf record -a -g --call-graph dwarf -F 997 sleep 60
其中主要的命令行选项如下，
-F选项指定perf以997次每秒的频率对 CPU 上运行的用户进程或者内核上下文进行采样 (Sampling)。由于 Linux 内核的时钟中断是以
1000次每秒的频率周期触发，所以按照997频率采样可以避免每次采样都采样到始终中断相关的处理，减少干扰。-a选项指定采样系统中所有的 CPU。-g选项指定记录下用户进程或者内核的调用栈。其中，
--call-graph dwarf指定调用栈收集的方式为dwarf，即libdwarf和libdunwind的方式。Perf 还支持fp和lbs方式。sleep 60则是通过perf指定运行的命令，这个命令起到了让perf运行 60 秒然后退出的效果。
在 perf record 之后，运行 perf report 查看采样结果的汇总，
# sudo perf report --stdio
[...snipped...]
27.51% 0.10% fio [kernel.kallsyms] [k] __generic_file_write_iter
|
---__generic_file_write_iter
|
|--99.95%-- ext4_file_write_iter
| __vfs_write
| vfs_write
| sys_write
| do_syscall_64
| return_from_SYSCALL_64
| 0x7ff91cd381cd
| fio_syncio_queue
| td_io_queue
| thread_main
| run_threads
--0.05%-- [...]
[...snipped...]
3.3.2 使用 Flamegraph
使用 Flamegraph，可以把前面产生的 perf record 的结果可视化，生成火焰图。
运行如下命令，
# perf script | stackcollapse-perf.pl > out.perf-folded
# cat out.perf-folded | flamegraph.pl > flamegraph_on_cpu_perf_fs_seq_write_sync_001.svg
然后，即可生成如下火焰图，
该火焰图是 SVG 格式的矢量图，基于 XML 文件定义。在浏览器里右击在新窗口打开图片，即可进入与火焰图的交互模式。该模式下，统计数据信息和缩放功能都可以移动和点击鼠标来完成交互。通过在交互模式下浏览和缩放火焰图，我们可以得出如下结论，
perf record共有 119644 个采样数据，将此定义为 100% CPU 时间。fio进程共有 91079 个采样数据，占用 76.13% 的 CPU 时间。fio的fio_syncio_queue用掉了 48.53% 的 CPU，其中绝大部分时间在内核态，sys_write系统调用就消耗了 45.78%。fio的file_invalidate_cache函数占用了 20.88% 的 CPU，其中大部分都在内核态，sys_fadvise64系统调用消耗了 20.81%。在这里我们注意到，
sys_write和sys_fadvise64系统调用 CPU 占用资源的比例是 2:1。而之前strace得出的两个系统调用消耗时间的比例是 3:1。这就意味着，sys_write花费了很多时间在睡眠态。在 Ext4 文件系统的写路径，存在热点锁。
ext4_file_write_iter函数里的 inode mutex 的 mutex 自旋等待时间，占用了 16.93% 的 CPU。与sys_write系统调用相比，CPU 消耗占比达到三分之一强。swapper为内核上下文，包含如下部分，native_safe_halt代表 CPU 处于 IDEL 状态，共有两次，9.04% 和 9.18%。smp_reschedule_interrupt代表 CPU 处理调度器的 IPI 中断，用于处理器间调度的负载均衡。共有两次，1.66％ 和 1.61%。这部分需要方大矢量图移动鼠标到相关函数才能看到。kblockd工作队列线程。由
block_run_queue_async触发，最终调用__blk_run_queue把 IO 发送到下层的 sampleblk 块驱动。共有两部份，合计 0.88%。rcu_gp_kthread处理 RCU 的内核线程，占用 0.04 % 的 CPU 时间。
综合以上分析，我们可以看到，火焰图不但可以帮助我们理解 CPU 全局资源的占用情况，而且还能进一步分析到微观和细节。例如局部的热锁，父子函数的调用关系，和所占 CPU 时间比例。
关于进一步的 Flamegraph 的介绍和资料，请参考 Brenden Gregg 的 Flamegraph 相关资源。
4. 小结
本文通过使用 Linux 下的各种追踪工具 Strace，Systemtap，Perf，Ftrace，来分析 fio 测试的运行情况。实际上，利用 Linux 下的动态追踪工具我们达到了以下目的，
- 掌握了本文中 fio 测试的主要特征，文件 IO size，IO 时间分布。这是性能分析里 workload analysis 方法的一部分。
- 了解了 fio 测试 On CPU 时间的分析方法。这是性能分析里 resource analysis 方法的一部分。
关于 Linux 动态追踪工具的更多信息，请参考延伸阅读章节里的链接。