• 内核追踪技术之 ftrace

    目录

    一、/sys/kernel/debug/trace 目录下的文件 常用的选项

    1、function_graph跟踪器

    2、function跟踪器

    二、查看系统支持哪些事件

    1、事件跟踪

    2、动态ftrace

    三、添加跟踪点

    四、跟踪标记

    内核提供的测试模块

    五、trace-cmd, kerneshark

    一、/sys/kernel/debug/trace 目录下的文件 常用的选项

    • available_tracers 当前系统所支持的跟踪器
    • available_events 当前系统所支持的事件
    • current_tracer 设置和显示当前正在使用的跟踪器，默认nop
    • trace 读取跟踪信息
    • tracing_on 用于开始或暂停跟踪
    • trace_points 设置ftrace的一些相关选项

    查看系统支持哪些跟踪器available_tracers

    1. /sys/kernel/debug/tracing# cat available_tracers 
    2. hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
    • hwlat 与硬件相关的延时
    • blk 跟踪块设备函数
    • mmiotrace 跟踪内存映射I/O操作
    • function_graph 函数调用关系图
    • wakeup 跟踪普通优先级的进程 从获得调度到被唤醒的最长延迟时间
    • wakeup_rt 跟踪RT类型的任务从获得调度到被唤醒的最长延迟时间
    • function 跟踪内核函数执行情况

    备注：系统的跟踪器是根据内核配置后所显示的，并不是所有的。比如，当前的跟踪器没有preempt[irqs]off,在内核中配置后，可以在当前文件夹下出现。

    1、function_graph跟踪器

    1.  
    2. /sys/kernel/debug/tracing#echo function_graph > current_tracer 
    3. echo 1 > tracing_on 
    4. ...
    5. echo 0 > tracing_on 
    6. cat trace

     函数调用关系图

    1.    1)   0.081 us    |        get_xsave_addr();
    2.    1)   0.079 us    |        finish_task_switch();
    3.    1) + 25.319 us   |      } /* schedule */
    4.    1) + 25.472 us   |    } /* exit_to_usermode_loop */
    5.    1)   0.076 us    |    fpregs_assert_state_consistent();
    6.    1)   0.121 us    |    switch_fpu_return();
    7.    1) + 35.360 us   |  }
    8.    1)               |  do_syscall_64() {
    9.    1)               |    __x64_sys_sendmsg() {
    10.    1)               |      __sys_sendmsg() {
    11.    1)               |        sockfd_lookup_light() {
    12.    1)               |          __fdget() {
    13.    1)               |            __fget_light() {
    14.    1)   0.110 us    |              __fget();
    15.    1)   0.262 us    |            }
    16.    1)   0.414 us    |          }
    17.    1)   0.579 us    |        }
    18.    1)               |        ___sys_sendmsg() {
    19.    1)               |          copy_msghdr_from_user() {
    20.    1)               |            rw_copy_check_uvector() {
    21.    1)               |              __check_object_size() {
    22.    1)   0.092 us    |                check_stack_object();
    23.    1)   0.246 us    |              }
    24.    1)   0.413 us    |            }
    25.    1)   0.655 us    |          }
    26.    1)               |          ____sys_sendmsg() {
    27.    1)               |            sock_sendmsg() {
    28.    1)               |              security_socket_sendmsg() {
    29.    1)               |                apparmor_socket_sendmsg() {
    30.    1)   0.074 us    |                  aa_unix_msg_perm();
    31.    1)   0.224 us    |                }
    32.    1)   0.405 us    |              }
    33.    1)               |              unix_stream_sendmsg() {
    34.    1)               |                wait_for_unix_gc() {
    35.    1)               |                  _cond_resched() {
    36.    1)   0.075 us    |                    rcu_all_qs();
    37.    1)   0.241 us    |                  }
    38.    1)   0.417 us    |                }

    2、function跟踪器

     function会跟踪当前系统中所有的函数，如果想跟踪单个进程则使用set_ftrace_pid

    1. #cat set_ftrace_pid 
    2. no pid
    3.  
    4. #echo 108432 > set_ftrace_pid 
    5. #cat set_ftrace_pid 
    6. 108432
    7.  
    8. #echo function > current_tracer 
    9.  
    10. #cat trace

    3、过滤选项

    ftrace可以输出的大量报告数据很容易让人不知所措。学习如何过滤掉不需要或不属于你跟踪范围的东西是关键——过滤函数

    1. root@ubuntu:/sys/kernel/tracing# wc -l available_filter_functions 
    2. 54574 available_filter_functions

    set_ftrace_filter    追踪的函数
    set_ftrace_notrace    不追踪函数

    set_graph_function
    set_graph_notrace

    tracing_cpu_mask    CPU核

    set_ftrace_pid    追踪进程/线程 PID
    set_ftrace_notrace_pid 不追踪 进程/线程PID

    set_event        追踪函数属于写事件组
    set_event_pid    当事件追踪的 进程、线程PID
    set_event_notrace_pid


    更多过滤选项
    'foo*' 以foo函数开通
    '*foo' 以foo函数结尾
    '*foo*' 函数中有foo
    'foo*bar' 收尾foo bar

    同时跟踪ksys_write ksys_read
    echo "ksys_write" > set_ftrace_filter
    echo "ksys_read" >> set_ftrace_filter

    二、查看系统支持哪些事件

    1. cat /sys/kernel/debug/tracing/available_events 
    2. initcall:initcall_level
    3. initcall:initcall_start
    4. initcall:initcall_finish
    5. raw_syscalls:sys_enter
    6. raw_syscalls:sys_exit
    7. syscalls:sys_enter_rt_sigreturn
    8. syscalls:sys_exit_rt_sigreturn
    9. syscalls:sys_enter_mmap
    10. syscalls:sys_exit_mmap
    11. ...

    1、事件跟踪

    两种跟踪机制：函数和跟踪点，前者属于简单的操作，后者可以输出开发者想要的参数、局部变量等信息。

    跟踪点的位置比较固定，一般是内核开发者添加上去的，如果在运行时没有开启DEBUG，那么不占用任何系统开销的。

    在源码中以trace_开头的函数,是ftrace的跟踪点。如：update_curr

    1. static void update_curr(struct cfs_rq *cfs_rq)
    2. {
    3.  
    4. 	if (entity_is_task(curr)) {
    5. 		struct task_struct *curtask = task_of(curr);
    6.  
    7. 		trace_sched_stat_runtime(curtask, delta_exec, curr->vruntime);
    8. 		cgroup_account_cputime(curtask, delta_exec);
    9. 		account_group_exec_runtime(curtask, delta_exec);
    10. 	}
    11.  
    12. }

    trace_sched_stat_runtime 是使用了sched_stat_runtime跟踪点，在命令行下也可以查询到

    筛选 grep sched_stat_runtime

    1. benshushu:tracing# cat /sys/kernel/debug/tracing/available_events | grep sched_stat_runtime
    2. sched:sched_stat_runtime

    找到跟踪点后如何跟踪这个事件

    1. # echo sched:sched_stat_runtime > /sys/kernel/debug/tracing/set_event
    2. # [ 4664.128181] Scheduler tracepoints stat_sleep, stat_iowait, stat_blocked and stat_runtime require the kernel parameter schedstats=enable or kernel.sched_schedstats=1
    1. # echo 1 > tracing_on 
    2. # cat trace
    3. # tracer: nop
    4. #
    5. # entries-in-buffer/entries-written: 217/217   #P:4
    6. #
    7. #                              _-----=> irqs-off
    8. #                             / _----=> need-resched
    9. #                            | / _---=> hardirq/softirq
    10. #                            || / _--=> preempt-depth
    11. #                            ||| /     delay
    12. #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
    13. #              | |       |   ||||       |         |
    14.             bash-678   [003] d...  4749.608750: sched_stat_runtime: comm=bash pid=678 runtime=3010992 [ns] vruntime=3326653851 [ns]
    15.      kworker/3:2-365   [003] d...  4749.611590: sched_stat_runtime: comm=kworker/3:2 pid=365 runtime=336064 [ns] vruntime=35834438828 [ns]
    16.        rcu_sched-10    [002] d...  4749.611633: sched_stat_runtime: comm=rcu_sched pid=10 runtime=142128 [ns] vruntime=54819089300 [ns]
    17.        rcu_sched-10    [002] d...  4749.618566: sched_stat_runtime: comm=rcu_sched pid=10 runtime=234512 [ns] vruntime=54819323812 [ns]
    18.        rcu_sched-10    [002] d...  4749.625277: sched_stat_runtime: comm=rcu_sched pid=10 runtime=244384 [ns] vruntime=54819568196 [ns]
    19.      kworker/0:1-786   [000] d...  4750.670649: sched_stat_runtime: comm=kworker/0:1 pid=786 runtime=274624 [ns] vruntime=33254509938 [ns]
    20.     kworker/u8:1-47    [002] d...  4751.269334: sched_stat_runtime: comm=kworker/u8:1 pid=47 runtime=323152 [ns] vruntime=54819552788 [ns]

     解释标头

    1. benshushu:tracing# cat trace
    2. # tracer: nop
    3. #
    4. # entries-in-buffer/entries-written: 217/217   #P:4
    5. #
    6. #                              _-----=> irqs-off
    7. #                             / _----=> need-resched
    8. #                            | / _---=> hardirq/softirq
    9. #                            || / _--=> preempt-depth
    10. #                            ||| /     delay
    11. #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
    12. #              | |       |   ||||       |         |
    13.             bash-678   [003] d...  4749.608750: sched_stat_runtime: comm=bash pid=678 runtime=3010992 [ns] vruntime=3326653851 [ns]

    TASK_PID 任务的PID

    irq-off：d表示中断已经关闭；若设置"." 表示中断没有关闭

    need-resched: 是否需要调度

                            N 表示设置了TIF_NEED_RESCHED和PREEMPT_NEED_RESCHED标志位，需要被调度

            n 表示设置了TIF_NEED_RESCHED

            p表示设置了PREEMPT_NEED_RESCHED

            . 表示不需要调度

    hardirq/softirq：表示是否发生了软中断或硬中断

            H 表示在一次硬中断中发生了一次硬中断 

            h 表示硬中断发生

            s 表示软中断

            .表示没有中断发生

    preempt-depth 表示抢占关闭的嵌套层级

    delay 表示延迟的时间长度

    083472e8ce284b51bac76348f731f1e7.png

    设置事件后，还可以对事件进行过滤

    1. //切换到事件下
    2. /sys/kernel/debug/tracing/events/sched/sched_stat_runtime# 
    3.  
    4. //跟踪sh开头的进程
    5. echo 'comm ~ "sh*" ' > filter
    6.

    2、动态ftrace

    在实际调试过程中，所需要的信息会被大量的ftrace覆盖，所以动态过滤方法很有用。

    set_ftrace_filter和set_ftrace_notrace选项配对使用。前者设置要跟踪的函数，后者设置不要跟踪的函数。

    available_filter_function文件可以列出当前系统支持的所有函数

    1. #cat available_filter_functions
    2. ....
    3. __ip6_flush_pending_frames
    4. ip6_flush_pending_frames
    5. ip6_autoflowlabel.part.0
    6. ip6_finish_output2
    7. ip6_copy_metadata
    8. ip6_fraglist_prepare
    9. ip6_frag_next
    10. ip6_fraglist_init
    11. ip6_setup_cork
    12. ip6_sk_dst_lookup_flow
    13. ip6_xmit
    14. ....

    如 只关注hrtimer_interrupt函数

    1. #echo hrtimer_interrupt > set_ftrace_filter 
    2.  
    3. # echo 1 > tracing_on 
    4. ...
    5. # echo 0 > tracing_on 
    6. # cat trace
    7.

    三、添加跟踪点

    内核中的跟踪点不能满足要求，可手动添加。

    以update_curr（）为例，观察cfs_rq就绪队列中min_vruntime成员变化情况。

    首先需要在include/trace/events/sched.h 的头文件中添加一个名为sched_stat_minvruntime的跟踪点。

    按照宏填写参数

    1. #define TRACE_EVENT(name,proto,args,struct,assign,print) \
    3. DECLARE_TRACE(name,PARAMS(proto),PATAMS(args))

    1. TRACE_EVENT(sched_stat_minvruntime,
    2.  
    3.         TP_PROTO(struct task_struct *tsk,u64 minvruntime),
    4.  
    5.         TP_ARGS(tsk,minvruntime),
    6.  
    7.         TP_STRUCT__entry(
    8.                 __array(        char,   comm,   TASK_COMM_LEN   )
    9.                 __field(        pid_t,  pid                     )
    10.                 __field(        u64,    vruntime)
    11.         ),
    12.  
    13.         TP_fast_assign(
    14.                 memcpy(__entry->comm, t->comm, TASK_COMM_LEN);
    15.                 __entry->pid    = t->pid;
    16.                 __entry->vruntime       =minruntime;
    17.         ),
    18.  
    19.         TP_printk("comm=%s pid=%d vruntime=%Lu [ns]", __entry->comm, __entry->pid,
    20.                         (unsigned long long)__entry->vruntime)
    21. );
    • name: 跟踪点名字
    • proto:该跟踪点的原型
    • args：参数
    • struct：定义跟踪器内部使用的_entry数据结构
    • assign:把参数复制到__entry数据结构中
    • print：输出的格式

    把trace_sched_stat_minvruntime(）添加到update_curr()函数中

    1. static void update_curr(struct cfs_rq *cfs_rq)
    2. {
    3.  
    4. 	if (entity_is_task(curr)) {
    5. 		struct task_struct *curtask = task_of(curr);
    6.  
    7. 		trace_sched_stat_runtime(curtask, delta_exec, curr->vruntime);
    8. 		trace_sched_stat_minvruntime(curtask,cfs_rq->mim_vruntime);
    9. 	}
    10. }

    重新编译内核，在sys节点上看到添加跟踪节点。

    1. cd /sys/kernel/debug/tracing/events/sched/sched_stat_minvruntime/
    2.  
    3. # ls
    4. enable	filter	format	id  trigger
    5. # cat format 
    6. name: sched_stat_minvruntime
    7. ID: 171
    8. format:
    9. 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
    10. 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
    11. 	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
    12. 	field:int common_pid;	offset:4;	size:4;	signed:1;
    13.  
    14. 	field:char comm[16];	offset:8;	size:16;	signed:0;
    15. 	field:pid_t pid;	offset:24;	size:4;	signed:1;
    16. 	field:u64 vruntime;	offset:32;	size:8;	signed:0;
    17.  
    18. print fmt: "comm=%s pid=%d vruntime=%Lu [ns]", REC->comm, REC->pid, (unsigned long long)REC->vruntime
    19.  
    20.

    查看添加的事件 

    1. tracing# echo sched:sched_stat_minvruntime > set_event
    2. tracing# echo 1 > tracing_on 
    3. tracing# cat trace
    4. # tracer: nop
    5. #
    6. # entries-in-buffer/entries-written: 587/587   #P:4
    7. #
    8. #                              _-----=> irqs-off
    9. #                             / _----=> need-resched
    10. #                            | / _---=> hardirq/softirq
    11. #                            || / _--=> preempt-depth
    12. #                            ||| /     delay
    13. #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
    14. #              | |       |   ||||       |         |
    15.             bash-555   [003] d.h.   236.982374: sched_stat_minvruntime: comm=bash pid=555 vruntime=1669227760 [ns]
    16.             bash-555   [003] d.h.   236.985426: sched_stat_minvruntime: comm=bash pid=555 vruntime=1672976144 [ns]
    17.             bash-555   [003] d...   236.986699: sched_stat_minvruntime: comm=bash pid=555 vruntime=1674223536 [ns]
    18.        rcu_sched-10    [002] d...   236.986838: sched_stat_minvruntime: comm=rcu_sched pid=10 vruntime=23631132868 [ns]
    19.        rcu_sched-10    [002] d...   236.994794: sched_stat_minvruntime: comm=rcu_sched

    四、跟踪标记

    trace_marker,可以跟踪用户程序。trace_marker是一个文件节点，允许用户程序写入字符串，ftrace会记录该写入动作的时间戳。

    可以观察用户程序在两个跟踪标记之间的内核空间中发生的事情

    trace_marker所在的文件路径

    /sys/kernel/debug/tracing/trace_marker

    1. int main()
    2. {
    3.     int fd_mark = open("/sys/kernel/debug/tracing/trace_marker", O_CREAT|O_RDWR, 0666);
    4.     int fd_trace = open("/sys/kernel/debug/tracing/tracing_on", O_CREAT|O_RDWR, 0666);
    5.  
    6.     write(fd_trace, "1", 2);
    7.     //添加marker
    8.     write(fd_mark, "start time...", 11);
    9.  
    10.  
    11.     /* to do something */
    12.  
    13.  
    14.     write(fd_mark, "end time...", 11);
    15.  
    16.     write(fd_trace, "0", 2);
    17.  
    18.     close(fd_mark);
    19.     close(fd_trace);
    20. }

    内核提供的测试模块

    sample/trace_events目录

    五、trace-cmd, kerneshark

    trace-cmd 遵循reset->record->stop->report，使用report收集数据，Ctrl+C终止，生成trace.data文件。

    追踪

    trace-cmd record -e 'sched_wakeup*' -e sched_switch -e 'sched_migrate*'

    解析 使用trace-cmd report解析data.dat文件 文字形式

    1. benshushu:~# trace-cmd report trace.dat 
    2. cpus=4
    3.        trace-cmd-6338  [003]   599.589634: sched_wakeup:         rcu_sched:10 [120] success=1 CPU:003
    4.        trace-cmd-6320  [000]   599.589635: sched_switch:         trace-cmd:6320 [120] R ==> trace-cmd:6337 [120]
    5.        trace-cmd-6338  [003]   599.590964: sched_wakeup:         ksoftirqd/3:26 [120] success=1 CPU:003
    6.        trace-cmd-6338  [003]   599.591186: sched_switch:         trace-cmd:6338 [120] R ==> rcu_sched:10 [120]
    7.        rcu_sched-10    [003]   599.591324: sched_switch:         rcu_sched:10 [120] W ==> ksoftirqd/3:26 [120]
    8.      ksoftirqd/3-26    [003]   599.591380: sched_switch:         ksoftirqd/3:26 [120] S ==> trace-cmd:6338 [120]
    9.        trace-cmd-6336  [002]   599.592586: sched_switch:         trace-cmd:6336 [120] S ==> swapper/2:0 [120]
    10.           -0     [002]   599.592718: sched_wakeup:         dhcpcd:733 [120] success=1 CPU:002
    11.        trace-cmd-6335  [001]   599.592781: sched_switch:         trace-cmd:6335 [120] S ==> trace-cmd:6320 [120]
    12.           -0     [002]   599.592887: sched_wakeup:         rcu_sched:10 [120] success=1 CPU:003
    13.           -0     [002]   599.592928: sched_switch:         swapper/2:0 [120] R ==> dhcpcd:733 [120]
    14.           dhcpcd-733   [002]   599.594394: sched_migrate_task:   comm=kworker/u8:2 pid=151 prio=120 orig_cpu=0 dest_cpu=2
    15.           dhcpcd-733   [002]   599.594628: sched_wakeup:         kworker/u8:2:151 [120] success=1 CPU:002
    16.           dhcpcd-733   [002]   599.594854: sched_switch:         dhcpcd:733 [120] D ==> kworker/u8:2:151 [120]
    17.     kworker/u8:2-151   [002]   599.595194: sched_wakeup_new:     kworker/u8:2:6339 [120] success=1 CPU:002
    18.     kworker/u8:2-151   [002]   599.595248: sched_switch:         kworker/u8:2:151 [120] S ==> kworker/u8:2:6339 [120]

    kernelshark是以图形的形式解析data.dat文件

    kernelshark trace.dat

    d33fe09266f64a818084acdcd4de569f.png

    参考

    内核ftrace
     

  • 相关阅读:
    大数据ClickHouse（十九）：Flink 写入 ClickHouse API
    软件测试内卷？都停一停，我测试员要出圈......
    集成随机惯性权重和差分变异操作的樽海鞘群算法-附代码
    个性化推送通知的3种方法，提升60% ROI
    buildadmin+tp8表格操作（2）----表头上方按钮绑定事件处理，实现功能（全选/全不选）
    什么是位域和位段？如何定义和使用位域？
    google voice获取、转移教程（2022）
    如何骚操作通过科目一斩获高分，python带你了解~
    VSCode运行python提示No module name ‘xxx‘
    为什么企业不愿意升级ERP系统
  • 原文地址：https://blog.csdn.net/WANGYONGZIXUE/article/details/127198828