ftrace 简介（2）

look_w

ftrace 的使用ftrace 在内核态工作，用户通过 debugfs 接口来控制和使用 ftrace 。从 2.6.30 开始，ftrace 支持两大类 tracer：传统 tracer 和 Non-Tracer Tracer 。下面将分别介绍他们的使用。
传统 Tracer 的使用使用传统的 ftrace 需要如下几个步骤：

• 选择一种 tracer
• 使能 ftrace
• 执行需要 trace 的应用程序，比如需要跟踪 ls，就执行 ls
• 关闭 ftrace
• 查看 trace 文件

用户通过读写 debugfs 文件系统中的控制文件完成上述步骤。使用 debugfs，首先要挂载她。命令如下：

1 2	# mkdir /debug # mount -t debugfs nodev /debug

此时您将在 /debug 目录下看到 tracing 目录。 Ftrace 的控制接口就是该目录下的文件。
选择 tracer 的控制文件叫作 current_tracer 。选择 tracer 就是将 tracer 的名字写入这个文件，比如，用户打算使用 function tracer，可输入如下命令：

1	#echo ftrace > /debug/tracing/current_tracer

文件 tracing_enabled 控制 ftrace 的开始和结束。

1	#echo 1 >/debug/tracing/tracing_enable

上面的命令使能 ftrace 。同样，将 0 写入 tracing_enable 文件便可以停止 ftrace 。
ftrace 的输出信息主要保存在 3 个文件中。

• Trace，该文件保存 ftrace 的输出信息，其内容可以直接阅读。
• latency_trace，保存与 trace 相同的信息，不过组织方式略有不同。主要为了用户能方便地分析系统中有关延迟的信息。
• trace_pipe 是一个管道文件，主要为了方便应用程序读取 trace 内容。算是扩展接口吧。

下面详细解析各种 tracer 的输出信息。
Function tracer 的输出
Function tracer 跟踪函数调用流程，其 trace 文件格式如下：

1 2 3 4 5 6 7

# tracer: function # #  TASK-PID   CPU#    TIMESTAMP        FUNCTION #   |  |       |          |                |   bash-4251  [01]  10152.583854:    path_put <-path_walk   bash-4251  [01] 10152.583855: dput <-path_put   bash-4251  [01] 10152.583855: _atomic_dec_and_lock <-dput

可以看到，tracer 文件类似一张报表，前 4 行是表头。第一行显示当前 tracer 的类型。第三行是 header 。
对于 function tracer，该表将显示 4 列信息。首先是进程信息，包括进程名和 PID ；第二列是 CPU，在 SMP 体系下，该列显示内核函数具体在哪一个 CPU 上执行；第三列是时间戳；第四列是函数信息，缺省情况下，这里将显示内核函数名以及它的上一层调用函数。
通过对这张报表的解读，用户便可以获得完整的内核运行时流程。这对于理解内核代码也有很大的帮助。有志于精读内核代码的读者，或许可以考虑考虑 ftrace 。
如上例所示，path_walk() 调用了 path_put 。此后 path_put 又调用了 dput，进而 dput 再调用 _atomic_dec_and_lock 。
Schedule switch tracer 的输出
Schedule switch tracer 记录系统中的进程切换信息。在其输出文件 trace 中 , 输出行的格式有两种：
第一种表示进程切换信息：

1 2 3

Context switches:        Previous task              Next Task   <pid>:<prio>:<state>  ==>  <pid>:<prio>:<state>

第二种表示进程 wakeup 的信息：

1 2 3

Wake ups:      Current task               Task waking up <pid>:<prio>:<state>    +  <pid>:<prio>:<state>

这里举一个实例：

1 2 3 4 5 6 7

# tracer: sched_switch # #  TASK_PID   CPU#     TIMESTAMP             FUNCTION #     |         |            |                  |    fon-6263  [000] 4154504638.932214:  6263:120:R +   2717:120:S    fon-6263  [000] 4154504638.932214:  6263:120:? ==> 2717:120:R    bash-2717 [000] 4154504638.932214:  2717:120:S +   2714:120:S

