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, "\0\260\35\0\0\0\0\0\0\320\37\0\0\0\0\0\0\300\35\0\0\0\0\0\0\340\37\0\0\0\0\0"..., 4096) = 4096 <0.000020>
[...snipped (512 write system calls)...]
1466326568.901551 write(3, "\0p\27\0\0\0\0\0\0\320\37\0\0\0\0\0\0\300\33\0\0\0\0\0\0\340\37\0\0\0\0\0"..., 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 时间比例。
4. 小结
本文通过使用 Linux 下的各种追踪工具 Strace，Systemtap，Perf，Ftrace，来分析 fio 测试的运行情况。实际上，利用 Linux 下的动态追踪工具我们达到了以下目的，
- 掌握了本文中 fio 测试的主要特征，文件 IO size，IO 时间分布。这是性能分析里 workload analysis 方法的一部分。
- 了解了 fio 测试 On CPU 时间的分析方法。这是性能分析里 resource analysis 方法的一部分。
关于 Linux 动态追踪工具的更多信息，请参考延伸阅读章节里的链接。
