【Ftrace专栏】function graph的trace输出格式使用

【Ftrace专栏】function graph的trace输出格式

使用Linux内核的function graph tracer可以跟踪函数耗时，分析内核代码的执行流，并且还提供了很多选项开关来对输出的内容进行定制，进一步提高分析效率，下面对常用的一些选项进行介绍。

1、tracce_options 使用

1. 一种是通过向/sys/kernel/tracing/options目录下的文件节点写入1或者0进行开启和关闭
   

2. 另外一种方法是通过向/sys/kernel/tracing/trace_options中写入option或者nooption来开启和关闭,可以读取trace_options来获取当前选项的使能情况:
   

2、默认输出

3、是否输出上下文信息

• 通过context-info可以控制是否输出上下文信息，如果你只想复制调用流程，可以关闭输出上下文：
• 通过context-info可以控制是否输出上下文信息，如果你只想复制调用流程，可以关闭输出上下文：

# echo 0 > options/context-info

4、输出绝对时间戳

• 如果想输出每条trace发生的时刻，可以开启funcgraph-abstime，这样会把绝对时间戳打印出来

echo 1 > options/funcgraph-abstime

5、输出进程名

• 如果想知道某条trace是在哪个进程的上下文发生的，或者说某条trace是哪个进程输出的，那么可以使用funcgraph-proc。

echo 1 > options/funcgraph-proc

6、输出中断、抢占计数信息

• 在使用function跟踪器的时候，我们可以看到中断、抢占的计数信息，function graph也是支持的，通过latency-format。

echo 1 > options/latency-format

• 上面可以看到，preempt-depth最小都是1，表示内核抢占是被关闭的，根据上面的调用栈，应该是可以抢占的，不太合理呀，那么这是为什么呢？
• 从trace的生成流程可以很容易理解：

ftrace_graph_func  -> prepare_ftrace_return      -> ftrace_test_recursion_trylock  		// 会关闭内核抢占          -> trace_test_and_set_recursion              -> preempt_disable_notrace      -> function_graph_enter    				// 生成trace      -> ftrace_test_recursion_unlock   		// 会开启内核抢占          -> trace_clear_recursion              -> preempt_enable_notrace

• 即：在function_graph_enter中创建trace的时候是关闭内核抢占的，所以看到的preempt-depth的值至少为1.

7、funcgraph-retval 输出函数返回值

7.1、参考博文：

• funcgraph-retval

参考博文解释：
- 将一个进程添加到某个cpu cgroup组的时候总是提示-EINVAL，
- 用bpftrace定位到原因是要添加的进程是RT进程，而目标cpu cgroup组没有给RT进程设置时间份额。

7.2、funcgraph-retval使用

• 这里用到的选项是funcgraph-retval，要使用这个选项前提是配置内核的时候需要开启CONFIG_FUNCTION_GRAPH_RETVAL
  
• 开启选项：
  echo 1 > options/funcgraph-retval
  
• 如果函数的返回值是负数，那么会按10进制输出，方便我们定位发生错误的位置，否则的话，按16进制输出。
• 这个选项一方面可以加速我们定位返回错误的内核代码，另外一方面也有助于我们理解跟踪代码的执行流，根据函数的返回值走不同的逻辑。

8、输出函数的返回地址

8.1、参考博文

• f输出函数的返回地址

8.2、funcgraph-retaddr 使用

• 这里用到的选项是funcgraph-retaddr，要使用这个选项前提是配置内核的时候需要开启CONFIG_FUNCTION_GRAPH_RETADDR：
  
• funcgraph-retaddr

echo 1 > options/funcgraph-retaddr

• 比如想知道preempt_count_sub具体是在哪行调用的：

# scripts/faddr2line /vmlinux vfs_write+0x1da/0x510
vfs_write+0x1da/0x510:
percpu_down_read at include/linux/percpu-rwsem.h:70
(inlined by) __sb_start_write at include/linux/fs.h:1725
(inlined by) sb_start_write at include/linux/fs.h:1861
(inlined by) file_start_write at include/linux/fs.h:2964
(inlined by) vfs_write at fs/read_write.c:675

• 上面的输出表示preempt_count_sub被几个内联函数调用的，结合内核代码理解这个内联过程：