ftrace 使用

最新推荐文章于 2024-08-07 16:27:35 发布

gracioushe

最新推荐文章于 2024-08-07 16:27:35 发布

阅读量1.2k

点赞数

分类专栏： kernel与Android 文章标签： linux function graph struct bash filter

kernel与Android 专栏收录该内容

132 篇文章 0 订阅

订阅专栏

　ftrace 操作概述

　　使用 ftrace 提供的跟踪器来调试或者分析内核时需要如下操作：

　　切换到目录 /sys/kernel/debug/tracing/ 下

　　查看 available_tracers 文件，获取当前内核支持的跟踪器列表

　　关闭 ftrace 跟踪，即将 0 写入文件 tracing_enabled

　　激活 ftrace_enabled ，否则 function 跟踪器的行为类似于 nop；另外，激活该选项还可以让一些跟踪器比如 irqsoff 获取更丰富的信息。建议使用 ftrace 时将其激活。要激活 ftrace_enabled ，可以通过 proc 文件系统接口来设置：

　　echo　1　>　/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 跟踪器使用示例

trace 文件给出的信息格式很清晰。首先，字段“tracer:”给出了当前所使用的跟踪器的名字，这里为 function 跟踪器。然后是跟踪信息记录的格式，TASK 字段对应任务的名字，PID 字段则给出了任务的进程 ID，字段 CPU# 表示运行被跟踪函数的 CPU 号，这里可以看到 idle 进程运行在 0 号 CPU 上，其进程 ID 是 0 ；字段 TIMESTAMP 是时间戳，其格式为“<secs>.<usecs>”，表示执行该函数时对应的时间戳；FUNCTION 一列则给出了被跟踪的函数，函数的调用者通过符号 “<-” 标明，这样可以观察到函数的调用关系。

　　function_graph 跟踪器

　　在 function 跟踪器给出的信息中，可以通过 FUNCTION 列中的符号 “<-” 来查看函数调用关系，但是由于中间会混合不同函数的调用，导致看起来非常混乱，十分不方便。function_graph 跟踪器则可以提供类似 C 代码的函数调用关系信息。通过写文件 set_graph_function 可以显示指定要生成调用关系的函数，缺省会对所有可跟踪的内核函数生成函数调用关系图。清单 2 给出了使用 function_grapch 跟踪器的示例，示例中将内核函数 __do_fault 作为观察对象，该函数在内核运作过程中会被频繁调用。

清单 2. function_graph 跟踪器使用示例

在文件 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 跟踪器使用示例

在 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 跟踪器使用示例

　[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　　　　　#　　/　　/　　　　||||||　　/　　|　　/　　　　　　　<idle>-0　　　　1dN...　4285us!:　trace_hardirqs_off_thunk　<-reschedule_interrupt　　<idle>-0　　　　1dN...　34373us+:　smp_reschedule_interrupt　<-reschedule_interrupt　　<idle>-0　　　　1dN...　34375us+:　native_apic_mem_write　<-smp_reschedule_interrupt　　<idle>-0　　　　1dN...　34380us+:　trace_hardirqs_on_thunk　<-restore_all_notrace　　<idle>-0　　　　1dN...　34384us　:　trace_hardirqs_on_caller　<-restore_all_notrace　　<idle>-0　　　　1dN...　34384us　:　<stack　trace>　　=>　trace_hardirqs_on_thunk　　[root@linux　tracing]#　cat　tracing_max_latency　　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/<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 是可以被其它进程抢占的。结构 struct task_struct 中的 lock_depth 字段是与大内核锁相关的，而最近的内核开发工作中有一部分是与移除大内核锁相关的，这里对该字段不再加以描述。

　　另外，还有用于跟踪禁止进程抢占的跟踪器 preemptoff 和跟踪中断 / 抢占禁止的跟踪器 preemptirqsoff，它们的使用方式与输出信息格式与 irqsoff 跟踪器类似，这里不再赘述。