三、ftrace的实现
研究 tracer 的实现是非常有乐趣的。理解 ftrace 的实现能够启发我们在自己的系统中设计更好的 trace 功能。
3.1ftrace 的整体构架
Ftrace 有两大组成部分，一是 framework，另外就是一系列的 tracer 。每个 tracer 完成不同的功能，它们统一由 framework 管理。ftrace 的 trace 信息保存在 ring buffer 中，由 framework 负责管理。Framework 利用 debugfs 系统在 /debugfs 下建立 tracing 目录，并提供了一系列的控制文件。
一句话总结：各类tracer往ftrace主框架注册，不同的trace则在不同的probe点把信息通过probe函数给送到ring buffer中，再由暴露在用户态debufs实现相关控制。对不同tracer来说：
- 1）需要实现probe点（需要跟踪的代码侦测点），有的probe点需要静态代码实现，有的probe点借助编译器在运行时动态替换，event tracing属于前者；
- 2）还要实现具体的probe函数，把需要记录的信息送到ring buffer中；
- 3）增加debugfs 相关的文件，实现信息的解析和控制。
而ring buffer 和debugfs的通用部分的管理由框架负责。
3.2Function tracer 的实现
Ftrace 采用 GCC 的 profile 特性在所有内核函数的开始部分加入一段 stub 代码，ftrace 重载这段代码来实现 trace 功能。gcc 的 -pg 选项将在每个函数入口处加入对 mcount 的调用代码。比如下面的 C 代码。
清单 1. test.c
//test.c void foo(void) { printf( “ foo ” ); }
用 gcc 编译：
gcc – S test.c
反汇编如下：
清单 2. test.c 不加入 pg 选项的汇编代码
_foo: pushl %ebp movl %esp, %ebp subl $8, %esp movl $LC0, (%esp) call _printf leave ret
再加入 -gp 选项编译：
gcc – pg – S test.c
得到的汇编如下：
清单 3. test.c 加入 pg 选项后的汇编代码
_foo: pushl %ebp movl %esp, %ebp subl $8, %esp LP3: movl $LP3,%edx call _mcount movl $LC0, (%esp) call _printf leave ret
增加 pg 选项后，gcc 在函数 foo 的入口处加入了对 mcount 的调用：call _mcount 。原本 mcount 由 libc 实现，但您知道内核不会连接 libc 库，因此 ftrace 编写了自己的 mcount stub 函数，并借此实现 trace 功能。
在每个内核函数入口加入 trace 代码，必然会影响内核的性能，为了减小对内核性能的影响，ftrace 支持动态 trace 功能。
当 CONFIG_DYNAMIC_FTRACE 被选中后，内核编译时会调用一个 perl 脚本：recordmcount.pl 将每个函数的地址写入一个特殊的段：__mcount_loc
在内核初始化的初期，ftrace 查询 __mcount_loc 段，得到每个函数的入口地址，并将 mcount 替换为 nop 指令。这样在默认情况下，ftrace 不会对内核性能产生影响。
当用户打开 ftrace 功能时，ftrace 将这些 nop 指令动态替换为 ftrace_caller，该函数将调用用户注册的 trace 函数。其具体的实现在相应 arch 的汇编代码中，以 x86 为例，在 entry_32.s 中：
清单 4. entry_32.s
ENTRY(ftrace_caller) cmpl $0, function_trace_stop jne ftrace_stub pushl %eax pushl %ecx pushl %edx movl 0xc(%esp), %eax movl 0x4(%ebp), %edx subl $MCOUNT_INSN_SIZE, %eax .globl ftrace_call ftrace_call: call ftrace_stubline 10popl %edx popl %ecx popl %eax .globl ftrace_stub ftrace_stub: ret END(ftrace_caller)
Function tracer 将 line10 这行代码替换为 function_trace_call() 。这样每个内核函数都将调用 function_trace_call() 。
在 function_trace_call() 函数内，ftrace 记录函数调用堆栈信息，并将结果写入 ring buffer，稍后，用户可以通过 debugfs 的 trace 文件读取该 ring buffer 中的内容。
3.3Irqsoff tracer 的实现
Irqsoff tracer 的实现依赖于 IRQ-Flags 。IRQ-Flags 是 Ingo Molnar 维护的一个内核特性。使得用户能够在中断关闭和打开时得到通知，ftrace 重载了其通知函数，从而能够记录中断禁止时间。即，中断被关闭时，记录下当时的时间戳。此后，中断被打开时，再计算时间差，由此便可得到中断禁止时间。
IRQ-Flags 封装开关中断的宏定义：
清单 5. IRQ-Flags 中断代码
#define local_irq_enable() \ do { trace_hardirqs_on (); raw_local_irq_enable(); } while (0)
ftrace 在文件 ftrace_irqsoff.c 中重载了 trace_hardirqs_on 。具体代码不再罗列，主要是使用了 sched_clock（）函数来获得时间戳。
3.4hw-branch 的实现
Hw-branch 只在 IA 处理器上实现，依赖于 x86 的 BTS 功能。BTS 将 CPU 实际执行到的分支指令的相关信息保存下来，即每个分支指令的源地址和目标地址。
软件可以指定一块 buffer，处理器将每个分支指令的执行情况写入这块 buffer，之后，软件便可以分析这块 buffer 中的功能。
Linux 内核的 DS 模块封装了 x86 的 BTS 功能。Debug Support 模块封装了和底层硬件的接口，主要支持两种功能：Branch trace store(BTS) 和 precise-event based sampling (PEBS) 。ftrace 主要使用了 BTS 功能。
3.5branch tracer 的实现
内核代码中常使用 likely 和 unlikely 提高编译器生成的代码质量。Gcc 可以通过合理安排汇编代码最大限度的利用处理器的流水线。合理的预测是 likely 能够提高性能的关键，ftrace 为此定义了 branch tracer，跟踪程序中 likely 预测的正确率。
为了实现 branch tracer，重新定义了 likely 和 unlikely 。具体的代码在 compiler.h 中。
清单 6. likely/unlikely 的 trace 实现
# ifndef likely # define likely(x) (__builtin_constant_p(x) ? !!(x) : __branch_check__(x, 1)) # endif # ifndef unlikely # define unlikely(x) (__builtin_constant_p(x) ? !!(x) : __branch_check__(x, 0)) # endif
其中 __branch_check 的实现如下：
清单 7. _branch_check_ 的实现
#define __branch_check__(x, expect) ({\ int ______r; \ static struct ftrace_branch_data \ __attribute__((__aligned__(4))) \ __attribute__((section("_ftrace_annotated_branch"))) \ ______f = { \ .func = __func__, \ .file = __FILE__, \ .line = __LINE__, \ }; \ ______r = likely_notrace(x);\ ftrace_likely_update(&______f, ______r, expect); \ ______r; \ })
ftrace_likely_update() 将记录 likely 判断的正确性，并将结果保存在 ring buffer 中，之后用户可以通过 ftrace 的 debugfs 接口读取分支预测的相关信息。从而调整程序代码，优化性能。
四、实战案列：隐藏的电灯开关
4.1iosnoop
首先，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 了。
4.2tpoint
为了更好的定位 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。看起来慢慢找到问题了。
4.3funccount
为了更好的看函数调用的次数，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 了。
4.4funcslower
为了更加确定系统的延迟是先前堆栈上面看到的函数引起的，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，就会记录。
4.5funccount (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 的值，但并没有起到作用。
4.6kprobe
因为 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 操作。
4.7funcgraph
为了更加确认，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。
4.8kprobe (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 做很多有意思的事情。
