前两天仿照 strings 工具写了个打印进程运行时堆栈可打印字符的工具 ffstrings 。结果没几天就被告知在 CentOS 上跑不通(uid: root, errno: EPERM):<

在反复调试无果之后，希望得到一种可以跟踪内核执行流的工具。功夫不负有心人，在内核文档中找到了—— ftrace 。

Ftrace 是位于内核内部的跟踪器，可以用来调试和分析发生在用户空间（内核空间）之外的延迟和性能问题。

虽然 Ftrace 是一款函数跟踪器，但也支持基于其它目的的跟踪，例如：跟踪上下文切换、跟踪高优先级任务的执行时间等等。另外还可以通过插件的方式自定义更多的跟踪。

当然，目前仅仅是做简单的介绍。毕竟最初的目的是为了确认 ffstrings 出现 EPERM 的原因。

启用 Ftrace

Ftrace 自版本 2.6.28 开始加入内核。首先要做的就是确保内核已经集成了 Ftrace 。当然，目前的内核版本都已经到 5.X 了，而且云服务器的普及，相信已经没有太多还在使用7、8年前 Linux 发行版的机器了吧 :)

Ftrace 使用 debugfs 文件系统以文件的形式来维护控制项和跟踪器输出。一般来说，这个文件系统将挂载在 /sys/kernel/debug 目录下。如果没有找到，那就主动先挂载上 debugfs 文件系统：

mount -t debugfs nodev /sys/kernel/debug

挂载文件系统之后，可以检查下 /sys/kernel/debug/tracing 目录，这里就是 Ftrace 全部的可配置项和输出。

几个重要的文件包括：

  • current_tracer, 配置当前跟踪器进行哪些项目的跟踪
  • available_tracers, 当前内核支持的所有跟踪项目
  • tracing_on, 开启/关闭跟踪器 (0 表示关闭, 1 表示开启)
  • trace, 用户可读的跟踪结果文件
  • trace_pipe, 与 trace 文件静态呈现的形式相对，里面的数据只能消费一次
  • trace_options, 配置输出文件的格式
  • tracing_max_latency, 记录最大延时
  • buffer_size_kb, 用于设置单个CPU使用的跟踪器缓存大小。跟踪器缓存使用环形缓存，老的缓存会在空间不足时被新缓存覆盖
  • tracing_cpumask, 用来配置需要监控的CPU
  • set_ftrace_filter, 显示指定跟踪特定的函数
  • set_ftrace_notrace, 与 set_ftrace_filter 功能恰好相反
  • set_ftrace_pid, 只跟踪特定的任务
  • set_graph_function, 设置要清晰显示调用关系的函数，以 C 语言缩进式地呈现
  • available_filter_functions, 显示目前可以跟踪的所有内核函数

使用 Ftrace

配置 current_tracer ，跟踪内核所有函数的调用

$ echo function > current_tracer

配置 tracing_enabled，开启跟踪器

$ echo 1 > tracing_on

查看 trace 文件中记录的跟踪器输出

$ head -15 trace
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
             zsh-23126 [000] d... 5252243.233084: do_syscall_64 <-entry_SYSCALL_64_after_hwframe
             zsh-23126 [000] .... 5252243.233084: SyS_rt_sigprocmask <-do_syscall_64
             zsh-23126 [000] .... 5252243.233084: sigprocmask <-SyS_rt_sigprocmask
             zsh-23126 [000] .... 5252243.233084: __set_current_blocked <-sigprocmask
             zsh-23126 [000] .... 5252243.233084: _raw_spin_lock_irq <-__set_current_blocked
             zsh-23126 [000] d... 5252243.233085: __set_task_blocked <-__set_current_blocked

OK，如果觉得这个结果并不直观，可以重新配置 current_tracer，使用 function_graph

$ echo function_graph > current_tracer
$ head -15 trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 0)               |      __fdget_pos() {
 0)   0.072 us    |        __fget_light();
 0)   0.377 us    |      }
 0)               |      vfs_read() {
 0)               |        rw_verify_area() {
 0)               |          security_file_permission() {
 0)               |            apparmor_file_permission() {
 0)               |              common_file_perm() {
 0)   0.079 us    |                aa_file_perm();
 0)   0.480 us    |              }
 0)   0.877 us    |            }

跟踪应用程序的系统调用

虽然 strace 就可以打印出任务的每个系统调用，但是，它所能完成的仅仅只是对每个系统调用及结果进行记录，而无法看到系统调用内部究竟发生了什么。而 ftrace 可以很好的完成这一点。当然，这需要一点点编码量。

回到最初的命题，执行 ffstrings 过程中，抛出了 EPERM 错误码。首先使用 strace 进行定位，究竟是哪个系统调用出了问题

$ strace ./ffstrings <PID>
# ... omitted output
read(4, 0x7f9ac2970000, 1024)           = -1 EPERM (Operation not permitted)
# ... omitted output

修改应用程序代码，添加两个新的函数 (trace_on, trace_off)。

Hint: 这段代码的健壮性并不好，请各位多担待

int trace_fd = -1;
int marker_fd = -1;
char *debugfs = "/sys/kernel/debug";

void trace_on()
{
	char path[256];

	strcpy(path, debugfs);  /* BEWARE buffer overflow */
	strcat(path,"/tracing/tracing_on");
	trace_fd = open(path, O_WRONLY);
	if (trace_fd >= 0)
		write(trace_fd, "1", 1);

	strcpy(path, debugfs);
	strcat(path,"/tracing/trace_marker");
	marker_fd = open(path, O_WRONLY);
    if (marker_fd >= 0)
	    write(marker_fd, "In critical area\n", 17);
}

void trace_off()
{
    if (marker_fd >= 0)
	    write(marker_fd, "Out critical area\n", 17);
    write(trace_fd, "0", 1);
    close(trace_fd);
    close(marker_fd);
    trace_fd = -1;
    marker_fd = -1;
}

在问题代码前后执行这两个新的函数

trace_on();
char c = getc(mem);
trace_off();

再去从 trace 文件中取一下执行结果（局部结果）

到此为止，就可以简单的实现对内核函数的跟踪。

不过，这仅仅只能看到内核函数调用，具体的调用关系，还是得拿到相应版本的内核代码仔细研读研读。毕竟，内核代码的改动也是相当频繁的，不同版本调用关系会出现很大的变化。

  __                    __                  
 / _| __ _ _ __   __ _ / _| ___ _ __   __ _ 
| |_ / _` | '_ \ / _` | |_ / _ \ '_ \ / _` |
|  _| (_| | | | | (_| |  _|  __/ | | | (_| |
|_|  \__,_|_| |_|\__, |_|  \___|_| |_|\__, |
                 |___/                |___/