写点什么

从 Ftrace 开始内核探索之旅

发布于: 2021 年 10 月 15 日
从Ftrace开始内核探索之旅

前言


操作系统内核对应用开发工程师来说就像一个黑盒,似乎很难窥探到其内部的运行机制。其实 Linux 内核很早就内置了一个强大的 tracing 工具:Ftrace,它几乎可以跟踪内核的所有函数,不仅可以用于调试和分析,还可以用于观察学习 Linux 内核的内部运行。虽然 Ftrace 在 2008 年就加入了内核,但很多应用开发工程师仍然不知道它的存在。本文就给你介绍一下 Ftrace 的基本使用。

Ftrace 初体验


先用一个例子体验一下使用简单且功能强大的 Ftrace。使用 root 用户进入/sys/kernel/debug/tracing 目录,执行 echo 和 cat 命令:

我们使用 Ftrace 的 function_graph 功能显示了内核函数 _do_fork() 所有子函数调用。左边的第一列是执行函数的 CPU,第二列 DURATION 显示在相应函数中花费的时间。我们注意到最后一行的耗时之前有个 + 号,提示用户注意延迟高的函数。+ 代表耗时大于 10 μs。如果耗时大于 100 μs,则显示 ! 号。


我们知道,fork 是建立父进程的一个完整副本,然后作为子进程执行。那么_do_fork()的第一件大事就是调用 copy_process() 复制父进程的数据结构,从上面输出的调用链信息也验证了这一点。


使用完后执行下面的命令关闭 function_graph:

# echo nop > current_tracer

# echo > set_graph_function

使用 Ftrace 的 function_graph 功能,可以查看内核函数的子函数调用链,帮助我们理解复杂的代码流程,而这只是 Ftrace 的功能之一。这么强大的功能,我们不必安装额外的用户空间工具,只要使用 echo 和 cat 命令访问特定的文件就能实现。Ftrace 对用户的使用接口正是 tracefs 文件系统。

tracefs 文件系统


用户通过 tracefs 文件系统使用 Ftrace,这很符合一切皆文件的 Linux 哲学。tracefs 文件系统一般挂载在/sys/kernel/tracing 目录。由于 Ftrace 最初是 debugfs 文件系统的一部分,后来才被拆分为自己的 tracefs。所以如果系统已经挂载了 debugfs,那么仍然会保留原来的目录结构,将 tracefs 挂载到 debugfs 的子目录下。我们可以使用 mount 命令查看当前系统 debugfs 和 tracefs 挂载点:


我使用的系统是 Ubuntu 20.04.2 LTS,可以看到,为了保持兼容,tracefs 同时挂载到了/sys/kernel/tracing 和/sys/kernel/debug/tracing。


tracefs 下的文件主要分两类:控制文件和输出文件。这些文件的名字都很直观,像前面例子通过 current_tracer 设置当前要使用的 tracer,然后从 trace 中读取结果。还有像 available_tracers 包含了当前内核可用的 tracer,可以设置 trace_options 自定义输出。

本文后面的示例假定你已经处在了/sys/kernel/tracing 或/sys/kernel/debug/tracing 目录下。

函数跟踪


Ftrace 实际上代表的就是 function trace(函数跟踪),因此函数追踪是 Ftrace 最初的一个主要功能。


Ftrace 可以跟踪几乎所有内核函数调用的详细信息,这是怎么做到的呢?简单来说,在编译内核的时候使用了 gcc 的 -pg 选项,编译器会在每个内核函数的入口处调用一个特殊的汇编函数“mcount” 或 “__fentry__”,如果跟踪功能被打开,mcount/fentry 会调用当前设置的 tracer,tracer 将不同的数据写入 ring buffer。

从上图可以看出,Ftrace 提供的 function hooks 机制在内核函数入口处埋点,根据配置调用特定的 tracer, tracer 将数据写入 ring buffer。Ftrace 实现了一个无锁的 ring buffer,所有的跟踪信息都存储在 ring buffer 中。用户通过 tracefs 文件系统接口访问函数跟踪的输出结果。


