Smarticen Notes

ftrace分析长延时内核函数

3 min read

基本使用

ftrace最开始的名字就叫做function tracer，可以看出最开始的目的就是调试内核函数的，现在随着功能的丰富，function tracer成为了其基础功能，不过这里也是我们最关注的功能。

ftrace的操作都是在tracefs这个虚拟文件系统中完成的。可以通过执行下面的命令来查看tracefs在所在机器上的挂载路径

cat /proc/mounts | grep tracefs

然后进入挂载的路径，执行后续的操作。

在tracefs下有很多文件，通过操作其下的文件来给内核的ftrace系统发送指令，然后cat某个文件获得结果。

可以先查询trace文件，默认的情况下tracer为nop，即什么都不做。接下来以do_mount为例，学习如何分析do_mount内核函数。

  • 启用function tracer，即写入function到current_tracer文件当中
# cat current_tracer
nop
# cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
# echo function > current_tracer
# cat current_tracer
function
  • 输出信息在tracer文件中可以读取到，默认情况下会输出所有内核函数的信息，但这样太多了，因此需要进行过滤，只输出关注的内核函数信息。通过往set_ftrace_filter写入内核函数即可完成过滤
# echo nop > current_tracer
# echo do_mount > set_ftrace_filter
# echo function > current_tracer
  • 执行一次mount操作，就可以在tracer文件中看到函数调用信息了，不过这里只能看到一层的调用关系
# mount -t tmpfs tmpfs /tmp/fs
# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 1/1   #P:12
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           mount-20889 [005] .... 2159455.499195: do_mount <-ksys_mount
  • 打开 ftrace 中的 func_stack_trace 选项来查看更多调用栈
# echo 1 > options/func_stack_trace
  • 为了进一步看到函数调用关系的时间开销，还可以启动function_graph tracer，这个tracer将内核函数以及子函数调用栈的耗时也都记录了。
# echo '!do_mount ' >> set_ftrace_filter ### 先把之前的do_mount filter给去掉。
# echo kfree_skb > set_graph_function  ### 设置kfree_skb()
# echo nop > current_tracer ### 暂时把current_tracer设置为nop, 这样可以清空trace
# echo function_graph > current_tracer ### 把current_tracer设置为function_graph

Graph View