技术笔记：Linux内核跟踪和性能分析

尽管通过打印进行调试可以满足大多数调试需求，但在某些情况下，我们需要在运行时监视Linux内核以跟踪奇怪的行为，包括延迟、CPU占用、调度问题等等。在Linux世界中，实现这一点最有用的工具是内核本身的一部分。最重要的是ftrace，这是一种Linux内核内部跟踪工具，也是本文章的主要主题。

使用Ftrace来检测代码

函数跟踪(Function Trace)，简称为Ftrace，它的作用远不止它的名字。例如，它可以用来测量处理中断所花费的时间，跟踪耗时的功能，计算激活高优先级任务的时间，跟踪上下文切换，等等。

Ftrace由Steven Rostedt开发，自2008年2.6.27版本以来一直包含在内核中。这个框架为记录数据提供了一个调试环缓冲区。这些数据是由内核集成的跟踪程序收集的。Ftrace工作在debugfs文件系统之上，大多数情况下，当它被启用时，它被挂载在自己的名为tracing的目录中。在大多数现代Linux发行版中，它默认挂载在/sys/kernel/debug/目录下(仅对root用户可用)，这意味着您可以在/sys/kernel/debug/tracing/中使用Ftrace。

为了在您的系统上支持Ftrace，需要启用以下内核选项:

CONFIG_FUNCTION_TRACER

CONFIG_FUNCTION_GRAPH_TRACER

CONFIG_STACK_TRACER

CONFIG_DYNAMIC_FTRACE

上述选项依赖于通过启用CONFIG_HAVE_FUNCTION_TRACER、CONFIG_HAVE_DYNAMIC_FTRACE和CONFIG_HAVE_FUNCTION_GRAPH_TRACER选项来支持跟踪特性的体系结构。

要挂载tracefs目录，您可以在/etc/fstab文件中添加以下一行:

tracefs /sys/kernel/debug/tracing tracefs defaults 0 0

或者你可以在运行时使用以下命令来挂载它:

mount -t tracefs nodev /sys/kernel/debug/tracing

目录的内容应该是这样的:

# ls /sys/kernel/debug/tracing/

README set_event_pid

available_events set_ftrace_filter

available_filter_functions set_ftrace_notrace

available_tracers set_ftrace_pid

buffer_size_kb set_graph_function

buffer_total_size_kb set_graph_notrace

current_tracer snapshot

dyn_ftrace_total_info stack_max_size

enabled_functions stack_trace

events stack_trace_filter

free_buffer trace

function_profile_enabled trace_clock

instances trace_marker

max_graph_depth trace_options

options trace_pipe

per_cpu trace_stat

printk_formats tracing_cpumask

saved_cmdlines tracing_max_latency

saved_cmdlines_size tracing_on

set_event tracing_thresh

我们不会描述所有这些文件和子目录，因为在官方文档中已经介绍过了。相反，我们将简单描述与上下文相关的文件:

available_tracers:可用的跟踪程序。

tracing_cumask:允许跟踪选定的CPUs。掩码应该以十六进制字符串格式指定。例如，要只跟踪core 0，您应该在该文件中包含1。要跟踪core 1，应该在其中包含一个2。对于core 3，应该包括数字8。

current_tracer:当前正在运行的跟踪程序。

tracing_on:负责启用或禁用向环形缓冲区写入数据的系统文件(要启用此功能，必须将数字1添加到文件中;若要禁用它，则添加数字0)。

trace:以人类可读格式保存跟踪数据的文件。

既然我们已经介绍了Ftrace并描述了它的功能，那么我们就可以深入研究它的用法，了解它在跟踪和调试方面有多么有用。

可用的tracers

我们可以使用以下命令查看可用的tracers列表:

# cat /sys/kernel/debug/tracing/available_tracers

blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup irqsoff function nop

让我们快速了解一下每种tracer的特点:

function:没有参数的函数调用tracer。

function_graph:带有子调用的函数调用tracer。

blk:与块设备I/O操作相关的调用和事件tracer(这就是blktrace所使用的)。

mmiotrace:内存映射的I/O操作tracer。它跟踪一个模块对硬件的所有调用。它是通过CONFIG_MMIOTRACE启用的，这取决于CONFIG_HAVE_MMIOTRACE_SUPPORT。

irqsoff:跟踪禁用中断的区域，并保存最大延迟时间最长的跟踪。这个跟踪程序依赖于CONFIG_IRQSOFF_TRACER。

