Linux ftrace的使用(2)

作者 by adtxl / 2022-04-28 / 暂无评论 / 451 个足迹

整理自《奔跑吧 Linux内核,张天飞著》

1. 动态ftrace

在配置内核时打开了CONFIG_DYNAMIC_FTRACE选项,就可以支持动态ftrace功能。set_ftrace_filter和set_ftrace_notrace这两个文件可以配对使用,其中,前者设置要跟踪的函数,后者指定不要跟踪的函数。

在实际的调试过程中,我们通常会被ftrace提供的大量信息淹没,因此动态过滤的方法非常有用。avaliable_filter_functions文件可以列出当前系统支持的所有函数,例如现在我只想关注hrtimer_nanosleep()和hrtimer_interrupt()这两个函数。

# cd /sys/kernel/debug/tracing
# echo hrtimer_nanosleep hrtimer_interrupt > set_ftrace_filter
# echo function > current_tracer
# echo 1 > tracing_on
# usleep 1
# echo 0 > tracing_on
# cat trace

抓取的数据如下:

# tracer: function
#
# entries-in-buffer/entries-written: 57/57   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     rcu_preempt-10    [002] d.h2 11073.199551: hrtimer_interrupt <-arch_timer_handler_virt
     rcu_preempt-10    [002] d.h2 11073.215430: hrtimer_interrupt <-arch_timer_handler_virt
     rcu_preempt-10    [002] d.h3 11073.235407: hrtimer_interrupt <-arch_timer_handler_virt
     rcu_preempt-10    [002] d.h2 11074.191632: hrtimer_interrupt <-arch_timer_handler_virt
     rcu_preempt-10    [000] d.h2 11074.603390: hrtimer_interrupt <-arch_timer_handler_virt
     rcu_preempt-10    [001] d.h1 11074.719377: hrtimer_interrupt <-arch_timer_handler_virt
     rcu_preempt-10    [001] d.h1 11074.735375: hrtimer_interrupt <-arch_timer_handler_virt
     rcu_preempt-10    [001] d.h1 11074.791404: hrtimer_interrupt <-arch_timer_handler_virt
     rcu_preempt-10    [001] d.h3 11075.828143: hrtimer_interrupt <-arch_timer_handler_virt
......

此外,过滤器还支持如下通配符。

  • <match>*:匹配所有match开头的函数
  • *<match>:匹配所有match结尾的函数
  • *<match>*:匹配所有包含match的函数

如果跟踪所有"hrtimer"开头的函数,可以"echo `hrtimer_*` > set_ftrace_filter"。还有两个非常有用的操作符,">"表示会覆盖过滤器里的内容;">>"表示新加的函数会增加到过滤器中,但不会覆盖。

# echo do_nanosleep > set_ftrace_filter     // 往过滤器里写入do_nanosleep
# cat set_ftrace_filter
do_nanosleep

# echo 'hrtimer_*' >> set_ftrace_filter     // 追加写入
# cat set_ftrace_filter
hrtimer_init_sleeper
hrtimer_active
hrtimer_reprogram
hrtimer_force_reprogram
hrtimer_update_softirq_timer
hrtimer_run_softirq
hrtimer_forward
hrtimer_init
hrtimer_wakeup
hrtimer_start_range_ns
hrtimer_try_to_cancel
hrtimer_cancel
hrtimer_get_next_event
hrtimer_next_event_without
hrtimer_interrupt
hrtimer_run_queues
hrtimer_nanosleep
do_nanosleep
hrtimer_nanosleep_restart

# echo '*preempt*' '*lock*' > set_ftrace_notrace    // 表示不跟踪包含preempt和lock的函数

# echo > set_ftrace_filter      // 向过滤器中输入空字符表示清空过滤器
cat set_ftrace_filter
#### all functions enabled ####

2. 事件跟踪

ftrace里的跟踪机制主要有两种,分别是函数和tracepoint。前者属于"傻瓜式"操作,后者tracepoint可以理解为一个Linux内核中的的占位符函数,内核子系统的开发者通常喜欢利用它来调试。

tracepoint可以输出开发者想要的参数、局部变量等信息。tracepoint的位置比较固定,一般都是内核开发者添加上去的,可以把它理解为传统C语言中#if DEBUG部分。如果在运行中没有开启DEBUG,那么是不占用任何系统开销的。

在阅读内核代码时经常会遇到以trace_开头的函数,例如CFS调度器里的update_curr()函数。

 */
