Linux内核跟踪和性能分析

手机

iphone11大小尺寸是多少？苹果iPhone11和iPhone13的区别是什么？

警方通报辅警执法直播中被撞飞：犯罪嫌疑人已投案

Linux内核跟踪和性能分析

2023-02-08 18:07:03 来源：博客园

尽管通过打印进行调试可以满足大多数调试需求，但在某些情况下，我们需要在运行时监视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_TRACERCONFIG_FUNCTION_GRAPH_TRACERCONFIG_STACK_TRACERCONFIG_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_pidavailable_events                             set_ftrace_filteravailable_filter_functions                   set_ftrace_notraceavailable_tracers                            set_ftrace_pidbuffer_size_kb                               set_graph_functionbuffer_total_size_kb                         set_graph_notracecurrent_tracer                               snapshotdyn_ftrace_total_info                        stack_max_sizeenabled_functions                            stack_traceevents                                       stack_trace_filterfree_buffer                                  tracefunction_profile_enabled                     trace_clockinstances                                    trace_markermax_graph_depth                              trace_optionsoptions                                      trace_pipeper_cpu                                      trace_statprintk_formats                               tracing_cpumasksaved_cmdlines                               tracing_max_latencysaved_cmdlines_size                          tracing_onset_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_tracersblk 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 > current_tracer# 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命令。我们启用缓冲区，运行这个命令，然后禁用它。这使得跟踪程序可以包含与命令运行时发生的所有系统调用相关的信息。在脚本的最后一行中，我们给出在控制台中显示跟踪数据的命令。一旦脚本运行，我们将看到以下打印输出(这只是一个小片段):

打印输出以缓冲区中的条目数量和写入的条目总数相关的信息开始。这两个数字之间的差就是填充缓冲区时丢失的事件数。然后，有一个包含以下信息的函数列表:

进程名(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 > current_tracer# 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有更多筛选选项。要了解更详细的信息，您可以在https://www.kernel.org/doc/Documentation/trace/ftrace.txt上阅读官方文档。

Tracing events

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

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

void kmem_cache_free(struct kmem_cache *cachep, void *objp){　　[...]　　trace_kmem_cache_free(_RET_IP_, objp);}

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

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

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

# cat /sys/kernel/debug/tracing/available_eventsmac80211:drv_return_voidmac80211:drv_return_intmac80211:drv_return_boolmac80211:drv_return_u32mac80211:drv_return_u64mac80211:drv_startmac80211:drv_get_et_stringsmac80211:drv_get_et_sset_countmac80211:drv_get_et_statsmac80211:drv_suspend[...]

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

# ls /sys/kernel/debug/tracing/eventsblock         gpio            napi          regmap       syscallscfg80211      header_event    net           regulator    taskclk           header_page     oom           rpm          timercompaction    i2c             pagemap       sched        udpenable        irq             power         signal       vmscanfib           kmem            printk        skb          workqueuefilelock      mac80211        random        sock         writebackfilemap       migrate         raw_syscalls  spiftrace        module          rcu           swiotlb

所有可能的事件在子目录中按子系统组合。在开始跟踪事件之前，我们将确保已启用向循环缓冲区写入。

关于hrtimers，通过列出/sys/kernel/debug/tracing/events/timer的内容，我们将拥有timer-related跟踪点，包括hrtimer-related跟踪点，如下所示:

# ls /sys/kernel/debug/tracing/events/timerenable                  hrtimer_init     timer_cancelfilter                  hrtimer_start    timer_expire_entryhrtimer_cancel          itimer_expire    timer_expire_exithrtimer_expire_entry    itimer_state     timer_inithrtimer_expire_exit     tick_stop        timer_start

现在让我们跟踪对hrtimer-related内核函数的访问。对于我们的跟踪程序，我们将使用nop，因为function和function_graph记录了太多信息，包括我们不感兴趣的事件信息。下面是我们将使用的脚本:

# cd /sys/kernel/debug/tracing/# echo 0 > tracing_on# echo > trace# echo nop > current_tracer# echo 1 > events/timer/enable# echo 1 > tracing_on;# sleep 1;# echo 0 > tracing_on;# echo 0 > events/timer/enable# less trace

我们首先禁用跟踪，以防它已经在运行。然后，在将当前跟踪器设置为nop之前，清除环形缓冲区数据。接下来，我们启用timer-related跟踪点，或者应该说，启用timer event跟踪。最后，我们启用跟踪并转储环形缓冲区的内容，如下所示:

在打印输出的最后，我们将找到有关hrtimer函数调用的信息(这里是一小部分)。关于配置事件跟踪的更多详细信息可以在这里找到:https://www.kernel.org/doc/Documentation/trace/events.txt。

使用Ftrace接口跟踪特定进程

使用Ftrace可以让您拥有启用跟踪的内核跟踪点/函数，而不管这些函数是代表哪个进程运行的。为了只跟踪代表特定函数执行的内核函数，应该将set_ftrace_pid变量设置为进程的进程ID (PID)，例如，可以使用pgrep获得该进程ID。如果进程尚未运行，您可以使用包装器shell脚本和exec命令作为已知PID执行命令，如下所示:

#!/bin/shcd /sys/kernel/debug/tracing/echo > traceecho nop > current_tracerecho "pid=$$"echo $$ > set_ftrace_pid# [can set other filtering here]echo function_graph > current_tracerecho 1 > tracing_onexec $*echo 0 > tracing_on

在上面的例子中，$$是当前执行进程(shell脚本本身)的PID。这是在set_ftrace_pid变量中设置的，然后启用function_graph跟踪程序，然后脚本执行命令(由脚本的第一个参数指定)。

假设脚本名为trace_process.sh，使用示例如下:

sudo ./trace_process.sh ls

现在我们熟悉了跟踪事件和跟踪点。我们能够跟踪和跟踪特定的内核事件或子系统。虽然就内核开发而言，跟踪是必须的，但遗憾的是，有些情况会影响内核的稳定性。这种情况可能需要off-target分析，这将在调试中解决。

关键词：跟踪程序打印输出函数调用