简介：ftrace 是 Linux 内核中提供的一种调试工具。使用 ftrace 可以对内核中发生的事情进行跟踪，这在调试 bug 或者分析内核时非常有用。本系列文章对 ftrace 进行了介绍，分为三部分。本文是第一部分，介绍了内核相关的编译选项、用户态访问 ftrace 的接口、ftrace 的数据文件，并对 ftrace 提供的跟踪器的用途进行了介绍，以使读者更好的了解和使用该工具。
ftrace 是内建于 Linux 内核的跟踪工具，从 2.6.27 开始加入主流内核。使用 ftrace 可以调试或者分析内核中发生的事情。ftrace 提供了不同的跟踪器，以用于不同的场合，比如跟踪内核函数调用、对上下文切换进行跟踪、查看中断被关闭的时长、跟踪内核态中的延迟以及性能问题等。系统开 发人员可以使用 ftrace 对内核进行跟踪调试，以找到内核中出现的问题的根源，方便对其进行修复。另外，对内核感兴趣的读者还可以通过 ftrace 来观察内核中发生的活动，了解内核的工作机制。
让内核支持 ftrace
使用 ftrace ，首先要将其编译进内核。内核源码目录下的 kernel/trace/Makefile 文件给出了 ftrace 相关的编译选项。
清单 1. ftrace 相关的配置选项列表
1.CONFIG_FUNCTION_TRACER 2.CONFIG_FUNCTION_GRAPH_TRACER 3.CONFIG_CONTEXT_SWITCH_TRACER 4.CONFIG_NOP_TRACER 5.CONFIG_SCHED_TRACER 6....ftrace 相关的配置选项比较多，针对不同的跟踪器有各自对应的配置选项。不同的选项有不同的依赖关系，内核源码目录下的 kernel/trace/Kconfig 文件描述了这些依赖关系。读者可以参考 Makefile 文件和 Konfig 文件，然后选中自己所需要的跟踪器。
通常在配置内核时，使用 make menuconfig 会更直观一些。以 2.6.33.1 版本的内核为例，要将 ftrace 编译进内核，可以选中 Kernel hacking （图 1 ）下的 Tracers 菜单项（图 2 ）。
图 1. Kernel hacking
图 2. Tracers
进入 Tracers 菜单下，可以看到内核支持的跟踪器列表。如图 3 所示，这里选中了所有的跟踪器，读者可以根据自己的需要选中特定的跟踪器。
图 3. 内核支持的跟踪器列表
这里要注意，如果是在 32 位 x86 机器上，编译时不要选中 General setup 菜单项（图 4 ）下的 Optimize for size 选项（图 5 ），否则就无法看到图 3 中的 Kernel Function Graph Tracer 选项。这是因为在 Konfig 文件中，针对 32 位 x86 机器，表项 FUNCTION_GRAPH_TRACER 有一个特殊的依赖条件：
图 4. General setup
图 5. Optimize for size
ftrace 通过 debugfs 向用户态提供了访问接口，所以还需要将 debugfs 编译进内核。激活对 debugfs 的支持，可以直接编辑内核配置文件 .config ，设置 CONFIG_DEBUG_FS=y ；或者在 make menuconfig 时到 Kernel hacking 菜单下选中对 debugfs 文件系统的支持，如图 6 所示。
图 6. debugfs 编译选项
配置完成后，编译安装新内核，然后启动到新内核。 注意，激活 ftrace 支持后，编译内核时会使用编译器的 -pg 选项，这是在 kernel/trace/Makefile 文件中定义的，如清单 2 所示。
清单 2. 激活编译选项 -pg
1.ifdef CONFIG_FUNCTION_TRACER 2.ORIG_CFLAGS := $(KBUILD_CFLAGS) 3.KBUILD_CFLAGS = $(subst -pg,,$(ORIG_CFLAGS)) 4.... 5.endif 6....使用 -pg 选项会在编译得到的内核映像中加入大量的调试信息。一般情况下，只是在开发测试阶段激活 ftrace 支持，以调试内核，修复 bug 。最终用于发行版的内核则会关闭 -pg 选项，也就无法使用 ftrace。
通过 debugfs 访问 ftrace
ftrace 通过 debugfs 向用户态提供访问接口。配置内核时激活 debugfs 后会创建目录 /sys/kernel/debug ，debugfs 文件系统就是挂载到该目录。要挂载该目录，需要将如下内容添加到 /etc/fstab 文件：
1.debugfs /sys/kernel/debug debugfs defaults 0 0或者可以在运行时挂载：
1.mount -t debugfs nodev /sys/kernel/debug激活内核对 ftrace 的支持后会在 debugfs 下创建一个 tracing 目录 /sys/kernel/debug/tracing 。该目录下包含了 ftrace 的控制和输出文件，如图 7 所示。根据编译内核时针对 ftrace 的设定不同，该目录下实际显示的文件和目录与这里也会不同。
图 7. tracing 目录下的文件
ftrace 的数据文件
/sys/kernel/debug/tracing 目录下文件和目录比较多，有些是各种跟踪器共享使用的，有些是特定于某个跟踪器使用的。在操作这些数据文件时，通常使用 echo 命令来修改其值，也可以在程序中通过文件读写相关的函数来操作这些文件的值。下面只对部分文件进行描述，读者可以参考内核源码包中 Documentation/trace 目录下的文档以及 kernel/trace 下的源文件以了解其余文件的用途。
- README文件提供了一个简短的使用说明，展示了 ftrace 的操作命令序列。可以通过 cat 命令查看该文件以了解概要的操作流程。
- current_tracer用于设置或显示当前使用的跟踪器；使用 echo 将跟踪器名字写入该文件可以切换到不同的跟踪器。系统启动后，其缺省值为 nop ，即不做任何跟踪操作。在执行完一段跟踪任务后，可以通过向该文件写入 nop 来重置跟踪器。
- available_tracers记录了当前编译进内核的跟踪器的列表，可以通过 cat 查看其内容；其包含的跟踪器与图 3 中所激活的选项是对应的。写 current_tracer 文件时用到的跟踪器名字必须在该文件列出的跟踪器名字列表中。
- trace文件提供了查看获取到的跟踪信息的接口。可以通过 cat 等命令查看该文件以查看跟踪到的内核活动记录，也可以将其内容保存为记录文件以备后续查看。
- tracing_enabled用于控制 current_tracer 中的跟踪器是否可以跟踪内核函数的调用情况。写入 0 会关闭跟踪活动，写入 1 则激活跟踪功能；其缺省值为 1 。
- set_graph_function设置要清晰显示调用关系的函数，显示的信息结构类似于 C 语言代码，这样在分析内核运作流程时会更加直观一些。在使用 function_graph 跟踪器时使用；缺省为对所有函数都生成调用关系序列，可以通过写该文件来指定需要特别关注的函数。
- buffer_size_kb用于设置单个 CPU 所使用的跟踪缓存的大小。跟踪器会将跟踪到的信息写入缓存，每个 CPU 的跟踪缓存是一样大的。跟踪缓存实现为环形缓冲区的形式，如果跟踪到的信息太多，则旧的信息会被新的跟踪信息覆盖掉。注意，要更改该文件的值需要先将 current_tracer 设置为 nop 才可以。
- tracing_on用于控制跟踪的暂停。有时候在观察到某些事件时想暂时关闭跟踪，可以将 0 写入该文件以停止跟踪，这样跟踪缓冲区中比较新的部分是与所关注的事件相关的；写入 1 可以继续跟踪。
- available_filter_functions记录了当前可以跟踪的内核函数。对于不在该文件中列出的函数，无法跟踪其活动。
- set_ftrace_filter和 set_ftrace_notrace在编译内核时配置了动态 ftrace （选中 CONFIG_DYNAMIC_FTRACE 选项）后使用。前者用于显示指定要跟踪的函数，后者则作用相反，用于指定不跟踪的函数。如果一个函数名同时出现在这两个文件中，则这个函数的执行状况不会 被跟踪。这些文件还支持简单形式的含有通配符的表达式，这样可以用一个表达式一次指定多个目标函数；具体使用在后续文章中会有描述。注意，要写入这两个文 件的函数名必须可以在文件 available_filter_functions 中看到。缺省为可以跟踪所有内核函数，文件 set_ftrace_notrace 的值则为空。
ftrace 跟踪器
ftrace 当前包含多个跟踪器，用于跟踪不同类型的信息，比如进程调度、中断关闭等。可以查看文件 available_tracers 获取内核当前支持的跟踪器列表。在编译内核时，也可以看到内核支持的跟踪器对应的选项，如之前图 3 所示。
- nop跟踪器不会跟踪任何内核活动，将 nop 写入 current_tracer 文件可以删除之前所使用的跟踪器，并清空之前收集到的跟踪信息，即刷新 trace 文件。
- function跟踪器可以跟踪内核函数的执行情况；可以通过文件 set_ftrace_filter 显示指定要跟踪的函数。
- function_graph跟踪器可以显示类似 C 源码的函数调用关系图，这样查看起来比较直观一些；可以通过文件 set_grapch_function 显示指定要生成调用流程图的函数。
- sched_switch跟踪器可以对内核中的进程调度活动进行跟踪。
- irqsoff跟踪器和 preemptoff跟踪器分别跟踪关闭中断的代码和禁止进程抢占的代码，并记录关闭的最大时长，preemptirqsoff跟踪器则可以看做它们的组合。
ftrace 还支持其它一些跟踪器，比如 initcall、ksym_tracer、mmiotrace、sysprof 等。ftrace 框架支持扩展添加新的跟踪器。读者可以参考内核源码包中 Documentation/trace 目录下的文档以及 kernel/trace 下的源文件，以了解其它跟踪器的用途和如何添加新的跟踪器。
ftrace 操作概述
使用 ftrace 提供的跟踪器来调试或者分析内核时需要如下操作：
- 切换到目录 /sys/kernel/debug/tracing/ 下
- 查看 available_tracers 文件，获取当前内核支持的跟踪器列表
- 关闭 ftrace 跟踪，即将 0 写入文件 tracing_enabled
- 激活 ftrace_enabled ，否则 function 跟踪器的行为类似于 nop；另外，激活该选项还可以让一些跟踪器比如
irqsoff 获取更丰富的信息。建议使用 ftrace 时将其激活。要激活 ftrace_enabled ，可以通过 proc
文件系统接口来设置：
1.echo1 > /proc/sys/kernel/ftrace_enabled - 将所选择的跟踪器的名字写入文件 current_tracer
- 将要跟踪的函数写入文件 set_ftrace_filter ，将不希望跟踪的函数写入文件 set_ftrace_notrace。通常直接操作文件 set_ftrace_filter 就可以了
- 激活 ftrace 跟踪，即将 1 写入文件 tracing_enabled。还要确保文件 tracing_on 的值也为 1，该文件可以控制跟踪的暂停
- 如果是对应用程序进行分析的话，启动应用程序的执行，ftrace 会跟踪应用程序运行期间内核的运作情况
- 通过将 0 写入文件 tracing_on 来暂停跟踪信息的记录，此时跟踪器还在跟踪内核的运行，只是不再向文件 trace 中写入跟踪信息；或者将 0 写入文件 tracing_enabled 来关闭跟踪
- 查看文件 trace 获取跟踪信息，对内核的运行进行分析调试
接下来将对跟踪器的使用以及跟踪信息的格式通过实例加以讲解。
fucntion 跟踪器
function 跟踪器可以跟踪内核函数的调用情况，可用于调试或者分析 bug ，还可用于了解和观察 Linux 内核的执行过程。清单 1 给出了使用 function 跟踪器的示例。
清单 1. function 跟踪器使用示例
01.[root@linux tracing]# pwd 02./sys/kernel/debug/tracing 03.[root@linux tracing]# echo 0 > tracing_enabled 04.[root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled 05.[root@linux tracing]# echo function > current_tracer 06.[root@linux tracing]# echo 1 > tracing_on 07.[root@linux tracing]# echo 1 > tracing_enabled 08. 09.# 让内核运行一段时间，这样 ftrace 可以收集一些跟踪信息，之后再停止跟踪10. 11.[root@linux tracing]# echo 0 > tracing_enabled 12.[root@linux tracing]# cat trace | head -10 13.# tracer: function 14.# 15.# TASK-PID CPU# TIMESTAMP FUNCTION 16.# | | | | | 17. -0 [000] 20654.426521: _raw_spin_lock <-scheduler_tick 18. -0 [000] 20654.426522: task_tick_idle <-scheduler_tick 19. -0 [000] 20654.426522: cpumask_weight <-scheduler_tick 20. -0 [000] 20654.426523: cpumask_weight <-scheduler_tick 21. -0 [000] 20654.426523: run_posix_cpu_timers <-update_process_times 22.-0 [000] 20654.426524: hrtimer_forward <-tick_sched_timer trace 文件给出的信息格式很清晰。首先，字段“tracer:”给出了当前所使用的跟踪器的名字，这里为 function
跟踪器。然后是跟踪信息记录的格式，TASK 字段对应任务的名字，PID 字段则给出了任务的进程 ID，字段 CPU# 表示运行被跟踪函数的
CPU 号，这里可以看到 idle 进程运行在 0 号 CPU 上，其进程 ID 是 0 ；字段 TIMESTAMP
是时间戳，其格式为“
function_graph 跟踪器
在 function 跟踪器给出的信息中，可以通过 FUNCTION 列中的符号 “<-” 来查看函数调用关系，但是由于中间会混合不同函数的调用，导致看起来非常混乱，十分不方便。function_graph 跟踪器则可以提供类似 C 代码的函数调用关系信息。通过写文件 set_graph_function 可以显示指定要生成调用关系的函数，缺省会对所有可跟踪的内核函数生成函数调用关系图。清单 2 给出了使用 function_grapch 跟踪器的示例，示例中将内核函数 __do_fault 作为观察对象，该函数在内核运作过程中会被频繁调用。
清单 2. function_graph 跟踪器使用示例
01.[root@linux tracing]# pwd 02./sys/kernel/debug/tracing 03.[root@linux tracing]# echo 0 > tracing_enabled 04.[root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled 05.[root@linux tracing]# echo function_graph > current_tracer 06.[root@linux tracing]# echo __do_fault > set_graph_function 07.[root@linux tracing]# echo 1 > tracing_on 08.[root@linux tracing]# echo 1 > tracing_enabled 09. 10.# 让内核运行一段时间，这样 ftrace 可以收集一些跟踪信息，之后再停止跟踪11. 12.[root@linux tracing]# echo 0 > tracing_enabled 13.[root@linux tracing]# cat trace | head -20 14.# tracer: function_graph 15.# 16.# CPU DURATION FUNCTION CALLS 17.# | | | | | | | 18.1) 9.936 us | } 19.1) 0.714 us | put_prev_task_fair(); 20.1) | pick_next_task_fair() { 21.1) | set_next_entity() { 22.1) 0.647 us | update_stats_wait_end(); 23.1) 0.699 us | __dequeue_entity(); 24.1) 3.322 us | } 25.1) 0.865 us | hrtick_start_fair(); 26.1) 6.313 us | } 27.1) | __switch_to_xtra() { 28.1) 1.601 us | memcpy(); 29.1) 3.938 us | } 30.[root@linux tracing]# echo > set_graph_function在文件 trace 的输出信息中，首先给出的也是当前跟踪器的名字，这里是 function_graph 。接下来是详细的跟踪信息，可以看到，函数的调用关系以类似 C 代码的形式组织。
CPU 字段给出了执行函数的 CPU 号，本例中都为 1 号 CPU。DURATION 字段给出了函数执行的时间长度，以 us 为单位。FUNCTION CALLS 则给出了调用的函数，并显示了调用流程。注意，对于不调用其它函数的函数，其对应行以“;”结尾，而且对应的 DURATION 字段给出其运行时长；对于调用其它函数的函数，则在其“}”对应行给出了运行时长，该时间是一个累加值，包括了其内部调用的函数的执行时长。 DURATION 字段给出的时长并不是精确的，它还包含了执行 ftrace 自身的代码所耗费的时间，所以示例中将内部函数时长累加得到的结果会与对应的外围调用函数的执行时长并不一致；不过通过该字段还是可以大致了解函数在时间 上的运行开销的。清单 2 中最后通过 echo 命令重置了文件 set_graph_function 。
sched_switch 跟踪器
sched_switch 跟踪器可以对进程的调度切换以及之间的唤醒操作进行跟踪，如清单 3 所示。
清单 3. sched_switch 跟踪器使用示例
01.[root@linux tracing]# pwd 02./sys/kernel/debug/tracing 03.[root@linux tracing]# echo 0 > tracing_enabled 04.[root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled 05.[root@linux tracing]# echo sched_switch > current_tracer 06.[root@linux tracing]# echo 1 > tracing_on 07.[root@linux tracing]# echo 1 > tracing_enabled 08. 09.# 让内核运行一段时间，这样 ftrace 可以收集一些跟踪信息，之后再停止跟踪10. 11.[root@linux tracing]# echo 0 > tracing_enabled 12.[root@linux tracing]# cat trace | head -10 13.# tracer: sched_switch 14.# 15.# TASK-PID CPU# TIMESTAMP FUNCTION 16.# | | | | | 17. bash-1408 [000] 26208.816058: 1408:120:S + [000] 1408:120:S bash18. bash-1408 [000] 26208.816070: 1408:120:S + [000] 1408:120:S bash19. bash-1408 [000] 26208.816921: 1408:120:R + [000] 9:120:R events/0 20. bash-1408 [000] 26208.816939: 1408:120:R ==> [000] 9:120:R events/0 21. events/0-9 [000] 26208.817081: 9:120:R + [000] 1377:120:R gnome-terminal22. events/0-9 [000] 26208.817088: 9:120:S ==> [000] 1377:120:R gnome-terminal在 sched_swich 跟踪器获取的跟踪信息中记录了进程间的唤醒操作和调度切换信息，可以通过符号‘ + ’和‘ ==> ’区分；唤醒操作记录给出了当前进程唤醒运行的进程，进程调度切换记录中显示了接替当前进程运行的后续进程。
描述进程状态的格式为“Task-PID:Priority:Task-State”。以示例跟踪信息中的第一条跟踪记录为例，可以看到进程 bash 的 PID 为 1408 ，其对应的内核态优先级为 120 ，当前状态为 S（可中断睡眠状态），当前 bash 并没有唤醒其它进程；从第 3 条记录可以看到，进程 bash 将进程 events/0 唤醒，而在第 4 条记录中发生了进程调度，进程 bash 切换到进程 events/0 执行。
在 Linux 内核中，进程的状态在内核头文件 include/linux/sched.h 中定义，包括可运行状态 TASK_RUNNING（对应跟踪信息中的符号‘ R ’）、可中断阻塞状态 TASK_INTERRUPTIBLE（对应跟踪信息中的符号‘ S ’）等。同时该头文件也定义了用户态进程所使用的优先级的范围，最小值为 MAX_USER_RT_PRIO（值为 100 ），最大值为 MAX_PRIO - 1（对应值为 139 ），缺省为 DEFAULT_PRIO（值为 120 ）；在本例中，进程优先级都是缺省值 120 。
irqsoff 跟踪器
当关闭中断时，CPU 会延迟对设备的状态变化做出反应，有时候这样做会对系统性能造成比较大的影响。irqsoff 跟踪器可以对中断被关闭的状况进行跟踪，有助于发现导致较大延迟的代码；当出现最大延迟时，跟踪器会记录导致延迟的跟踪信息，文件 tracing_max_latency 则记录中断被关闭的最大延时。
清单 4. irqsoff 跟踪器使用示例
01.[root@linux tracing]# pwd 02./sys/kernel/debug/tracing 03.[root@linux tracing]# echo 0 > tracing_enabled 04.[root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled 05.[root@linux tracing]# echo irqsoff > current_tracer 06.[root@linux tracing]# echo 1 > tracing_on 07.[root@linux tracing]# echo 1 > tracing_enabled 08. 09.# 让内核运行一段时间，这样 ftrace 可以收集一些跟踪信息，之后再停止跟踪10. 11.[root@linux tracing]# echo 0 > tracing_enabled 12.[root@linux tracing]# cat trace | head -35 13.# tracer: irqsoff 14.# 15.# irqsoff latency trace v1.1.5 on 2.6.33.1 16.# -------------------------------------------------------------------- 17.# latency: 34380 us, #6/6, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:2) 18.# ----------------- 19.# | task: -0 (uid:0 nice:0 policy:0 rt_prio:0) 20.# ----------------- 21.# => started at: reschedule_interrupt 22.# => ended at: restore_all_notrace 23.# 24.# 25.# _------=> CPU# 26.# / _-----=> irqs-off 27.# | / _----=> need-resched 28.# || / _---=> hardirq/softirq 29.# ||| / _--=> preempt-depth 30.# |||| /_--=> lock-depth 31.# |||||/ delay 32.# cmd pid |||||| time | caller 33.# \ / |||||| \ | / 34. -0 1dN... 4285us!: trace_hardirqs_off_thunk <-reschedule_interrupt 35. -0 1dN... 34373us+: smp_reschedule_interrupt <-reschedule_interrupt 36. -0 1dN... 34375us+: native_apic_mem_write <-smp_reschedule_interrupt 37. -0 1dN... 34380us+: trace_hardirqs_on_thunk <-restore_all_notrace 38. -0 1dN... 34384us : trace_hardirqs_on_caller <-restore_all_notrace 39. -0 1dN... 34384us : 40.=> trace_hardirqs_on_thunk 41.[root@linux tracing]# cat tracing_max_latency 42.34380从清单 4 中的输出信息中，可以看到当前 irqsoff 延迟跟踪器的版本信息。接下来是最大延迟时间，以 us 为单位，本例中为 34380 us ，查看文件 tracing_max_latency 也可以获取该值。从“task:”字段可以知道延迟发生时正在运行的进程为 idle（其 pid 为 0 ）。中断的关闭操作是在函数 reschedule_interrupt 中进行的，由“=> started at:”标识，函数 restore_all_ontrace 重新激活了中断，由“=> ended at:”标识；中断关闭的最大延迟发生在函数 trace_hardirqs_on_thunk 中，这个可以从最大延迟时间所在的记录项看到，也可以从延迟记录信息中最后的“=>”标识所对应的记录行知道这一点。
在输出信息中，irqs-off、need_resched 等字段对应于进程结构 struct task_struct
的字段或者状态标志，可以从头文件 arch/
另外，还有用于跟踪禁止进程抢占的跟踪器 preemptoff 和跟踪中断 / 抢占禁止的跟踪器 preemptirqsoff，它们的使用方式与输出信息格式与 irqsoff 跟踪器类似，这里不再赘述。
跟踪指定模块中的函数
前面提过，通过文件 set_ftrace_filter 可以指定要跟踪的函数，缺省目标为所有可跟踪的内核函数；可以将感兴趣的函数通过 echo 写入该文件。为了方便使用，set_ftrace_filter 文件还支持简单格式的通配符。
- begin*选择所有名字以 begin 字串开头的函数
- *middle*选择所有名字中包含 middle 字串的函数
- *end选择所有名字以 end 字串结尾的函数
需要注意的是，这三种形式不能组合使用，比如“begin*middle*end”实际的效果与“begin”相同。另外，使用通配符表达式 时，需要用单引号将其括起来，如果使用双引号，shell 可能会对字符‘ * ’进行扩展，这样最终跟踪的对象可能与目标函数不一样。
通过该文件还可以指定属于特定模块的函数，这要用到 mod 指令。指定模块的格式为：
1.echo ':mod:[module_name]' > set_ftrace_filter下面给出了一个指定跟踪模块 ipv6 中的函数的例子。可以看到，指定跟踪模块 ipv6 中的函数会将文件 set_ftrace_filter 的内容设置为只包含该模块中的函数。
清单 5. 指定跟踪 ipv6 模块中的函数
01.[root@linux tracing]# pwd 02./sys/kernel/debug/tracing 03.[root@linux tracing]# echo ':mod:ipv6' > set_ftrace_filter 04.[root@linux tracing]# cat set_ftrace_filter | head -5 05.ipv6_opt_accepted 06.inet6_net_exit 07.ipv6_gro_complete 08.inet6_create 09.ipv6_addr_copy
内核头文件 include/linux/kernel.h 中描述了 ftrace 提供的工具函数的原型，这些函数包括 trace_printk、tracing_on/tracing_off 等。本文通过示例模块程序向读者展示如何在代码中使用这些工具函数。
使用 trace_printk 打印跟踪信息
ftrace 提供了一个用于向 ftrace 跟踪缓冲区输出跟踪信息的工具函数，叫做 trace_printk()，它的使用方式与 printk() 类似。可以通过 trace 文件读取该函数的输出。从头文件 include/linux/kernel.h 中可以看到，在激活配置 CONFIG_TRACING 后，trace_printk() 定义为宏：
1.#define trace_printk(fmt, args...) \ 2. ...下面通过一个示例模块 ftrace_demo 来演示如何使用 trace_printk() 向跟踪缓冲区输出信息，以及如何查看这些信息。这里的示例模块程序中仅提供了初始化和退出函数，这样读者不会因为需要为模块创建必要的访问接口比如设备文 件而分散注意力。注意，编译模块时要加入 -pg 选项。
清单 1. 示例模块 ftrace_demo
01./* 02.* ftrace_demo.c 03.*/ 04.#include 05.#include 06.#include 07. 08.MODULE_LICENSE("GPL"); 09. 10.static int ftrace_demo_init(void) 11.{ 12. trace_printk("Can not see this in trace unless loaded for the second time\n"); 13. return 0; 14.} 15. 16.static void ftrace_demo_exit(void) 17.{ 18. trace_printk("Module unloading\n"); 19.} 20. 21.module_init(ftrace_demo_init); 22.module_exit(ftrace_demo_exit);示例模块非常简单，仅仅是在模块初始化函数和退出函数中输出信息。接下来要对模块的运行进行跟踪，如清单 2 所示。
清单 2. 对模块 ftrace_demo 进行跟踪
01.[root@linux tracing]# pwd 02./sys/kernel/debug/tracing 03.[root@linux tracing]# echo 0 > tracing_enabled 04.[root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled 05.[root@linux tracing]# echo function_graph > current_tracer 06. 07.# 事先加载模块 ftrace_demo 08. 09.[root@linux tracing]# echo ':mod:ftrace_demo' > set_ftrace_filter 10.[root@linux tracing]# cat set_ftrace_filter 11.ftrace_demo_init 12.ftrace_demo_exit 13. 14.# 将模块 ftrace_demo 卸载15. 16.[root@linux tracing]# echo 1 > tracing_enabled 17. 18.# 重新进行模块 ftrace_demo 的加载与卸载操作19. 20.[root@linux tracing]# cat trace 21.# tracer: function_graph 22.# 23.# CPU DURATION FUNCTION CALLS 24.# | | | | | | | 25.1) | /* Can not see this in trace unless loaded for the second time */ 26.0) | /* Module unloading */在这个例子中，使用 mod 指令显式指定跟踪模块 ftrace_demo 中的函数，这需要提前加载该模块，否则在写文件 set_ftrace_filter 时会因为找不到该模块报错。这样在第一次加载模块时，其初始化函数 ftrace_demo_init 中调用 trace_printk 打印的语句就跟踪不到了。因此这里会将其卸载，然后激活跟踪，再重新进行模块 ftrace_demo 的加载与卸载操作。最终可以从文件 trace 中看到模块在初始化和退出时调用 trace_printk() 输出的信息。
这里仅仅是为了以简单的模块进行演示，故只定义了模块的 init/exit 函数，重复加载模块也只是为了获取初始化函数输出的跟踪信息。实践中，可以在模块的功能函数中加入对 trace_printk 的调用，这样可以记录模块的运作情况，然后对其特定功能进行调试优化。还可以将对 trace_printk() 的调用通过宏来控制编译，这样可以在调试时将其开启，在最终发布时将其关闭。
使用 tracing_on/tracing_off 控制跟踪信息的记录
在跟踪过程中，有时候在检测到某些事件发生时，想要停止跟踪信息的记录，这样，跟踪缓冲区中较新的数据是与该事件有关的。在用户态，可以通过向 文件 tracing_on 写入 0 来停止记录跟踪信息，写入 1 会继续记录跟踪信息。而在内核代码中，可以通过函数 tracing_on() 和 tracing_off() 来做到这一点，它们的行为类似于对 /sys/kernel/debug/tracing 下的文件 tracing_on 分别执行写 1 和 写 0 的操作。使用这两个函数，会对跟踪信息的记录控制地更准确一些，这是因为在用户态写文件 tracing_on 到实际暂停跟踪，中间由于上下文切换、系统调度控制等可能已经经过较长的时间，这样会积累大量的跟踪信息，而感兴趣的那部分可能会被覆盖掉了。
现在对清单 1 中的代码进行修改，使用 tracing_off() 来控制跟踪信息记录的暂停。
清单 3. 使用 tracing_off 的模块 ftrace_demo
01./* 02.* ftrace_demo.c 03.* modified to demostrate the usage of tracing_off 04.*/ 05.#include 06.#include 07.#include 08. 09.MODULE_LICENSE("GPL"); 10. 11.static int ftrace_demo_init(void) 12.{ 13. trace_printk("ftrace_demo_init called\n"); 14. tracing_off(); 15. return 0; 16.} 17. 18.static void ftrace_demo_exit(void) 19.{ 20. trace_printk("ftrace_demo_exit called\n"); 21. tracing_off(); 22.} 23. 24.module_init(ftrace_demo_init); 25.module_exit(ftrace_demo_exit);下面对其进行跟踪，如清单 4 所示。
清单 4. 跟踪
01.[root@linux tracing]# pwd 02./sys/kernel/debug/tracing 03.[root@linux tracing]# echo 0 > tracing_enabled 04.[root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled 05.[root@linux tracing]# echo 1 > tracing_on 06.[root@linux tracing]# echo function > current_tracer 07.[root@linux tracing]# echo 1 > tracing_enabled 08. 09.# 加载模块 ftrace_demo，模块初始化函数 ftrace_demo_init 被调用10. 11.[root@linux tracing]# cat tracing_on 12.0 13.[root@linux tracing]# cat trace | wc -l 14.120210 15.[root@linux tracing]# cat trace | grep -n ftrace_demo_init 16.120187: insmod-2897 [000] 2610.504611: ftrace_demo_init <-do_one_initcall 17.120193: insmod-2897 [000] 2610.504667: ftrace_demo_init: ftrace_demo_init called 18. 19.[root@linux tracing]# echo 1 > tracing_on # 继续跟踪信息的记录20. 21.# 卸载模块 ftrace_demo，模块函数 ftrace_demo_exit 被调用22. 23.[root@linux tracing]# cat tracing_on 24.0 25.[root@linux tracing]# wc -l trace 26.120106 trace 27.[root@linux tracing]# grep -n ftrace_demo_exit trace 28.120106: rmmod-2992 [001] 3016.884449: : ftrace_demo_exit called在这个例子中，跟踪开始之前需要确保 tracing_on 的值为 1。跟踪开始后，加载模块 ftrace_demo，其初始化方法 ftrace_demo_init 被调用，该方法会调用 tracing_off() 函数来暂停跟踪信息的记录，这时文件 tracing_on 的值被代码设置为 0。查看文件 trace，可以看到 ftrace_demo_init 相关的记录位于跟踪信息的末端，这是因为从调用 trace_off() 到其生效需要一段时间，这段时间中的内核活动会被记录下来；相比从用户态读写 tracing_on 文件，这段时间开销要小了许多。卸载模块时的情况与此类似。从这里可以看到，在代码中使用 tracing_off() 可以控制将感兴趣的信息保存在跟踪缓冲区的末端位置，不会很快被新的信息所覆盖，便于及时查看。
实际代码中，可以通过特定条件（比如检测到某种异常状况，等等）来控制跟踪信息的记录，函数的使用方式类似如下的形式：
1.if (condition) 2. tracing_on() or tracing_off()跟踪模块运行状况时，使用 ftrace 命令操作序列在用户态进行必要的设置，而在代码中则可以通过 traceing_on() 控制在进入特定代码区域时开启跟踪信息，并在遇到某些条件时通过 tracing_off() 暂停；读者可以在查看完感兴趣的信息后，将 1 写入 tracing_on 文件以继续记录跟踪信息。实践中，可以通过宏来控制是否将对这些函数的调用编译进内核模块，这样可以在调试时将其开启，在最终发布时将其关闭。
用户态的应用程序可以通过直接读写文件 tracing_on 来控制记录跟踪信息的暂停状态，以便了解应用程序运行期间内核中发生的活动。