• Linux动态追踪——ftrace

    目录

    摘要

    1 初识

    1.1 tracefs

    1.2 文件描述

    2 函数跟踪

    2.1 函数的调用栈

    2.2 函数调用栈

    2.3 函数的子调用

    3 事件跟踪

    4 简化命令行工具

    5 总结

    摘要

            Linux下有多种动态追踪的机制，常用的有 ftrace、perf、eBPF 等，每种机制适应于不同的场景，今天学习一下ftrace的常见用法。

            ftrace 是一个内部跟踪器，旨在帮助开发人员查找内核内部发生的情况。ftrace 是几个分类跟踪实用程序的框架，其最常见的用途是函数跟踪、事件跟踪。

    1 初识

    1.1 tracefs

            ftrace 提供了类似于 procfs 的虚拟文件系统，以文件的形式为用户空间提供了交互接口。这样，我们不用依赖额外的工具，就能跟 ftrace 交互，完成跟踪的目标。

            ftracefs 挂载点通常位于 /sys/kernel/tracing 目录，如果你的这个目录下什么都没有，那么可以通过这个命令安装挂载点：

    mount -t tracefs nodev /sys/kernel/tracing

            进入 tracing 目录查看，真是多：

    1. [root@172 ~]# cd /sys/kernel/tracing/
    2. [root@172 tracing]# ls
    3. available_events            kprobe_events        set_ftrace_notrace  trace_marker_raw
    4. available_filter_functions  kprobe_profile       set_ftrace_pid      trace_options
    5. available_tracers           max_graph_depth      set_graph_function  trace_pipe
    6. buffer_size_kb              options              set_graph_notrace   trace_stat
    7. ...

    1.2 文件描述

            其中 available_tracers 描述了支持的跟踪器的种类，常用的是 function 和 function_graph

    1. [root@172 tracing]# cat available_tracers 
    2. hwlat blk function_graph wakeup_dl wakeup_rt wakeup function nop

            current_tracer 表示正在使用的跟踪器：

    1. [root@172 tracing]# cat current_tracer 
    2. nop

            available_filter_functions 为可跟踪的完整函数列表：

    1. [root@172 tracing]# cat available_filter_functions  |grep "sys_open"
    2. do_sys_open
    3. __x64_sys_open
    4. __ia32_sys_open
    5. __x64_sys_openat
    6. __ia32_sys_openat
    7. __ia32_compat_sys_open
    8. __ia32_compat_sys_openat
    9. __x64_sys_open_by_handle_at
    10. __ia32_sys_open_by_handle_at
    11. __ia32_compat_sys_open_by_handle_at
    12. proc_sys_open

            其它常见文件含义如下：

    • current_tracer：顾名思义为当前在用的跟踪器
    • function_profile_enabled：启用函数性能分析器
    • set_ftrace_filter：选择跟踪函数的列表
    • se_event_pid：设置跟踪进程的PID
    • tracing_on：启用跟踪
    • trace_options：跟踪的选项类型
    • trace_stat：函数性能分析输出的目录
    • trace：跟踪的输出文件

            ​​​​​​​看完了又好像啥都没看一样，还是看看实操什么样的！

    2 函数跟踪

            前面写了，ftrace 支持好几种类型的跟踪器，这里实际使用一下看看效果如何。

    2.1 函数的调用栈

            这里看下那个程序有调用到 fork 这个系统调用呢？通过 available_filter_functions 输出知道了其支持查看 _do_fork 这个函数的跟踪：

    1. [root@172 tracing]# cat available_filter_functions | grep "fork"
    2. _do_fork
    3. ...

            那我们就跟踪下 __do_fork 的调用：

    1. # 设置跟踪器类型为 function
    2. [root@172 tracing]# echo function > current_tracer 
    3. # 设置要跟踪的函数名
    4. [root@172 tracing]# echo _do_fork > set_ftrace_filter 
    5. # 启用跟踪
    6. [root@172 tracing]# echo 1 > tracing_on 
    7. # 触发 fork 系统调用
    8. [root@172 tracing]# ps aux | grep "bash" | grep -v "grep"
    9. root        1485  0.0  0.7 236608  5940 pts/0    Ss   15:09   0:01 -bash

            查看 trace 输出：

    1. [root@172 tracing]# cat trace
    2. # tracer: function
    3. #
    4. #                              _-----=> irqs-off
    5. #                             / _----=> need-resched
    6. #                            | / _---=> hardirq/softirq
    7. #                            || / _--=> preempt-depth
    8. #                            ||| /     delay
    9. #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
    10. #              | |       |   ||||       |         |
    11.             bash-1485  [000] ....  2832.519248: _do_fork <-do_syscall_64
    12.             bash-1485  [000] ....  2832.519502: _do_fork <-do_syscall_64
    13.             bash-1485  [000] ....  2837.109585: _do_fork <-do_syscall_64
    14.             bash-1485  [000] ....  2837.113690: _do_fork <-do_syscall_64
    15.             bash-1485  [000] ....  2838.637411: _do_fork <-do_syscall_64
    16.             bash-1485  [000] ....  2838.639147: _do_fork <-do_syscall_64

            其中 TASK-PID 表示调用 _do_fork 的进程 id，CPU 000 表示该进程运行在0号 cpu，TIMESTAMP 为函数调用的时间戳，FUNCTION 显示了 _do_fork 由  do_syscall_64 调用。

            执行完毕后还需要关闭跟踪：

    1. [root@172 tracing]# echo 0 > tracing_on
    2. [root@172 tracing]# echo > set_ftrace_filter 
    3. [root@172 tracing]# echo > current_tracer 
    4. [root@172 tracing]# echo nop > current_tracer

    2.2 函数调用栈

            有时候只知道函数被哪些进程调用，信息可能还不够全面，我们需要知道详细的调用栈，方便理清执行流程。这就依赖 options/func_stack_track 选项了。具体执行过程跟刚刚还是差不多的。

    1. [root@172 tracing]# echo function > current_tracer 
    2. [root@172 tracing]# echo 0 >tracing_on 
    3. [root@172 tracing]# echo _do_fork > set_ftrace_filter
    4. # 开启跟踪函数的调用栈
    5. [root@172 tracing]# echo 1 > options/func_stack_trace 
    6. [root@172 tracing]# echo 1 > tracing_on 
    7. [root@172 tracing]# cat trace
    8. # tracer: function
    9. #
    10. #                              _-----=> irqs-off
    11. #                             / _----=> need-resched
    12. #                            | / _---=> hardirq/softirq
    13. #                            || / _--=> preempt-depth
    14. #                            ||| /     delay
    15. #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
    16. #              | |       |   ||||       |         |
    17.             bash-1485  [000] ....  4195.579130: _do_fork <-do_syscall_64
    18.             bash-1485  [000] ....  4195.579157: 
    19.  => 0xffffffffc0871061
    20.  => _do_fork
    21.  => do_syscall_64
    22.  => entry_SYSCALL_64_after_hwframe
    23.             bash-1485  [000] ....  4195.582865: _do_fork <-do_syscall_64
    24.             bash-1485  [000] ....  4195.582882: 
    25.  => 0xffffffffc0871061
    26.  => _do_fork
    27.  => do_syscall_64
    28.  => entry_SYSCALL_64_after_hwframe
    29. [root@172 tracing]# echo 0 > tracing_on
    30. [root@172 tracing]# echo 0 > options/func_stack_trace
    31. [root@172 tracing]# echo > set_ftrace_filter 
    32. [root@172 tracing]# echo nop > current_tracer

            这次的输出明显更全面了，可以看出调用栈最顶层的入口是 entry_SYSCALL_64_after_hwframe 函数。完事还是要记得关闭。

    2.3 函数的子调用

            知道了函数的调用栈，没发现问题，可能调用都是合理的，这时候可能想知道这个函数内部做了些什么事情，有没有异常，这时就用到了 function_graph 跟踪器。

    1. [root@172 tracing]# echo _do_fork > set_graph_function
    2. [root@172 tracing]# echo function_graph > current_tracer
    3. [root@172 tracing]# echo 1 > tracing_on
    4. [root@172 tracing]# cat trace | head -n 20
    5. # tracer: function_graph
    6. #
    7. # CPU  DURATION                  FUNCTION CALLS
    8. # |     |   |                     |   |   |   |
    9.  0)               |  _do_fork() {
    10.  0)               |    copy_process.part.34() {
    11.  0)   0.116 us    |      _raw_spin_lock_irq();
    12.  0)               |      recalc_sigpending() {
    13.  0)   0.099 us    |        recalc_sigpending_tsk();
    14.  0)   1.068 us    |      }
    15.  0)   0.475 us    |      tsk_fork_get_node();
    16.  0)               |      kmem_cache_alloc_node() {
    17.  0)               |        _cond_resched() {
    18.  0)   0.109 us    |          rcu_all_qs();
    19.  0)   1.074 us    |        }
    20.  0)   0.105 us    |        should_failslab();
    21.  0)   1.143 us    |        memcg_kmem_get_cache();
    22.  0)   0.109 us    |        memcg_kmem_put_cache();
    23.  0)   6.998 us    |      }
    24.  0)               |      __memcg_kmem_charge() {
    25. [root@172 tracing]# echo 0 > tracing_on 
    26. [root@172 tracing]# echo nop > current_tracer
    27. [root@172 tracing]# echo > set_graph_function

            输出中的 DURATION 列表示执行耗时，FUNCTION 下的调用层级也很明显。

    3 事件跟踪

            available_events 描述了 ftrace 支持跟踪的所有事件，这也是内核提前定义的一批静态跟踪点：

    1. [root@172 tracing]# cat available_events | grep "kill"
    2. syscalls:sys_exit_tkill
    3. syscalls:sys_enter_tkill
    4. syscalls:sys_exit_tgkill
    5. syscalls:sys_enter_tgkill
    6. syscalls:sys_exit_kill
    7. syscalls:sys_enter_kill
    8. [root@172 tracing]# cat available_events | grep "tcp"
    9. tcp:tcp_probe
    10. tcp:tcp_retransmit_synack
    11. tcp:tcp_rcv_space_adjust
    12. tcp:tcp_destroy_sock
    13. tcp:tcp_receive_reset
    14. tcp:tcp_send_reset
    15. tcp:tcp_retransmit_skb
    16. [root@172 tracing]# cat available_events | grep "net:"
    17. net:netif_rx_ni_entry
    18. net:netif_rx_entry
    19. net:netif_receive_skb_entry
    20. net:napi_gro_receive_entry
    21. net:napi_gro_frags_entry
    22. net:netif_rx
    23. net:netif_receive_skb
    24. net:net_dev_queue
    25. net:net_dev_xmit_timeout
    26. net:net_dev_xmit
    27. net:net_dev_start_xmit

            支持的事件种类也比较多，有 syscall、net、tcp、udp 等等。netif_receive_skb 用于处理内核从网卡收到的网络包，其主要对收到的 skb 进行校验然后交给 IP 层处理。通过下面的命令查看 netif_receive_skb 支持的选项：

    1. [root@172 tracing]# ls events/net/netif_receive_skb
    2. enable  filter  format  hist  id  trigger

             让我们跟踪一下 netif_receive_skb 这个事件：

    1. [root@172 tracing]# echo 1 > events/net/netif_receive_skb/enable
    2. [root@172 tracing]# echo 1 > tracing_on 
    3. [root@172 tracing]# cat trace
    4. # tracer: nop
    5. #
    6. #                              _-----=> irqs-off
    7. #                             / _----=> need-resched
    8. #                            | / _---=> hardirq/softirq
    9. #                            || / _--=> preempt-depth
    10. #                            ||| /     delay
    11. #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
    12. #              | |       |   ||||       |         |
    13.           -0     [000] ..s.  7835.671429: netif_receive_skb: dev=eth0 skbaddr=0000000073ef12d9 len=40
    14.           -0     [000] ..s.  7836.593411: netif_receive_skb: dev=eth0 skbaddr=0000000073ef12d9 len=92
    15.           -0     [000] ..s.  7836.638960: netif_receive_skb: dev=eth0 skbaddr=00000000b6a6098d len=40
    16. [root@172 tracing]# echo 0 > tracing_on 
    17. [root@172 tracing]# echo 0 > events/net/netif_receive_skb/enable

    4 简化命令行工具

            你可能觉得 tracefs 每次跟踪都涉及多个文件的操作，这也太麻烦了。实际上，也有一个同样烦恼于此的小哥提供了更简单的命令，可以一次性配置好几个文件，也就是 trace-cmd。

            例如可以通过这样的命令来跟踪函数的调用栈：

    1. # 执行跟踪命令一段时间
    2. [root@172 /]# trace-cmd record -p function -l '_do_fork' --func-stack
    3.   plugin 'function'
    4. Hit Ctrl^C to stop recording
    5. ^CCPU0 data recorded at offset=0x4bf000
    6.     4096 bytes in size
    7. [root@172 /]# 
    8. # 查看跟踪结果
    9. [root@172 /]# trace-cmd report
    10. cpus=1
    11.             bash-1662  [000]   333.965070: function:             _do_fork
    12.             bash-1662  [000]   333.965096: kernel_stack:         
    13. => __this_module (ffffffffc062e061)
    14. => _do_fork (ffffffff942b02c5)
    15. => do_syscall_64 (ffffffff9420419b)
    16. => entry_SYSCALL_64_after_hwframe (ffffffff94c000ad)

             跟踪函数的子调用：

    1. [root@172 /]# 
    2. [root@172 /]# trace-cmd record -p function_graph -g '_do_fork'
    3.   plugin 'function_graph'
    4. Hit Ctrl^C to stop recording
    5. ^CCPU0 data recorded at offset=0x4bf000
    6.     208896 bytes in size
    7. [root@172 /]# trace-cmd report | head -n20
    8. cpus=1
    9.             bash-1662  [000]   641.179614: funcgraph_entry:                   |  _do_fork() {
    10.             bash-1662  [000]   641.179629: funcgraph_entry:                   |    copy_process.part.34() {
    11.             bash-1662  [000]   641.179629: funcgraph_entry:        0.030 us   |      _raw_spin_lock_irq();
    12.             bash-1662  [000]   641.179630: funcgraph_entry:                   |      recalc_sigpending() {
    13.             bash-1662  [000]   641.179630: funcgraph_entry:        0.034 us   |        recalc_sigpending_tsk();
    14.             bash-1662  [000]   641.179630: funcgraph_exit:         0.268 us   |      }
    15.             bash-1662  [000]   641.179630: funcgraph_entry:        0.123 us   |      tsk_fork_get_node();
    16.             bash-1662  [000]   641.179631: funcgraph_entry:                   |      kmem_cache_alloc_node() {

            跟踪静态事件：

    1. [root@172 /]# trace-cmd record -e net:netif_receive_skb
    2. Hit Ctrl^C to stop recording
    3. ^CCPU0 data recorded at offset=0x4bf000
    4.     4096 bytes in size
    5. [root@172 /]# trace-cmd report
    6. cpus=1
    7.           -0     [000]   770.613285: netif_receive_skb:    dev=eth0 skbaddr=0xffff8b4078ce4b00 len=40
    8.           -0     [000]   771.040836: netif_receive_skb:    dev=eth0 skbaddr=0xffff8b4078ce4b00 len=112
    9.           -0     [000]   771.473463: netif_receive_skb:    dev=eth0 skbaddr=0xffff8b4078ce4d00 len=203

    5 总结

            事件跟踪主要依赖于内核中定义的静态事件点，这些事件点可以理解为内核中的特定位置，当某些特定事件发生时，例如系统调用、中断处理或进程状态改变等，这些事件点就会被触发。通过 tracefs 文件系统，开发人员可以启用这些事件点，从而收集有关内核某些部分运行情况的数据。事件跟踪的一个显著特点是它可以设定跟踪条件，使得跟踪过程更加精细化和有针对性。

            相比之下，函数跟踪则更加关注于程序执行过程中的函数调用情况。在函数跟踪中，ftrace 会在指定的函数入口添加 trace 函数，从而记录函数的调用栈和相关信息。这种跟踪方式使得开发人员能够观察到函数是如何被调用的，以及它们在执行过程中的行为。函数跟踪的一个优势在于它可以轻松地过滤出需要关注的函数，从而避免被大量无关信息淹没。

            总结来说，事件跟踪和函数跟踪在 ftrace 中各有侧重。事件跟踪主要关注内核中特定事件的发生和变化，而函数跟踪则更侧重于程序执行过程中的函数调用情况。根据具体的调试需求，开发人员可以选择使用合适的跟踪机制来获取所需的信息。

  • 相关阅读:
    基于Kubernetes集群构建MongoDB
    React18 新特性
    变量、流程控制与游标（MySQL）
    我说HashMap初始容量是16，面试官让我回去等通知
    [附源码]计算机毕业设计JAVA线上图书销售管理系统
    scipy.optimize.minimize函数介绍
    基于低代码平台打造新时代的OA系统
    父组件可以监听到子组件的生命周期吗？
    Redis数据类型-Set-原理
    新的node节点加入集群
  • 原文地址：https://blog.csdn.net/qq_33724710/article/details/136601719