在前面的文章中，我提到了我们会用 ftrace 来解决问题，在开始之前，我先聊聊外面大牛们是如何用 ftrace 来解决问题的，第一个例子，显而易见，就是 Brendan Gregg 的。在 Ftrace: The hidden ligh switch 这篇文章中，Gregg 写到他是如何用基于 ftrace 定制的工具 perf tools 来解决一个问题的，这里，我并不准备完全翻译这篇文章，主要是会说说，他解决问题的时候步骤，用到的相关工具，以及详细说明下这些工具是如何实现的。
首先来说说他遇到的问题，在 Netflix 里面，他们升级了一次 Ubuntu 的系统，然后就发现 Cassandra 数据库的 I/O 使用量急剧膨胀，I/O 使用膨胀有很多原因，譬如缓存缺失，record 的大小膨胀，readahead 膨胀等，但到底是哪一个呢？
iosnoop
首先，Gregg 使用 iosnoop 工具进行检查，iosnoop 用来跟踪 I/O 的详细信息，当然也包括 latency，结果如下：
# ./iosnoop -ts
STARTs ENDs COMM PID TYPE DEV BLOCK BYTES LATms
13370264.614265 13370264.614844 java 8248 R 202,32 1431244248 45056 0.58
13370264.614269 13370264.614852 java 8248 R 202,32 1431244336 45056 0.58
13370264.614271 13370264.614857 java 8248 R 202,32 1431244424 45056 0.59
13370264.614273 13370264.614868 java 8248 R 202,32 1431244512 45056 0.59
[...]
# ./iosnoop -Qts
STARTs ENDs COMM PID TYPE DEV BLOCK BYTES LATms
13370410.927331 13370410.931182 java 8248 R 202,32 1596381840 45056 3.85
13370410.927332 13370410.931200 java 8248 R 202,32 1596381928 45056 3.87
13370410.927332 13370410.931215 java 8248 R 202,32 1596382016 45056 3.88
13370410.927332 13370410.931226 java 8248 R 202,32 1596382104 45056 3.89
[...]
上面看不出来啥，一个繁忙的 I/O，势必会带来高的 latency。我们来说说 iosnoop 是如何做的。
iosnoop 主要是处理的 block 相关的 event，主要是：
-
block:block_rq_issue- I/O 发起的时候的事件 -
block:block_rq_complete- I/O 完成事件 -
block:block_rq_insert- I/O 加入队列的时间
如果使用了 -Q 参数，我们对于 I/O 开始事件就用 block:block_rq_insert，否则就用的 block:block_rq_issue 。下面是我用 FIO 测试 trace 的输出：
fio-30749 [036] 5651360.257707: block_rq_issue: 8,0 WS 4096 () 1367650688 + 8 [fio]
<idle>-0 [036] 5651360.257768: block_rq_complete: 8,0 WS () 1367650688 + 8 [0]
我们根据 1367650688 + 8 能找到对应的 I/O block sector，然后根据 issue 和 complete 的时间就能知道 latency 了。
tpoint
为了更好的定位 I/O 问题，Gregg 使用 tpoint 来追踪 block_rq_insert，如下：
# ./tpoint -H block:block_rq_insert
Tracing block:block_rq_insert. Ctrl-C to end.
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
java-16035 [000] 13371565.253582: block_rq_insert: 202,16 WS 0 () 550505336 + 88 [java]
java-16035 [000] 13371565.253582: block_rq_insert: 202,16 WS 0 () 550505424 + 56 [java]
java-8248 [007] 13371565.278372: block_rq_insert: 202,32 R 0 () 660621368 + 88 [java]
java-8248 [007] 13371565.278373: block_rq_insert: 202,32 R 0 () 660621456 + 88 [java]
java-8248 [007] 13371565.278374: block_rq_insert: 202,32 R 0 () 660621544 + 24 [java]
java-8249 [007] 13371565.311507: block_rq_insert: 202,32 R 0 () 660666416 + 88 [java]
[...]
然后也跟踪了实际的堆栈:
# ./tpoint -s block:block_rq_insert 'rwbs ~ "*R*"' | head -1000
Tracing block:block_rq_insert. Ctrl-C to end.
java-8248 [005] 13370789.973826: block_rq_insert: 202,16 R 0 () 1431480000 + 8 [java]
java-8248 [005] 13370789.973831: <stack trace>
=> blk_flush_plug_list
=> blk_queue_bio
=> generic_make_request.part.50
=> generic_make_request
=> submit_bio
=> do_mpage_readpage
=> mpage_readpages
=> xfs_vm_readpages
=> read_pages
=> __do_page_cache_readahead
=> ra_submit
=> do_sync_mmap_readahead.isra.24
=> filemap_fault
=> __do_fault
=> handle_pte_fault
=> handle_mm_fault
=> do_page_fault
=> page_fault
java-8248 [005] 13370789.973831: block_rq_insert: 202,16 R 0 () 1431480024 + 32 [java]
java-8248 [005] 13370789.973836: <stack trace>
=> blk_flush_plug_list
=> blk_queue_bio
=> generic_make_request.part.50
[...]
tpoint 的实现比较简单，譬如上面的 block:block_rq_insert，它直接会找 events/block/block_rq_insert 是否存在，如果存在，就是找到了对应的 event。然后给这个 event 的 enable 文件写入 1，如果我们要开启堆栈，就往 options/stacktrace 里面也写入 1。
从上面的堆栈可以看到，有 readahead 以及 page fault 了。在 Netflix 新升级的 Ubuntu 系统里面，默认的 direct map page size 是 2 MB，而之前的 系统是 4 KB，另外就是默认的 readahead 是 2048 KB，老的系统是 128 KB。看起来慢慢找到问题了。
funccount
为了更好的看函数调用的次数，Gregg 使用了 funccount 函数，譬如检查 submit_bio ：
# ./funccount -i 1 submit_bio
Tracing "submit_bio"... Ctrl-C to end.
FUNC COUNT
submit_bio 27881
FUNC COUNT
submit_bio 28478
# ./funccount -i 1 filemap_fault
Tracing "filemap_fault"... Ctrl-C to end.
FUNC COUNT
filemap_fault 2203
FUNC COUNT
filemap_fault 3227
[...]
上面可以看到，有 10 倍的膨胀。对于 funccount 脚本，主要是需要开启 function profile 功能，也就是给 function_profile_enabled 文件写入 1，当打开之后，就会在 trace_stat 目录下面对相关的函数进行统计，可以看到 function0，function1 这样的文件，0 和 1 就是对应的 CPU。cat 一个文件:
cat function0
Function Hit Time Avg s^2
-------- --- ---- --- ---
schedule 56 12603274 us 225058.4 us 4156108562 us
do_idle 51 4750521 us 93147.47 us 5947176878 us
call_cpuidle 51 4748981 us 93117.27 us 5566277250 us
就能知道各个函数的 count 了。
funcslower
为了更加确定系统的延迟是先前堆栈上面看到的函数引起的，Gregg 使用了 funcslower 来看执行慢的函数：
# ./funcslower -P filemap_fault 1000
Tracing "filemap_fault" slower than 1000 us... Ctrl-C to end.
0) java-8210 | ! 5133.499 us | } /* filemap_fault */
0) java-8258 | ! 1120.600 us | } /* filemap_fault */
0) java-8235 | ! 6526.470 us | } /* filemap_fault */
2) java-8245 | ! 1458.30 us | } /* filemap_fault */
[...]
可以看到，filemap_fault 这个函数很慢。对于 funcslower，我们主要是用 tracing_thresh 来进行控制，给这个文件写入 threshold，如果函数的执行时间超过了 threshold，就会记录。
funccount (again)
Gregg 根据堆栈的情况，再次对 readpage 和 readpages 进行统计
# ./funccount -i 1 '*mpage_readpage*'
Tracing "*mpage_readpage*"... Ctrl-C to end.
FUNC COUNT
mpage_readpages 364
do_mpage_readpage 122930
FUNC COUNT
mpage_readpages 318
do_mpage_readpage 110344
[...]
仍然定位到是 readahead 的写放大引起，但他们已经调整了 readahead 的值，但并没有起到作用。
kprobe
因为 readahead 并没有起到作用，所以 Gregg 准备更进一步，使用 dynamic tracing。他注意到上面堆栈的函数 __do_page_cache_readahead() 有一个 nr_to_read 的参数，这个参数表明的是每次 read 需要读取的 pages 的个数，使用 kprobe：
# ./kprobe -H 'p:do __do_page_cache_readahead nr_to_read=%cx'
Tracing kprobe m. Ctrl-C to end.
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
java-8714 [000] 13445354.703793: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
java-8716 [002] 13445354.819645: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
java-8734 [001] 13445354.820965: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
java-8709 [000] 13445354.825280: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
[...]
可以看到，每次 nr_to_read 读取了 512 （200 的 16 进制）个 pages。在上面的例子，他并不知道 nr_to_read 实际的符号是多少，于是用 %cx 来猜测的，也真能蒙对，太猛了。
关于 kprobe 的使用，具体可以参考 kprobetrace 文档，kprobe 解析需要 trace 的 event 之后，会将其写入到 kprobe_events 里面，然后在 events/kprobes/<EVENT>/ 进行对应的 enable 和 filter 操作。
funcgraph
为了更加确认，Gregg 使用 funcgraph 来看 filemap_fault 的实际堆栈，来看 nr_to_read 到底是从哪里传进来的。
# ./funcgraph -P filemap_fault | head -1000
2) java-8248 | | filemap_fault() {
2) java-8248 | 0.568 us | find_get_page();
2) java-8248 | | do_sync_mmap_readahead.isra.24() {
2) java-8248 | 0.160 us | max_sane_readahead();
2) java-8248 | | ra_submit() {
2) java-8248 | | __do_page_cache_readahead() {
2) java-8248 | | __page_cache_alloc() {
2) java-8248 | | alloc_pages_current() {
2) java-8248 | 0.228 us | interleave_nodes();
2) java-8248 | | alloc_page_interleave() {
2) java-8248 | | __alloc_pages_nodemask() {
2) java-8248 | 0.105 us | next_zones_zonelist();
2) java-8248 | | get_page_from_freelist() {
2) java-8248 | 0.093 us | next_zones_zonelist();
2) java-8248 | 0.101 us | zone_watermark_ok();
2) java-8248 | | zone_statistics() {
2) java-8248 | 0.073 us | __inc_zone_state();
2) java-8248 | 0.074 us | __inc_zone_state();
2) java-8248 | 1.209 us | }
2) java-8248 | 0.142 us | prep_new_page();
2) java-8248 | 3.582 us | }
2) java-8248 | 4.810 us | }
2) java-8248 | 0.094 us | inc_zone_page_state();
找到了一个比较明显的函数 max_sane_readahead。对于 funcgraph，主要就是将需要关注的函数放到 set_graph_function 里面，然后在 current_tracer 里面开启 function_graph。
kprobe (again)
然后，Gregg 继续使用 kprobe 来 trace max_sane_readahead 函数，这次不用猜测寄存器了，直接用 $retval 来看返回值:
# ./kprobe 'r:m max_sane_readahead $retval'
Tracing kprobe m. Ctrl-C to end.
java-8700 [000] 13445377.393895: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8723 [003] 13445377.396362: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8701 [001] 13445377.398216: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8738 [000] 13445377.399793: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8728 [000] 13445377.408529: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
[...]
发现仍然是 0x200 个 pages，然后他在发现，readahead 的属性其实是在 file_ra_state_init 这个函数就设置好了，然后这个函数是在文件打开的时候调用的。但他在进行 readahead tune 的时候，一直是让 Cassandra 运行着，也就是无论怎么改 readahead，都不会起到作用，于是他把 Cassandra 重启，问题解决了。
# ./kprobe 'r:m max_sane_readahead $retval'
Tracing kprobe m. Ctrl-C to end.
java-11918 [007] 13445663.126999: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
java-11918 [007] 13445663.128329: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
java-11918 [007] 13445663.129795: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
java-11918 [007] 13445663.131164: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
[...]
这次只会读取 0x80 个 pages 了。
小结
上面就是一个完完整整使用 ftrace 来定位问题的例子，可以看到，虽然 Linux 系统在很多时候对我们是一个黑盒，但是有了 ftrace，如果在黑暗中开启了一盏灯，能让我们朝着光亮前行。我们内部也在基于 ftrace 做很多有意思的事情，如果你感兴趣，欢迎联系我 tl@pingcap.com。
