OpenWrt 使用 perf ftrace 跟踪内核函数调用

发表于 Waline：

构建集成 ftrace 的内核镜像

make menuconfig
依次选择

1
2
3
4
5
KERNEL_PERF_EVENTS
PACKAGE_perf
KERNEL_FTRACE
KERNEL_DYNAMIC_FTRACE
KERNEL_FUNCTION_GRAPH_TRACER

跟踪函数使用情况

用 perf ftrace -F <func> 查找可以被 ftrace 跟踪的函数，参数支持通配符*。比如查找 nf_ 开头的函数，用 perf ftrace -F "nf_*"：

1
2
3
4
5
6
7
8
9
> perf ftrace -F "nf_*"

nf_hook_entry_head
nf_hook_slow
nf_hook_slow_list
nf_ct_get_tuple_skb
nf_ct_attach
nf_conntrack_destroy
# 以下省略

确定需要跟踪的函数后，用 -T <func> 参数指定，此参数可以指定多次以同时跟踪多个函数。

如下为在一台正在处理网络数据的路由器上跟踪 nf_hook_slow 的结果：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
> perf ftrace -T nf_hook_slow

# tracer: function
#
# entries-in-buffer/entries-written: 0/0   #P:4
#
#           TASK-PID     CPU#     TIMESTAMP  FUNCTION
#              | |         |         |         |
          <idle>-0       [002]   5540.021468: nf_hook_slow <-__ip_local_out
          <idle>-0       [003]   5540.021469: nf_hook_slow <-ip_local_deliver
          <idle>-0       [002]   5540.021476: nf_hook_slow <-ip_output
          <idle>-0       [003]   5540.021481: nf_hook_slow <-__netif_receive_skb_core
    kworker/u8:4-6043    [000]   5540.021484: nf_hook_slow <-__netif_receive_skb_core
          <idle>-0       [003]   5540.021485: nf_hook_slow <-ip_rcv
          <idle>-0       [003]   5540.021492: nf_hook_slow <-ip_local_deliver
          <idle>-0       [003]   5540.021499: nf_hook_slow <-__netif_receive_skb_core
          <idle>-0       [003]   5540.021504: nf_hook_slow <-ip_rcv
          <idle>-0       [003]   5540.021510: nf_hook_slow <-ip_local_deliver
    kworker/u8:4-6043    [000]   5540.021516: nf_hook_slow <-__netif_receive_skb_core
          <idle>-0       [003]   5540.021516: nf_hook_slow <-__netif_receive_skb_core

# 以下省略

输出的信息分别为 TASK-PID (进程/进程ID)、CPU# (核编号)、TIMESTAMP (时间戳)、和 FUNCTION (函数)。

跟踪调用栈

使用 -G 参数可以跟踪调用栈，用法与 -T 相同。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
> perf ftrace -G nf_hook_slow

# tracer: function_graph                                                      
#                                                                                     
# CPU  DURATION                  FUNCTION CALLS                                              
# |     |   |                     |   |   |   |                             
 2)   6.093 us    |  __local_bh_enable_ip();                                       
 3)   5.208 us    |  mutex_unlock();                                          
 2)               |  nf_hook_slow() {                                       
 2)               |    riscv_intc_irq() {                                        
 2)               |      handle_IPI() {                                     
 2)   0.693 us    |        irq_enter();                                            
 2)   0.829 us    |        aclint_swi_clear();                                 
 2)               |        __wake_up() {                                      
 2)   0.931 us    |          _raw_spin_lock_irqsave();                           
 2)   1.060 us    |          __wake_up_common();                                   
 2)   0.828 us    |          _raw_spin_unlock_irqrestore();                         
 2)   7.326 us    |        }                                                        
 2)               |        irq_exit() {                                             
 2)   1.450 us    |          idle_cpu();                                            
 2)   4.368 us    |        }                                                        
 2) + 19.059 us   |      }                                                          
 2) + 21.640 us   |    }                                                            
 2)               |    nf_flow_offload_inet_hook [nf_flow_table_inet]() {    
 2)               |      nf_flow_offload_ip_hook [nf_flow_table]() {                
 2)   0.662 us    |        nf_flow_tuple_encap [nf_flow_table]();                   
 2)               |        flow_offload_lookup [nf_flow_table]() {                  
 2)   0.816 us    |          flow_offload_hash [nf_flow_table]();            
 2)   3.051 us    |        }                                                  
 2)   0.668 us    |        flow_offload_get_timeout [nf_flow_table]();              
 2)   0.646 us    |        nf_flow_encap_pop [nf_flow_table]();                     
 2)               |        nf_flow_snat_port [nf_flow_table]() {                    
 2)   0.668 us    |          inet_proto_csum_replace4();                            
 2)   2.293 us    |        }

输出的信息分别为 CPU# (核编号)、DURATION (函数执行时长)、和 FUNCTION CALLS (函数调用)。
函数执行时长大于 10 us 会标记加号，大于 100 us 会标记叹号。