Song Baohua: A Complete Case of Ftrace

Introduction to Ftrace

Ftrace is one of the most effective tools for code-level practice analysis on Linux. For example, if we make a system call and it takes too long to get out, we want to know where the time is spent and use Ftrace to track the time distribution at the first level.

Ftrace case

Write a proc module that contains a proc's read and write entry.test_proc_show() deliberately calls a function of kill_time(), while the function of kill_time() calls functions of mdelay(2) and kill_moretime(), which calls mdelay(2) within the body of the function.

The kill_time() and kill_moretime() functions are preceded by noinline to avoid being optimized by the compiler 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 file_operations test_proc_fops = { .owner = THIS_MODULE, .open = test_proc_open, .read = seq_read, .write = test_proc_write, .llseek = seq_lseek, .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_AUTHOR("Barry Song <[email protected]>"); MODULE_DESCRIPTION("proc exmaple"); MODULE_LICENSE("GPL v2");

The Makefile corresponding to the module is as follows:

KVERS = $(shell uname -r) # Kernel modules obj-m += proc.o # Specify flags for the module compilation. #EXTRA_CFLAGS=-g -O0 build: kernel_modules kernel_modules: make -C /lib/modules/$(KVERS)/build M=$(CURDIR) modules clean: make -C /lib/modules/$(KVERS)/build M=$(CURDIR) clean

Compile and load:

$ make baohua@baohua-perf:~/develop/training/debug/ftrace/proc$ $ sudo insmod proc.ko [sudo] password for baohua:

The / proc/test_dir/test_rw file can then be read and written in the / proc directory.

Let's use Ftrace to track the function test_proc_show().

We write all the commands to start ftrace into a script 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 "$@"

Then use this script to start cat/proc/test_dir/test_rw so that the test_proc_show() function under ftrace is traced.

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

Result of reading trace:

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

Then open the file 1 with vim and find that it has more than 600 lines:

Long enough to see!!

How do I read the Ftrace results?

How do I read the Ftrace results?The answer is very simple: if it's a leaf function, show the time it takes up directly in front of it. If it's a non-leaf function, wait until} before showing the time, as shown in the following figure:

If the delay is large, there will be special labels such as +, #etc.

'$' - 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 Folds Ftrace
The Ftrace file above is too big to see.We can fold it with vim, but we need a special configuration for vim. I store it in my ~directory under the name. 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

We then configure vim to open the previous 600-line file 1 for this template:

vim -S ~/.fungraph-vim 1

So what we see here is:

We can move the cursor to line 5, and when the keyboard taps za, it expands to:

Continue to expand kill_time() in line 6, press za:

We can use the z and a keys to search for or expand the results of Ftrace.

Last, https://github.com/brendangre... Ftrace functions are well encapsulated and integrated. We recommend that you use perf-tools to use Ftrace for better and simpler results.

Talk about perf-tools when you're free.

More exciting updates...Welcome to the WeChat Public Number: linux Reading Yard (id: linuxdev)

Add new comment

0 comments