ftrace和trace-cmd：跟踪内核函数的利器

今天，我们将要讨论的调试工具ftrace。ftrace自Linux内核2.6或2008年以来就已经存在了，所以即使你正在调试较旧的系统，也可以使用它。

什么是ftrace？

ftrace是Linux内核功能，可让你跟踪Linux内核函数调用。你为什么想这么做？好吧，假设你正在调试一个怪异的问题，并且已经盯着内核版本的源代码并想知道到底发生了什么，那么查看被调用的功能有助于我们更好地了解内核中发生的事情以及所涉及的系统。

ftrace是一个动态跟踪系统。这意味着当开始使用内核函数时，该函数的代码会更改。所以让我们假设我是从do_page_fault以前开始跟踪该函数的。内核将在该程序集中插入一些额外的指令，以在每次调用该函数时通知跟踪系统。之所以可以添加额外的指令，是因为Linux在每个函数中都编译了一些额外的NOP指令，因此有必要在需要时添加跟踪代码。

这很棒，因为这意味着当我不使用ftrace跟踪内核时，它根本不会影响性能。当我开始跟踪时，跟踪的功能越多，开销就越大。

ftrace第一步

与strace和perf不同，ftrace并非完全是一个程序：你不只是运行ftrace my_cool_function就可以了，实际上如果你阅读了使用Ftrace调试内核，它会先告诉你cd /sys/kernel/debug/tracing并随后进行各种文件系统操作，然后开始。使用ftrace简单的示例就像：

cd /sys/kernel/debug/tracing
echo function > current_tracer
echo do_page_fault > set_ftrace_filter
cat trace

幸运的是，ftrace团队还认为该界面不是用户友好的，因此有一个易于使用的界面，称为trace-cmd！trace-cmd是带有命令行参数的普通程序。我们接下来会使用它，这里是trace-cmd的简介：Ftrace的前端。

trace-cmd入门：跟踪一个函数

首先，安装trace-cmd：

sudo apt-get install trace-cmd

对于第一个ftrace演示，我决定想知道内核何时处理页面错误。当Linux分配内存时，它通常会很懒惰（“你并不是真的打算使用该内存，对吗？”）。这意味着当应用程序尝试实际写入其分配的内存时，会出现页面错误，然后内核需要为应用程序提供物理内存以供使用。让我们开始用trace-cmd跟踪do_page_fault函数：

$ sudo trace-cmd record -p function -l do_page_fault
  plugin 'function'
Hit Ctrl^C to stop recording

我跑了几秒钟，然后打了Ctrl+C。它创建了一个2.5MB的文件，名为trace.dat。让我们看看该文件是什么：

$ sudo trace-cmd report
          chrome-15144 [000] 11446.466121: function:             do_page_fault
          chrome-15144 [000] 11446.467910: function:             do_page_fault
          chrome-15144 [000] 11446.469174: function:             do_page_fault
          chrome-15144 [000] 11446.474225: function:             do_page_fault
          chrome-15144 [000] 11446.474386: function:             do_page_fault
          chrome-15144 [000] 11446.478768: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.480172: function:             do_page_fault
          chrome-1830  [003] 11446.486696: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.488983: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.489034: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.489045: function:             do_page_fault

它向我显示了进程名称（chrome），进程ID（15144），CPU（000）和被跟踪的功能。通过查看整个报告：

sudo trace-cmd report | grep chrome

在这几秒钟内，Chrome出现了大约500个页面错误。

一个很简单和使用的功能：使用如下命令可以查看所有可以追踪的函数:

sudo trace-cmd list -f

用ftrace跟踪一个进程

好的，假设我想知道一个程序/进程发生的所有事情。我使用一个称为Hugo的静态网站生成器，Hugo的PID现在在我的计算机上是25314，所以我用以下命令记录了所有进程功能：

sudo trace-cmd record -p function -P 25314 
sudo trace-cmd report

输出大概有一万多行，这里有一些有趣的摘录。这看起来像clock_gettime系统调用运行时发生的情况：

 compat_SyS_clock_gettime
    SyS_clock_gettime
       clockid_to_kclock
       posix_clock_realtime_get
          getnstimeofday64
             __getnstimeofday64
                arch_counter_read
    __compat_put_timespec

这与任务调度有关：

 cpufreq_sched_irq_work
    wake_up_process
       try_to_wake_up
          _raw_spin_lock_irqsave
             do_raw_spin_lock
          _raw_spin_lock
             do_raw_spin_lock
          walt_ktime_clock
             ktime_get
                arch_counter_read
          walt_update_task_ravg
             exiting_task

即使我不太了解这些功能，也能够看到所有这些函数调用。

“功能图”跟踪

还有另一种跟踪模式，称为function_graph。这与函数跟踪器相同，除了它会同时检测进入和退出功能：

sudo trace-cmd record -p function_graph -P 25314
sudo trace-cmd report

这是一个输出片段（来自futex代码）：

             |      futex_wake() {
             |        get_futex_key() {
             |          get_user_pages_fast() {
  1.458 us   |            __get_user_pages_fast();
  4.375 us   |          }
             |          __might_sleep() {
  0.292 us   |            ___might_sleep();
  2.333 us   |          }
  0.584 us   |          get_futex_key_refs();
             |          unlock_page() {
  0.291 us   |            page_waitqueue();
  0.583 us   |            __wake_up_bit();
  5.250 us   |          }
  0.583 us   |          put_page();
+ 24.208 us  |        }

我们在此示例中看到get_futex_key紧接着被调用futex_wake。接着我们查看内核中futex_wake的定义如下：

static int
futex_wake(u32 __user *uaddr, unsigned int flags, int nr_wake, u32 bitset)
{
	struct futex_hash_bucket *hb;
	struct futex_q *this, *next;
	union futex_key key = FUTEX_KEY_INIT;
	int ret;
	WAKE_Q(wake_q);

	if (!bitset)
		return -EINVAL;

	ret = get_futex_key(uaddr, flags & FLAGS_SHARED, &key, VERIFY_READ);

futex_wake第一个调用的函数确实是get_futex_key，读取函数跟踪绝对是一种比读取内核代码更容易发现错误的方法，而且可以看到所有函数花费了多长时间。

跟踪事件

某些事件与函数调用的对应性不是很好。例如，你可能想知道何时在CPU上或在CPU之外调度程序！因此，内核还为你提供了一些事件，以便你可以看到何时发生了一些重要的事情。你可以通过以下方式查看所有这些事件的列表：

sudo cat /sys/kernel/debug/tracing/available_events

我查看了所有sched_switch事件，我不确定sched_switch是什么，但是我想这与调度有关，让我们来跟踪它看看：

sudo trace-cmd record -e sched:sched_switch
sudo trace-cmd report

输出看起来像这样：

 16169.624862:   Chrome_ChildIOT:24817 [112] S ==> chrome:15144 [120]
 16169.624992:   chrome:15144 [120] S ==> swapper/3:0 [120]
 16169.625202:   swapper/3:0 [120] R ==> Chrome_ChildIOT:24817 [112]
 16169.625251:   Chrome_ChildIOT:24817 [112] R ==> chrome:1561 [112]
 16169.625437:   chrome:1561 [112] S ==> chrome:15144 [120]

因此你可以看到它从PID 24817-> 15144->内核-> 24817-> 1561-> 15114的切换过程。

小结

我们学习了有关ftrace和trace-cmd的一些基本知识，像任何内核工具一样，它在不同内核版本之间的工作方式也有所不同，但是只要你尝试使用它，就会发现它很有用，尤其是在跟踪内核函数调用和性能的时候。