ftrace使用说明(二)

精选转载

lilinji 2012-08-16 09:54:06 博主文章分类：Linux_Soft

文章标签 软件 文章分类 运维

1.1 Ftrace数据文件介绍

/sys/kernel/debug/tracing目录下文件和目录比较多，有些是各种跟踪器共享使用的，有些是特定于某个跟踪器使用的。在操作这些数据文件时，通常使用 echo命令来修改其值，也可以在程序中通过文件读写相关的函数来操作这些文件的值。下面只对部分文件进行描述，读者可以参考内核源码包中 Documentation/trace 目录下的文档以及 kernel/trace 下的源文件以了解其余文件的用途。

README：提供了一个简短的使用说明，展示了ftrace的操作命令序列。可以通过 cat 命令查看该文件以了解概要的操作流程。
current_tracer：用于设置或显示当前使用的跟踪器；使用 echo 将跟踪器名字写入该文件可以切换到不同的跟踪器。系统启动后，其缺省值为 nop ，即不做任何跟踪操作。在执行完一段跟踪任务后，可以通过向该文件写入 nop 来重置跟踪器。
available_tracers：记录了当前编译进内核的跟踪器的列表，可以通过 cat 查看其内容；其包含的跟踪器与内核配置选项中所激活的选项是对应的。写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 的值则为空。

1.2 Ftrace操作

1.设置tracer

由前述可知，available_tracers中记录的tracer都是有效的。假设现在已经在目录/sys/kernel/debug/tracing下。

打开trace功能，设置function跟踪器：

# echo function > current_tracer

# cat current_tracer

function

2.开启/关闭tracer

启动：#echo 1 > /proc/sys/kernel/ftrace_enabled

停止：#echo 0 > /proc/sys/kernel/ftrace_enabled

3.暂停/继续跟踪情况

暂停：#echo 0 > tracing_on

继续：#echo 1 > tracing_on

4.观察结果

#cat trace | head -10

5. 跟踪指定的process

也许我们只需要跟踪指定的process，或者指定一组process；

[root@RedHat tracing]# cat set_ftrace_pid

no pid

[root@RedHat tracing]# echo $$ > set_ftrace_pid

上述将使得function tracer只跟踪bash shell；如果我们想要跟踪指定的process，需要创建以下脚本程序：

[root@RedHat tracing]# cat /home/tools/ftracer/ftrace-me

#!/bin/sh

DEBUGFS=`grep debugfs /proc/mounts | awk ‘{ print $2; }’`

echo $$ > $DEBUGFS/tracing/set_ftrace_pid

echo function > $DEBUGFS/tracing/current_tracer

exec $*

[root@RedHat tracing]# /home/tools/ftracer/ftrace-me ls –ltr

Note, you must clear the set_ftrace_pid file if you want to go back to generic function tracing after performing the above.

  [root@RedHat tracing]# echo -1 > set_ftrace_pid

2 调试实例

2.1 Function跟踪器

Function tracer的主要功能是跟踪函数调用。使用方法如下：

[root@RedHat tracing]#

[root@RedHat tracing]# pwd

/sys/kernel/debug/tracing

[root@RedHat tracing]# echo 0 > tracing_enabled

