How to use ftrace to trace your kernel module(使用Ftrace跟踪你的内核模块)

AUTHOR： Joseph Yang (杨红刚) <ganggexiongqi@gmail.com>

CONTENT: How to use ftrace to trace your kernel module(使用Ftrace跟踪你的内核模块)

NOTE： linux-3.0

LAST MODIFIED：09-06-2011

-----------------------------------------------------------------------------------------------------------

Distributed and Embedded System Lab (分布式嵌入式系统实验室，兰州大学)


===============================================================

在下面的内核模块中我们故意设计了一个“除零错误”。并使用Ftrace来跟踪这个错误。

内核模块在/sys/kernel/下创建了kobj4ftrace文件夹，kobj4ftrace下有一个data文件。

你可以向data输入一个整数(echo 3 > data),然后读出data的值(24/3=8)8。

但是在内核模块中没有检查分母是否为零，这样当我们输入0，再读出结果时，将会触发一个“除零错误”。

----------- tl.c ---------------

/*
This is a simple module used for showing How to
use Ftrace to trace your driver.
-----------------------------------------------------
Function: you can "echo your_data > /sys/kernel/kobj4ftrace/data"
This module will divide 24 with 'your_data' and store
the result in
/sys/kernel/kobj4ftrace/data.
To check the result you can use 'cat' cmd.
How to use:
$echo 2 > /sys/kernel/kobj4ftrace/data
$cat /sys/kernel/kobj4ftrace/data
12  // <=== 24/2

Compile: # make  -Wall -C /lib/modules/`uname -r`/build  M=`pwd` modules
!!! Note: Here is a bug: when your data is 0, then there will be a
'Divide Fault'.
*/
#include <linux/kobject.h>
#include <linux/string.h>
#include <linux/sysfs.h>
#include <linux/module.h>
#include <linux/init.h>

static int data = 0;
int devide(int data)
{
return 24/data;
}

int caculater(int data)
{
int result;

result = devide(data);
return result;
}
static ssize_t data_show(struct kobject *kobj, struct kobj_attribute *attr,
char *buf)
{
int result;
result = caculater(data);
return sprintf(buf, "%d\n", result);
}

static ssize_t data_store(struct kobject *kobj, struct kobj_attribute *attr,
const char *buf, size_t count)
{
sscanf(buf, "%du", &data);
return count;
}

static struct kobj_attribute data_attribute =
__ATTR(data, 0666, data_show, data_store);

static struct attribute *attrs[] = {
&data_attribute.attr,
NULL,	/* need to NULL terminate the list of attributes */
};

static struct attribute_group attr_group = {
.attrs = attrs,
};

static struct kobject *my_kobj;

static int __init my_init(void)
{
int retval;
/* file is located under /sys/kernel/ */
my_kobj = kobject_create_and_add("kobj4ftrace", kernel_kobj);
if (!my_kobj)
return -ENOMEM;

/* Create the files associated with this kobject */
retval = sysfs_create_group(my_kobj, &attr_group);
if (retval)
kobject_put(my_kobj);

return retval;
}

static void __exit my_exit(void)
{
kobject_put(my_kobj);
}

module_init(my_init);
module_exit(my_exit);
MODULE_LICENSE("GPL");
MODULE_AUTHOR("Joseph <ganggexiongqi@gmail.com>");

----------------- 操作步骤 ---------------------

Trace the kernel bug:

# mount -t debugfs nodev /sys/kernel/debug

# cd /sys/kernel/debug/tracing

Load your module:

#insmod tl.ko

Set the trace filter

# echo ':mod:tl' > set_ftrace_filter //注意，tl为你要跟踪的模块的名字

Check the filter to see functions in your module.

# cat set_ftrace_filter



devide



caculater

data_store

data_show

Choose a the tracer:

#echo function_graph > current_tracer

Enable trace:

#sysctl kernel.ftrace_enabled=1

Trace begin:

#echo 1 >tracing_enabled

#cat trace_pipe > /tmp/trace_result&

Do something:

# cd /sys/kernel/kobj4ftrace

