1.什么是ftrace
ftrace (Function Tracer)是一个针对Linux内核的跟踪框架。虽然它最初的名字是Function Tracer，来自于ftrace记录内核运行时执行的各种函数调用相关信息的能力，但ftrace的跟踪能力覆盖了更广泛的内核内部操作。
通过各种跟踪插件，ftrace可以针对不同的静态跟踪点，例如调度事件、中断、内存映射I/O、CPU电源状态转换，以及与文件系统和虚拟化相关的操作。此外，还可以动态跟踪内核函数调用，可以通过使用globs将其限制在函数子集内，还可以生成调用图并提供堆栈使用报告。同时，ftrace可以用来测量Linux内核中的各种延迟，比如禁用中断或抢占的时间。
通过启用CONFIG_FUNCTION_TRACER内核配置选项，可以构建一个启用了ftrace的Linux内核。与ftrace的整个运行时交互是通过包含在特定挂载的debugfs文件系统中的可读和可写的虚拟文件来执行的;因此，ftrace不需要专门的用户空间实用程序来操作。然而，还有额外的用户空间实用工具，为数据记录、分析和可视化提供了更高级的功能;
2.内核配置
由于ftrace 工具已经移植到Linux系统中，内核一般会默认配置debugfs,但是所需要的tracer追踪器默认可能只提供nop, 如果需要其他的tracer ， 需要额外配置menuconfig,如下所示：
我目前只配置 function , function_graph这两个tracer供测试所需。如果需要其他tracer,可自行研究使用。
Kernel Hacking -> Compile-time checks and compiler options —>Debug Filesystem
Kernel Hacking -> Tracers:
Kernel Function Tracer (FUNCTION_TRACER)
Enable/disable ftrace dynamically (DYNAMIC_FTRACE)
Trace max stack (STACK_TRACER）
3.ftrace的使用
3.1trancer命令序列
当内核启动的时候，用户可以进入/sys/kernel/debug/tracing 目录查看当前支持的trance 命令。README文件提供了一个简短的使用说明，展示了 ftrace 的操作命令序列。
roo@arm:/sys/kernel/debug/tracing# ls
available_events printk_formats stack_trace_filter
available_filter_functions README timestamp_mode
available_tracers saved_cmdlines trace
buffer_size_kb saved_cmdlines_size trace_clock
buffer_total_size_kb saved_tgids trace_marker
current_tracer set_event trace_marker_raw
dyn_ftrace_total_info set_event_pid trace_options
enabled_functions set_ftrace_filter trace_pipe
events set_ftrace_notrace tracing_cpumask
free_buffer set_ftrace_pid tracing_on
instances set_graph_function tracing_thresh
max_graph_depth set_graph_notrace uprobe_events
options stack_max_size uprobe_profile
per_cpu stack_trace
- current_tracer:
这用于设置或显示已配置的当前tracer。 - available_tracers:
用于获取内核已配的支持的tracer。这里列出的tracer可以通过将它们的名称回显到current_tracer来配置。 - tracing_on:
这将设置或显示是否启用对tracer环缓冲区的写入。 在此文件中echo 0以禁用tracer，或echo 1以启用tracer。 注意，这只禁用写入循环缓冲区，跟踪开销仍然可能发生。 - trace:
该文件以对人有好的方式将追踪的log保存下来。注意，在读取(打开)这个文件时，跟踪是暂时禁用的。
-set_ftrace_filter/set_ftrace_notrace:
在编译内核时配置了动态 ftrace （选中 CONFIG_DYNAMIC_FTRACE 选项）后使用。前者用于显示指定要跟踪的函数，后者则作用相反，用于指定不跟踪的函数。如果一个函数名同时出现在这两个文件中，则这个函数的执行状况不会 被跟踪。这些文件还支持简单形式的含有通配符的表达式，这样可以用一个表达式一次指定多个目标函数；具体使用在后续文章中会有描述。注意，要写入这两个文 件的函数名必须可以在文件 available_filter_functions 中看到。缺省为可以跟踪所有内核函数，文件 set_ftrace_notrace 的值则为空。 - set_graph_function：
设置要清晰显示调用关系的函数，显示的信息结构类似于 C 语言代码，这样在分析内核运作流程时会更加直观一些。在使用function_graph 跟踪器时使用；缺省为对所有函数都生成调用关系序列，可以通过写该文件来指定需要特别关注的函数。 - Other:
以上只介绍几个常用的tracer, 如果有需要可以查看相关文档。
- ftrace使用手册：kernel-src/Documentation/trace/ftrace.txt
- ftrace设计文档：kernel-src/Documentation/trace/ftrace-design.txt
3.2查看当前支持的tracer
root@Superman:/sys/kernel/debug/tracing# cat available_tracers
hwlt blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
3.3 查看/设置当前运行的tracer
root@Superman:/sys/kernel/debug/tracing# cat current_tracer
nop
默认是nop,我们可通过回显命令进行设置当前运行的tracer。如下
root@Superman:/sys/kernel/debug/tracing# cat current_tracer
nop
root@Superman:/sys/kernel/debug/tracing# echo function_graph > current_tracer
root@Superman:/sys/kernel/debug/tracing# cat current_tracer
function_graph
3.4开启/关闭tracer
sysctl kernel.ftrace_enabled=1
sysctl kernel.ftrace_enabled=0
3.5暂停/继续
echo 0 > tracing_on
echo 1 > tracing_on
3.6查看已经收集的结果
cat trace
这里会将结果以文本的形式显示到终端，我个人喜欢将其用重定向的方式保存至文件，然后用其他编辑工具，如UE来查看分析。
cat trace >> MyTracer.txt
也可以通过管道的形式，或者正则表达式等方式捕获自己想要的信息。
4.调用实例
使用前，先将debugfs 挂载至用户文件夹下。
mkdir /debug
mount -t debugfs nodev /debug
cd /debug/tracing
4.1 function
**#查看当前支持的traceer
# cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
# 显示当前运行的tracer
# cat current_tracer
nop
# 设置tracer:function
# echo function > current_tracer
# cat current_tracer
function
# 停止tacer 并清空trace
# echo 0 > tracing_on
# echo 0 > trace
# cat trace
tracer: function
entries-in-buffer/entries-written: 0/0 #P:2
_-----=> irqs-off
/ _----=> need-resched
| / _---=> hardirq/softirq
|| / _--=> preempt-depth
||| / delay
TASK-PID CPU# |||| TIMESTAMP FUNCTION
| | | |||| | |
# 执行tracer，捕获sleep 内核动作， 停止tracer
# echo 1 > tracing_on && sleep 1 && echo 0 > tracing_on
# 读取trcer, 只显示前50行
# cat trace | head -n 50
tracer: function
#entries-in-buffer/entries-written: 84487/98407 #P:2
_-----=> irqs-off
/ _----=> need-resched
| / _---=> hardirq/softirq
|| / _--=> preempt-depth
||| / delay
TASK-PID CPU# |||| TIMESTAMP FUNCTION
| | | |||| | |
<idle>-0 [000] dn.. 6715.669331: smp_reschedule_interrupt <-reschedule_interrupt
<idle>-0 [000] dn.. 6715.669331: scheduler_ipi <-smp_reschedule_interrupt
<idle>-0 [000] .N.. 6715.669332: rcu_idle_exit <-do_idle
<idle>-0 [000] dN.. 6715.669332: rcu_dynticks_eqs_exit <-rcu_idle_exit
<idle>-0 [000] .N.. 6715.669332: arch_cpu_idle_exit <-do_idle
<idle>-0 [000] .N.. 6715.669332: tick_nohz_idle_exit <-do_idle
<idle>-0 [000] dN.. 6715.669332: ktime_get <-tick_nohz_idle_exit
<idle>-0 [000] dN.. 6715.669333: update_ts_time_stats <-tick_nohz_idle_exit
<idle>-0 [000] dN.. 6715.669333: nr_iowait_cpu <-update_ts_time_stats
<idle>-0 [000] dN.. 6715.669333: cpu_load_update_nohz_stop <-tick_nohz_idle_exit
<idle>-0 [000] dN.. 6715.669333: _raw_spin_lock <-cpu_load_update_nohz_stop
<idle>-0 [000] dN.. 6715.669333: update_rq_clock <-cpu_load_update_nohz_stop
<idle>-0 [000] dN.. 6715.669333: cpu_load_update <-cpu_load_update_nohz_stop
<idle>-0 [000] dN.. 6715.669333: sched_avg_update <-cpu_load_update
<idle>-0 [000] dN.. 6715.669334: timer_clear_idle <-tick_nohz_idle_exit
<idle>-0 [000] dN.. 6715.669334: calc_load_nohz_stop <-tick_nohz_idle_exit
<idle>-0 [000] dN.. 6715.669334: hrtimer_cancel <-tick_nohz_idle_exit
<idle>-0 [000] dN.. 6715.669334: hrtimer_try_to_cancel <-hrtimer_cancel
<idle>-0 [000] dN.. 6715.669334: hrtimer_active <-hrtimer_try_to_cancel
<idle>-0 [000] dN.. 6715.669334: lock_hrtimer_base.isra.19 <-hrtimer_try_to_cancel
<idle>-0 [000] dN.. 6715.669334: _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.19
<idle>-0 [000] dN.. 6715.669334: __remove_hrtimer <-hrtimer_try_to_cancel
<idle>-0 [000] dN.. 6715.669335: _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
<idle>-0 [000] dN.. 6715.669335: hrtimer_forward <-tick_nohz_idle_exit
<idle>-0 [000] dN.. 6715.669335: hrtimer_start_range_ns <-tick_nohz_idle_exit
<idle>-0 [000] dN.. 6715.669335: lock_hrtimer_base.isra.19 <-hrtimer_start_range_ns
<idle>-0 [000] dN.. 6715.669335: _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.19
<idle>-0 [000] dN.. 6715.669335: enqueue_hrtimer <-hrtimer_start_range_ns
<idle>-0 [000] dN.. 6715.669336: tick_program_event <-hrtimer_start_range_ns
<idle>-0 [000] dN.. 6715.669336: clockevents_program_event <-tick_program_event
<idle>-0 [000] dN.. 6715.669336: ktime_get <-clockevents_program_event
<idle>-0 [000] dN.. 6715.669336: lapic_next_deadline <-clockevents_program_event
<idle>-0 [000] dN.. 6715.669339: _raw_spin_unlock_irqrestore <-hrtimer_start_range_ns
<idle>-0 [000] dN.. 6715.669339: account_idle_ticks <-tick_nohz_idle_exit
<idle>-0 [000] .N.. 6715.669339: sched_ttwu_pending <-do_idle
<idle>-0 [000] .N.. 6715.669340: schedule_idle <-do_idle
<idle>-0 [000] dN.. 6715.669340: rcu_note_context_switch <-__schedule
<idle>-0 [000] dN.. 6715.669340: _raw_spin_lock <-__schedule
<idle>-0 [000] dN.. 6715.669340: update_rq_clock <-__schedule
# **
trace 文件给出的信息格式很清晰。
首先，字段“tracer:”给出了当前所使用的跟踪器的名字，这里为 function 跟踪器。然后是跟踪信息记录的格式，TASK 字段对应任务的名字，PID 字段则给出了任务的进程 ID，字段 CPU# 表示运行被跟踪函数的 CPU 号，这里可以看到 idle 进程运行在 0 号 CPU 上，其进程 ID 是 0 ；字段 TIMESTAMP 是时间戳，其格式为“.”，表示执行该函数时对应的时间戳；FUNCTION 一列则给出了被跟踪的函数，函数的调用者通过符号 “<-” 标明，这样可以观察到函数的调用关系。
4.2 function_graph
# echo function_graph > current_tracer
# echo 0 > tracing_on && echo 0 > trace
# echo 1 > tracing_on && sleep 1 && echo 0 > tracing_on
# cat trace | head -n 500
tracer: function_graph
CPU DURATION FUNCTION CALLS
| | | | | | |
0) | _cond_resched() {
0) 0.118 us | rcu_all_qs();
0) 0.488 us | }
0) 0.707 us | } /* wait_for_unix_gc */
0) | security_socket_getpeersec_dgram() {
0) 0.104 us | apparmor_socket_getpeersec_dgram();
0) 0.351 us | }
0) | sock_alloc_send_pskb() {
0) | alloc_skb_with_frags() {
0) | __alloc_skb() {
0) | kmem_cache_alloc_node() {
0) | _cond_resched() {
0) 0.110 us | rcu_all_qs();
0) 0.314 us | }
0) 0.537 us | }
0) | __kmalloc_reserve.isra.43() {
0) | __kmalloc_node_track_caller() {
0) 0.108 us | kmalloc_slab();
0) | _cond_resched() {
0) 0.119 us | rcu_all_qs();
0) 0.325 us | }
0) 0.766 us | }
0) 0.980 us | }
0) 0.119 us | ksize();
0) 2.068 us | }
0) 2.302 us | }
0) 0.118 us | skb_set_owner_w();
0) 2.734 us | }
0) 0.110 us | unix_scm_to_skb();
0) 0.105 us | skb_put();
0) | skb_copy_datagram_from_iter() {
0) | __check_object_size() {
0) 0.114 us | check_stack_object();
0) 0.126 us | __virt_addr_valid();
0) 0.122 us | __check_heap_object();
0) 0.783 us | }
0) 1.040 us | }
0) 0.109 us | _raw_spin_lock();
0) 0.116 us | maybe_add_creds();
0) | skb_queue_tail() {
0) 0.118 us | _raw_spin_lock_irqsave();
0) 0.125 us | _raw_spin_unlock_irqrestore();
0) 0.563 us | }
0) | sock_def_readable() {
0) | __wake_up_sync_key() {
0) | __wake_up_common_lock() {
0) 0.118 us | _raw_spin_lock_irqsave();
0) | __wake_up_common() {
0) | ep_poll_callback() {
0) 0.113 us | _raw_spin_lock_irqsave();
0) 0.118 us | _raw_spin_unlock_irqrestore();
0) 0.601 us | }
0) 0.856 us | }
0) 0.118 us | _raw_spin_unlock_irqrestore();
0) 1.521 us | }
0) 1.723 us | }
0) 1.935 us | }
0) 0.110 us | put_pid();
0) 9.173 us | } /* unix_stream_sendmsg */
0) + 10.304 us | } /* sock_sendmsg */
0) + 10.535 us | } /* sock_write_iter */
0) + 10.781 us | } /* do_iter_readv_writev */
0) 0.110 us | __fsnotify_parent();
0) 0.122 us | fsnotify();
0) + 12.727 us | } /* do_iter_write */
0) 0.112 us | kfree();
0) + 13.928 us | } /* vfs_writev */
0) 0.105 us | fput();
0) + 15.088 us | } /* do_writev */
0) + 15.307 us | } /* SyS_writev */
0) + 15.573 us | } /* do_syscall_64 */
0) | do_syscall_64() {
0) | SyS_poll() {
0) | do_sys_poll() {
0) | __check_object_size() {
0) 0.122 us | check_stack_object();
0) 0.344 us | }
0) | __fdget() {
0) | __fget_light() {
0) 0.117 us | __fget();
0) 0.330 us | }
0) 0.547 us | }
0) | sock_poll() {
0) | unix_poll() {
0) | __pollwait() {
0) | add_wait_queue() {
0) 0.117 us | _raw_spin_lock_irqsave();
0) 0.114 us | _raw_spin_unlock_irqrestore();
0) 0.779 us | }
0) 0.989 us | }
0) 1.230 us | }
0) 1.475 us | }
0) 0.111 us | fput();
0) | poll_schedule_timeout() {
0) | schedule_hrtimeout_range() {
0) | schedule_hrtimeout_range_clock() {
0) | schedule() {
0) 0.107 us | rcu_note_context_switch();
0) 0.110 us | _raw_spin_lock();
0) 0.121 us | update_rq_clock();
0) | deactivate_task() {
0) | dequeue_task_fair() {
0) | dequeue_entity() {
0) | update_curr() {
0) 0.119 us | update_min_vruntime();
0) 0.140 us | cpuacct_charge();
0) 0.617 us | }
0) 0.108 us | __update_load_avg_se.isra.38();
0) 0.114 us | clear_buddies();
0) 0.111 us | account_entity_dequeue();
0) 0.107 us | update_cfs_group();
0) 0.108 us | update_min_vruntime();
0) 1.930 us | }
0) | dequeue_entity() {
0) | update_curr() {
0) 0.123 us | __calc_delta();
0) 0.110 us | update_min_vruntime();
0) 0.581 us | }
0) 0.129 us | __update_load_avg_se.isra.38();
0) 0.108 us | clear_buddies();
0) 0.119 us | account_entity_dequeue();
0) | update_cfs_group() {
0) 0.128 us | reweight_entity();
0) 0.375 us | }
0) 0.119 us | update_min_vruntime();
0) 2.189 us | }
0) 0.111 us | hrtick_update();
0) 4.680 us | }
0) 4.934 us | }
0) | pick_next_task_fair() {
0) 0.110 us | check_cfs_rq_runtime();
0) | pick_next_entity() {
0) 0.109 us | clear_buddies();
0) 0.345 us | }
0) | pick_next_entity() {
0) 0.110 us | clear_buddies();
0) 0.315 us | }
0) | put_prev_entity() {
0) 0.108 us | check_cfs_rq_runtime();
0) 0.332 us | }
0) | set_next_entity() {
0) 0.126 us | __update_load_avg_se.isra.38();
0) 0.349 us | }
0) | put_prev_entity() {
0) 0.104 us | check_cfs_rq_runtime();
0) 0.319 us | }
0) | set_next_entity() {
0) 0.131 us | __update_load_avg_se.isra.38();
0) 0.353 us | }
0) 3.002 us | }
0) | switch_mm_irqs_off() {
0) 0.207 us | load_new_mm_cr3();
0) 0.500 us | }
function_graph 跟踪器则可以提供类似 C 代码的函数调用关系信息。通过写文件 set_graph_function 可以显示指定要生成调用关系的函数，缺省会对所有可跟踪的内核函数生成函数调用关系图。
函数图跟踪器对函数的进入与退出进行跟踪，这对于跟踪它的执行时间很有用。函数执行时间超过10微秒的标记一个“+”号，超过1000微秒的标记为一个“！”号。通过echo function_graph > current_tracer可以启用函数图跟踪器。
CPU 字段给出了执行函数的 CPU 号，本例中都为 1 号 CPU。
DURATION 字段给出了函数执行的时间长度，以 us 为单位。
FUNCTION CALLS 则给出了调用的函数，并显示了调用流程。注意，
对于不调用其它函数的函数，其对应行以“;”结尾，而且对应的 DURATION 字段给出其运行时长.
对于调用其它函数的函数，则在其“}”对应行给出了运行时长，该时间是一个累加值，包括了其内部调用的函数的执行时长。DURATION 字段给出的时长并不是精确的，它还包含了执行 ftrace 自身的代码所耗费的时间，所以示例中将内部函数时长累加得到的结果会与对应的外围调用函数的执行时长并不一致；不过通过该字段还是可以大致了解函数在时间上的运行开销的。
4.脚本示例
#!/bin/sh
dir=/sys/kernel/debug/tracing
sysctl kernel.ftrace_enabled=1
echo function_graph > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on#
sleep 1
echo 0 > ${dir}/tracing_on
cat ${dir}/trace > ~/mytrace.txt
#!/bin/sh
echo "format nvme..."
mkfs.fat /dev/nvme0n1p1
echo "mount nvme to /mnt"
mount /dev/nvme0n1p1 /mnt/
dir=/sys/kernel/debug/tracing
sysctl kernel.ftrace_enabled=1
echo "SSD Write..."
echo nop > ${dir}/current_tracer
echo function_graph > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on
dd if=/dev/zero of=/mnt/zero.bin bs=1M count=512
echo 0 > ${dir}/tracing_on
cat ${dir}/trace > ~/SSD_Write.txt
echo "SSD Read..."
echo nop > ${dir}/current_tracer
echo function_graph > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on
dd if=/mnt/zero.bin of=/dev/null bs=1M count=512
echo 0 > ${dir}/tracing_on
cat ${dir}/trace > ~/SSD_Read.txt
577
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