preemptoff:取决于CONFIG_PREEMPT_TRACER。它类似于irqsoff，但是跟踪并记录禁用抢占的时间。

preemtirqsoff:类似于irqsoff和preemptoff，但它跟踪并记录禁用irqs和/或抢占的最大时间。

CONFIG_SCHED_TRACER启用的wakeup和wakeup_rt:前者跟踪并记录最高优先级任务在被唤醒后被调度所需的最大延迟，而后者跟踪并记录仅用于实时(RT)任务所需的最大延迟(与当前唤醒跟踪程序的方式相同)。

nop:最简单的跟踪器，顾名思义，它什么都不做。nop跟踪程序只是显示trace_printk()调用的输出。

irqsoff、preemptoff和preemtirqsoff是所谓的延迟跟踪器。它们测量中断被禁用多长时间，抢占被禁用多长时间，以及中断和/或抢占被禁用多长时间。Wakeup延迟跟踪器测量一个进程在被所有任务或RT任务唤醒后需要多长时间才能运行。

The function tracer

我们将从函数跟踪器开始介绍Ftrace。让我们来看一个测试脚本:

# cd /sys/kernel/debug/tracing

# echo function

# echo 1 > tracing_on

# sleep 1

# echo 0 > tracing_on

# less trace

这个脚本相当简单，但有几件事值得注意。我们通过将当前跟踪程序的名称写入current_tracer文件来启用当前跟踪程序。接下来，我们将1写入tracing_on，这将启用循环缓冲区。语法要求在1和>之间有个空格，“echo1> tracing_on”将不能工作。一行之后，我们禁用它(如果将0写入tracing_on，缓冲区将不会被清除，Ftrace也不会被禁用)。

我们为什么要这么做?在两个echo命令之间，我们看到sleep 1命令。我们启用缓冲区，运行这个命令，然后禁用它。这使得跟踪程序可以包含与命令运行时发生的所有系统调用相关的信息。在脚本的最后一行中，我们给出在控制台中显示跟踪数据的命令。一旦脚本运行，我们将看到以下打印输出(这只是一个小片段):

打印输出以缓冲区中的条目数量和写入的条目总数相关的信息开始。这两个数字之间的差就是填充缓冲区时丢失的事件数。然后，有一个包含以下信息的//代码效果参考：http://www.lyjsj.net.cn/wx/art_23374.html

进程名(TASK)。

进程标识符(PID)。

进程运行的CPU (CPU#)。

函数开始时间(TIMESTAMP)。这个时间戳是自启动以来的时间。

被跟踪函数的名称(FUNCTION)和在 '<-' 符号后面被调用的父函数。例如，在输出的第一行中，irq_may_run函数是由handle_fasteoi_irq调用的。

现在我们已经熟悉了函数跟踪器及其特性，我们可以了解下一个跟踪器，它具有更丰富的特性，并提供更多的跟踪信息，例如调用graph。

The function_graph tracer

function_graph tracer的工作方式就像function tracer一样，但是以更详细的方式:显示每个函数的入口和出口点。使用这个跟踪器，我们可以跟踪带有子调用的函数，并测量每个函数的执行时间。

让我们编辑前面例子中的脚本:

# cd /sys/kernel/debug/tracing

# echo function_graph

# echo 1 > tracing_on

# sleep 1

# echo 0 > tracing_on

# less trace

运行这个脚本后，我们得到以下打印输出:

# tracer: function_graph

#

# CPU DURATION FUNCTION CALLS

# | | | | | | |

5) 0.400 us | } / set_next_buddy /

5) 0.305 us | update_load_avg_se();

5) 0.340 us | update_load_avg_cfs_rq();

5) | update_cfs_group() {

5) | reweight_entity() {

5) | update_curr() {

5) 0.376 us | calc_delta();

5) 0.308 us | update_min_vruntime();

5) 1.754 us | }

5) 0.317 us | account_entity_dequeue();

5) 0.260 us | account_entity_enqueue();

5) 3.537 us | }

5) 4.221 us | }

5) 0.261 us | hrtick_update();

5) + 16.852 us | } / dequeue_task_fair /

5) + 23.353 us | } / deactivate_task /

5) | pick_next_task_fair() {

5) 0.286 us | update_curr();

5) 0.271 us | check_cfs_rq_runtime();

5) | pick_next_entity() {

5) 0.441 us | wakeup_preempt_entity.isra.77();

