linux: ftrace使用手册
文章目录
- 1. 前言
- 2. 背景
- 3. ftrace
-
- 3.1 简介
- 3.2 ftrace 文件系统
- 3.3 ftrace 使用
-
- 3.3.1 current_tracer
- 3.3.2 available_tracers
- 3.3.3 tracing_on
- 3.3.4 trace
- 3.3.5 trace_pipe
- 3.3.5 trace_options
- 3.3.6 options
- 3.3.7 tracing_max_latency
- 3.3.8 tracing_thresh
- 3.3.9 buffer_size_kb
- 3.3.10 buffer_total_size_kb
- 3.3.11 free_buffer
- 3.3.12 tracing_cpumask???
- 3.3.13 set_ftrace_filter
- 3.3.14 set_ftrace_notrace
- 3.3.15 set_ftrace_pid
- 3.3.16 set_ftrace_notrace_pid
- 3.3.17 set_event_pid
- 3.3.18 set_event_notrace_pid
- 3.3.19 set_graph_function
- 3.3.20 set_graph_notrace
- 3.3.21 available_filter_functions
- 3.3.22 dyn_ftrace_total_info
- 3.3.23 enabled_functions
- 3.3.24 function_profile_enabled
- 3.3.25 trace_stat
- 3.3.26 kprobe_events
- 3.3.27 kprobe_profile
- 3.3.28 max_graph_depth
- 3.3.29 printk_formats
- 3.3.29 saved_cmdlines
- 3.3.30 saved_cmdlines_size
- 3.3.31 saved_tgids
- 3.3.32 snapshot
- 3.3.33 stack_max_size
- 3.3.34 stack_trace
- 3.3.35 stack_trace_filter
- 3.3.36 trace_clock
- 3.3.37 trace_marker
- 3.3.38 trace_marker_raw
- 3.3.39 uprobe_events
- 3.3.40 uprobe_profile
- 3.3.41 instances
- 3.3.42 events
- 3.3.43 set_event
- 3.3.44 available_events
- 3.3.45 timestamp_mode
- 3.3.46 hwlat_detector
- 3.3.47 per_cpu
- 4. 各类 tracer
-
- 4.1 简介
-
- 4.1.1 function
- 4.1.2 function_graph
- 4.1.3 blk
- 4.1.4 hwlat
- 4.1.5 irqsoff
- 4.1.6 preemptoff
- 4.1.7 preemptirqsoff
- 4.1.8 wakeup
- 4.1.9 wakeup_rt
- 4.1.10 wakeup_dl
- 4.1.11 mmiotrace
- 4.1.12 branch
- 4.1.13 nop
- 5. tracer 使用示例
-
- 5.1 function
- 5.2 wakeup
- 5.3 function_graph
- 6. 追踪选项
-
- 6.1 print-parent
- 6.2 sym-offset
- 6.3 sym-addr
- 6.4 trace_printk
- 6.5 annotate
- 6.6 userstacktrace
- 6.7 sym-userobj
- 6.8 其它
- 7. 过滤命令
-
- 7.1 mod 过滤命令
- 7.2 traceon/traceoff 过滤命令
- 7.3 snapshot 过滤命令
- 7.4 启用/关闭事件过滤命令
- 7.5 其它
1. 前言
限于作者能力水平,本文可能存在谬误,因此而给读者带来的损失,作者不做任何承诺。
2. 背景
本文基于对 Linux 内核 ftrace 文档 的翻译而成。
3. ftrace
3.1 简介
ftrace
是 Linux 内核内置的追踪机制,用来帮助系统设计人员了解内核内部当前发生的事情,它可以用于用户空间调试和分析内核延迟和性能问题。
虽然 ftrace
通常被认为是 function tracer
,但它实际上已经发展为内核的追踪框架。
3.2 ftrace 文件系统
ftrace
通过 sysfs
向用户空间导出接口:
# mount
tracefs on /sys/kernel/debug/tracing type tracefs (rw,relatime)
ftrace
目录树默认挂载在 /sys/kernel/debug/tracing
路径下。
3.3 ftrace 使用
3.3.1 current_tracer
内核集成了各种 tracer ,如用来追踪内核函数的 function tracer
等等。通过文件 available_tracers
可以查看当前编译到内核的 tracer 列表:
# cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
current_tracer
表示当前启用的 tracer ,默认为 nop
,即不做任何追踪工作:
# cat current_tracer
nop
通过写 current_tracer
可以修改当前 tracer ,available_tracers
中包含的是可以写入到 current_tracer
的 tracer 名。如想追踪系统内核函数调用,可以向 current_tracer
写入 function
:
# echo function > current_tracer
# cat current_tracer
function
3.3.2 available_tracers
available_tracers
文件中包含的是当前编译到内核的 tracer 列表,也即可以写到 current_tracer
的 tracer 名。
3.3.3 tracing_on
向 tracing_on
写入 1,启用追踪;向 tracing_on
写入 0,停止追踪。追踪使用 ring buffer
记录追踪数据。修改 tracing_on
不会影响 ring buffer
当前记录的内容。
# echo 1 > tracing_on 启用追踪过程
# echo 0 > tracing_on 关闭追踪过程
3.3.4 trace
trace
文件包含当前追踪的内容,以人类可读的格式展现。看一个简单例子:
# echo function > current_tracer
# echo 1 > tracing_on
# cat trace
...
<idle>-0 [001] dNh. 8786.470388: __enqueue_entity <-enqueue_entity<idle>-0 [001] dNh. 8786.470388: hrtick_update <-enqueue_task_fair<idle>-0 [001] dNh. 8786.470388: ttwu_do_wakeup <-ttwu_do_activate<idle>-0 [001] dNh. 8786.470389: check_preempt_curr <-ttwu_do_wakeup<idle>-0 [001] dNh. 8786.470389: resched_curr <-check_preempt_curr
...
# echo 0 > tracing_on
我们看到,trace
文件包含了内核函数调用记录。
3.3.5 trace_pipe
trace_pipe
和 trace
一样,都是记录当前的追踪内容,但它和 trace
不一样的是:
o 对 trace_pipe
的读操作将会阻塞,直到有新的追踪数据进来为止;
o 当前从trace_pipe
读取的内容将被消耗掉,再次读 trace_pipe
又会阻塞到新数据进来为止。
3.3.5 trace_options
trace_options
列举可以用来控制追踪系统写入到 trace
和 trace_pipe
中内容的选项。trace_options
中列举的每一个选项名,在 options 目录
下都有一个对应文件,对 options 目录
下的文件写 0 或 1 来关闭或启用对应的选项,以达到控制追踪系统写入到 trace
和 trace_pipe
的内容。我们在 set_ftrace_pid
文件说明中,对此选项做进一步说明。
3.3.6 options
trace_options
列举选项目录,目录下是每选项一个的文件,通过对这些文件写 0 或 1 来关闭或启用对应的选项。
3.3.7 tracing_max_latency
有些 tracer
记录最大延迟。如禁用中断的最长时间(即最大中断延迟)。tracing_max_latency
记录当前的最大延迟时间,单位为 微妙(us)
。当追踪过程中,如果有延迟时间大于 tracing_max_latency
记录的时长,将更新 tracing_max_latency
文件。 trace
文件记录当前的延迟时间。
3.3.8 tracing_thresh
有些 延迟追踪 tracer
,只有延迟时间大于某个阈值的时候,才记录追踪数据,此时tracing_thresh
记录这个阈值。tracing_thresh
需要 大于 0
才会激活这种机制,小于等于0的值没有意义。
3.3.9 buffer_size_kb
buffer_size_kb
记录 CPU buffer
的大小,单位为 KB
。per_cpu/cpuX/buffer_size_kb
记录 每个CPU buffer
大小,单位为 KB
。可通过写 buffer_size_kb
来改变 CPU buffer
的大小。
3.3.10 buffer_total_size_kb
buffer_total_size_kb
记录所有 CPU buffer
的总大小,即所有 CPU buffer 大小总和,如有 128 个 CPU buffer ,每个大小 7KB,则 buffer_total_size_kb
记录的总大小为 128 * 7KB = 896。buffer_total_size_kb
文件是只读的。
3.3.11 free_buffer
TODO:
3.3.12 tracing_cpumask???
指定追踪的 CPU buffer 掩码,如追踪所有 128 个 CPU buffer,则:
# cat tracing_cpumask
ffffffff,ffffffff,ffffffff,ffffffff
所有 128 个 CPU buffer 掩码位全为1。
3.3.13 set_ftrace_filter
只对文件 set_ftrace_filter
中列举的函数进行追踪。可以写入 set_ftrace_filter
的函数名列举在 available_filter_functions
中。通常是写函数名到 set_ftrace_filter
,但也可以写 available_filter_functions
列举函数所在的行位置到 set_ftrace_filter
,行位置起始编号为 1 。
3.3.14 set_ftrace_notrace
set_ftrace_notrace
和 set_ftrace_filter
刚好相反,系统禁用对其中列举函数的追踪。
3.3.15 set_ftrace_pid
系统对 set_ftrace_pid
文件中包含的 PID 关联的进程进行追踪。如果开启了 options/function-fork
选项,fork 的子进程的 PID 也会自动加入文件,同时该选项也会引起系统自动将退出进程的 PID 从文件中移除。
3.3.16 set_ftrace_notrace_pid
set_ftrace_notrace_pid
和 set_ftrace_pid
相反,系统不对 set_ftrace_notrace_pid
文件中包含的 PID 关联的进程进行追踪。如果开启了 options/function-fork
选项,fork 的子进程的 PID 也会自动加入文件,同时该选项也会引起系统自动将退出进程的 PID 从文件中移除。
如果 set_ftrace_pid
和 set_ftrace_notrace_pid
同时包含某个进程 PID ,set_ftrace_notrace_pid
的设置具有更高优先级。
3.3.17 set_event_pid
仅跟踪 set_event_pid
中 PID 指定进程的 event 。如果开启了 options/event-fork
选项,fork 的子进程的 PID 也会自动加入文件,同时该选项也会引起系统自动将退出进程的 PID 从文件中移除。
3.3.18 set_event_notrace_pid
不跟踪 set_event_pid 中 PID 指定进程的 event 。如果开启了 options/event-fork
选项,fork 的子进程的 PID 也会自动加入文件,同时该选项也会引起系统自动将退出进程的 PID 从文件中移除。
3.3.19 set_graph_function
function_graph
tracer 追踪文件中列举的函数。注意,set_ftrace_filter
和 set_ftrace_notrace
仍会影响 被追踪
或 不被追踪
的函数列表。
3.3.20 set_graph_notrace
set_graph_notrace
和 set_graph_function
相反,包含不被 function_graph
tracer 追踪的函数列表。
3.3.21 available_filter_functions
可以被追踪的函数列表,即可以写到 set_ftrace_filter,set_ftrace_notrace,set_graph_function,set_graph_notrace
文件的函数列表。
3.3.22 dyn_ftrace_total_info
用于调试,记录系统中可被追踪的函数总数。
3.3.23 enabled_functions
TODO:
3.3.24 function_profile_enabled
如果设置了 function_profile_enabled ,将启用对所有支持函数的 function 追踪,如果启用了 graph_function tracer ,也将启用对所有支持函数的 graph_function 追踪。同时也会保留调用的函数数量的直方图,还将跟踪在这些函数中花费的时间。直方图内容可以显示在文件中:trace_stat/function[cpu]
。如:
# echo 1 > function_profile_enabled
# cat trace_stat/function0Function Hit Time Avg s^2-------- --- ---- --- ---schedule 4368 334221648 us 76515.94 us 735411.5 us do_syscall_64 15508 222285003 us 14333.56 us 19887.52 us schedule_hrtimeout_range 1879 189004501 us 100587.8 us 220126.6 us schedule_hrtimeout_range_clock 1879 189003100 us 100587.0 us 222184.7 us
...
3.3.25 trace_stat
包含各种追踪系统统计数据的目录,为每个 CPU buffer 建立1个目录:trace_stat/function[cpu]
。
# ls -l trace_stat
total 0
-rw-r--r-- 1 root root 0 4月 12 10:06 function0
-rw-r--r-- 1 root root 0 4月 12 10:06 function1
...
3.3.26 kprobe_events
kprobe 追踪相关,见后面的叙述。
3.3.27 kprobe_profile
kprobe 追踪相关,见后面的叙述。
3.3.28 max_graph_depth
function graph 追踪中,显示函数调用栈的最大深度。
3.3.29 printk_formats
如果某个追踪事件上报到 ring buffer 的数据引用了字符串,那么 ring buffer 只会记录该字符串的指针地址,这样我们没法知道该指针指向的字符串内容到底是个啥。printk_formats
列举了字符串指针 和 指向的字符串,这样就可以通过地址来查找到字符串的内容。
# cat printk_formats
0xffffffff950be839 : "CPU_ON"
0xffffffff950be839 : "CPU_ON"
0xffffffff950be840 : "CPU_OFF"
0xffffffff950be840 : "CPU_OFF"
0xffffffff950c6525 : "thaw_processes"
0xffffffff950c6525 : "thaw_processes"
0xffffffff950c66e4 : "suspend_enter"
...
3.3.29 saved_cmdlines
文件记录 进程 PID
和 进程名
的映射。除非特别去记录 进程名
,否则 trace event 通常只会记录 进程 PID
。ftrace 追踪系统维护一个 进程 PID
和 进程名
的映射 到 saved_cmdlines
缓存文件,当输出追踪信息时,通过文件 saved_cmdlines
将 进程 PID
映射为 进程名
显示出来,如果当前 saved_cmdlines
没有某个 进程 PID
的映射项,输出显示 进程名
为 <…>
,如:
<...>-4587 [001] .... 19257.259293: vfs_open <-path_openat
选项文件 options/record-cmd
设为 0 ,表示在追踪过程中,不缓存 进程 PID
到 进程名
的映射数据到文件 saved_cmdlines
,默认 options/record-cmd
的值为 1。
3.3.30 saved_cmdlines_size
默认 saved_cmdlines
只缓存 128
个进程名映射项,如果要增加缓存数目,通过修改 saved_cmdlines_size
来完成。
3.3.31 saved_tgids
文件记录 进程 PID
到 进程所在进程组 ID
的映射表。如果选项文件 options/record-tgid
为 1 ,每当发生进程切换时,进程 PID
到 进程所在进程组 ID
的映射将记录到文件 saved_tgids
。默认 options/record-tgid
为 0 。
3.3.32 snapshot
见后面的叙述。
3.3.33 stack_max_size
见后面的叙述。
3.3.34 stack_trace
见后面的叙述。
3.3.35 stack_trace_filter
见后面的叙述。
3.3.36 trace_clock
记录追踪事件到 ring buffer 时,总会记录它的时间戳信息。时间戳来源于指定的时钟,默认情况下,ftrace 使用 CPU 本地时钟,这个时间变换很快,并且是特定于 CPU 的。
# cat trace_clock
[local] global counter uptime perf mono mono_raw boot x86-tsc
有时候可能有需求,要形成全局的参照,这时候使用 CPU 本地时钟 local ,可能就不合适了。我们可以通过命令:
# echo global > trace_clock
# cat trace_clock
local [global] counter uptime perf mono mono_raw boot x86-tsc
修改 trace_clock
文件,将会清空 ring buffer 和 snapshot 缓冲内容。
3.3.37 trace_marker
写这个文件,将写入到 ftrace buffer ???
3.3.38 trace_marker_raw
TODO:
3.3.39 uprobe_events
见后面的叙述。
3.3.40 uprobe_profile
TODO:
3.3.41 instances
TODO:
3.3.42 events
trace event 目录
,包含静态编译到内核的 event tracepoint
。
3.3.43 set_event
写文件 set_event
将启用指定的 trace event
。可写入的 trace event
名,查看文件 available_events
。
3.3.44 available_events
系统支持的 trace event
列表,可通过写 trace event
名到文件 set_event
启用。
3.3.45 timestamp_mode
TODO:
3.3.46 hwlat_detector
包含延迟检查硬件信息文件。
3.3.47 per_cpu
包含追踪系统 每 CPU buffer 包含的信息。
4. 各类 tracer
4.1 简介
4.1.1 function
跟踪所有内核函数的 tracer。
4.1.2 function_graph
类似于 function tracer ,和 function tracer 不同的是:function tracer 只跟踪函数的进入,而 function_graph tracer 既跟踪函数的进入,又跟踪函数的退出,因此可以绘制类似于C代码的函数调用图。
4.1.3 blk
block tracer,供 blktrace 存储 IO 工具使用。
4.1.4 hwlat
硬件延迟 tracer ,用来检测是否有硬件产生的延迟。
4.1.5 irqsoff
追踪中断延迟,记录最大中断延迟到 tracing_max_latency
。
4.1.6 preemptoff
追踪禁用抢占的最长时间,记录最长禁用时间到 tracing_max_latency
。
4.1.7 preemptirqsoff
追踪 中断延迟 和 禁用抢占 两者中的最长时间,记录到 tracing_max_latency
。
4.1.8 wakeup
追踪记录最高优先级任务,从其被唤醒开始到被调度的最大延迟,记录到 tracing_max_latency
。
4.1.9 wakeup_rt
类似于 wakeup
tracer ,但仅追踪记录 RT 任务。
4.1.10 wakeup_dl
类似于 wakeup
tracer ,但仅追踪记录 DL(DeadLine) 任务。
4.1.11 mmiotrace
TODO:
4.1.12 branch
用来追踪系统中 likely()
或 unlikely()
调用,用于观察 likely() 或 unlikely()
分支预测是否正确。
4.1.13 nop
关闭 tracer 。
5. tracer 使用示例
5.1 function
# echo function > current_tracer
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat trace 查看追踪信息
# tracer: function
#
# entries-in-buffer/entries-written: 205087/1383792 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID TGID CPU# |||| TIMESTAMP FUNCTION
# | | | | |||| | |vmtoolsd-1512 (-----) [000] .... 29892.117923: __inode_wait_for_writeback <-inode_wait_for_writebackvmtoolsd-1512 (-----) [000] .... 29892.117923: bit_waitqueue <-__inode_wait_for_writeback
...
5.2 wakeup
# echo wakeup > current_tracer
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat trace 查看追踪信息
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 4.15.0-142-generic
# --------------------------------------------------------------------
# latency: 112 us, #146/146, CPU#2 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: kworker/2:1H-313 (uid:0 nice:-20 policy:0 rt_prio:0)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \\ / ||||| \\ | / <idle>-0 2dNs. 1us : 0:120:R + [002] 313:100:R kworker/2:1H<idle>-0 2dNs. 4us : ttwu_do_activate <-try_to_wake_up<idle>-0 2dNs. 4us : ttwu_stat <-try_to_wake_up<idle>-0 2dNs. 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up<idle>-0 2.Ns. 5us : _raw_spin_lock_irq <-run_timer_softirq<idle>-0 2.Ns. 6us : _raw_spin_lock_irq <-run_timer_softirq<idle>-0 2dNs. 6us : __next_timer_interrupt <-run_timer_softirq<idle>-0 2dNs. 8us : call_timer_fn <-run_timer_softirq<idle>-0 2dNs. 8us : delayed_work_timer_fn <-call_timer_fn<idle>-0 2dNs. 8us : __queue_work <-delayed_work_timer_fn<idle>-0 2dNs. 9us : get_work_pool <-__queue_work<idle>-0 2dNs. 10us : _raw_spin_lock <-__queue_work<idle>-0 2dNs. 10us : insert_work <-__queue_work<idle>-0 2dNs. 11us : get_pwq.isra.20 <-insert_work<idle>-0 2dNs. 12us : wake_up_process <-insert_work<idle>-0 2dNs. 13us : try_to_wake_up <-wake_up_process...<idle>-0 2d... 302us : __schedule <-schedule_idle<idle>-0 2d... 302us : 0:120:R ==> [002] 1732: 0:R rtkit-daemon# cat tracing_max_latency 查看最大延迟为 302us
302
5.3 function_graph
# echo function_graph > current_tracer
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat trace 查看追踪信息
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |3) 2.319 us | } /* apparmor_socket_recvmsg */3) 3.737 us | } /* security_socket_recvmsg */3) | unix_stream_recvmsg() {3) | unix_stream_read_generic() {3) | mutex_lock() {3) | _cond_resched() {3) 0.481 us | rcu_all_qs();3) 1.369 us | }3) 2.188 us | }3) 0.479 us | _raw_spin_lock();3) 0.526 us | mutex_unlock();3) 0.465 us | put_pid();3) 6.043 us | }3) 7.018 us | }3) + 12.114 us | } /* sock_recvmsg */...3) ! 122.290 us | }3) ! 123.110 us | }3) ! 125.997 us | }...------------------------------------------3) gnome-t-3300 => <idle>-0 ------------------------------------------3) 0.621 us | finish_task_switch();3) # 1956.576 us | } /* schedule_idle */3) * 11216.74 us | } /* do_idle */
function_graph
是很有用的 tracer ,因为它追踪了函数的进入和退出,所以能够评测函数的执行时间。在上面我们看到 #,*,!
等这些奇怪的符号,它们的含义是用来标记值得注意的时间消耗,这些符号的具体含义如下:
‘$’ - greater than 1 second
‘@’ - greater than 100 millisecond
‘*’ - greater than 10 millisecond
‘#’ - greater than 1000 microsecond
‘!’ - greater than 100 microsecond
‘+’ - greater than 10 microsecond
‘ ‘ - less than or equal to 10 microsecond.
6. 追踪选项
# cat trace_options 查看支持的追踪选项
print-parent
nosym-offset
nosym-addr
noverbose
noraw
nohex
nobin
noblock
trace_printk
annotate
...
要禁用
某个选项,通过在选项名前加上 "no"
前缀,然后写入到 trace_options
文件,或者写 0 到 options/选项名
文件;
要启用
某个选项,通过移除选项名前 "no"
前缀,然后写入到 trace_options
文件,或者写 1 到 options/选项名
文件。
6.1 print-parent
function tracer的输出数据中,是否输出调用链中 caller 函数。
# cat trace_options | grep print-parent
print-parent
# echo function > current_tracer
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat trace 查看追踪信息irqbalance-995 [003] .... 32160.569842: seq_put_decimal_ull <-show_statirqbalance-995 [003] .... 32160.569843: kstat_irqs_usr <-show_stat# echo noprint-parent > trace_options
# cat trace_options
noprint-parent
...
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat traceupdate-notifier-2727 [003] .... 32315.372687: copy_msghdr_from_userupdate-notifier-2727 [003] .... 32315.372689: rw_copy_check_uvectorupdate-notifier-2727 [003] .... 32315.372689: __check_object_sizeupdate-notifier-2727 [003] .... 32315.372690: check_stack_objectupdate-notifier-2727 [003] .... 32315.372691: sock_recvmsg
看看,后一记录没有了 <-
标记的调用链。
6.2 sym-offset
以函数名+偏移形式显示调用链:
# echo sym-offset > trace_options
# cat trace 查看追踪信息gnome-terminal--3300 [000] .... 33488.523955: sock_poll+0x0/0x90 <-do_sys_poll+0x367/0x600
...
6.3 sym-addr
# echo sym-addr > trace_options
# cat trace 查看追踪信息compiz-2280 [003] .... 33594.617764: sock_poll+0x0/0x90 <ffffffff9484dc30> <-do_sys_poll+0x367/0x600 <ffffffff9429bec7>
...
6.4 trace_printk
写 0 禁用 trace_printk() 写入缓冲区。
6.5 annotate
有些时候,当 CPU 的 buffer 被填满时,其中一个 CPU 的 buffer 有很多新近的事件数据,因此其包含的事件数据时间范围更短;而另一个 CPU 的 buffer 可能只有几个新近的
事件数据,这使得其包含的事件数据的时间范围较前一个CPU更早。当报告事件数据时,会先显示时间上更靠前的数据,看起来就像是只有包含时间上更早事件数据的CPU在运行一样,让人困惑。当开启 annotate
选项时,每当报告另一个CPU buffer的数据时,就会插入一个注释行,提示接下来输出的是另一个 CPU buffer 的数据。如:
<idle>-0 [001] d... 36111.794219: nohz_balance_enter_idle <-__tick_nohz_idle_enter<idle>-0 [001] d... 36111.794219: rcu_irq_exit <-irq_exit<idle>-0 [001] d... 36111.794219: rcu_eqs_enter_common <-rcu_irq_exit<idle>-0 [001] .... 36111.794221: rcu_idle_exit <-do_idle<idle>-0 [001] d... 36111.794221: rcu_dynticks_eqs_exit <-rcu_idle_exit<idle>-0 [001] .... 36111.794221: arch_cpu_idle_exit <-do_idle<idle>-0 [001] d... 36111.794222: arch_cpu_idle_enter <-do_idle<idle>-0 [001] d... 36111.794222: tsc_verify_tsc_adjust <-arch_cpu_idle_enter<idle>-0 [001] d... 36111.794223: local_touch_nmi <-arch_cpu_idle_enter<idle>-0 [001] d... 36111.794223: tick_check_broadcast_expired <-do_idle<idle>-0 [001] d... 36111.794224: cpuidle_get_cpu_driver <-do_idle<idle>-0 [001] d... 36111.794224: rcu_idle_enter <-do_idle<idle>-0 [001] d... 36111.794224: rcu_eqs_enter_common <-rcu_idle_enter<idle>-0 [001] d... 36111.794224: cpuidle_not_available <-do_idle<idle>-0 [001] d... 36111.794225: default_idle_call <-do_idle<idle>-0 [001] d... 36111.794225: arch_cpu_idle <-default_idle_call<idle>-0 [001] d... 36111.794225: default_idle <-arch_cpu_idle
## CPU 2 buffer started #compiz-2280 [002] .... 36111.798775: __check_object_size <-do_sys_poll...
看上面的输出,当从 CPU 1 的 buffer 切换到 CPU 2 的 buffer 时,输出了一个注释行:
## CPU 2 buffer started #
这就是 annotate
选项的作用。
6.6 userstacktrace
在每个 trace event 后记录当前用户间线程的堆栈。
6.7 sym-userobj
当 userstacktrace
开启时,开启 sym-userobj
时将输出堆栈中地址所属的 文件/目标/行号
,并且打印地址在所属目标文件内的相对地址。这在启用了 ASLR(Address Space Layout Randomization)
,否则在应用退出后,你将再没有机会将栈中地址解析为对应的 文件/目标/行号
。如:
a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]
6.8 其它
TODO
7. 过滤命令
ftrace 过滤命令有如下通用格式:
echo <function>:<command>:<parameter> > set_ftrace_filter
echo <function>:<command>:<parameter> >> set_ftrace_filter
7.1 mod 过滤命令
mod
命令用来控制每 module 的函数过滤。
如:
echo 'write*:mod:ext3' > set_ftrace_filter
其中 mod
命令使能每 module 的函数过滤,write*:mod:ext3
合起来的意思就是值追踪模块 ext3 中的匹配 write* 模式的函数。用下面的命令移除上述过滤器:
echo '!write*:mod:ext3' >> set_ftrace_filter
就是在过滤表示式前加一个 !
号。下面列举了几个常见 mod 操作命令:
echo '!*:mod:!ext3' >> set_ftrace_filter 禁用除了ext3外其它所有模块函数的跟踪
echo '!*:mod:*' >> set_ftrace_filter 禁用对所有模块的追踪
...
7.2 traceon/traceoff 过滤命令
在特定的函数被调用时,打开或关闭追踪系统。
echo '__schedule_bug:traceoff:5' > set_ftrace_filter 前5次__schedule_bug()调用关闭trace
echo '!__schedule_bug:traceoff:0' > set_ftrace_filter 移除上一条过滤规则echo '__schedule_bug:traceoff' > set_ftrace_filter 只要调用__schedule_bug()就关闭trace
echo '!__schedule_bug:traceoff' > set_ftrace_filter 移除上一条过滤规则
7.3 snapshot 过滤命令
echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter 触发snapshot每当native_flush_tlb_others()被调用时
echo '!native_flush_tlb_others:snapshot' > set_ftrace_filter 移除上一条过滤规则echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter 只触发一次snapshot
echo '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter 移除上一条过滤规则
7.4 启用/关闭事件过滤命令
命令格式如下:
echo <function>:enable_event:<system>:<event>[:count] > set_ftrace_filter
echo <function>:disable_event:<system>:<event>[:count] > set_ftrace_filter
如:
# 启用事件 sched:sched_switch 的过滤规则
echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > set_ftrace_filter# 移除事件 sched:sched_switch 过滤规则的两种方式
echo '!try_to_wake_up:enable_event:sched:sched_switch:0' > set_ftrace_filter
echo '!schedule:disable_event:sched:sched_switch' > set_ftrace_filter
7.5 其它
dump: 某 function 触发时,导出 trace 缓冲内容到控制台
cpudump: 某 function 触发时,导出执行 function 的 CPU 的缓冲内容到控制台
stacktrace: 某 function 触发时,记录 stack trace
命令的格式同前面一样:
echo <function>:<command>:<parameter> > set_ftrace_filter
其中的 command
分别是 dump,cpudump,stacktrace
。