你可能已经意识到,如果每个内核函数入口都加入跟踪代码,必然会非常影响内核的性能,幸好 Ftrace 支持动态跟踪功能。如果启用了 CONFIG_DYNAMIC_FTRACE 选项,编译内核时所有的 mcount/fentry 调用点都会被收集记录。在内核的初始化启动过程中,会根据编译期记录的列表,将 mcount/fentry 调用点替换为 NOP 指令。NOP 就是 no-operation,不做任何事,直接转到下一条指令。因此在没有开启跟踪功能的情况下,Ftrace 不会对内核性能产生任何影响。在开启追踪功能时,Ftrace 才会将 NOP 指令替换为 mcount/fentry。


启用函数追踪功能,只需要将 current_tracer 文件的内容设置为 "function":

文件头已经很好的解释了每一列的含义。前两项是被追踪的任务名称和 PID,大括号内是执行跟踪的 CPU。TIMESTAMP 是启动后的时间,后面是被追踪的函数,它的调用者在 <- 之后。


我们可以设置 set_ftrace_filter 选择想要跟踪的函数:

trace_pipe 包含了与 trace 相同的输出,从这个文件的读取会返回一个无尽的事件流,它也会消耗事件,所以在读取一次后,它们就不再在跟踪缓冲区中了。


也许你只想跟踪一个特定的进程,可以通过设置 set_ftrace_pid 内容为 PID 指定想追踪的特定进程。让 tracer 只追踪 PID 列在这个文件中的线程:


# echo [PID] > set_ftrace_pid

# echo function > current_tracer

如果设置了 function-fork 选项,那么当一个 PID 被列在 set_ftrace_pid 这个文件中时,其子任务的 PID 将被自动添加到这个文件中,并且子任务也将被 tracer 追踪。


# echo function-fork > trace_options


取消 function-fork 选项:

取消 set_ftrace_pid 的设置:


# echo > set_ftrace_pid

Ftrace function_graph


文章开始例子已经展示过,function_graph 可以打印出函数的调用图,揭示代码的流程。function_graph 不仅跟踪函数的输入,而且跟踪函数的返回,这使得 tracer 能够知道被调用的函数的深度。function_graph 可以让人更容易跟踪内核的执行流程。


我们再看一个例子:

前面提到过,函数耗时大于 10 μs,前面会有 + 号提醒用户注意,其他的符号还有:


  • $ :延迟大于 1 秒

  • :延迟大于 100 ms

  • :延迟大于 10 ms

  • :延迟大于 1 ms

  • :延迟大于 100 μs

  • :延迟大于 10 μs

函数 Profiler


函数 Profiler 提供了内核函数调用的统计数据,可以观察哪些内核函数正在被使用,并能发现哪些函数的执行耗时最长。

这里有一个要注意的地方,确保使用的是 0 >,而不是 0>。这两者的含义不一样,0>是对文件描述符 0 的重定向。同样要避免使用 1>,因为这是对文件描述符 1 的重定向。


现在可以从 trace_stat 目录中读取 profile 的统计数据。在这个目录中,profile 数据按照 CPU 保存在名为 function[n] 文件中。我使用的 4 核 CPU,看一下 profile 结果:

第一行是每一列的名称,分别是函数名称(Function),调用次数(Hit),函数的总时间(Time)、平均函数时间(Avg)和标准差(s^2)。输出结果显示,tcp_sendmsg() 在 3 个 CPU 上都是最频繁的,tcp_v4_rcv() 在 CPU2 上被调用了 1618 次,平均延迟为 17.218 us。


最后要注意一点,在使用 Ftrace Profiler 时,尽量通过 set_ftrace_filter 限制 profile 的范围,避免对所有的内核函数都进行 profile。


追踪点 Tracepoints


Tracepoints 是内核的静态埋点。内核维护者在他认为重要的位置放置静态 tracepoints 记录上下文信息,方便后续排查问题。例如系统调用的开始和结束,中断被触发,网络数据包发送等等。