# echo 2 > data

# cat data

12 // '24/2 = 12'

Make an error:

# echo 0 > data

# cat data // 24/0 ----> divide error!!!!!

Terminate the tracing:

#echo 0 > tracing_enabled

Analysis the tracing result:

#vim /tmp/trace_result

ERR | data_store();

------------------------------------------

0) bash-3234 => cat-3688

------------------------------------------

0) 9.898 us | data_show();

------------------------------------------

0) cat-3688 => bash-3234

------------------------------------------

0) 8.028 us | data_store();

------------------------------------------

0) bash-3234 => cat-3689

------------------------------------------

0) | data_show() { // 注意： 这里就是出现问题的地方！！！

-----------------------------------------------------------------------------------



但是，这里我有个问题没有搞清楚，为什么结果不是：

...



data_show(){

caculater() {

devide() {

结果中只是跟踪到了，最上层的data_show，这是为什么呢？？？

--------动态地跟踪你的内核模块------------
还是上面的例子tl.c
比如你想知道每次调用data_store函数时 data的值到底是多少？
这时你可以添加一个probe到kprobe_events
#cd /sys/kernel/debug/tracing
#echo “p:myprobe tl:data_store data=@data" > kprobe_events
#echo 1 > events/kprobes/myprobe/enable //使能
//do something


#echo 8 > /sys/kernel/kobj4ftrace/data
#vim trace //读取跟踪结果

# tracer: nop

#

# TASK-PID CPU# TIMESTAMP FUNCTION

# | | | | |

<...>-8096 [000] 195687.878983: myprobe2: (data_store+0x0/0x30 [tl]) data=8

------------------------------------------------------------------------------------------------------------------
MORE INFO about how to use kprobe your can ref this 'Documentation/trace/kprobetrace.txt'

------------------------------------------------------------------

--------------------------跟踪一个函数和它调用的所有子函数 //
使用ftrace跟踪模块的初始化代码

//sys_init_module和sys_delete_module这两个系统调用在用户空间是怎么使用的

可以用来跟踪内核模块的初始化代码,和清除代码。

sys_init_module函数中完成模块的全部初始化工作后（包括把模块加入全局的模块列表，调用模块本身的初始化函数)，把模块状态置为MODULE_STATE_LIVE，最后，使用rmmod工具卸载模块时，会调用系统调用delete_module，会把模块的状态置为MODULE_STATE_GOING。这是模块内部维护的一个状态。

-----------------------------------------------------------------------

#echo 0 > tracing_enabled

#echo 1 > /proc/sys/kernel/ftrace_enabled

# echo function_graph > current_tracer

#echo sys_init_module > set_graph_function

#echo smp_apic_timer_interrupt > set_ftrace_notrace

#echo > trace

#echo 1 > tracing_on

#echo 1 > tracing_enabled

// #insmod your_module_name.ko

// #rmmod your_module_name

#echo 0 > tracing_enabled

--------- 找到是那个函数调用了指定的函数 // "sys_init_module" and "sys_delete_module"

#echo 0 > tracing_enabled

#echo 1 > /proc/sys/kernel/ftrace_enabled

#echo sys_init_module > set_ftrace_filter

# echo sys_delete_module >> set_ftrace_filter

# echo function > current_tracer

#echo 1 > options/func_stack_trace

#echo 1 > tracing_enabled

// insmod tl.ko

// rmmod tl

#echo 0 > tracing_enabled

# vim trace // Check the trace result

1 # tracer: function

2 #

3 # TASK-PID CPU# TIMESTAMP FUNCTION

4 # | | | | |

5 insmod-3494 [000] 852.444934: sys_init_module <-sysenter_do_call

6 insmod-3494 [000] 852.444938: <stack trace>

7 => sysenter_do_call

8 rmmod-3496 [000] 853.739722: sys_delete_module <-sysenter_do_call

9 rmmod-3496 [000] 853.739726: <stack trace>

10 => sysenter_do_call

可以看出 是 sysenter_do_call 调用了sys_init_module 和 sys_delete_module