⚠ 转载请注明出处：作者：ZobinHuang，更新日期：Jan.30 2022
本作品由 ZobinHuang 采用 知识共享署名-非商业性使用-禁止演绎 4.0 国际许可协议 进行许可，在进行使用或分享前请查看权限要求。若发现侵权行为，会采取法律手段维护作者正当合法权益，谢谢配合。
目录
有特定需要的内容直接跳转到相关章节查看即可。
何为 Trace 和 Profile?
so_profiling_and_tracing, book_system_performance 就系统性能的分析而言，可以分为两个不同的动作：
Profiling
Profiling 可以理解为从系统中收集 (采样) 运行过程中的信息 (e.g. 比如运行时间等)，然后从中发现系统运行瓶颈等信息。如上图所示的是
本文介绍的 Ftrace，就带有 Profiling 的功能。
Tracing
而 Tracing 可以理解为追踪任务运行的流程，例如我们可以使用 strace 来跟踪 System Call 的调用，使用 tcpdump 来追踪网络数据包的发送和到达等。我们可以把 Tracing 分为以下的两类:
libc 等库用于追踪用户程序对库函数的调用。
本文介绍的 Ftrace，属于静态仪表类型的 Trace 工具。
Ftrace
Ftrace 是一种内核原生的追踪工具。由 Steven Rostedt 开发 book_system_performance，并且在内核版本 2.6.27 (2008) 年的时候加入内核主线。Ftrace 的基本结构如下所示:
如上所示是 Ftrace 的基本结构，我们可以看到在内核中有 Ftrace 的 Profiler 和 Tracer 在工作，我们在下文中将分别介绍它们的功能，以及具体操作手段。
tracefs 文件系统
使用 Ftrace 工具的接口是 tracefs 文件系统。它应该被 mount 在以下位置:
1
2
3
4
5
6
7
8
9
10
11
12root@zobin-ubuntu-devbox:/home/zobin# mount -t tracefs
tracefs on /sys/kernel/tracing type tracefs (rw,nosuid,nodev,noexec,relatime)
root@zobin-ubuntu-devbox:/home/zobin# ls /sys/kernel/tracing/
available_events dyn_ftrace_total_info kprobe_events saved_cmdlines_size set_ftrace_pid timestamp_mode tracing_cpumask
available_filter_functions enabled_functions kprobe_profile saved_tgids set_graph_function trace tracing_max_latency
available_tracers error_log max_graph_depth set_event set_graph_notrace trace_clock tracing_on
buffer_percent events options set_event_notrace_pid snapshot trace_marker tracing_thresh
buffer_size_kb free_buffer per_cpu set_event_pid stack_max_size trace_marker_raw uprobe_events
buffer_total_size_kb function_profile_enabled printk_formats set_ftrace_filter stack_trace trace_options uprobe_profile
current_tracer hwlat_detector README set_ftrace_notrace stack_trace_filter trace_pipe
dynamic_events instances saved_cmdlines set_ftrace_notrace_pid synthetic_events trace_stat
Ftrace 在历史上曾经使用过 debugfs 文件系统接口来进行操作，直到后来独立出来了自己的文件系统。但是 debugfs 文件系统仍然保留了 Ftrace 的入口 (i.e. 以一个子文件夹的形式存在)，具体在如下位置:
1
2
3
4
5
6
7
8
9
10
11
12root@zobin-ubuntu-devbox:/home/zobin# mount -t debugfs
debugfs on /sys/kernel/debug type debugfs (rw,nosuid,nodev,noexec,relatime)
root@zobin-ubuntu-devbox:/home/zobin# ls /sys/kernel/debug/tracing/
available_events dyn_ftrace_total_info kprobe_events saved_cmdlines_size set_ftrace_pid timestamp_mode tracing_cpumask
available_filter_functions enabled_functions kprobe_profile saved_tgids set_graph_function trace tracing_max_latency
available_tracers error_log max_graph_depth set_event set_graph_notrace trace_clock tracing_on
buffer_percent events options set_event_notrace_pid snapshot trace_marker tracing_thresh
buffer_size_kb free_buffer per_cpu set_event_pid stack_max_size trace_marker_raw uprobe_events
buffer_total_size_kb function_profile_enabled printk_formats set_ftrace_filter stack_trace trace_options uprobe_profile
current_tracer hwlat_detector README set_ftrace_notrace stack_trace_filter trace_pipe
dynamic_events instances saved_cmdlines set_ftrace_notrace_pid synthetic_events trace_stat
如上所示，我们可以看到在 tracing 目录下有若干的文件，我们会在下面具体的操作中对这些文件的功能进行解释。
Ftrace Function Profiler
Ftrace Function Profiler 提供了内核函数运行的静态数据，我们可以通过它来找到运行时间较长的内核函数，也即找到系统瓶颈。
Ftrace Function Profiler 通过在每个内核函数的最开始运行被编译好的 Profiling Call 来实现 Profiling。在 GCC 编译的时候，如果启用了 -pg 选项，则编译器会自动地在函数最开始处插入 mcount() 调用。从 GCC 4.6 版本以来，插入的调用则变为 __fentry__()。
下面我们尝试对部分函数进行 Profiling。
我们首先确认一下 Ftrace 的初始化状态:
1
2
3
4root@zobin-ubuntu-devbox:/sys/kernel/debug/tracing# cat set_ftrace_filter
#### all functions enabled ####
root@zobin-ubuntu-devbox:/sys/kernel/debug/tracing# cat function_profile_enabled
0
然后我们运行如下脚本:
1
2
3
4
5echo 'tcp*' > set_ftrace_filter
echo 1 > function_profile_enabled
sleep 10
echo 0 > function_profile_enabled
echo > set_ftrace_filter
然后我们对输出进行观察:
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
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133root@zobin-ubuntu-devbox:/sys/kernel/debug/tracing# head trace_stat/function*
==> trace_stat/function0 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function1 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
tcp_recvmsg 1 4.045 us 4.045 us 0.000 us
tcp_recvmsg_locked 1 3.252 us 3.252 us 0.000 us
tcp_write_timer 1 2.408 us 2.408 us 0.000 us
tcp_poll 2 1.313 us 0.656 us 0.068 us
tcp_write_timer_handler 1 1.020 us 1.020 us 0.000 us
tcp_rcv_space_adjust 1 0.467 us 0.467 us 0.000 us
tcp_release_cb 1 0.348 us 0.348 us 0.000 us
tcp_stream_memory_free 2 0.320 us 0.160 us 0.000 us
==> trace_stat/function10 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function11 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
tcp_sendmsg 3 230.274 us 76.758 us 539.782 us
tcp_sendmsg_locked 3 198.174 us 66.058 us 445.199 us
tcp_push 3 144.392 us 48.130 us 61.359 us
tcp_write_xmit 3 142.835 us 47.611 us 59.649 us
tcp_v4_do_rcv 6 88.430 us 14.738 us 56.166 us
tcp_rcv_established 6 85.988 us 14.331 us 54.772 us
tcp_v4_rcv 6 81.338 us 13.556 us 163.050 us
tcp_data_ready 3 36.735 us 12.245 us 7.659 us
==> trace_stat/function12 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function13 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function14 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function15 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function16 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
tcp_wfree 3 5.223 us 1.741 us 0.201 us
==> trace_stat/function17 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function18 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function19 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function2 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function20 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function21 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function22 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function23 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function3 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
tcp_v4_rcv 7 271.222 us 38.746 us 908.842 us
tcp_v4_do_rcv 7 245.733 us 35.104 us 850.498 us
tcp_rcv_established 7 241.681 us 34.525 us 841.727 us
tcp_send_ack 2 96.244 us 48.122 us 2.590 us
tcp_data_queue 6 86.503 us 14.417 us 112.886 us
tcp_data_ready 4 74.480 us 18.620 us 1.477 us
tcp_ack 7 29.204 us 4.172 us 19.283 us
tcp_v4_early_demux 7 17.127 us 2.446 us 0.639 us
==> trace_stat/function4 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function5 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function6 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
tcp_sendmsg 7 554.454 us 79.207 us 419.218 us
tcp_sendmsg_locked 7 508.787 us 72.683 us 269.840 us
tcp_push 7 441.902 us 63.128 us 233.553 us
tcp_write_xmit 7 436.902 us 62.414 us 229.824 us
tcp_v4_do_rcv 8 198.514 us 24.814 us 337.225 us
tcp_rcv_established 8 195.133 us 24.391 us 333.934 us
tcp_v4_rcv 8 190.304 us 23.788 us 559.113 us
tcp_data_queue 4 128.238 us 32.059 us 133.134 us
==> trace_stat/function7 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function8 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
==> trace_stat/function9 <==
Function Hit Time Avg s^2
-------- --- ---- --- ---
tcp_orphan_update 6 23.298 us 3.883 us 2.978 us
tcp_orphan_count_sum 6 7.929 us 1.321 us 0.189 us
tcp_write_timer 1 2.172 us 2.172 us 0.000 us
tcp_write_timer_handler 1 0.828 us 0.828 us 0.000 us
可以观察到在 trace_stat 下有多个文件的输出，输出格式是 functionX，其中 X 代表的是 CPU 的核心编号。我们在上面看到一共有 24 个文件输出，因为我们做实验的平台是一个 24 核心的平台。在输出的数据中，我们可以看到函数名称 (Function)、调用次数 (Hit)、各个函数的总运行时间 (Time)、各个函数的平均每次调用的运行时间 (Avg)，以及运行时间的标准差 (s^2)。
Ftrace Function Tracer
使用 trace
下面我们基于 trace 文件进行 Tracing。
首先我们确认一下 Ftrace Tracer 的初始化状态:
1
2
3
4root@zobin-ubuntu-devbox:/sys/kernel/debug/tracing# cat set_ftrace_filter
#### all functions enabled ####
root@zobin-ubuntu-devbox:/sys/kernel/debug/tracing# cat current_tracer
nop
接着我们运行如下脚本:
1
2
3
4
5
6
7echo 1 > tracing_on
echo '*sleep' > set_ftrace_filter
echo function > current_tracer
sleep 10
cat trace > /tmp/out.trace01.txt
echo nop > current_tracer
echo > set_ftrace_filter
然后我们就可以从文件中观察到如下输出:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22root@zobin-ubuntu-devbox:/sys/kernel/debug/tracing# more /tmp/out.trace01.txt
# tracer: function
#
# entries-in-buffer/entries-written: 52/52 #P:24
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
sleep-5912 [022] .... 2559.449999: __x64_sys_clock_nanosleep <-do_syscall_64
sleep-5912 [022] .... 2559.450001: common_nsleep <-__x64_sys_clock_nanosleep
sleep-5912 [022] .... 2559.450002: hrtimer_nanosleep <-common_nsleep
sleep-5912 [022] .... 2559.450002: do_nanosleep <-hrtimer_nanosleep
node-5128 [017] .... 2560.118227: __x64_sys_clock_nanosleep <-do_syscall_64
node-5128 [017] .... 2560.118229: common_nsleep <-__x64_sys_clock_nanosleep
node-5128 [017] .... 2560.118229: hrtimer_nanosleep <-common_nsleep
node-5128 [017] .... 2560.118229: do_nanosleep <-hrtimer_nanosleep
sleep-5925 [007] .... 2560.394063: __x64_sys_clock_nanosleep <-do_syscall_64
sleep-5925 [007] .... 2560.394064: common_nsleep <-__x64_sys_clock_nanosleep
在上面输出的每一行中，我们可以观察到进程的 PID (PID)、进程名称 (TASK)，运行的 CPU 核心 (CPU#)，运行的时间戳 (TIMESTAMP)，以及函数的调用情况 (FUNCTION)。