[root@RedHat tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled

[root@RedHat tracing]# echo function > current_tracer

[root@RedHat tracing]# echo 1 > tracing_on

[root@RedHat tracing]# echo 1 > tracing_enabled

# 运行一段时间，即可采用ftrace手机一些跟踪信息

[root@RedHat tracing]# echo 0 > tracing_enabled

[root@RedHat tracing]# cat trace | head -10

# tracer: function

# TASK-PID CPU# TIMESTAMP FUNCTION

# | | | | |

automount-1878 [000] 8901.818000: _raw_spin_lock_irq <-__schedule

automount-1878 [000] 8901.818000: update_rq_clock <-__schedule

automount-1878 [000] 8901.818000: put_prev_task_fair <-__schedule

automount-1878 [000] 8901.818000: update_curr <-put_prev_task_fair

automount-1878 [000] 8901.818000: pick_next_task_fair <-__schedule

automount-1878 [000] 8901.818000: clear_buddies <-pick_next_task_fair

[root@RedHat tracing]#

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

2.2 function_graph跟踪器

function_graph跟踪器也是用来跟踪系统调用的。

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

使用方法如下：

[root@RedHat tracing]# echo 0 > tracing_enabled

[root@RedHat tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled

[root@RedHat tracing]# echo function_graph > current_tracer

[root@RedHat tracing]# echo __do_fault > set_graph_function

[root@RedHat tracing]# echo 1 > tracing_on

[root@RedHat tracing]# echo 1 > tracing_enabled

# 运行一段时间，即可采用ftrace手机一些跟踪信息

[root@RedHat tracing]# echo 0 > tracing_enabled

[root@RedHat tracing]# cat trace | head -20

# tracer: function_graph

# CPU DURATION FUNCTION CALLS

# | | | | | | |

0) 0.000 us | calc_global_load();

0) ! 3000.000 us | } /* do_timer */

0) ! 3000.000 us | } /* tick_do_update_jiffies64 */

0) | update_process_times() {

0) | account_process_tick() {

0) | account_system_time() {

0) 0.000 us | acct_update_integrals();

0) 0.000 us | }

0) | run_local_timers() {

0) 0.000 us | hrtimer_run_queues();

0) 0.000 us | raise_softirq();

0) 0.000 us | }

0) | rcu_check_callbacks() {

0) 0.000 us | idle_cpu();

0) 0.000 us | __rcu_pending();

[root@RedHat tracing]# echo > set_graph_function

解析：在文件 trace 的输出信息中，首先给出的也是当前跟踪器的名字，这里是 function_graph 。接下来是详细的跟踪信息，可以看到，函数的调用关系以类似 C 代码的形式组织。

CPU 字段给出了执行函数的 CPU 号，本例中都为 1 号 CPU。DURATION 字段给出了函数执行的时间长度，以 us 为单位。FUNCTION CALLS 则给出了调用的函数，并显示了调用流程。注意，对于不调用其它函数的函数，其对应行以“;”结尾，而且对应的 DURATION 字段给出其运行时长；对于调用其它函数的函数，则在其“}”对应行给出了运行时长，该时间是一个累加值，包括了其内部调用的函数的执行时长。 DURATION 字段给出的时长并不是精确的，它还包含了执行 ftrace 自身的代码所耗费的时间，所以示例中将内部函数时长累加得到的结果会与对应的外围调用函数的执行时长并不一致；不过通过该字段还是可以大致了解函数在时间上的运行开销的。最后通过 echo 命令重置了文件。

注：The “+” that are there are annotation marker. When the duration is greater than 10 microseconds, a “+” is shown. If the duration is greater than 100 microseconds a “!” will be displayed.

2.3 irqsoff跟踪器

当关闭中断时，CPU会延迟对设备的状态变化做出反应，有时候这样做会对系统性能造成比较大的影响。irqsoff 跟踪器可以对中断被关闭的状况进行跟踪，有助于发现导致较大延迟的代码；当出现最大延迟时，跟踪器会记录导致延迟的跟踪信息，文件 tracing_max_latency 则记录中断被关闭的最大延时。

使用方法如下（因为实用的是虚拟机，输出信息有误）：

[root@RedHat tracing]# pwd

/sys/kernel/debug/tracing

[root@RedHat tracing]# echo 0 > tracing_enabled

