ftrace工具

lzhf1122

于 2023-01-11 09:48:07 发布

阅读量192

点赞数

分类专栏： Linux stability 文章标签： linux 网络运维

本文链接：https://blog.csdn.net/lzhf1122/article/details/128639308

版权

Linux stability 专栏收录该内容

26 篇文章 7 订阅

订阅专栏

ftrace工具

简介
开ftrace功能
Ftrace案例
Ftrace结果怎么读？
vim对Ftrace进行折叠

简介

Ftrace是Linux进行代码级实践分析最有效的工具之一，比如我们进行一个系统调用，出来的时间过长，我们想知道时间花哪里去了，利用Ftrace就可以追踪到一级级的时间分布。

开ftrace功能

9269 CONFIG_FTRACE=y
9271 CONFIG_FUNCTION_TRACER=y
9272 CONFIG_FUNCTION_GRAPH_TRACER=y
9273 CONFIG_DYNAMIC_FTRACE=y
9274 CONFIG_FUNCTION_PROFILER=y
9276 CONFIG_TRACE_PREEMPT_TOGGLE=y
9277 CONFIG_IRQSOFF_TRACER=y
9278 CONFIG_PREEMPT_TRACER=y
9279 CONFIG_SCHED_TRACER=y
9283 CONFIG_FTRACE_SYSCALLS=y

Ftrace案例

写一个proc模块，包含一个proc的读和写的入口。test_proc_show()故意调用了一个kill_time()的函数，而kill_time()的函数，又调用了mdelay(2)和kill_moretime()的函数，该函数体内调用mdelay(2)。

kill_time()的函数和kill_moretime()函数前面都加了noinline以避免被编译器inline优化掉。

#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/init.h>
#include <linux/version.h>
#include <linux/proc_fs.h>
#include <linux/seq_file.h>
#include <linux/delay.h>
#include <linux/uaccess.h>
static unsigned int variable;
static struct proc_dir_entry *test_dir, *test_entry;
static noinline void kill_moretime(void)
{
	mdelay(2);
}
static noinline void kill_time(void)
{
	mdelay(2);
	kill_moretime();
}
static int test_proc_show(struct seq_file *seq, void *v)
{
	unsigned int *ptr_var = seq->private;
	kill_time();
	seq_printf(seq, "%u\n", *ptr_var);
	return 0;
}
static ssize_t test_proc_write(struct file *file, const char __user *buffer,
size_t count, loff_t *ppos)
{
	struct seq_file *seq = file->private_data;
	unsigned int *ptr_var = seq->private;
	int err;
	char *kbuffer;
	if (!buffer || count > PAGE_SIZE - 1)
		return -EINVAL;
	kbuffer = (char *)__get_free_page(GFP_KERNEL);
	if (!kbuffer)
		return -ENOMEM;
	err = -EFAULT;
	if (copy_from_user(kbuffer, buffer, count))
		goto out;
	kbuffer[count] = '\0';
	*ptr_var = simple_strtoul(kbuffer, NULL, 10);
	return count;
out:
	free_page((unsigned long)buffer);
	return err;
}
static int test_proc_open(struct inode *inode, struct file *file)
{
	return single_open(file, test_proc_show, PDE_DATA(inode));
}
static const struct proc_ops test_proc_fops =
{
	.proc_open = test_proc_open,
	.proc_read = seq_read,
	.proc_write = test_proc_write,
	.proc_lseek = seq_lseek,
	.proc_release = single_release,
};
static __init int test_proc_init(void)
{
	test_dir = proc_mkdir("test_dir", NULL);
	if (test_dir) {
		test_entry = proc_create_data("test_rw",0666, test_dir, 		&test_proc_fops, &variable);
		if (test_entry)
			return 0;
	}
	return -ENOMEM;
}
module_init(test_proc_init);
static __exit void test_proc_cleanup(void)
{
	remove_proc_entry("test_rw", test_dir);
	remove_proc_entry("test_dir", NULL);
}
module_exit(test_proc_cleanup);
MODULE_DESCRIPTION("proc exmaple");
MODULE_LICENSE("GPL v2");

模块对应的Makefile如下:

export ARCH=arm64
export CROSS_COMPILE=aarch64-linux-gnu-
KERNEL_DIR ?=~/linux_rt/linux-rt-5.15/
obj-m := proc.o
modules:
	$(MAKE) -C $(KERNEL_DIR) M=$(PWD) modules
clean:
	$(MAKE) -C $(KERNEL_DIR) M=$(PWD) clean
install:
	cp *.ko $(KERNEL_DIR)/kmodules

编译并且加载：

$ sudo insmod proc.ko

之后/proc目录下/proc/test_dir/test_rw文件可被读写。
下面我们用Ftrace来跟踪test_proc_show()这个函数。
我们把启动ftrace的所有命令写到一个脚本function.sh里面：

