linux学习中
分类： LINUX
2010-11-12 09:37:42
简介： ftrace 是 Linux 内核中提供的一种调试工具。使用 ftrace 可以对内核中发生的事情进行跟踪，这在调试 bug 或者分析内核时非常有用。本系列文章对 ftrace 进行了介绍，分为三部分。本文是第二部分，通过示例介绍了如何使用 ftrace 中的跟踪器，并对不同格式的跟踪信息进行了描述，同时还对如何使用 ftrace 调试指定内核模块进行了介绍。通过对本文的学习，读者可以了解如何在实践中使用 ftrace 。
ftrace 操作概述
使用 ftrace 提供的跟踪器来调试或者分析内核时需要如下操作：
echo 1 > /proc/sys/kernel/ftrace_enabled |
接下来将对跟踪器的使用以及跟踪信息的格式通过实例加以讲解。
fucntion 跟踪器
function 跟踪器可以跟踪内核函数的调用情况，可用于调试或者分析 bug ，还可用于了解和观察 Linux 内核的执行过程。清单 1 给出了使用 function 跟踪器的示例。
[root@linux tracing]# pwd
/sys/kernel/debug/tracing
[root@linux tracing]# echo 0 > tracing_enabled
[root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled
[root@linux tracing]# echo function > current_tracer
[root@linux tracing]# echo 1 > tracing_on
[root@linux tracing]# echo 1 > tracing_enabled
# 让内核运行一段时间，这样 ftrace 可以收集一些跟踪信息，之后再停止跟踪
[root@linux tracing]# echo 0 > tracing_enabled
[root@linux tracing]# cat trace | head -10
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
|
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 作为观察对象，该函数在内核运作过程中会被频繁调用。
[root@linux tracing]# pwd
/sys/kernel/debug/tracing
[root@linux tracing]# echo 0 > tracing_enabled
[root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled
[root@linux tracing]# echo function_graph > current_tracer
[root@linux tracing]# echo __do_fault > set_graph_function
[root@linux tracing]# echo 1 > tracing_on
[root@linux tracing]# echo 1 > tracing_enabled
# 让内核运行一段时间，这样 ftrace 可以收集一些跟踪信息，之后再停止跟踪
[root@linux tracing]# echo 0 > tracing_enabled
[root@linux tracing]# cat trace | head -20
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
1) 9.936 us | }
1) 0.714 us | put_prev_task_fair();
1) | pick_next_task_fair() {
1) | set_next_entity() {
1) 0.647 us | update_stats_wait_end();
1) 0.699 us | __dequeue_entity();
1) 3.322 us | }
1) 0.865 us | hrtick_start_fair();
1) 6.313 us | }
1) | __switch_to_xtra() {
1) 1.601 us | memcpy();
1) 3.938 us | }
[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 所示。
[root@linux tracing]# pwd
/sys/kernel/debug/tracing
[root@linux tracing]# echo 0 > tracing_enabled
[root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled
[root@linux tracing]# echo sched_switch > current_tracer
[root@linux tracing]# echo 1 > tracing_on
[root@linux tracing]# echo 1 > tracing_enabled
# 让内核运行一段时间，这样 ftrace 可以收集一些跟踪信息，之后再停止跟踪
[root@linux tracing]# echo 0 > tracing_enabled
[root@linux tracing]# cat trace | head -10
# tracer: sched_switch
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
bash-1408 [000] 26208.816058: 1408:120:S + [000] 1408:120:S bash
bash-1408 [000] 26208.816070: 1408:120:S + [000] 1408:120:S bash
bash-1408 [000] 26208.816921: 1408:120:R + [000] 9:120:R events/0
bash-1408 [000] 26208.816939: 1408:120:R ==> [000] 9:120:R events/0
events/0-9 [000] 26208.817081: 9:120:R + [000] 1377:120:R gnome-terminal
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 则记录中断被关闭的最大延时。
[root@linux tracing]# pwd /sys/kernel/debug/tracing [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled [root@linux tracing]# echo irqsoff > current_tracer [root@linux tracing]# echo 1 > tracing_on [root@linux tracing]# echo 1 > tracing_enabled # 让内核运行一段时间，这样 ftrace 可以收集一些跟踪信息，之后再停止跟踪 [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# cat trace | head -35 # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 2.6.33.1 # -------------------------------------------------------------------- # latency: 34380 us, #6/6, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:2) # ----------------- # | task: -0 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # => started at: reschedule_interrupt # => ended at: restore_all_notrace # # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| /_--=> lock-depth # |||||/ delay # cmd pid |||||| time | caller # \ / |||||| \ | / |
从清单 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*middle*end”实际的效果与“begin”相同。另外，使用通配符表达式时，需要用单引号将其括起来，如果使用双引号，shell 可能会对字符‘ * ’进行扩展，这样最终跟踪的对象可能与目标函数不一样。
通过该文件还可以指定属于特定模块的函数，这要用到 mod 指令。指定模块的格式为：
echo ':mod:[module_name]' > set_ftrace_filter |
下面给出了一个指定跟踪模块 ipv6 中的函数的例子。可以看到，指定跟踪模块 ipv6 中的函数会将文件 set_ftrace_filter 的内容设置为只包含该模块中的函数。
[root@linux tracing]# pwd /sys/kernel/debug/tracing [root@linux tracing]# echo ':mod:ipv6' > set_ftrace_filter [root@linux tracing]# cat set_ftrace_filter | head -5 ipv6_opt_accepted inet6_net_exit ipv6_gro_complete inet6_create ipv6_addr_copy |
小结
本系列文章对 ftrace 的配置和使用进行了介绍。本文是其中的第二部分，介绍了 ftrace 所提供的跟踪器的使用，重点对不同格式的跟踪信息进行了描述，并对如何跟踪指定模块中的函数进行了介绍。当前 Linux 内核中 ftrace 支持多个跟踪器，由于篇幅限制，这里不能对其全部加以描述。读者可参照参考资料中给出的信息对 ftrace 跟踪器进行更深入的了解。下一篇文章将对如何在代码中通过 ftrace 提供的工具函数与 ftrace 交互进行描述。
