linux性能分析工具专题-ftrace（延时分析/函数追踪）

本文调试环境用到 基于4.4的ubuntu（虚拟机），uname -a版本信息如下：

Linux ubuntu 4.4.0-148-generic #174~14.04.1-Ubuntu SMP Thu May 9 08:17:37 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

概念

ftrace基础概念

ftrace是一个内核中追踪器，用于帮助系统开发者或者设计者查看内核运行情况，可以调试或者分析延迟、性能问题。最早ftrace是一个function tracer，仅能够记录内核函数调用流程。如今trace已经成为一个framework，采用plugin的方式支持开发人员添加各种种类的trace功能。

ftrace工具集介绍

ftrace工作在debugfs文件系统上，常见在linux如下目录：/sys/kernel/debug/tracing。
路径下有 帮助文档 README，可以随时查看。

root@ubuntu:/sys/kernel/debug/tracing# ls
available_events            instances            set_event_pid       trace_clock
available_filter_functions  kprobe_events        set_ftrace_filter   trace_marker
available_tracers           kprobe_profile       set_ftrace_notrace  trace_options
buffer_size_kb              max_graph_depth      set_ftrace_pid      trace_pipe
buffer_total_size_kb        options              set_graph_function  trace_stat
current_tracer              per_cpu              set_graph_notrace   tracing_cpumask
dyn_ftrace_total_info       printk_formats       snapshot            tracing_max_latency
enabled_functions           README               stack_max_size      tracing_on
events                      saved_cmdlines       stack_trace         tracing_thresh
free_buffer                 saved_cmdlines_size  stack_trace_filter  uprobe_events
function_profile_enabled    set_event            trace               uprobe_profile

其中重点关注的文件有：
1、trace查看选择：
available_tracers ：支持的跟踪器；current_tracer ：当前的跟踪器，可以echo选择；
2、trace使能
tracing_on ：是否往循环buffer写跟踪记录，可以echo设置；
3、trace过滤器选择（可选）
set_ftrace_filter/set_graph_notrace：（function跟踪器）函数过滤器，echo xxx设置要跟踪的函数，echo [空格]可以禁止过滤；set_ftrace_notrace为反向过滤器，设置后输出除了函数以外内容；
set_graph_function/set_graph_notrace：（function_graph跟踪器）函数过滤器，设置后只跟踪对应函数；set_graph_notrace为反向过滤器，打开后进入对应函数会关闭跟踪。
4、trace数据读取
trace：可以cat读取跟踪记录的buffer内容（查看的时候 会临时停止跟踪）；
trace_pipe：类似trace可以动态读取的流媒体文件（差异是每次读取后，再读取会读取新内容）

root@ubuntu:/sys/kernel/debug/tracing# cat available_tracers //查询支持的跟踪器
blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
root@ubuntu:/sys/kernel/debug/tracing# cat current_tracer // 查询当前的跟踪器
nop
root@ubuntu:/sys/kernel/debug/tracing# cat tracing_on // 查看是否往循环buffer写跟踪记录
1

典型追踪器使用举例

function—执行顺序函数调用跟踪程序

available_filter_functions：列出当前可以跟踪的内核函数，不在该文件中列出的函数，无法跟踪其活动
enabled_functions：显示有回调附着的函数名称。
function_profile_enabled：打开此选项，在trace_stat中就会显示function的统计信息。
set_ftrace_filter：用于指定跟踪的函数
set_ftrace_notrace：用于指定不跟踪的函数
set_ftrace_pid：用于指定要跟踪特定进程的函数

echo function > current_tracer // 设置function跟踪器
echo 1 >tracing_on // 使能
echo 0 >tracing_on // 关闭使能（结束记录）
cat trace >~/trace_function.log // 把trace内容重定向到文件

查看文件内容如下：分别是PID，对应CPU，函数执行开始时间戳，函数的名字以及其父函数；

# tracer: function
#
# entries-in-buffer/entries-written: 51222/2244202   #P:1
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           gdbus-2549  [000] .... 32939.114074: __fget <-__fget_light
           gdbus-2549  [000] .... 32939.114074: eventfd_poll <-do_sys_poll
           gdbus-2549  [000] .... 32939.114075: __pollwait <-eventfd_poll
           gdbus-2549  [000] .... 32939.114075: add_wait_queue <-__pollwait
           gdbus-2549  [000] .... 32939.114075: _raw_spin_lock_irqsave <-add_wait_queue
           gdbus-2549  [000] d... 32939.114076: _raw_spin_unlock_irqrestore <-add_wait_queue
           gdbus-2549  [000] .... 32939.114076: fput <-do_sys_poll
           gdbus-2549  [000] .... 32939.114076: __fdget <-do_sys_poll
           gdbus-2549  [000] .... 32939.114076: __fget_light <-__fdget

function_graph—展示子函数调用层次的跟踪程序

function_graph通过图形方式显示函数的调用层次和耗时问题，体现每一个函数进入退出。非常方便测量函数耗时细节和调用栈信息。你想要确认一个内核接口内部细节，识别内部细节耗时可以使用它。
max_graph_depth：函数嵌套最大深度，默认不限制
set_graph_function：显示函数调用关系，使用function_graph跟踪器默认显示函数调用关系
set_graph_notrace：不跟踪特定的函数嵌套调用

echo function_graph > current_tracer // 设置function跟踪器
echo 1 >tracing_on // 使能
echo 0 >tracing_on // 关闭使能（结束记录）
cat trace >~/trace_function.log // 把trace内容重定向到文件

查看文件内容如下：分别是所在CPU，函数执行时间（+和！表示相对较高的地方，需要重点关注），函数调用层次。和 C 语言一样使用了花括号标记每个函数的边界，它展示了每个函数的开始和结束；不能调用其它任何函数的叶子函数用分号标记。

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
   0)   0.908 us    |        } /* pick_next_entity */
   0)               |        set_next_entity() {
   0)   0.136 us    |          update_stats_wait_end();
   0)   1.188 us    |        }
   ... // 省略
   0)   1.325 us    |          }
   0) + 42.115 us   |        }
   0)   0.052 us    |        restore_nameidata();
   0) + 42.829 us   |      }

过滤器举例，如果在使能trace之前输入：echo printk > set_graph_function，会针对设置函数进行指定跟踪，内容如下

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
   0)               |  printk() {
   0)               |    vprintk_default() {
   0)               |      vprintk_emit() {
   0)   0.104 us    |        _raw_spin_lock();
   0)               |        log_store() {
   0)   0.107 us    |          log_make_free_space();
   0)   1.061 us    |        }
   0)   0.101 us    |        _raw_spin_unlock();
   0)               |        console_trylock() {
   0)               |          down_trylock() {
   0)   0.093 us    |            _raw_spin_lock_irqsave();
   0)   0.130 us    |            _raw_spin_unlock_irqrestore();
   0)   1.780 us    |          }
   0)   2.618 us    |        }
   0)               |        console_unlock() {
   0)   0.096 us    |          _raw_spin_lock_irqsave();
   0)   0.128 us    |          _raw_spin_unlock_irqrestore();

blk（待补充）

mmiotrace（待补充）

nop—空跟踪器，相当于禁止跟踪

参考资料

内核文档：https://www.kernel.org/doc/Documentation/trace/ftrace.txt
ftrace作者的一篇指导：https://events.static.linuxfound.org/slides/2010/linuxcon_japan/linuxcon_jp2010_rostedt.pdf
优秀blog：https://www.cnblogs.com/arnoldlu/p/7211249.html
优秀blog：https://blog.selectel.com/kernel-tracing-ftrace/