前言：虽然之前一直听说过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;//清空tracerecho function_graph > current_tracer;//使用图形显示调用关系echo ip_rcv > set_graph_function;//设置过滤函数,可以设置多个echo 1 > tracing_enabled开始追踪
传统 Tracer 的使用
使用传统的 ftrace 需要如下几个步骤：
- 选择一种 tracer
- 使能 ftrace
- 执行需要 trace 的应用程序，比如需要跟踪 ls，就执行 ls
- 关闭 ftrace
- 查看 trace 文件
用户通过读写 debugfs 文件系统中的控制文件完成上述步骤。使用 debugfs，首先要挂载她。命令如下：
# mkdir /debug # mount -t debugfs nodev /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 available_events dyn_ftrace_total_info instances printk_formats set_ftrace_filter stack_max_size trace_marker_raw tracing_on available_filter_functions enabled_functions kprobe_events saved_cmdlines set_ftrace_notrace stack_trace trace_options tracing_thresh available_tracers events kprobe_profile saved_cmdlines_size set_ftrace_pid stack_trace_filter trace_pipe uprobe_events buffer_size_kb free_buffer max_graph_depth saved_tgids set_graph_function trace trace_stat uprobe_profile buffer_total_size_kb function_profile_enabled options set_event set_graph_notrace trace_clock tracing_cpumask
可以看到，里面有非常多的文件和目录，具体的含义，大家可以去详细的看官方文档的解释，后面只会重点介绍一些文件。
2.1Function
我们可以通过 available_tracers 这个文件知道当前 ftrace 支持哪些插件。
cat available_tracers hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
通常用的最多的就是function和function_graph，当然，如果我们不想 trace 了，可以使用nop。我们首先打开function：
echo function > current_tracer cat current_tracer function
上面我们将 function 写入到了 current_tracer 来开启 function 的 trace，我通常会在 cat 下 current_tracer 这个文件，主要是防止自己写错了。然后 ftrace 就开始工作了，会将相关的 trace 信息放到 trace 文件里面，我们直接读取这个文件就能获取相关的信息。
cat trace | head -n 15 # tracer: function # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | bash-29409 [002] .... 16158426.215771: mutex_unlock <-tracing_set_tracer <idle>-0 [039] d... 16158426.215771: call_cpuidle <-do_idle <idle>-0 [039] d... 16158426.215772: cpuidle_enter <-call_cpuidle <idle>-0 [039] d... 16158426.215773: cpuidle_enter_state <-cpuidle_enter bash-29409 [002] .... 16158426.215773: __fsnotify_parent <-vfs_write <idle>-0 [039] d... 16158426.215773: sched_idle_set_state <-cpuidle_enter_state
我们可以设置只跟踪特定的 function
echo schedule > set_ftrace_filter cat set_ftrace_filter schedule cat trace | head -n 15 # tracer: function # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | bash-29409 [010] .... 16158462.591708: schedule <-schedule_timeout kworker/u81:2-29339 [008] .... 16158462.591736: schedule <-worker_thread sshd-29395 [012] .... 16158462.591788: schedule <-schedule_hrtimeout_range_clock rcu_sched-9 [010] .... 16158462.595475: schedule <-schedule_timeout java-23597 [006] .... 16158462.600326: schedule <-futex_wait_queue_me java-23624 [020] .... 16158462.600855: schedule <-schedule_hrtimeout_range_clock
当然，如果我们不想 trace schedule 这个函数，也可以这样做：
echo '!schedule' > set_ftrace_filter
或者也可以这样做：
echo schedule > set_ftrace_notrace
Function filter 的设置也支持 *match，match* ，*match* 这样的正则表达式，譬如我们可以 echo '*lock*' < set_ftrace_notrace 来禁止跟踪带 lock 的函数，set_ftrace_notrace 文件里面这时候就会显示：
cat set_ftrace_notrace xen_pte_unlock read_hv_clock_msr read_hv_clock_tsc update_persistent_clock read_persistent_clock set_task_blockstep user_enable_block_step ...
2.2Function Graph
相比于 function，function_graph 能让我们更加详细的去知道内核函数的上下文，我们打开 function_graph：
echo function_graph > current_tracer cat trace | head -15 # tracer: function_graph # # CPU DURATION FUNCTION CALLS # | | | | | | | 10) 0.085 us | sched_idle_set_state(); 10) | cpuidle_reflect() { 10) 0.035 us | menu_reflect(); 10) 0.288 us | } 10) | rcu_idle_exit() { 10) 0.034 us | rcu_dynticks_eqs_exit(); 10) 0.296 us | } 10) 0.032 us | arch_cpu_idle_exit(); 10) | tick_nohz_idle_exit() { 10) 0.073 us | ktime_get(); 10) | update_ts_time_stats() {
我们也可以只跟踪某一个函数的堆栈
echo kfree > set_graph_function cat trace | head -n 15 # tracer: function_graph # # CPU DURATION FUNCTION CALLS # | | | | | | | 16) | kfree() { 16) 0.147 us | __slab_free(); 16) 1.437 us | } 10) 0.162 us | kfree(); 17) @ 923817.3 us | } /* intel_idle */ 17) 0.044 us | sched_idle_set_state(); 17) ==========> | 17) | smp_apic_timer_interrupt() { 17) | irq_enter() { 17) | rcu_irq_enter() { 17) 0.049 us | rcu_dynticks_eqs_exit();
2.3Event
上面提到了 function 的 trace，在 ftrace 里面，另外用的多的就是 event 的 trace，我们可以在 events 目录下面看支持那些事件：
ls events/ alarmtimer cma ext4 fs_dax i2c kvm mmc nmi printk regulator smbus task vmscan xdp block compaction fib ftrace iommu kvmmmu module oom random rpm sock thermal vsyscall xen bpf cpuhp fib6 gpio irq libata mpx page_isolation ras sched spi thermal_power_allocator wbt xhci-hcd btrfs dma_fence filelock header_event irq_vectors mce msr pagemap raw_syscalls scsi swiotlb timer workqueue cgroup enable filemap header_page jbd2 mdio napi percpu rcu signal sync_trace tlb writeback clk exceptions fs huge_memory kmem migrate net power regmap skb syscalls udp x86_fpu
上面列出来的都是分组的，我们可以继续深入下去，譬如下面是查看sched相关的事件：
ls events/sched/ enable sched_migrate_task sched_process_exit sched_process_wait sched_stat_sleep sched_switch sched_wakeup_new filter sched_move_numa sched_process_fork sched_stat_blocked sched_stat_wait sched_wait_task sched_waking sched_kthread_stop sched_pi_setprio sched_process_free sched_stat_iowait sched_stick_numa sched_wake_idle_without_ipi sched_kthread_stop_ret sched_process_exec sched_process_hang sched_stat_runtime sched_swap_numa sched_wakeup
对于某一个具体的事件，我们也可以查看：
ls events/sched/sched_wakeup enable filter format hist id trigger
不知道大家注意到了没有，上述目录里面，都有一个enable的文件，我们只需要往里面写入 1，就可以开始 trace 这个事件。譬如下面就开始 tracesched_wakeup这个事件：
echo 1 > events/sched/sched_wakeup/enable cat trace | head -15 # tracer: nop # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | bash-29409 [012] d... 16158657.832294: sched_wakeup: comm=kworker/u81:1 pid=29359 prio=120 target_cpu=008 kworker/u81:1-29359 [008] d... 16158657.832321: sched_wakeup: comm=sshd pid=29395 prio=120 target_cpu=010 <idle>-0 [012] dNs. 16158657.835922: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=012 <idle>-0 [024] dNh. 16158657.836908: sched_wakeup: comm=java pid=23632 prio=120 target_cpu=024 <idle>-0 [022] dNh. 16158657.839921: sched_wakeup: comm=java pid=23624 prio=120 target_cpu=022 <idle>-0 [016] dNh. 16158657.841866: sched_wakeup: comm=java pid=23629 prio=120 target_cpu=016
我们也可以 tracesched里面的所有事件：
echo 1 > events/sched/enable cat trace | head -15 # tracer: nop # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | bash-29409 [010] d... 16158704.468377: sched_waking: comm=kworker/u81:2 pid=29339 prio=120 target_cpu=008 bash-29409 [010] d... 16158704.468378: sched_stat_sleep: comm=kworker/u81:2 pid=29339 delay=164314267 [ns] bash-29409 [010] d... 16158704.468379: sched_wake_idle_without_ipi: cpu=8 bash-29409 [010] d... 16158704.468379: sched_wakeup: comm=kworker/u81:2 pid=29339 prio=120 target_cpu=008 bash-29409 [010] d... 16158704.468382: sched_stat_runtime: comm=bash pid=29409 runtime=360343 [ns] vruntime=131529875864926 [ns] bash-29409 [010] d... 16158704.468383: sched_switch: prev_comm=bash prev_pid=29409 prev_prio=120 prev_state=S ==> next_comm=swapper/10 next_pid=0 next_prio=120
当然也可以 trace 所有的事件：
echo 1 > events/enable cat trace | head -15 # tracer: nop # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | bash-29409 [010] .... 16158761.584188: writeback_mark_inode_dirty: bdi (unknown): ino=3089 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES flags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES bash-29409 [010] .... 16158761.584189: writeback_dirty_inode_start: bdi (unknown): ino=3089 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES flags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES bash-29409 [010] .... 16158761.584190: writeback_dirty_inode: bdi (unknown): ino=3089 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES flags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES bash-29409 [010] .... 16158761.584193: do_sys_open: "trace" 8241 666 bash-29409 [010] .... 16158761.584193: kmem_cache_free: call_site=ffffffff8e862614 ptr=ffff91d241fa4000 bash-29409 [010] .... 16158761.584194: sys_exit: NR 2 = 3
【文章福利】小编推荐自己的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 version = 6 CPU 27 is empty cpus=40 trace-cmd-29557 [003] 16159201.985281: sched_waking: comm=kworker/u82:3 pid=28507 prio=120 target_cpu=037 trace-cmd-29557 [003] 16159201.985283: sched_migrate_task: comm=kworker/u82:3 pid=28507 prio=120 orig_cpu=37 dest_cpu=5 trace-cmd-29557 [003] 16159201.985285: sched_stat_sleep: comm=kworker/u82:3 pid=28507 delay=137014529 [ns] trace-cmd-29585 [023] 16159201.985286: sched_stat_runtime: comm=trace-cmd pid=29585 runtime=217630 [ns] vruntime=107586626253137 [ns] trace-cmd-29557 [003] 16159201.985286: sched_wake_idle_without_ipi: cpu=5 trace-cmd-29595 [037] 16159201.985286: sched_stat_runtime: comm=trace-cmd pid=29595 runtime=213227 [ns] vruntime=105364596011783 [ns] trace-cmd-29557 [003] 16159201.985287: sched_wakeup: kworker/u82:3:28507 [120] success=1 CPU:005
当然，在report的时候也可以加入自己的 filter 来过滤数据，譬如下面，我们就过滤出sched_wakeup事件并且是success为 1 的。
trace-cmd report -F 'sched/sched_wakeup: success == 1' | head -10 version = 6 CPU 27 is empty cpus=40 trace-cmd-29557 [003] 16159201.985287: sched_wakeup: kworker/u82:3:28507 [120] success=1 CPU:005 trace-cmd-29557 [003] 16159201.985292: sched_wakeup: trace-cmd:29561 [120] success=1 CPU:007 <idle>-0 [032] 16159201.985294: sched_wakeup: qps_json_driver:24669 [120] success=1 CPU:032 <idle>-0 [032] 16159201.985298: sched_wakeup: trace-cmd:29590 [120] success=1 CPU:026 <idle>-0 [010] 16159201.985300: sched_wakeup: trace-cmd:29563 [120] success=1 CPU:010 trace-cmd-29597 [037] 16159201.985302: sched_wakeup: trace-cmd:29595 [120] success=1 CPU:039 <idle>-0 [010] 16159201.985302: sched_wakeup: sshd:29395 [120] success=1 CPU:010
大家可以注意下success == 1，这其实是一个对事件里面 field 进行的表达式运算了，对于不同的事件，我们可以通过查看起 format 来知道它的实际 fields 是怎样的，譬如：
cat events/sched/sched_wakeup/format name: sched_wakeup ID: 294 format: field:unsigned short common_type; offset:0; size:2; signed:0; field:unsigned char common_flags; offset:2; size:1; signed:0; field:unsigned char common_preempt_count; offset:3; size:1; signed:0; field:int common_pid; offset:4; size:4; signed:1; field:char comm[16]; offset:8; size:16; signed:1; field:pid_t pid; offset:24; size:4; signed:1; field:int prio; offset:28; size:4; signed:1; field:int success; offset:32; size:4; signed:1; field:int target_cpu; offset:36; size:4; signed:1; print fmt: "comm=%s pid=%d prio=%d target_cpu=%03d", REC->comm, REC->pid,
