通过使用一个名为 ftrace
的机制来阐明追踪内核函数的一些情况。它使得任何 Linux 用户可以轻松地追踪内核,并且了解更多关于 Linux 内核内部如何工作。
ftrace
默认产生的输出往往是巨大的,因为内核总是忙碌的。为了节省空间,很多情况下我会通过截断来给出尽量小的输出。
我使用 Fedora 来演示下面的例子,但是它们应该在其他最新的 Linux 发行版上同样可以运行。
ftrace
现在已经是内核中的一部分了,你不再需要事先安装它了。也就是说,如果你在使用最近的 Linux 系统,那么 ftrace
是已经启用了的。为了验证 ftrace
是否可用,运行 mount
命令并查找 tracefs
。如果你看到类似下面的输出,表示 ftrace
已经启用,你可以轻松地尝试本文中下面的例子。下面有些命令需要在 root 用户下使用(用 sudo
执行是不够的)。
# mount | grep tracefsnone on /sys/kernel/tracing type tracefs (rw,relatime,seclabel)
要想使用 ftrace
,你首先需要进入上面 mount
命令中找到的特定目录中,在那个目录下运行文章中的其他命令。
# cd /sys/kernel/tracing
首先,你需要理解捕捉踪迹和获取输出的一般流程。如果你直接运行 ftrace
,不会运行任何特定的 ftrace
命令。相反的,基本操作是通过标准 Linux 命令来写入或读取一些文件。
一般的步骤如下:
有多种不同的追踪器可供使用。之前提到,在运行任何命令前,你需要进入一个特定的目录下,因为需要的文件在这些目录下。我在我的例子中使用了相对路径(而不是绝对路径)。
你可以查看 available_tracers
文件内容来查看所有可用的追踪器类型。你可以看下面列出了几个。不需要担心这些:
$ pwd/sys/kernel/tracing$ sudo cat available_tracershwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
在所有输出的追踪器中,我会聚焦于下面三个特殊的:启用追踪的 function
和 function_graph
,以及停止追踪的 nop
。
通常情况默认的追踪器设定为 nop
。即在特殊文件中 current_tracer
中的 “无操作”,这意味着追踪目前是关闭的:
$ pwd/sys/kernel/tracing$ sudo cat current_tracernop
在启用任何追踪功能之前,请你看一下保存追踪输出的文件。你可以用 cat 命令查看名为 trace
的文件的内容:
# cat trace# tracer: nop## entries-in-buffer/entries-written: 0/0 #P:8## _-----=> irqs-off# / _----=> need-resched# | / _---=> hardirq/softirq# || / _--=> preempt-depth# ||| / delay# TASK-PID CPU# |||| TIMESTAMP FUNCTION# | | | |||| | |
你可以通过向 current_tracer
文件写入 function
来启用第一个追踪器 function
(文件原本内容为 nop
,意味着追踪是关闭的)。把这个操作看成是启用追踪的一种方式:
$ pwd/sys/kernel/tracing$ sudo cat current_tracernop$ echo function > current_tracer$$ cat current_tracerfunction
现在你已启用追踪,是时候查看输出了。如果你查看 trace
文件内容,你将会看到许多被连续写入的内容。我通过管道只展示了文件内容的前 20 行。根据左边输出的标题,你可以看到在某个 CPU 上运行的任务和进程 ID。根据右边输出的内容,你可以看到具体的内核函数和其父函数。中间显示了时间戳信息:
# sudo cat trace | head -20# tracer: function## entries-in-buffer/entries-written: 409936/4276216 #P:8## _-----=> irqs-off# / _----=> need-resched# | / _---=> hardirq/softirq# || / _--=> preempt-depth# ||| / delay# TASK-PID CPU# |||| TIMESTAMP FUNCTION# | | | |||| | | <idle>-0 [000] d... 2088.841739: tsc_verify_tsc_adjust <-arch_cpu_idle_enter <idle>-0 [000] d... 2088.841739: local_touch_nmi <-do_idle <idle>-0 [000] d... 2088.841740: rcu_nocb_flush_deferred_wakeup <-do_idle <idle>-0 [000] d... 2088.841740: tick_check_broadcast_expired <-do_idle <idle>-0 [000] d... 2088.841740: cpuidle_get_cpu_driver <-do_idle <idle>-0 [000] d... 2088.841740: cpuidle_not_available <-do_idle <idle>-0 [000] d... 2088.841741: cpuidle_select <-do_idle <idle>-0 [000] d... 2088.841741: menu_select <-do_idle <idle>-0 [000] d... 2088.841741: cpuidle_governor_latency_req <-menu_select
请记住当追踪打开后,这意味着追踪结果会被一直连续写入直至你关闭追踪。
关闭追踪是简单的。你只需要在 current_tracer
文件中用 nop
替换 function
追踪器即可:
$ sudo cat current_tracerfunction$ sudo echo nop > current_tracer$ sudo cat current_tracernop
现在尝试第二个名为 function_graph
的追踪器。你可以使用和上面相同的步骤:在 current_tracer
文件中写入 function_graph
:
$ sudo echo function_graph > current_tracer$ sudo cat current_tracerfunction_graph
注意到目前 trace
文件的输出格式已经发生变化。现在,你可以看到 CPU ID 和内核函数的执行时长。接下来,一个花括号表示一个函数的开始,以及它内部调用了哪些其他函数:
# cat trace | head -20# tracer: function_graph## CPU DURATION FUNCTION CALLS# | | | | | | | 6) | n_tty_write() { 6) | down_read() { 6) | __cond_resched() { 6) 0.341 us | rcu_all_qs(); 6) 1.057 us | } 6) 1.807 us | } 6) 0.402 us | process_echoes(); 6) | add_wait_queue() { 6) 0.391 us | _raw_spin_lock_irqsave(); 6) 0.359 us | _raw_spin_unlock_irqrestore(); 6) 1.757 us | } 6) 0.350 us | tty_hung_up_p(); 6) | mutex_lock() { 6) | __cond_resched() { 6) 0.404 us | rcu_all_qs(); 6) 1.067 us | }
你可以使用下面的步骤来调整追踪器以看到更深层次的函数调用。完成之后,你可以查看 trace
文件的内容并发现输出变得更加详细了。为了文章的可读性,这个例子的输出被省略了:
# cat max_graph_depth0# echo 1 > max_graph_depth ## or:# echo 2 > max_graph_depth# sudo cat trace
上面的步骤足以让你开始追踪。但是它产生的输出内容是巨大的,当你想试图找到自己感兴趣的内容时,往往会很困难。通常你更希望能够只追踪特定的函数,而忽略其他函数。但如果你不知道它们确切的名称,你怎么知道要追踪哪些进程?有一个文件可以帮助你解决这个问题 —— available_filter_functions
文件提供了一个可供追踪的函数列表:
$ sudo wc -l available_filter_functions 63165 available_filter_functions
现在试着搜索一个你所知道的简单内核函数。用户空间由 malloc
函数用来分配内存,而内核由 kmalloc
函数,它提供类似的功能。下面是所有与 kmalloc
相关的函数:
$ sudo grep kmalloc available_filter_functionsdebug_kmallocmempool_kmallockmalloc_slabkmalloc_orderkmalloc_order_tracekmalloc_fix_flagskmalloc_large_node__kmalloc__kmalloc_track_caller__kmalloc_node__kmalloc_node_track_caller[...]
在 available_filter_functions
文件的输出中,你可以看到一些以括号内文字结尾的行,例如下面的例子中的 [kvm_intel]
。这些函数与当前加载的内核模块 kvm_intel
有关。你可以运行 lsmod
命令来验证:
$ sudo grep kvm available_filter_functions | tail__pi_post_block [kvm_intel]vmx_vcpu_pi_load [kvm_intel]vmx_vcpu_pi_put [kvm_intel]pi_pre_block [kvm_intel]pi_post_block [kvm_intel]pi_wakeup_handler [kvm_intel]pi_has_pending_interrupt [kvm_intel]pi_update_irte [kvm_intel]vmx_dump_dtsel [kvm_intel]vmx_dump_sel [kvm_intel]$ lsmod | grep -i kvmkvm_intel 335872 0kvm 987136 1 kvm_intelirqbypass 16384 1 kvm
为了实现对特定函数或模式的追踪,你可以利用 set_ftrace_filter
文件来指定你要追踪上述输出中的哪些函数。这个文件也接受 *
模式,它可以扩展到包括具有给定模式的其他函数。作为一个例子,我在我的机器上使用 ext4 文件系统。我可以用下面的命令指定 ext4 的特定内核函数来追踪:
# mount | grep home/dev/mapper/fedora-home on /home type ext4 (rw,relatime,seclabel)# pwd/sys/kernel/tracing# cat set_ftrace_filter#### all functions enabled ####$$ echo ext4_* > set_ftrace_filter$$ cat set_ftrace_filterext4_has_free_clustersext4_validate_block_bitmapext4_get_group_numberext4_get_group_no_and_offsetext4_get_group_desc[...]
现在当你可以看到追踪输出时,你只能看到与内核函数有关的 ext4
函数,而你之前已经为其设置了一个过滤器。所有其他的输出都被忽略了:
# cat trace |head -20## tracer: function## entries-in-buffer/entries-written: 3871/3871 #P:8## _-----=> irqs-off# / _----=> need-resched# | / _---=> hardirq/softirq# || / _--=> preempt-depth# ||| / delay# TASK-PID CPU# |||| TIMESTAMP FUNCTION# | | | |||| | | cupsd-1066 [004] .... 3308.989545: ext4_file_getattr <-vfs_fstat cupsd-1066 [004] .... 3308.989547: ext4_getattr <-ext4_file_getattr cupsd-1066 [004] .... 3308.989552: ext4_file_getattr <-vfs_fstat cupsd-1066 [004] .... 3308.989553: ext4_getattr <-ext4_file_getattr cupsd-1066 [004] .... 3308.990097: ext4_file_open <-do_dentry_open cupsd-1066 [004] .... 3308.990111: ext4_file_getattr <-vfs_fstat cupsd-1066 [004] .... 3308.990111: ext4_getattr <-ext4_file_getattr cupsd-1066 [004] .... 3308.990122: ext4_llseek <-ksys_lseek cupsd-1066 [004] .... 3308.990130: ext4_file_read_iter <-new_sync_read
你并不总是知道你想追踪什么,但是,你肯定知道你不想追踪什么。因此,有一个 set_ftrace_notrace
—— 请注意其中的 “no”。你可以在这个文件中写下你想要的模式,并启用追踪。这样除了所提到的模式外,任何其他东西都会被追踪到。这通常有助于删除那些使我们的输出变得混乱的普通功能:
$ sudo cat set_ftrace_notrace#### no functions disabled ####
到目前为止,你一直在追踪内核中发生的一切。但是,它无法帮助你追踪与某个特定命令有关的事件。为了达到这个目的,你可以按需打开和关闭跟踪,并且在它们之间,运行我们选择的命令,这样你就不会在跟踪输出中得到额外的输出。你可以通过向 tracing_on
写入 1
来启用跟踪,写 0
来关闭跟踪。
# cat tracing_on0# echo 1 > tracing_on# cat tracing_on1### Run some specific command that we wish to trace here #### echo 0 > tracing_on# cat tracing_on0
如果你想追踪与正在运行的特定进程有关的活动,你可以将该 PID 写入一个名为 set_ftrace_pid
的文件,然后启用追踪。这样一来,追踪就只限于这个 PID,这在某些情况下是非常有帮助的。
$ sudo echo $PID > set_ftrace_pid
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。
原创声明:本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。
如有侵权,请联系 cloudcommunity@tencent.com 删除。