查看文件 trace 获取跟踪信息，对内核的运行进行分析调试
接下来将对跟踪器的使用以及跟踪信息的格式通过实例加以讲解。
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 文件还支持简单格式的通配符。
人格的完善是本，财富的确立是末。