#!/bin/bash
debugfs=/sys/kernel/debug
echo nop > $debugfs/tracing/current_tracer
echo 0 > $debugfs/tracing/tracing_on
echo $$ > $debugfs/tracing/set_ftrace_pid
echo function_graph > $debugfs/tracing/current_tracer
#replace test_proc_show by your function name
echo test_proc_show > $debugfs/tracing/set_graph_function
echo 1 > $debugfs/tracing/tracing_on
exec "$@"

然后用这个脚本去启动cat /proc/test_dir/test_rw，这样ftrace下面test_proc_show()函数就被trace了。

# ./function.sh cat /proc/test_dir/test_rw
0

读取trace的结果：

# cat /sys/kernel/debug/tracing/trace > 1

接着用vim打开这个文件1，发现这个文件有600多行：

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 2)               |  test_proc_show [proc]() {
 2)               |    kill_time [proc]() {
 2)               |      __delay() {
 2) + 15.648 us   |        arch_timer_evtstrm_available();
 2)               |        do_interrupt_handler() {
 2)   ==========> |
 2)               |          gic_handle_irq() {
 2)               |            handle_domain_irq() {
 2)               |              irq_enter() {
 2)               |                irq_enter_rcu() {
 2)   5.968 us    |                  preempt_count_add();
 2)   6.320 us    |                  irqtime_account_irq();
 2) + 51.424 us   |                }
 2) + 67.888 us   |              }

Ftrace结果怎么读？

Ftrace结果怎么读？答案非常简单：如果是叶子函数，就直接在这个函数的前面显示它占用的时间，如果是非叶子，要等到 }的时候，再显示时间，
延迟比较大的部分，会有+、#等特殊标号

 '$' - greater than 1 second
 '@' - greater than 100 milisecond
 '*' - greater than 10 milisecond
 '#' - greater than 1000 microsecond
 '!' - greater than 100 microsecond
 '+' - greater than 10 microsecond
 ' ' - less than or equal to 10 microsecond.

vim对Ftrace进行折叠

上面那个Ftrace文件太大了，大到看不清。我们可以用vim来折叠之，不过需要一个vim的特别配置，我把它存放在了我的~目录，名字叫.fungraph-vim：

" Enable folding for ftrace function_graph traces.
"
" To use, :source this file while viewing a function_graph trace, or use vim's
" -S option to load from the command-line together with a trace.  You can then
" use the usual vim fold commands, such as "za", to open and close nested
" functions.  While closed, a fold will show the total time taken for a call,
" as would normally appear on the line with the closing brace.  Folded
" functions will not include finish_task_switch(), so folding should remain
" relatively sane even through a context switch.
"
" Note that this will almost certainly only work well with a
" single-CPU trace (e.g. trace-cmd report --cpu 1).

function! FunctionGraphFoldExpr(lnum)
  let line = getline(a:lnum)
  if line[-1:] == '{'
    if line =~ 'finish_task_switch() {$'
      return '>1'
    endif
    return 'a1'
  elseif line[-1:] == '}'
    return 's1'
  else
    return '='
  endif
endfunction
function! FunctionGraphFoldText()
  let s = split(getline(v:foldstart), '|', 1)
  if getline(v:foldend+1) =~ 'finish_task_switch() {$'
    let s[2] = ' task switch  '
  else
    let e = split(getline(v:foldend), '|', 1)
    let s[2] = e[2]
  endif
  return join(s, '|')
endfunction

setlocal foldexpr=FunctionGraphFoldExpr(v:lnum)
setlocal foldtext=FunctionGraphFoldText()
setlocal foldcolumn=12
setlocal foldmethod=expr

之后我们配置vim为这个模板来打开前面那个600多行的文件1:
vim -S ~/.fungraph-vim 1
这样我们看到的样子是：

              1 # tracer: function_graph
              2 #
              3 # CPU  DURATION                  FUNCTION CALLS
              4 # |     |   |                     |   |   |   |
-             5  2)               |  test_proc_show [proc]() {
|-            6  2)               |    kill_time [proc]() {
||+           7  2)               |      __delay() {--------------------------------------------------------------------------------------------------------------------------------------------------------
||+         244  2)               |      kill_moretime [proc]() {-------------------------------------------------------------------------------------------------------------------------------------------
||          514  2) # 7619.840 us |    }
|+          515  2)               |    seq_printf() {-------------------------------------------------------------------------------------------------------------------------------------------------------
|           518  2) # 7793.760 us |  }

我们可以用z、a两个按键，搜索或者展开Ftrace的结果

最后，https://github.com/brendangregg/perf-tools对Ftrace的功能进行了很好的封装和集成，建议大家用perf-tools来使用Ftrace，则效果更佳更简单。

链接: 宋宝华：关于Ftrace的一个完整案例