5) 0.306 us | clear_buddies();

5) 1.645 us | }

------------------------------------------

5) SCTP ti-27174 => Composi-2089

------------------------------------------

5) 0.632 us | switch_to_xtra();

5) 0.350 us | finish_task_switch();

5) ! 271.440 us | } / schedule /

5) | _cond_resched() {

5) 0.267 us | rcu_all_qs();

5) 0.834 us | }

5) ! 273.311 us | } / futex_wait_queue_me /

在这个图中，DURATION表示运行一个函数所花费的时间。注意 + 和 ! 符号。加号(+)表示函数耗时超过10微秒，而感叹号(!)表示耗时超过100微秒。在FUNCTION_CALLS下面，我们找到与每个函数调用相关的信息。用于显示每个函数的起始和完成的符号与C编程语言中的相同:括号({})划分函数，一个在开始，一个在结束;不调用任何其他函数的叶子函数用分号(;)标记。

Ftrace还允许使用tracing_thresh选项将跟踪限制在超过一定时间的函数上。应该记录函数的时间阈值必须以微秒单位写入该文件。这可以用来查找内核中花费很长时间的例程。在内核启动时使用它可能很有趣，可以帮助优化启动时间。要在启动时设置阈值，可以在内核命令行中设置，如下所示:

tracing_thresh=200 ftrace=function_graph

这将跟踪所有耗时超过200微秒(0.2毫秒)的函数。您可以使用任何时间间隔的阈值。

在运行时，您可以简单地执行 echo 200 > tracing_thresh 。

Function filters

选择要跟踪的函数。不用说，要跟踪的函数越少，开销就越少。Ftrace打印输出可能很大，并且找到您正在寻找的内容可能非常困难。但是，我们可以使用过滤器来简化搜索:打印输出只显示我们感兴趣的函数的信息。要做到这一点，我们只需要在set_ftrace_filter文件中写入函数名，如下所示:

# echo kfree > set_ftrace_filter

要禁用过滤器，我们在这个文件中添加一个空行:

# echo > set_ftrace_filter

执行如下命令:

# echo kfree > set_ftrace_notrace

结果相反:打印输出将为我们提供除kfree()之外的所有函数的信息。另一个有用的选项是set_ftrace_pid。此工具用于跟踪可以代表特定进程调用的函数。

Ftrace有更多筛选选项。要了解更详细的信息，您可以在上阅读官方文档。

Tracing events

在介绍跟踪事件之前，让我们讨论一下跟踪点(tracepoints)。跟踪点是触发系统事件的特殊代码插入。跟踪点可以是动态的(意味着它们附加了几个检查)，也可以是静态的(没有附加检查)。

静态跟踪点不会以任何方式影响系统；它们只是在检测函数的末尾为函数调用添加了几个字节，并在单独的部分中添加了一个数据结构。动态跟踪点在执行相关代码片段时调用跟踪函数。跟踪数据被写入循环缓冲区。跟踪点可以包含在代码中的任何地方。事实上，它们已经可以在很多内核函数中找到。让我们看看摘自mm/slab.c的kmem_cache_free函数:

void kmem_cache_free(struct kmem_cache cachep, void objp)

{

　　【...】

　　trace_kmem_cache_free(_RETIP, objp);

}

kmem_cache_free本身就是一个跟踪点。只要看看其他内核函数的源代码，我们就能找到无数的例子。

Linux内核有一个特殊的API用于处理来自用户空间的跟踪点。在“/sys/kernel/debug/tracing”目录下，有一个存放系统事件的“events”目录。这些可用于跟踪。在这个上下文中，系统事件可以理解为内核中包含的跟踪点。

可以通过运行以下命令查看这些列表:

# cat /sys/kernel/debug/tracing/available_events

mac80211:drv_return_void

mac80211:drv_return_int

mac80211:drv_return_bool

mac80211:drv_return_u32

mac80211:drv_return_u64

mac80211:drv_start

mac80211:drv_get_et_strings

mac80211:drv_get_et_sset_count

mac80211:drv_get_et_stats

mac80211:drv_suspend

【...】

一个很长的列表将在控制台中打印出来，使用:模式。这有点不方便。我们可以使用下面的命令打印出一个更加结构化的列表:

# ls /sys/kernel/debug/tracing/events

block gpio napi regmap syscalls

cfg80211 header_event net regulator task

clk