前言：虽然之前一直听说过ftrace，但从来没将它用在实战中，在一次客户排查问题中，遇到了比较奇怪的现象，一位精通内核的朋友建议使用ftrace来定位一下。虽然那一次并没有使用ftrace，但也让我觉得，后面我们势必要提供ftrace 相关的工具帮助我们在线上定位问题，所以自己也决定重新学习使用下ftrace，当然也决定写一系列的相关出来，这里就先简单介绍下 ftrace。 一、什么是 ftrace 首先我们需要知道，什么是 ftrace？根据Linux Doc 的介绍，ftrace 是一个 Linux 内部的 trace 工具，能够帮助开发者和系统设计者知道内核当前正在干啥，从而更好的去分析性能问题。
Ftrace 能帮我们分析内核特定的事件，譬如调度，中断等，也能帮我们去追踪动态的内核函数，以及这些函数的调用栈还有栈的使用这些。它也能帮我们去追踪延迟，譬如中断被屏蔽，抢占被禁止的时间，以及唤醒一个进程之后多久开始执行的时间。
可以看到，使用 ftrace 真的能做到对系统内核非常系统的剖析，甚至都能通过 ftrace 来学习 Linux 内核，不过在更进一步之前，我们需要学会的是 - 如何使用 ftrace。
二、如何使用 要使用 ftrace，首先就是需要将系统的 debugfs 或者 tracefs 给挂载到某个地方，幸运的是，几乎所有的 Linux 发行版，都开启了 debugfs/tracefs 的支持，所以我们也没必要去重新编译内核了。
在比较老的内核版本，譬如 CentOS 7 的上面，debugfs 通常被挂载到 /sys/kernel/debug 上面（debug 目录下面有一个 tracing 目录），而比较新的内核，则是将 tracefs 挂载到 /sys/kernel/tracing，无论是什么，我都喜欢将 tracing 目录直接 link 到 /tracing。后面都会假设直接进入了 /tracing 目录，后面，我会使用 Ubuntu 16.04 来举例子，内核版本是 4.13 来举例子。
在使用ftrace之前，需要内核进行支持，也就是内核需要打开编译中的ftrace相关选项，关于怎么激活ftrace选项的问题，可以google之，下面只说明重要的设置步骤：
mkdir /debug；mount -t debugs nodev /debug; /*挂载debugfs到创建的目录中去*/
cd /debug; cd tracing; /*如果没有tracing目录，则内核目前还没有支持ftrace，需要配置参数，重新编译*/。
echo nop > current_tracer;//清空tracer
echo function_graph > current_tracer;//使用图形显示调用关系
echo ip_rcv > set_graph_function;//设置过滤函数,可以设置多个
echo 1 > tracing_enabled开始追踪
传统 Tracer 的使用
使用传统的 ftrace 需要如下几个步骤：
用户通过读写 debugfs 文件系统中的控制文件完成上述步骤。使用 debugfs，首先要挂载她。命令如下：
# mkdir /debug 此时您将在 /debug 目录下看到 tracing 目录。Ftrace 的控制接口就是该目录下的文件。
选择 tracer 的控制文件叫作 current_tracer 。选择 tracer 就是将 tracer 的名字写入这个文件，比如，用户打算使用 function tracer，可输入如下命令：
#echo ftrace > /debug/tracing/current_tracer文件 tracing_enabled 控制 ftrace 的开始和结束。
#echo 1 >/debug/tracing/tracing_enable上面的命令使能 ftrace 。同样，将 0 写入 tracing_enable 文件便可以停止 ftrace 。
ftrace 的输出信息主要保存在 3 个文件中。
Trace，该文件保存 ftrace 的输出信息，其内容可以直接阅读。
latency_trace，保存与 trace 相同的信息，不过组织方式略有不同。主要为了用户能方便地分析系统中有关延迟的信息。
trace_pipe 是一个管道文件，主要为了方便应用程序读取 trace 内容。算是扩展接口吧。
我们使用 ls 来看看目录下面到底有什么：
README current_tracer hwlat_detector per_cpu set_event_pid snapshot trace_marker tracing_max_latency可以看到，里面有非常多的文件和目录，具体的含义，大家可以去详细的看官方文档的解释，后面只会重点介绍一些文件。
2.1Function 我们可以通过 available_tracers 这个文件知道当前 ftrace 支持哪些插件。
cat available_tracers通常用的最多的就是function和function_graph，当然，如果我们不想 trace 了，可以使用nop。我们首先打开function：
echo function > current_tracer上面我们将 function 写入到了 current_tracer 来开启 function 的 trace，我通常会在 cat 下 current_tracer 这个文件，主要是防止自己写错了。然后 ftrace 就开始工作了，会将相关的 trace 信息放到 trace 文件里面，我们直接读取这个文件就能获取相关的信息。
cat trace | head -n 15我们可以设置只跟踪特定的 function
echo schedule > set_ftrace_filter当然，如果我们不想 trace schedule 这个函数，也可以这样做：
echo '!schedule' > set_ftrace_filter或者也可以这样做：
echo schedule > set_ftrace_notraceFunction filter 的设置也支持 *match，match* ，*match* 这样的正则表达式，譬如我们可以 echo '*lock*' < set_ftrace_notrace 来禁止跟踪带 lock 的函数，set_ftrace_notrace 文件里面这时候就会显示：
cat set_ftrace_notrace2.2Function Graph 相比于 function，function_graph 能让我们更加详细的去知道内核函数的上下文，我们打开 function_graph：
echo function_graph > current_tracer我们也可以只跟踪某一个函数的堆栈
echo kfree > set_graph_function2.3Event 上面提到了 function 的 trace，在 ftrace 里面，另外用的多的就是 event 的 trace，我们可以在 events 目录下面看支持那些事件：
ls events/上面列出来的都是分组的，我们可以继续深入下去，譬如下面是查看sched相关的事件：
ls events/sched/对于某一个具体的事件，我们也可以查看：
ls events/sched/sched_wakeup不知道大家注意到了没有，上述目录里面，都有一个enable的文件，我们只需要往里面写入 1，就可以开始 trace 这个事件。譬如下面就开始 tracesched_wakeup这个事件：
echo 1 > events/sched/sched_wakeup/enable我们也可以 tracesched里面的所有事件：
echo 1 > events/sched/enable当然也可以 trace 所有的事件：
echo 1 > events/enable【文章福利 】小编推荐自己的Linux内核技术交流群:【865977150 】整理了一些个人觉得比较好的学习书籍、视频资料共享在群文件里面，有需要的可以自行添加哦！！！前100名进群领取，额外赠送一份价值699的内核资料包 （含视频教程、电子书、实战项目及代码)2.4trace-cmd 从上面的例子可以看到，其实使用 ftrace 并不是那么方便，我们需要手动的去控制多个文件，但幸运的是，我们有 trace-cmd，作为 ftrace 的前端，trace-cmd 能够非常方便的让我们进行 ftrace 的操作，譬如我们可以使用 record 命令来 trace sched 事件：
trace-cmd record -e sched然后使用report命令来查看 trace 的数据：
trace-cmd report | head -10当然，在report的时候也可以加入自己的 filter 来过滤数据，譬如下面，我们就过滤出sched_wakeup事件并且是success为 1 的。
trace-cmd report -F 'sched/sched_wakeup: success == 1' | head -10大家可以注意下success == 1，这其实是一个对事件里面 field 进行的表达式运算了，对于不同的事件，我们可以通过查看起 format 来知道它的实际 fields 是怎样的，譬如：
cat events/sched/sched_wakeup/format三、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 用 gcc 编译：
gcc – S test.c
反汇编如下：
清单 2. test.c 不加入 pg 选项的汇编代码
_foo: 再加入 -gp 选项编译：
gcc – pg – S test.c
得到的汇编如下：
清单 3. test.c 加入 pg 选项后的汇编代码
_foo: 增加 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) 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() \ 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 其中 __branch_check 的实现如下：
清单 7. _branch_check_ 的实现
#define __branch_check__(x, expect) ({\ ftrace_likely_update() 将记录 likely 判断的正确性，并将结果保存在 ring buffer 中，之后用户可以通过 ftrace 的 debugfs 接口读取分支预测的相关信息。从而调整程序代码，优化性能。
四、实战案列：隐藏的电灯开关 4.1iosnoop 首先，Gregg 使用 iosnoop 工具进行检查，iosnoop 用来跟踪 I/O 的详细信息，当然也包括 latency，结果如下：
# ./iosnoop -ts上面看不出来啥，一个繁忙的 I/O，势必会带来高的 latency。我们来说说 iosnoop 是如何做的。
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 的输出：我们根据1367650688 + 8能找到对应的 I/O block sector，然后根据 issue 和 complete 的时间就能知道 latency 了。
4.2tpoint 为了更好的定位 I/O 问题，Gregg 使用 tpoint 来追踪 block_rq_insert，如下：
# ./tpoint -H block:block_rq_insert然后也跟踪了实际的堆栈：
# ./tpoint -s block:block_rq_insert 'rwbs ~ "*R*"' | head -1000tpoint 的实现比较简单，譬如上面的 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上面可以看到，有 10 倍的膨胀。对于 funccount 脚本，主要是需要开启 function profile 功能，也就是给 function_profile_enabled 文件写入 1，当打开之后，就会在 trace_stat 目录下面对相关的函数进行统计，可以看到 function0，function1 这样的文件，0 和 1 就是对应的 CPU。cat 一个文件:
cat function0就能知道各个函数的 count 了。
4.4funcslower 为了更加确定系统的延迟是先前堆栈上面看到的函数引起的，Gregg 使用了 funcslower 来看执行慢的函数：
# ./funcslower -P filemap_fault 1000可以看到，filemap_fault 这个函数很慢。对于 funcslower，我们主要是用 tracing_thresh 来进行控制，给这个文件写入 threshold，如果函数的执行时间超过了 threshold，就会记录。
4.5funccount (again) Gregg 根据堆栈的情况，再次对 readpage 和 readpages 进行统计：
# ./funccount -i 1 '*mpage_readpage*'仍然定位到是 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'可以看到，每次 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找到了一个比较明显的函数 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'发现仍然是 0x200 个 pages，然后他在发现，readahead 的属性其实是在 file_ra_state_init 这个函数就设置好了，然后这个函数是在文件打开的时候调用的。但他在进行 readahead tune 的时候，一直是让 Cassandra 运行着，也就是无论怎么改 readahead，都不会起到作用，于是他把 Cassandra 重启，问题解决了。
# ./kprobe 'r:m max_sane_readahead $retval'这次只会读取 0x80 个 pages 了。
上面就是一个完完整整使用 ftrace 来定位问题的例子，可以看到，虽然 Linux 系统在很多时候对我们是一个黑盒，但是有了 ftrace，如果在黑暗中开启了一盏灯，能让我们朝着光亮前行。我们内部也在基于 ftrace 做很多有意思的事情。