第一行表示进程 fon 进程 wakeup 了 bash 进程。其中 fon 进程的 pid 为 6263，优先级为 120，进程状态为 Ready 。她将进程 ID 为 2717 的 bash 进程唤醒。
第二行表示进程切换发生，从 fon 切换到 bash 。
irqsoff tracer 输出
有四个 tracer 记录内核在某种状态下最长的时延，irqsoff 记录系统在哪里关中断的时间最长； preemptoff/preemptirqsoff 以及 wakeup 分别记录禁止抢占时间最长的函数，或者系统在哪里调度延迟最长 (wakeup) 。这些 tracer 信息对于实时应用具有很高的参考价值。
为了更好的表示延迟，ftrace 提供了和 trace 类似的 latency_trace 文件。以 irqsoff 为例演示如何解读该文件的内容。

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21

# tracer: irqsoff irqsoff latency trace v1.1.5 on 2.6.26 -------------------------------------------------------------------- latency: 12 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)     -----------------     | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0)     ----------------- => started at: sys_setpgid => ended at:   sys_setpgid #                _------=> CPU# #               / _-----=> irqs-off #              | / _----=> need-resched #              || / _---=> hardirq/softirq #              ||| / _--=> preempt-depth #              |||| / #              |||||     delay #  cmd     pid ||||| time  |   caller #     \   /    |||||   \   |   /     bash-3730  1d...    0us : _write_lock_irq (sys_setpgid)     bash-3730  1d..1    1us+: _write_unlock_irq (sys_setpgid)     bash-3730  1d..2   14us : trace_hardirqs_on (sys_setpgid)

在文件的头部，irqsoff tracer 记录了中断禁止时间最长的函数。在本例中，函数 trace_hardirqs_on 将中断禁止了 12us 。
文件中的每一行代表一次函数调用。 Cmd 代表进程名，pid 是进程 ID 。中间有 5 个字符，分别代表了 CPU#，irqs-off 等信息，具体含义如下：
CPU# 表示 CPU ID ；
irqs-off 这个字符的含义如下：’ d ’表示中断被 disabled 。’ . ’表示中断没有关闭；
need-resched 字符的含义：’ N ’表示 need_resched 被设置，’ . ’表示 need-reched 没有被设置，中断返回不会进行进程切换；
hardirq/softirq 字符的含义 : 'H' 在 softirq 中发生了硬件中断， 'h' – 硬件中断，’ s ’表示 softirq，’ . ’不在中断上下文中，普通状态。
preempt-depth: 当抢占中断使能后，该域代表 preempt_disabled 的级别。
在每一行的中间，还有两个域：time 和 delay 。 time: 表示从 trace 开始到当前的相对时间。 Delay 突出显示那些有高延迟的地方以便引起用户注意。当其显示为 ! 时，表示需要引起注意。
function graph tracer 输出
Function graph tracer 和 function tracer 类似，但输出为函数调用图，更加容易阅读：

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20

# tracer: function_graph # # CPU  OVERHEAD/DURATION      FUNCTION CALLS # |     |   |                 |   |   |   | 0)               |  sys_open() { 0)               |    do_sys_open() { 0)               |      getname() { 0)               |        kmem_cache_alloc() { 0)   1.382 us    |          __might_sleep(); 0)   2.478 us    |        } 0)               |        strncpy_from_user() { 0)               |          might_fault() { 0)   1.389 us    |            __might_sleep(); 0)   2.553 us    |          } 0)   3.807 us    |        } 0)   7.876 us    |      } 0)                |      alloc_fd() { 0)   0.668 us    |        _spin_lock(); 0)   0.570 us    |        expand_files(); 0)   0.586 us    |        _spin_unlock();

OVERHEAD 为 ! 时提醒用户注意，该函数的性能比较差。上面的例子中可以看到 sys_open 调用了 do_sys_open，依次又调用了 getname()，依此类推。
Sysprof tracer 的输出
Sysprof tracer 定时对内核进行采样，她的输出文件中记录了每次采样时内核正在执行哪些内核函数，以及当时的内核堆栈情况。
每一行前半部分的格式和 3.1.1 中介绍的 function tracer 一样，只是，最后一部分 FUNCTION 有所不同。
Sysprof tracer 中，FUNCTION 列格式如下：

1	Identifier  address frame_pointer/pid

当 identifier 为 0 时，代表一次采样的开始，此时第三个数字代表当前进程的 PID ；
Identifier 为 1 代表内核态的堆栈信息；当 identifier 为 2 时，代表用户态堆栈信息；显示堆栈信息时，第三列显示的是 frame_pointer，用户可能需要打开 system map 文件查找具体的符号，这是 ftrace 有待改进的一个地方吧。
当 identifier 为 3 时，代表一次采样结束。