这篇文章上次修改于 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 性能优化实战.