static void update_curr(struct cfs_rq *cfs_rq)
{
......
    curr->vruntime += calc_delta_fair(delta_exec, curr);
    update_min_vruntime(cfs_rq);

    if (entity_is_task(curr)) {
        struct task_struct *curtask = task_of(curr);

        trace_sched_stat_runtime(curtask, delta_exec, curr->vruntime);
        cgroup_account_cputime(curtask, delta_exec);
        account_group_exec_runtime(curtask, delta_exec);
    }
......
}

update_curr()函数使用了一个sched_stat_runtime的tracepoint,我们可以在avaliable_events文件中查到,把想要跟踪的事件添加到set_event文件中即可,该文件同样支持通配符。

# cd /sys/kernel/debug/tracing
# cat available_events | grep sched_stat_runtime
sched:sched_stat_runtime

# echo sched:sched_stat_runtime > set_event
# echo 1 > tracing_on
# cat trace

# echo sched:* > set_event      // 支持通配符,跟踪所有sched开头的事件
# echo *:* > set_event          // 跟踪系统所有事件

输出如下:


# tracer: nop
#
# entries-in-buffer/entries-written: 456/51078   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
 mali-cmar-backe-5672  [002] d..2  5880.987504: sched_stat_runtime: comm=mali-cmar-backe pid=5672 runtime=117420 [ns] vruntime=216701544114 [ns]
          Colors-5658  [002] d..2  5880.987548: sched_stat_runtime: comm=Colors pid=5658 runtime=50800 [ns] vruntime=216706582321 [ns]
 mali-cmar-backe-5672  [002] d..2  5880.987621: sched_stat_runtime: comm=mali-cmar-backe pid=5672 runtime=73240 [ns] vruntime=216701590175 [ns]
......

另外事件跟踪还支持另外一个强大的功能,可以设定跟踪条件,做到更精细化的设置。每个tracepoint都定义一个format格式,其中定义了该tracepoint支持的域。

# cd /sys/kernel/debug/tracing/events/sched/sched_stat_runtime
# cat format

输出如下:

name: sched_stat_runtime
ID: 246
format:
    field:unsigned short common_type;   offset:0;   size:2; signed:0;
    field:unsigned char common_flags;   offset:2;   size:1; signed:0;
    field:unsigned char common_preempt_count;   offset:3;   size:1; signed:0;
    field:int common_pid;   offset:4;   size:4; signed:1;

    field:char comm[16];    offset:8;   size:16;    signed:0;
    field:pid_t pid;    offset:24;  size:4; signed:1;
    field:u64 runtime;  offset:32;  size:8; signed:0;
    field:u64 vruntime; offset:40;  size:8; signed:0;

print fmt: "comm=%s pid=%d runtime=%Lu [ns] vruntime=%Lu [ns]", REC->comm, REC->pid, (unsigned long long)REC->runtime, (unsigned long long)REC->vruntime

例如,sched_stat_runtime这个tracepoint支持8个域,前4个是通用域,后4个是该tracepoint支持的域,comm是一个字符串域,其他都是数字域。

支持类似C语言表达式对事件进行过滤,对于数字域支持==, !=, <, <=, >, >=, &操作符,对于字符串域支持==, !=, ~操作符。

例如只想跟踪进程名字开头为sh的所有进程的sched_stat_runtime事件。

# cd /sys/kernel/debug/tracing/events/sched/sched_stat_runtime
# echo 'comm ~ "sh*"' > filter      // 跟踪所有进程名字开头为sh的
echo 'pid==5658' > filter           // 跟踪进程PID为5658的

输出如下:

#
# entries-in-buffer/entries-written: 474/51988245   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          Colors-5658  [003] d..2 18238.020119: sched_stat_runtime: comm=Colors pid=5658 runtime=1010360 [ns] vruntime=1531587993187 [ns]
          Colors-5658  [003] dn.2 18238.023648: sched_stat_runtime: comm=Colors pid=5658 runtime=425020 [ns] vruntime=1531588418207 [ns]
          Colors-5658  [003] dn.2 18238.023837: sched_stat_runtime: comm=Colors pid=5658 runtime=52780 [ns] vruntime=1531588470987 [ns]
          Colors-5658  [003] dn.2 18238.024666: sched_stat_runtime: comm=Colors pid=5658 runtime=637600 [ns] vruntime=1531589108587 [ns]

3. 添加tracepoint

内核各个子系统目前已经有大量的tracepoint,如果觉得这些tracepoint还不满足需求,可以自己手动添加一个,这在实际工作中也是很常用的技巧。

还是以CFS

独特见解