这篇文章上次修改于 899 天前,可能其部分内容已经发生变化,如有疑问可询问作者。
使用动态追踪,可以在不修改代码、不重启服务的情况下,动态了解应用程序或者内核的行为,这对排查线上问题、特别是不容易重现的问题尤其有效。
Linux 提供了一系列的动态追踪机制,比如 ftrace、perf、eBPF 等
1 ftrace
当想要了解某个内核函数的调用过程时, 可以使用 ftrace 跟踪到它的执行过程。ftrace 的使用接口与 procfs 类似,通过 debugfs 以普通文件的形式向用户空间提供访问接口。
切到 debugfs 的挂载点:
$ cd /sys/kernel/debug/tracing
$ ls
README instances set_ftrace_notrace trace_marker_raw
available_events kprobe_events set_ftrace_pid trace_options
...
查询所有支持的跟踪器:
$ cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
- function 表示跟踪函数执行。
- funcion_graph 表示跟踪函数的调用关系。
查询支持的函数和事件:
$ cat available_filter_functions
$ cat available_events
接下来以 ls 命令为例,看下 ftrace 的使用方法。
一:ls 调用 open 系统调用打开目录文件,而 open 在内核中对应的函数名称为 do_sys_open。所以,需要将跟踪函数设为 open:
$ echo do_sys_open > set_graph_function
二:配置跟踪项,开启函数调用跟踪,并跟踪调用进程:
$ echo function_graph > current_tracer
$ echo funcgraph-proc > trace_options
三:开启跟踪:
$ echo 1 > tracing_on
四:执行一个 ls 命令后,再关闭跟踪:
$ ls
$ echo 0 > tracing_on
五:查看跟踪结果:
$ cat trace
# tracer: function_graph
#
# CPU TASK/PID DURATION FUNCTION CALLS
# | | | | | | | | |
0) ls-12276 | | do_sys_open() {
0) ls-12276 | | getname() {
0) ls-12276 | | getname_flags() {
0) ls-12276 | | kmem_cache_alloc() {
0) ls-12276 | | _cond_resched() {
0) ls-12276 | 0.049 us | rcu_all_qs();
0) ls-12276 | 0.791 us | }
0) ls-12276 | 0.041 us | should_failslab();
0) ls-12276 | 0.040 us | prefetch_freepointer();
0) ls-12276 | 0.039 us | memcg_kmem_put_cache();
0) ls-12276 | 2.895 us | }
0) ls-12276 | | __check_object_size() {
0) ls-12276 | 0.067 us | __virt_addr_valid();
0) ls-12276 | 0.044 us | __check_heap_object();
0) ls-12276 | 0.039 us | check_stack_object();
0) ls-12276 | 1.570 us | }
0) ls-12276 | 5.790 us | }
0) ls-12276 | 6.325 us | }
...
- 第一列是运行的 CPU
- 第二列是任务名称和进程 ID
- 第三列是函数执行延迟
- 最后一列是函数调用关系图
也可以用 trace-cmd 代替 ftrace。安装 trace-cmd:
# Ubuntu
$ apt-get install trace-cmd
# CentOS
$ yum install trace-cmd
ftrace 的五步可简化为两步:
$ trace-cmd record -p function_graph -g do_sys_open -O funcgraph-proc ls
$ trace-cmd report
...
ls-12418 [000] 85558.075341: funcgraph_entry: | do_sys_open() {
ls-12418 [000] 85558.075363: funcgraph_entry: | getname() {
ls-12418 [000] 85558.075364: funcgraph_entry: | getname_flags() {
ls-12418 [000] 85558.075364: funcgraph_entry: | kmem_cache_alloc() {
ls-12418 [000] 85558.075365: funcgraph_entry: | _cond_resched() {
ls-12418 [000] 85558.075365: funcgraph_entry: 0.074 us | rcu_all_qs();
ls-12418 [000] 85558.075366: funcgraph_exit: 1.143 us | }
ls-12418 [000] 85558.075366: funcgraph_entry: 0.064 us | should_failslab();
ls-12418 [000] 85558.075367: funcgraph_entry: 0.075 us | prefetch_freepointer();
ls-12418 [000] 85558.075368: funcgraph_entry: 0.085 us | memcg_kmem_put_cache();
ls-12418 [000] 85558.075369: funcgraph_exit: 4.447 us | }
ls-12418 [000] 85558.075369: funcgraph_entry: | __check_object_size() {
ls-12418 [000] 85558.075370: funcgraph_entry: 0.132 us | __virt_addr_valid();
ls-12418 [000] 85558.075370: funcgraph_entry: 0.093 us | __check_heap_object();
ls-12418 [000] 85558.075371: funcgraph_entry: 0.059 us | check_stack_object();
ls-12418 [000] 85558.075372: funcgraph_exit: 2.323 us | }
ls-12418 [000] 85558.075372: funcgraph_exit: 8.411 us | }
ls-12418 [000] 85558.075373: funcgraph_exit: 9.195 us | }
...
2 perf
perf 可以用来分析 CPU cache、CPU 迁移、分支预测、指令周期等各种硬件事件,也可以只对感兴趣的事件进行动态追踪。perf 既可以跟踪内核事件,也可以跟踪用户空间的函数。
查看 perf 支持的所有事件:
$ perf list
2.1 跟踪内核函数 do_sys_open
添加 do_sys_open 探针:
$ perf probe --add do_sys_open
Added new event:
probe:do_sys_open (on do_sys_open)
You can now use it in all perf tools, such as:
perf record -e probe:do_sys_open -aR sleep 1
对 10s 内 do_sys_open 采样:
$ perf record -e probe:do_sys_open -aR sleep 10
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.148 MB perf.data (19 samples) ]
查看采样结果:
$ perf script
perf 12886 [000] 89565.879875: probe:do_sys_open: (ffffffffa807b290)
sleep 12889 [000] 89565.880362: probe:do_sys_open: (ffffffffa807b290)
sleep 12889 [000] 89565.880382: probe:do_sys_open: (ffffffffa807b290)
sleep 12889 [000] 89565.880635: probe:do_sys_open: (ffffffffa807b290)
sleep 12889 [000] 89565.880669: probe:do_sys_open: (ffffffffa807b290)
但是我们还希望追踪它打开了哪些文件,通过追踪它的参数即可得知。
根据该文档 https://wiki.ubuntu.com/Debug%20Symbol%20Packages 安装调试信息后,查看 do_sys_open 的所有参数:
$ perf probe -V do_sys_open
Available variables at do_sys_open
@<do_sys_open+0>
char* filename
int dfd
int flags
struct open_flags op
umode_t mode
重新添加探针:
# 先删除旧的探针
perf probe --del probe:do_sys_open
# 添加带参数的探针
$ perf probe --add 'do_sys_open filename:string'
Added new event:
probe:do_sys_open (on do_sys_open with filename:string)
You can now use it in all perf tools, such as:
perf record -e probe:do_sys_open -aR sleep 1
重新采样并查看记录:
# 重新采样记录
$ perf record -e probe:do_sys_open -aR ls
# 查看结果
$ perf script
perf 13593 [000] 91846.053622: probe:do_sys_open: (ffffffffa807b290) filename_string="/proc/13596/status"
ls 13596 [000] 91846.053995: probe:do_sys_open: (ffffffffa807b290) filename_string="/etc/ld.so.cache"
ls 13596 [000] 91846.054011: probe:do_sys_open: (ffffffffa807b290) filename_string="/lib/x86_64-linux-gnu/libselinux.so.1"
ls 13596 [000] 91846.054066: probe:do_sys_open: (ffffffffa807b290) filename_string="/lib/x86_64-linux-gnu/libc.so.6”
...
# 使用完成后不要忘记删除探针
$ perf probe --del probe:do_sys_open
便可以看懂 open 打开的文件了。
执行 strace 时也和看到以上打开的动态库:
$ strace ls
...
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
...
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
...
但是 perf 比 strace 对进程的性能影响更小。perf 跟踪内核事件,而 strace 跟踪进程,需要在内核态和用户态切换,还需要借助 SIGSTOP 信号挂起目标进程。
perf 也提供了 trace 子命令,与 strace 很像:
$ perf trace ls
? ( ): ls/14234 ... [continued]: execve()) = 0
0.177 ( 0.013 ms): ls/14234 brk( ) = 0x555d96be7000
0.224 ( 0.014 ms): ls/14234 access(filename: 0xad98082 ) = -1 ENOENT No such file or directory
0.248 ( 0.009 ms): ls/14234 access(filename: 0xad9add0, mode: R ) = -1 ENOENT No such file or directory
0.267 ( 0.012 ms): ls/14234 openat(dfd: CWD, filename: 0xad98428, flags: CLOEXEC ) = 3
0.288 ( 0.009 ms): ls/14234 fstat(fd: 3</usr/lib/locale/C.UTF-8/LC_NAME>, statbuf: 0x7ffd2015f230 ) = 0
0.305 ( 0.011 ms): ls/14234 mmap(len: 45560, prot: READ, flags: PRIVATE, fd: 3 ) = 0x7efe0af92000
0.324 Dockerfile test.sh
( 0.008 ms): ls/14234 close(fd: 3</usr/lib/locale/C.UTF-8/LC_NAME> ) = 0
...
但 perf 可跟踪所有进程,而 strace 只能跟踪特定的进程。
2.2 用户空间的库函数
readline 是从终端读取用户输入,并将这些数据返回调用方。所以,相对于 open 系统调用,我们更关注 readline 调用的结果。
通过 -x 指定 bash 二进制文件的路径,就可以动态跟踪库函数。这其实就是跟踪了所有用户在 bash 中执行的命令:
# 为 /bin/bash 添加 readline 探针
$ perf probe -x /bin/bash 'readline%return +0($retval):string'
# 采样记录
$ perf record -e probe_bash:readline__return -aR sleep 5
# 查看结果
$ perf script
bash 13348 [000] 93939.142576: probe_bash:readline__return: (5626ffac1610 <- 5626ffa46739) arg1="ls"
# 跟踪完成后删除探针
$ perf probe --del probe_bash:readline__return
如果不确定探针格式,也可以通过下面的命令,查询所有支持的函数和函数参数:
# 查询所有的函数
$ perf probe -x /bin/bash —funcs
# 查询函数的参数
$ perf probe -x /bin/bash -V readline
Available variables at readline
@<readline+0>
char* prompt
3 eBPF 和 BCC
ftrace 和 perf 有一个共同的缺陷,那就是不够灵活,没法像 DTrace 那样通过脚本自由扩展。
而 eBPF 就是 Linux 版的 DTrace,可以通过 C 语言自由扩展。
BCC 把 eBPF 中的各种事件源(比如 kprobe、uprobe、tracepoint 等)和数据操作(称为 Maps),都转换成了 Python 接口(也支持 lua)。这样,使用 BCC 进行动态追踪时,编写简单的脚本就可以了。
参考
倪鹏飞. Linux 性能优化实战.
没有评论