在 Linux 的早期,内核维护者就一直想在内核中加入静态 tracepoints,尝试过各种策略。Ftrace 创造了 Event Tracing 基础设施,让开发者使用 TRACE_EVENT() 宏添加内核 tracepoints,不用创建自定义内核模块,使用 Event Tracing 基础设施来注册埋点函数。


现在内核中的 Tracepoints 都使用了 TRACE_EVENT() 宏来定义,tracepoints 记录的上下文信息作为 Trace events 进入 Event Tracing 基础设施,这样我们就可以复用 Ftrace 的 tracefs ,通过文件接口来配置 tracepoint events,并使用 trace 或 trace_pipe 文件查看事件输出。


所有的 tracepoint events 的控制文件都在 events 目录下,按照类别以子目录形式组织:

我们以 events/sched/sched_process_fork 事件为例,该事件是在 include/trace/events/sched.h 中由 TRACE_EVENT 宏所定义:

TRACE_EVENT 宏会根据事件名称 sched_process_fork 生成 tracepoint 方法 trace_sched_process_fork()。你会在 kernel/fork.c 的 _do_fork() 中看到调用这个 tracepoint 方法。_do_fork() 是进程 fork 的主流程,在这里放置 tracepoint 是一个合适的位置,trace_sched_process_fork(current, p) 记录当前进程和 fork 出的子进程信息:

在 events/sched/sched_process_fork 目录下,有这个事件的控制文件:

我们演示如何通过 enable 文件开启和关闭这个 tracepoint 事件:

前五列分别是进程名称,PID,CPU ID,irqs-off 等标志位,timestamp 和 tracepoint 事件名称。其余部分是 tracepoint 格式字符串,包含当前这个 tracepoint 记录的重要信息。格式字符串可以在 events/sched/sched_process_fork/format 文件中查看:

通过这个 format 文件,我们可以了解这个 tracepoint 事件每个字段的含义。


我们再演示一个使用 trigger 控制文件的例子:

这个例子使用了 hist triggers,通过 sched_process_fork 事件来统计 _do_fork 的次数,并按照进程 ID 生成直方图。输出显示了 PID 24493 在追踪期间 fork 了 24 个子进程,最后几行显示了统计数据。


关于 Hist Triggers 的详细介绍可以参考文档 Event Histograms。


我的系统内核版本是 5.8.0-59-generic,当前可用的 tracepoints events 有 2547 个:

Event Tracing 基础设施应该是 Ftrace 的另一大贡献,它提供的 TRACE_EVENT 宏统一了内核 tracepoint 的实现方式,为 tracepoint events 提供了基础支持。perf 的 tracepoint events 也是基于 Ftrace 实现的。


利用 Tracepoints 理解内核代码


由于 tracepoints 是内核维护者在流程重要位置设置的埋点,因此我们可以从 tracepoints 入手来学习内核代码。所有的 tracepoints 都定义在 include/trace/events/ 目录下的头文件中,例如进程调度相关的 tracepoints 定义在 include/trace/events/sched.h 中,我们以 sched_switch 为例:

TRACE_EVENT 宏会根据事件名称 sched_switch 生成 tracepoint 方法 trace_sched_switch(),在源码中查找该方法,发现在 kernel/sched/core.c 的 __schedule()中调用了 trace_sched_switch() :

这样我们就找到了 scheduler 的主流程,可以从这里开始阅读进程调度的源码。


写在最后


Ftrace 就包含在内核源码中 kernel/trace,理解了 Ftrace 内核不再是黑箱,你会有豁然开朗的感觉,内核源码忽然有条理了起来。让我们从 Ftrace 开始内核探索之旅吧。

发布于: 2021 年 10 月 15 日阅读数: 14
用户头像

坚持自主创新,提供技术干货 2021.09.09 加入

金蝶天燕云,提供技术热点、技术场景、技术测评等干货文章,欢迎大家交流!传送门:https://mp.weixin.qq.com/mp/profile_ext?action=home&__biz=MzkyODI0ODAzOA==&scene=124#wechat_redirect

评论

发布
暂无评论
从Ftrace开始内核探索之旅