ftrace总结
一. 简介
ftrace 的作用是帮助开发人员了解 Linux 内核的运行时行为，以便进行故障调试或性能分析
从名字上分析，ftrace = function trace，表示可以进行函数级 trace，最早 ftrace 就是一个 function tracer，仅能够记录内核的函数调用流程。如今 ftrace 已经成为一个 framework，采用 plugin 的方式支持开发人员添加更多种类的 trace 功能。
接着介绍ftrace之前，我们需要先简单介绍一下debugfs，因为ftrace是需要debugfs支持的。为什么需要debugfs支持呢？因为我们作为user/debuger是工作在user space，也就是用户态的，如果要获取调试内核的函数，获取到内核的函数log，就需要内核空间和用户空间交互数据。DebugFS，顾名思义，是一种用于内核调试的虚拟文件系统，内核开发者通过debugfs和用户空间交换数据。（类似的虚拟文件系统还有procfs和sysfs等。procfs，其目的是反映进程的状态信息；而sysfs主要用于Linux设备模型。不论是procfs或是sysfs的接口应该保持相对稳定，因为用户态程序很可能会依赖它们。）。虚拟文件系统都并不实际存储在硬盘上，而是Linux内核运行起来后才建立起来。
默认情况下，debugfs会被挂载在目录/sys/kernel/debug之下，如果你的发行版里没有自动挂载，可以用如下命令手动完成
# mount -t debugfs none /your/debugfs/dir
但是一般情况下，我们常用的Linux发行版，比如ubuntu 18.04 20.04，会自动挂载，一般是自动挂载到：
/sys/kernel/debug，或者/sys/kernel/tracing
二. 简明用法
简单流程可以概括位：设置tracer类型 --> 设置tracer参数 --> 启动ftrace --> 获取结果
一般情况下，我们首先要通过文件 tracing_enable 把tracer开关先关闭，因为如果开关没有关闭的情况下，一旦先设置好了tracer类型，开始源源不断的记录log了，会让我们的log文件变得很大，不好去分析。
# echo 0 > tracing_on
2.1 设置tracer类型
首先要知道系统支持的tracer类型，可以通过下面的方式查看：
# cd /sys/kernel/debug/tracing # cat available_tracers hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
# echo function > current_tracer //设置 tracer 类型为 function
2.2 设置tracer参数
set_ftrace_filter 表示要跟踪的函数，这里我们只跟踪 mutex_unlock 函数
# echo mutex_unlock > set_ftrace_filter
2.3 启动ftrace
通过下面这个命令：
# echo 1 > tracing_on
# echo 0 > tracing_on //运行一段时间之后可以关闭ftrace，log会保留在trace文件中
2.4 获取trace结果
trace结果保存在trace文件中
# tracer: function # # entries-in-buffer/entries-written: 165/165 #P:8 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | <...>-202430 [001] .... 1212056.188933: mutex_unlock <-rb_simple_write <...>-202430 [001] .... 1212056.188953: mutex_unlock <-tracing_release_generic_tr <...>-202430 [001] .... 1212056.189069: mutex_unlock <-tty_ioctl <...>-202430 [001] .... 1212056.189070: mutex_unlock <-tty_do_resize <...>-202430 [001] .... 1212056.189107: mutex_unlock <-process_output_block <...>-202430 [001] .... 1212056.189108: mutex_unlock <-do_tty_write <...>-202558 [005] .... 1212056.189129: mutex_unlock <-flush_to_ldisc <...>-202318 [003] .... 1212056.189204: mutex_unlock <-n_tty_read <...>-162326 [000] .... 1212056.260795: mutex_unlock <-psi_avgs_work <...>-162326 [000] .... 1212056.260799: mutex_unlock <-psi_avgs_work kworker/5:0-45 [005] .... 1212056.348817: mutex_unlock <-intel_fbc_flush kworker/5:0-45 [005] .... 1212056.552841: mutex_unlock <-intel_fbc_flush <...>-176455 [006] .... 1212056.676822: mutex_unlock <-psi_avgs_work <...>-187521 [007] .... 1212056.708794: mutex_unlock <-psi_avgs_work <...>-174712 [004] .... 1212056.708810: mutex_unlock <-psi_avgs_work kworker/5:0-45 [005] .... 1212056.756854: mutex_unlock <-intel_fbc_flush <...>-202013 [003] .... 1212056.900793: mutex_unlock <-pci_pme_list_scan <...>-176455 [006] .... 1212056.932793: mutex_unlock <-psi_avgs_work kworker/5:0-45 [005] .... 1212056.960851: mutex_unlock <-intel_fbc_flush <...>-202318 [003] .... 1212057.073399: mutex_unlock <-n_tty_write <...>-202318 [003] .... 1212057.073401: mutex_unlock <-do_tty_write <...>-202558 [005] .... 1212057.073454: mutex_unlock <-flush_to_ldisc
从 trace 信息我们可以获取很多重要信息：
- 进程信息，TASK-PID
- 进程运行的 CPU
- 执行函数时的系统状态，包括中断，抢占等状态信息
- 执行函数的时间辍
与function trace相似，下面贴两个function_graph trace和 trace event的示例：
function_graph trace:
# cat available_tracers hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop # echo function_graph > current_tracer # echo dev_attr_show > set_graph_function # echo 1 > tracing_on # cat trace # tracer: function_graph # # CPU DURATION FUNCTION CALLS # | | | | | | | 0) | dev_attr_show() { 0) | energy_uj_show() { 0) | get_energy_counter [intel_rapl_common]() { 0) | cpus_read_lock() { 0) | _cond_resched() { 0) 0.283 us | rcu_all_qs(); 0) 0.880 us | } 0) 1.521 us | } 0) | rapl_read_data_raw [intel_rapl_common]() { 0) | rapl_msr_read_raw [intel_rapl_msr]() { 0) | rdmsrl_safe_on_cpu() { 0) | rdmsr_safe_on_cpu() { 0) 0.271 us | __init_waitqueue_head(); 0) | smp_call_function_single_async() { 0) | generic_exec_single() { 0) | __rdmsr_safe_on_cpu() { 0) | complete() { 0) 0.268 us | _raw_spin_lock_irqsave(); 0) | __wake_up_locked() { 0) 0.298 us | __wake_up_common(); 0) 0.836 us | } 0) 0.281 us | _raw_spin_unlock_irqrestore(); 0) 2.476 us | } 0) 3.610 us | } 0) 4.315 us | } 0) 4.941 us | } 0) | wait_for_completion() { 0) | _cond_resched() { 0) 0.270 us | rcu_all_qs(); 0) 0.800 us | } 0) 0.271 us | _raw_spin_lock_irq(); 0) 1.920 us | } 0) 8.231 us | } 0) 8.824 us | } 0) 9.413 us | } 0) + 10.670 us | } 0) 0.269 us | cpus_read_unlock(); 0) + 13.757 us | } 0) + 15.976 us | } 0) + 17.029 us | }
trace event:
trace event 就是利用 ftrace 框架，实现低性能损耗，对执行流无影响的一种信息输出机制。相比 printk，trace event： 不开启没有性能损耗 开启后不影响代码流程 不需要重新编译内核即可获取 debug 信息 系统支持的所有 trace event 都位于 /sys/kernel/debug/tracing/events 目录 # cd /sys/kernel/debug/tracing/events/sched/sched_switch # echo 1 > enable # echo 0 > trace # cat trace # tracer: nop # # entries-in-buffer/entries-written: 221/221 #P:4 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | <idle>-0 [003] d... 3408.075314: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120 chrome-4737 [003] d... 3408.075465: sched_switch: prev_comm=chrome prev_pid=4737 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
三. ftrace使用技巧
如果我们不想 trace schedule 这个函数，也可以这样做：
echo '!schedule' > set_ftrace_filter
或者
echo schedule > set_ftrace_notrace
Function filter 的设置也支持
*match，match* ，*match* 这样的正则表达式，譬如我们可以 echo '*lock*' < set_ftrace_notrace 来禁止跟踪带 lock 的函数，set_ftrace_notrace 文件里面这时候就会显示：cat set_ftrace_notrace xen_pte_unlock read_hv_clock_msr read_hv_clock_tsc update_persistent_clock read_persistent_clock set_task_blockstep user_enable_block_step
trace-cmd
从上面的例子可以看到，其实使用 ftrace 并不是那么方便，我们需要手动的去控制多个文件，但幸运的是，我们有
trace-cmd，作为 ftrace 的前端，trace-cmd 能够非常方便的让我们进行 ftrace 的操作，譬如我们可以使用 record 命令来 trace sched 事件：trace-cmd record -e sched
然后使用 report 命令来查看 trace 的数据：
trace-cmd report | head -10 version = 6 CPU 27 is empty cpus=40 trace-cmd-29557 [003] 16159201.985281: sched_waking: comm=kworker/u82:3 pid=28507 prio=120 target_cpu=037 trace-cmd-29557 [003] 16159201.985283: sched_migrate_task: comm=kworker/u82:3 pid=28507 prio=120 orig_cpu=37 dest_cpu=5 trace-cmd-29557 [003] 16159201.985285: sched_stat_sleep: comm=kworker/u82:3 pid=28507 delay=137014529 [ns] trace-cmd-29585 [023] 16159201.985286: sched_stat_runtime: comm=trace-cmd pid=29585 runtime=217630 [ns] vruntime=107586626253137 [ns] trace-cmd-29557 [003] 16159201.985286: sched_wake_idle_without_ipi: cpu=5 trace-cmd-29595 [037] 16159201.985286: sched_stat_runtime: comm=trace-cmd pid=29595 runtime=213227 [ns] vruntime=105364596011783 [ns] trace-cmd-29557 [003] 16159201.985287: sched_wakeup: kworker/u82:3:28507 [120] success=1 CPU:005
当然，在 report 的时候也可以加入自己的 filter 来过滤数据，譬如下面，我们就过滤出 sched_wakeup 事件并且是 success 为 1 的。
trace-cmd report -F 'sched/sched_wakeup: success == 1' | head -10 version = 6 CPU 27 is empty cpus=40 trace-cmd-29557 [003] 16159201.985287: sched_wakeup: kworker/u82:3:28507 [120] success=1 CPU:005 trace-cmd-29557 [003] 16159201.985292: sched_wakeup: trace-cmd:29561 [120] success=1 CPU:007 <idle>-0 [032] 16159201.985294: sched_wakeup: qps_json_driver:24669 [120] success=1 CPU:032 <idle>-0 [032] 16159201.985298: sched_wakeup: trace-cmd:29590 [120] success=1 CPU:026 <idle>-0 [010] 16159201.985300: sched_wakeup: trace-cmd:29563 [120] success=1 CPU:010 trace-cmd-29597 [037] 16159201.985302: sched_wakeup: trace-cmd:29595 [120] success=1 CPU:039 <idle>-0 [010] 16159201.985302: sched_wakeup: sshd:29395 [120] success=1 CPU:010
四. Graphics
How to enable kernel log in systrace Boot into android, adb shell echo 524288 > /sys/kernel/debug/tracing/buffer_size_kb cd /sys/kernel/debug/tracing cat set_event echo "i915:*" > set_event #enable i915 trace echo 1 > tracing_on cat trace echo "\!i915:*" > set_event #disable i915 trace cat set_event
参考链接：
1. linux的debugfs: https://www.cnblogs.com/cl1024cl/archive/2013/05/14/6205698.html
2. 使用ftrace跟踪系统问题 https://www.jianshu.com/p/99e127973abe
3. ftrace简介 https://www.cnblogs.com/danxi/p/6417828.html
