今天,我们将要讨论的调试工具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
的一些基本知识,像任何内核工具一样,它在不同内核版本之间的工作方式也有所不同,但是只要你尝试使用它,就会发现它很有用,尤其是在跟踪内核函数调用和性能的时候。