工具博客转载-ftrace
阅读原文时间:2023年07月11日阅读:1

https://linux.cn/article-9273-1.html

https://lwn.net/Articles/365835/

Documentation/trace/events.txt

trace/ftrace-design.txt

什么是 ftrace?

ftrace 是一个 Linux 内核特性,它可以让你去跟踪 Linux 内核的函数调用。为什么要这么做呢?好吧,假设你调试一个奇怪的问题,而你已经得到了你的内核版本中这个问题在源代码中的开始的位置,而你想知道这里到底发生了什么?

每次在调试的时候,我并不会经常去读内核源代码,但是,极个别的情况下会去读它!例如,本周在工作中,我有一个程序在内核中卡死了。查看到底是调用了什么函数,能够帮我更好的理解在内核中发生了什么,哪些系统涉及其中!(在我的那个案例中,它是虚拟内存系统)。

我认为 ftrace 是一个十分好用的工具(它肯定没有 strace 那样使用广泛,也比它难以使用),但是它还是值得你去学习。因此,让我们开始吧!

使用 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 是一个带命令行参数的普通程序。我们后面将使用它!我在 LWN 上找到了一个 trace-cmd 的使用介绍:trace-cmd: Ftrace 的一个前端

开始使用 trace-cmd:让我们仅跟踪一个函数

首先,我需要去使用 sudo apt-get install trace-cmd 安装 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 ID(000),以及它跟踪的函数。

通过察看整个文件,(sudo trace-cmd report | grep chrome)可以看到,我们跟踪了大约 1.5 秒,在这 1.5 秒的时间段内,Chrome 发生了大约 500 个页面故障。真是太酷了!这就是我们做的第一个 ftrace!

下一个 ftrace 技巧:我们来跟踪一个进程!

好吧,只看一个函数是有点无聊!假如我想知道一个程序中都发生了什么事情。我使用一个名为 Hugo 的静态站点生成器。看看内核为 Hugo 都做了些什么事情?

在我的电脑上 Hugo 的 PID 现在是 25314,因此,我使用如下的命令去记录所有的内核函数:

sudo trace-cmd record --help # I read the help!
sudo trace-cmd record -p function -P 25314 # record for PID 25314

sudo trace-cmd report 输出了 18,000 行。如果你对这些感兴趣,你可以看 这里是所有的 18,000 行的输出

18,000 行太多了,因此,在这里仅摘录其中几行。

当系统调用 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” 跟踪

这里有另外一个模式,称为 function_graph。除了它既可以进入也可以退出一个函数外,其它的功能和函数跟踪器是一样的。这里是那个跟踪器的输出

  1. sudo trace-cmd record -p function_graph -P 25314

同样,这里只是一个片断(这次来自 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 | }

我们看到在这个示例中,在 futex_wake 后面调用了 get_futex_key。这是在源代码中真实发生的事情吗?我们可以检查一下!!这里是在 Linux 4.4 中 futex_wake 的定义 (我的内核版本是 4.4)。

为节省时间我直接贴出来,它的内容如下:

  1. 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! 太棒了!相比阅读内核代码,阅读函数跟踪肯定是更容易的找到结果的办法,并且让人高兴的是,还能看到所有的函数用了多长时间。

如何知道哪些函数可以被跟踪

如果你去运行 sudo trace-cmd list -f,你将得到一个你可以跟踪的函数的列表。它很简单但是也很重要。

最后一件事:事件!

现在,我们已经知道了怎么去跟踪内核中的函数,真是太酷了!

还有一类我们可以跟踪的东西!有些事件与我们的函数调用并不相符。例如,你可能想知道当一个程序被调度进入或者离开 CPU 时,都发生了什么事件!你可能想通过“盯着”函数调用计算出来,但是,我告诉你,不可行!

由于函数也为你提供了几种事件,因此,你可以看到当重要的事件发生时,都发生了什么事情。你可以使用 sudo cat /sys/kernel/debug/tracing/available_events 来查看这些事件的一个列表。

我查看了全部的 schedswitch 事件。我并不完全知道 schedswitch 是什么,但是,我猜测它与调度有关。

  1. sudo cat /sys/kernel/debug/tracing/available_events
    sudo trace-cmd record -e sched:sched_switch
    sudo trace-cmd report

输出如下:

  1. 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 -> kernel -> 24817 -> 1561 -> 15114。(所有的这些事件都发生在同一个 CPU 上)。

ftrace 是如何工作的?

ftrace 是一个动态跟踪系统。当我们开始 ftrace 内核函数时,函数的代码会被改变。让我们假设去跟踪 do_page_fault 函数。内核将在那个函数的汇编代码中插入一些额外的指令,以便每次该函数被调用时去提示跟踪系统。内核之所以能够添加额外的指令的原因是,Linux 将额外的几个 NOP 指令编译进每个函数中,因此,当需要的时候,这里有添加跟踪代码的地方。

这是一个十分复杂的问题,因为,当不需要使用 ftrace 去跟踪我的内核时,它根本就不影响性能。而当我需要跟踪时,跟踪的函数越多,产生的开销就越大。

(或许有些是不对的,但是,我认为的 ftrace 就是这样工作的)

更容易地使用 ftrace:brendan gregg 的工具及 kernelshark

正如我们在文件中所讨论的,你需要去考虑很多的关于单个的内核函数/事件直接使用 ftrace 都做了些什么。能够做到这一点很酷!但是也需要做大量的工作!

Brendan Gregg (我们的 Linux 调试工具“大神”)有个工具仓库,它使用 ftrace 去提供关于像 I/O 延迟这样的各种事情的信息。这是它在 GitHub 上全部的 perf-tools 仓库。

这里有一个权衡,那就是这些工具易于使用,但是你被限制仅能用于 Brendan Gregg 认可并做到工具里面的方面。它包括了很多方面!:)

另一个工具是将 ftrace 的输出可视化,做的比较好的是 kernelshark。我还没有用过它,但是看起来似乎很有用。你可以使用 sudo apt-get install kernelshark 来安装它。

手机扫一扫

移动阅读更方便

阿里云服务器
腾讯云服务器
七牛云服务器