[root@RedHat tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled

[root@RedHat tracing]# echo irqsoff > current_tracer

[root@RedHat tracing]# echo 1 > tracing_on

[root@RedHat tracing]# echo 1 > tracing_enabled

# 运行一段时间，即可采用ftrace手机一些跟踪信息

[root@RedHat tracing]# echo 0 > tracing_enabled

[root@RedHat tracing]# cat trace | head -35

# tracer: irqsoff

# irqsoff latency trace v1.1.5 on 3.2.0trace

# ——————————————————————–

# latency: 3833000 us, #220/220, CPU#0 | (M:desktop 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: common_interrupt

# => ended at: do_softirq

# _——=> CPU#

# / _—–=> irqs-off

# | / _—-=> need-resched

# || / _—=> hardirq/softirq

# ||| / _–=> preempt-depth

# |||| / delay

# cmd pid ||||| time | caller

# \ / ||||| \ | /

<idle>-0 0dN.. 0us : acpi_pm_read <-do_timer

<idle>-0 0dN.. 0us : calc_global_load <-do_timer

<idle>-0 0dN.. 0us : account_idle_ticks <-tick_nohz_restart_sched_tick

<idle>-0 0dN.. 0us : hrtimer_cancel <-tick_nohz_restart_sched_tick

<idle>-0 0dN.. 0us : hrtimer_try_to_cancel <-hrtimer_cancel

<idle>-0 0dN.. 0us : lock_hrtimer_base <-hrtimer_try_to_cancel

<idle>-0 0dN.. 0us : _raw_spin_lock_irqsave <-lock_hrtimer_base

<idle>-0 0dN.. 0us : __remove_hrtimer <-hrtimer_try_to_cancel

<idle>-0 0dN.. 0us : hrtimer_force_reprogram <-__remove_hrtimer

<idle>-0 0dN.. 0us : tick_program_event <-hrtimer_force_reprogram

<idle>-0 0dN.. 0us : clockevents_program_event <-tick_program_event

<idle>-0 0dN.. 0us : ktime_get <-clockevents_program_event

<idle>-0 0dN.. 0us : acpi_pm_read <-ktime_get

<idle>-0 0dN.. 0us : lapic_next_event <-clockevents_program_event

<idle>-0 0dN.. 0us : native_apic_mem_write <-lapic_next_event

[root@RedHat tracing]# cat tracing_max_latency

3833000

[root@RedHat tracing]#

解析：从输出信息中，可以看到当前 irqsoff 延迟跟踪器的版本信息。接下来是最大延迟时间，以us为单位，本例中为3833000us ，查看文件 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 字段是与大内核锁相关的，而最近的内核开发工作中有一部分是与移除大内核锁相关的，这里对该字段不再加以描述。

2.4 Function Profiling

# echo nop > current_tracer

# echo 1 > function_profile_enabled

# cat trace_stat/function0 |head

Function Hit Time Avg

——– — —- —

schedule 923 325906219 us 353094.4 us

vfs_read 238 109621612 us 460595.0 us

sys_read 208 108491821 us 521595.2 us

do_sync_read 123 49456207 us 402082.9 us

pipe_read 63 48292785 us 766552.1 us

pipe_wait 63 48276550 us 766294.4 us

sys_futex 5 48068145 us 9613629 us

do_futex 5 48068115 us 9613623 us

2.5 sched_switch跟踪器

sched_switch 跟踪器可以对进程的调度切换以及之间的唤醒操作进行跟踪，使用方法如下：

[root@RedHat tracing]# pwd

/sys/kernel/debug/tracing

[root@RedHat tracing]# echo 0 > tracing_enabled

[root@RedHat tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled

[root@RedHat tracing]# echo sched_switch > current_tracer

[root@RedHat tracing]# echo 1 > tracing_on

[root@RedHat tracing]# echo 1 > tracing_enabled

# 运行一段时间，即可采用ftrace手机一些跟踪信息

[root@RedHat tracing]# echo 0 > tracing_enabled

[root@RedHat tracing]# cat trace | head -10

[root@RedHat tracing]# 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 。

进程状态：

R – running : wants to run, may not actually be running

S – sleep : process is waiting to be woken up (handles signals)

D – disk sleep (uninterruptible sleep) : process must be woken up (ignores signals)

T – stopped : process suspended

t – traced : process is being traced (with something like gdb)

Z – zombie : process waiting to be cleaned up

X – unknown

2.6 跟踪指定模块中的函数

前面提过，通过文件 set_ftrace_filter 可以指定要跟踪的函数，缺省目标为所有可跟踪的内核函数；可以将感兴趣的函数通过 echo 写入该文件。为了方便使用，set_ftrace_filter 文件还支持简单格式的通配符。