ftrace 使用
ftrace 是 Linux 内核中提供的一种调试工具。使用 ftrace 可以对内核中发生的事情进行跟踪，这在调试 bug 或者分析内核时非常有用。本系列文章对 ftrace 进行了介绍，分为三部分。本文是第二部分，通过示例介绍了如何使用 ftrace 中的跟踪器，并对不同格式的跟踪信息进行了描述，同时还对如何使用 ftrace 调试指定内核模块进行了介绍。通过对本文的学习，读者可以了解如何在实践中使用 ftrace 。
ftrace 操作概述
使用 ftrace 提供的跟踪器来调试或者分析内核时需要如下操作：
切换到目录 /sys/kernel/debug/tracing/ 下 查看 available_tracers 文件，获取当前内核支持的跟踪器列表 关闭 ftrace 跟踪，即将 0 写入文件 tracing_on 激活 ftrace_enabled ，否则 function 跟踪器的行为类似于 nop；另外，激活该选项还可以让一些跟踪器比如 irqsoff 获取更丰富的信息。建议使用 ftrace 时将其激活。要激活 ftrace_enabled ，可以通过 proc 文件系统接口来设置： echo 1 > /proc/sys/kernel/ftrace_enabled
接下来将对跟踪器的使用以及跟踪信息的格式通过实例加以讲解。
fucntion 跟踪器
function 跟踪器可以跟踪内核函数的调用情况，可用于调试或者分析 bug ，还可用于了解和观察 Linux 内核的执行过程。清单 1 给出了使用 function 跟踪器的示例。
清单 1. function 跟踪器使用示例
<u><em><strong># pwd</strong></em></u>
/sys/kernel/debug/tracing
#
<strong><em><u># echo 0 > tracing_on
# echo 1 > /proc/sys/kernel/ftrace_enabled</u></em></strong>
#
<u><em><strong># cat available_tracers</strong></em></u>
function_graph wakeup_rt wakeup preemptirqsoff preemptoff irqsoff function nop
#
<strong><em><u># echo function > current_tracer
</u></em></strong>#
<em><strong><u># cat trace</u></strong></em>
# tracer: function
#
# entries-in-buffer/entries-written: 0/0 #P:1
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<strong><em><u># echo 1 > tracing_on
</u></em></strong># 让内核运行一段时间，这样ftrace可以收集一些跟踪信息，之后再停止跟踪。
<em><strong><u># echo 0 > tracing_on</u></strong></em>
<u><em><strong># cat trace | head -20</strong></em></u>
# tracer: function
#
# entries-in-buffer/entries-written: 66612/66612 #P:1
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
sh-167 [000] ...1 5297.185311: mutex_unlock <-rb_simple_write
sh-167 [000] ...1 5297.185324: __fsnotify_parent <-vfs_write
sh-167 [000] ...1 5297.185328: fsnotify <-vfs_write
sh-167 [000] ...1 5297.185332: __srcu_read_lock <-fsnotify
sh-167 [000] ...1 5297.185336: add_preempt_count <-__srcu_read_lock
sh-167 [000] ...2 5297.185340: sub_preempt_count <-__srcu_read_lock
sh-167 [000] ...1 5297.185344: __srcu_read_unlock <-fsnotify
sh-167 [000] ...1 5297.185347: __sb_end_write <-vfs_write
sh-167 [000] ...1 5297.185351: add_preempt_count <-__percpu_counter_add
#
trace 文件给出的信息格式很清晰。首先，字段“tracer:”给出了当前所使用的跟踪器的名字，这里为 function 跟踪器。然后是跟踪信息记录的格式，TASK 字段对应任务的名字，PID 字段则给出了任务的进程 ID，字段 CPU# 表示运行被跟踪函数的 CPU 号，这里可以看到 sh 进程运行在 0 号 CPU 上，其进程 ID 是 167 ；字段 TIMESTAMP 是时间戳，其格式为“<secs>.<usecs>”，表示执行该函数时对应的时间戳；FUNCTION 一列则给出了被跟踪的函数，函数的调用者通过符号 “<-” 标明，这样可以观察到函数的调用关系。
function_graph 跟踪器
在 function 跟踪器给出的信息中，可以通过 FUNCTION 列中的符号 “<-” 来查看函数调用关系，但是由于中间会混合不同函数的调用，导致看起来非常混乱，十分不方便。function_graph 跟踪器则可以提供类似 C 代码的函数调用关系信息。通过写文件 set_graph_function 可以显示指定要生成调用关系的函数，缺省会对所有可跟踪的内核函数生成函数调用关系图。清单 2 给出了使用 function_grapch 跟踪器的示例，示例中将内核函数 __do_fault 作为观察对象，该函数在内核运作过程中会被频繁调用。
清单 2. function_graph 跟踪器使用示例
<strong><em><u># pwd</u></em></strong>
/sys/kernel/debug/tracing
#
<strong><em><u># echo 0 > tracing_on
# echo 1 > /proc/sys/kernel/ftrace_enabled</u></em></strong>
#
<u><em><strong># echo function_graph > current_tracer
# echo __do_fault > set_graph_function</strong></em></u>
#
<strong><em><u># cat trace</u></em></strong>
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
#
<strong><em><u># echo 1 > tracing_on</u></em></strong>
# 让内核运行一段时间，这样ftrace可以收集一些跟踪信息，之后再停止跟踪。
<strong><em><u># echo 0 > tracing_on</u></em></strong>
#
<strong><em><u># cat trace | head -20</u></em></strong>
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) | __do_fault() {
0) | filemap_fault() {
0) | find_get_page() {
0) 1.156 us | __rcu_read_lock();
0) 0.891 us | __rcu_read_unlock();
0) + 30.531 us | }
0) + 47.157 us | }
0) | _raw_spin_lock() {
0) 1.086 us | add_preempt_count();
0) + 14.211 us | }
0) 0.898 us | add_mm_counter_fast();
0) | page_add_file_rmap() {
0) 0.875 us | __rcu_read_lock();
0) 0.890 us | __rcu_read_unlock();
0) + 26.937 us | }
0) | __sync_icache_dcache() {
<strong><em><u># echo > set_graph_function</u></em></strong>
在文件 trace 的输出信息中，首先给出的也是当前跟踪器的名字，这里是 function_graph 。接下来是详细的跟踪信息，可以看到，函数的调用关系以类似 C 代码的形式组织。
CPU 字段给出了执行函数的 CPU 号，本例中都为 1 号 CPU。DURATION 字段给出了函数执行的时间长度，以 us 为单位。FUNCTION CALLS 则给出了调用的函数，并显示了调用流程。注意，对于不调用其它函数的函数，其对应行以“;”结尾，而且对应的 DURATION 字段给出其运行时长；对于调用其它函数的函数，则在其“}”对应行给出了运行时长，该时间是一个累加值，包括了其内部调用的函数的执行时长。DURATION 字段给出的时长并不是精确的，它还包含了执行 ftrace 自身的代码所耗费的时间，所以示例中将内部函数时长累加得到的结果会与对应的外围调用函数的执行时长并不一致；不过通过该字段还是可以大致了解函数在时间上的运行开销的。清单 2 中最后通过 echo 命令重置了文件 set_graph_function 。
irqsoff 跟踪器
当关闭中断时，CPU 会延迟对设备的状态变化做出反应，有时候这样做会对系统性能造成比较大的影响。irqsoff 跟踪器可以对中断被关闭的状况进行跟踪，有助于发现导致较大延迟的代码；当出现最大延迟时，跟踪器会记录导致延迟的跟踪信息，文件 tracing_max_latency 则记录中断被关闭的最大延时。
清单 4. irqsoff 跟踪器使用示例
<strong><em><u># pwd</u></em></strong> /sys/kernel/debug/tracing # <strong><em><u># echo 0 > tracing_on # echo 1 > /proc/sys/kernel/ftrace_enabled</u></em></strong> # <strong><em><u># echo irqsoff > current_tracer</u></em></strong> # <strong><em><u># cat trace</u></em></strong> # tracer: irqsoff # <strong><em><u># echo 1 > tracing_on</u></em></strong> # 让内核运行一段时间，这样ftrace可以收集一些跟踪信息，之后再停止跟踪。 <strong><em><u># echo 0 > tracing_on</u></em></strong> # <strong><em><u># cat trace</u></em></strong> # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 3.10.17-00008-g5868add # -------------------------------------------------------------------- # latency: 1098962 us, #86/86, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:1) # ----------------- # | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # => started at: rcu_idle_enter # => ended at: sc_enter_idle # # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| / delay # cmd pid ||||| time | caller # \ / ||||| \ | / <idle>-0 0d..1 2us+: rcu_idle_enter <idle>-0 0d..2 7us+: rcu_eqs_enter_common.isra.43 <-rcu_idle_enter <idle>-0 0d..2 11us+: arch_cpu_idle <-cpu_startup_entry <idle>-0 0d..2 15us+: cpuidle_idle_call <-arch_cpu_idle <idle>-0 0d..2 19us+: cpuidle_get_cpu_driver <-cpuidle_idle_call <idle>-0 0d..2 23us+: menu_select <-cpuidle_idle_call <idle>-0 0d..2 26us+: pm_qos_request <-menu_select <idle>-0 0d..2 31us+: tick_nohz_get_sleep_length <-menu_select <idle>-0 0d..2 34us+: ns_to_timespec <-menu_select <idle>-0 0d..2 39us+: nr_iowait_cpu <-menu_select <idle>-0 0d..2 43us+: nr_iowait_cpu <-menu_select <idle>-0 0d..2 52us+: cpuidle_enter_state <-cpuidle_idle_call <idle>-0 0d..2 55us+: ktime_get <-cpuidle_enter_state <idle>-0 0d..2 59us+: __gptimer_clocksource_read <-ktime_get <idle>-0 0d..2 64us+: sc_enter_idle <-cpuidle_enter_state <idle>-0 0d..2 68us+: ktime_get <-sc_enter_idle <idle>-0 0d..2 71us+: __gptimer_clocksource_read <-ktime_get <idle>-0 0d..2 76us+: emc_clk_get <-sc_enter_idle <idle>-0 0d..2 80us+: sci_glb_read <-emc_clk_get <idle>-0 0d..2 84us+: get_dpll_clk <-emc_clk_get <idle>-0 0d..2 87us+: sci_glb_read <-get_dpll_clk <idle>-0 0d..2 91us+: sc_cpuidle_light_sleep_en.part.1 <-sc_enter_idle <idle>-0 0d..2 95us+: sci_glb_clr <-sc_cpuidle_light_sleep_en.part.1 <idle>-0 0d..2 100us+: __hwspin_lock_timeout <-sci_glb_clr <idle>-0 0d..2 104us+: msecs_to_jiffies <-__hwspin_lock_timeout <idle>-0 0d..2 107us+: __hwspin_trylock <-__hwspin_lock_timeout <idle>-0 0d..2 111us+: _raw_spin_trylock <-__hwspin_trylock <idle>-0 0d..2 115us+: add_preempt_count <-_raw_spin_trylock <idle>-0 0d..3 119us+: __hwspinlock_trylock <-__hwspin_trylock <idle>-0 0d..3 124us+: __hwspin_unlock <-sci_glb_clr <idle>-0 0d..3 127us+: __hwspinlock_unlock <-__hwspin_unlock <idle>-0 0d..3 131us+: _raw_spin_unlock_irqrestore <-__hwspin_unlock <idle>-0 0d..3 135us+: sub_preempt_count <-_raw_spin_unlock_irqrestore <idle>-0 0d..2 139us+: sci_glb_read <-sc_cpuidle_light_sleep_en.part.1 <idle>-0 0d..2 143us+: sci_glb_set <-sc_cpuidle_light_sleep_en.part.1 <idle>-0 0d..2 147us+: __hwspin_lock_timeout <-sci_glb_set <idle>-0 0d..2 151us+: msecs_to_jiffies <-__hwspin_lock_timeout <idle>-0 0d..2 154us+: __hwspin_trylock <-__hwspin_lock_timeout <idle>-0 0d..2 158us+: _raw_spin_trylock <-__hwspin_trylock <idle>-0 0d..2 162us+: add_preempt_count <-_raw_spin_trylock <idle>-0 0d..3 165us+: __hwspinlock_trylock <-__hwspin_trylock <idle>-0 0d..3 170us+: __hwspin_unlock <-sci_glb_set <idle>-0 0d..3 174us+: __hwspinlock_unlock <-__hwspin_unlock <idle>-0 0d..3 178us+: _raw_spin_unlock_irqrestore <-__hwspin_unlock <idle>-0 0d..3 182us+: sub_preempt_count <-_raw_spin_unlock_irqrestore <idle>-0 0d..2 186us+: sci_glb_set <-sc_cpuidle_light_sleep_en.part.1 <idle>-0 0d..2 189us+: __hwspin_lock_timeout <-sci_glb_set <idle>-0 0d..2 193us+: msecs_to_jiffies <-__hwspin_lock_timeout <idle>-0 0d..2 196us+: __hwspin_trylock <-__hwspin_lock_timeout <idle>-0 0d..2 201us+: _raw_spin_trylock <-__hwspin_trylock <idle>-0 0d..2 204us+: add_preempt_count <-_raw_spin_trylock <idle>-0 0d..3 208us+: __hwspinlock_trylock <-__hwspin_trylock <idle>-0 0d..3 212us+: __hwspin_unlock <-sci_glb_set <idle>-0 0d..3 216us+: __hwspinlock_unlock <-__hwspin_unlock <idle>-0 0d..3 220us+: _raw_spin_unlock_irqrestore <-__hwspin_unlock <idle>-0 0d..3 224us!: sub_preempt_count <-_raw_spin_unlock_irqrestore <idle>-0 0d..2 1098854us+: sc_cpuidle_light_sleep_dis.part.2 <-sc_enter_idle <idle>-0 0d..2 1098858us+: sci_glb_set <-sc_cpuidle_light_sleep_dis.part.2 <idle>-0 0d..2 1098862us+: __hwspin_lock_timeout <-sci_glb_set <idle>-0 0d..2 1098865us+: msecs_to_jiffies <-__hwspin_lock_timeout <idle>-0 0d..2 1098869us+: __hwspin_trylock <-__hwspin_lock_timeout <idle>-0 0d..2 1098873us+: _raw_spin_trylock <-__hwspin_trylock <idle>-0 0d..2 1098876us+: add_preempt_count <-_raw_spin_trylock <idle>-0 0d..3 1098880us+: __hwspinlock_trylock <-__hwspin_trylock <idle>-0 0d..3 1098885us+: __hwspin_unlock <-sci_glb_set <idle>-0 0d..3 1098889us+: __hwspinlock_unlock <-__hwspin_unlock <idle>-0 0d..3 1098892us+: _raw_spin_unlock_irqrestore <-__hwspin_unlock <idle>-0 0d..3 1098896us+: sub_preempt_count <-_raw_spin_unlock_irqrestore <idle>-0 0d..2 1098900us+: sci_glb_clr <-sc_cpuidle_light_sleep_dis.part.2 <idle>-0 0d..2 1098904us+: __hwspin_lock_timeout <-sci_glb_clr <idle>-0 0d..2 1098907us+: msecs_to_jiffies <-__hwspin_lock_timeout <idle>-0 0d..2 1098911us+: __hwspin_trylock <-__hwspin_lock_timeout <idle>-0 0d..2 1098915us+: _raw_spin_trylock <-__hwspin_trylock <idle>-0 0d..2 1098919us+: add_preempt_count <-_raw_spin_trylock <idle>-0 0d..3 1098923us+: __hwspinlock_trylock <-__hwspin_trylock <idle>-0 0d..3 1098927us+: __hwspin_unlock <-sci_glb_clr <idle>-0 0d..3 1098931us+: __hwspinlock_unlock <-__hwspin_unlock <idle>-0 0d..3 1098934us+: _raw_spin_unlock_irqrestore <-__hwspin_unlock <idle>-0 0d..3 1098938us+: sub_preempt_count <-_raw_spin_unlock_irqrestore <idle>-0 0d..2 1098942us+: ktime_get <-sc_enter_idle <idle>-0 0d..2 1098946us+: __gptimer_clocksource_read <-ktime_get <idle>-0 0d..2 1098950us+: ns_to_timeval <-sc_enter_idle <idle>-0 0d..2 1098954us+: ns_to_timespec <-ns_to_timeval <idle>-0 0d..1 1098959us+: sc_enter_idle <idle>-0 0d..1 1098967us!: trace_hardirqs_on <-sc_enter_idle <idle>-0 0d..1 1099082us : <stack trace> => trace_hardirqs_on => sc_enter_idle => cpuidle_enter_state => cpuidle_idle_call => arch_cpu_idle => cpu_startup_entry => rest_init => start_kernel # <strong><em><u># cat tracing_max_latency</u></em></strong> 1098962 #
从清单 4 中的输出信息中，可以看到当前 irqsoff 延迟跟踪器的版本信息。接下来是最大延迟时间，以 us 为单位，本例中为 1098962 us ，查看文件 tracing_max_latency 也可以获取该值。从“task:”字段可以知道延迟发生时正在运行的进程为 idle（其 pid 为 0 ）。中断的关闭操作是在函数 rcu_idle_enter中进行的，由“=> started at:”标识，函数 sc_enter_idle重新激活了中断，由“=> ended at:”标识；中断关闭的最大延迟发生在函数 trace_hardirqs_on、sc_enter_idle、cpuidle_enter_state等中，这个可以从最大延迟时间所在的记录项看到，也可以从延迟记录信息中最后的“=>”标识所对应的记录行知道这一点。
在输出信息中，irqs-off、need_resched 等字段对应于进程结构 struct task_struct 的字段或者状态标志，可以从头文件 arch/<platform>/include/asm/thread_info.h 中查看进程支持的状态标志，include/linux/sched.h 则给出了结构 struct task_struct 的定义。其中，irqs-off 字段显示是否中断被禁止，为‘ d ’表示中断被禁止；need_resched 字段表示进程状态（若显示为‘ N ’表示设置了进程状态标志 TIF_NEED_RESCHED）。hardirq/softirq 字段表示当前是否发生硬件中断 / 软中断；preempt-depth 表示是否禁止进程抢占，例如在持有自旋锁的情况下进程是不能被抢占的，本例中进程 idle 是可以被其它进程抢占的。
另外，还有用于跟踪禁止进程抢占的跟踪器 preemptoff 和跟踪中断 / 抢占禁止的跟踪器 preemptirqsoff，它们的使用方式与输出信息格式与 irqsoff 跟踪器类似，这里不再赘述。
跟踪指定模块中的函数
前面提过，通过文件 set_ftrace_filter 可以指定要跟踪的函数，缺省目标为所有可跟踪的内核函数；可以将感兴趣的函数通过 echo 写入该文件。为了方便使用，set_ftrace_filter 文件还支持简单格式的通配符。
begin*选择所有名字以 begin 字串开头的函数 *middle*选择所有名字中包含 middle 字串的函数 *end选择所有名字以 end 字串结尾的函数需要注意的是，这三种形式不能组合使用，比如“begin*middle*end”实际的效果与“begin”相同。另外，使用通配符表达式时，需要用单引号将其括起来，如果使用双引号，shell 可能会对字符‘ * ’进行扩展，这样最终跟踪的对象可能与目标函数不一样。
通过该文件还可以指定属于特定模块的函数，这要用到 mod 指令。指定模块的格式为：
echo ':mod:[module_name]' > set_ftrace_filter
下面给出了一个指定跟踪模块 ipv6 中的函数的例子。可以看到，指定跟踪模块 ipv6 中的函数会将文件 set_ftrace_filter 的内容设置为只包含该模块中的函数。
清单 5. 指定跟踪 ipv6 模块中的函数
<strong><em><u># pwd</u></em></strong> /sys/kernel/debug/tracing <em><strong><u># echo ':mod:ipv6' > set_ftrace_filter # cat set_ftrace_filter | head -5</u></strong></em> ipv6_opt_accepted inet6_net_exit ipv6_gro_complete inet6_create ipv6_addr_copy</span>
小结
本系列文章对 ftrace 的配置和使用进行了介绍。本文是其中的第二部分，介绍了 ftrace 所提供的跟踪器的使用，重点对不同格式的跟踪信息进行了描述，并对如何跟踪指定模块中的函数进行了介绍。当前 Linux 内核中 ftrace 支持多个跟踪器，由于篇幅限制，这里不能对其全部加以描述。读者可参照参考资料中给出的信息对 ftrace 跟踪器进行更深入的了解。下一篇文章将对如何在代码中通过 ftrace 提供的工具函数与 ftrace 交互进行描述。
参考资料
内核文档 Documentation/trace/ftrace.txt 。 LWN 上的文章 Secrets of the Ftrace function tracer 以及其它与 ftrace 相关的文章。 查看内核源码 kernel/trace 目录下的文件以了解 ftrace 支持的各种跟踪器。 《 Understanding the Linux Kernel, Third Edition 》 描述了 Linux 内核的实现。 在 developerWorks Linux 专区 寻找为 Linux 开发人员（包括 Linux 新手入门 ）准备的更多参考资料，查阅我们 最受欢迎的文章和教程 。 在 developerWorks 上查阅所有 Linux 技巧 和 Linux 教程 。【特此声明】
以上内容转载自http://www.ibm.com/developerworks/cn/linux/l-cn-ftrace2/，并经本人在3.10.17内核上验证通过。