Ftrace: Fedora Mini-Conf Session at FOSS.in’10

I gave a talk on Ftrace in Fedora Mini-Conf  at FOSS.in’10.

The slides are at https://fedoraproject.org/wiki/File:Fedora_Ftrace.pdf

I started my presentation with an example. I setup function_ftrace as  current_tracer and set

the trace filter for all the ext3 functions and started the tracing:

[sourcecode language=”text” gutter=”false”]

$ echo function_ftrace > /sys/kernel/debug/tracing/current_tracer

$ echo ext3* > /sys/kernel/debug/tracing/set_ftrace_filter

$ echo 1  > /sys/kernel/debug/tracing/tracing_on

[/sourcecode]

Then after creating a ext3 filesystem, I created a directory on it.

We got a trace in the /sys/kernel/debug/tracing/trace file. A snippet from it :-

[sourcecode language=”text” gutter=”false”]
1) ! 23988.06 us |    } /* ext3_new_inode */
1)                         |    ext3_bread() {
1)                         |      ext3_getblk() {
1)                         |        ext3_get_blocks_handle() {
1)   0.461 us              |          ext3_block_to_path();
1)   0.365 us              |          ext3_get_branch();
1)                         |          ext3_new_blocks() {
1)                         |            ext3_dirty_inode() {
1)   0.602 us              |              ext3_journal_start_sb();
1)                         |              ext3_mark_inode_dirty() {
1)                         |                ext3_reserve_inode_write() {
[/sourcecode]

This kind of stuff helps when you try to understand the kernel code because you know what functions are getting called.

Second example I took to get the function trace when the system system OOPs. I did following setting to get the trace:-

[sourcecode language=”text” gutter=”false”]
echo function_graph > /sys/kernel/debug/tracing/current_tracer
echo 5 > /sys/kernel/debug/tracing/buffer_size_kb
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo 1 > /proc/sys/kernel/ftrace_dump_on_oops
[/sourcecode]

I used one  simple character driver for that. It can be downloaded from

http://wp.neependra.net/kernel/char-dev-read-write-oop.tar.gz

I had following for the read operation

[sourcecode language=”cpp” gutter=”false”]
static ssize_t mycdrv1_read (struct file *file, char __user * buf, size_t lbuf, loff_t * ppos)
{
*(int *)0 = 0;
}
[/sourcecode]

After inserting the module I created the character device

[sourcecode language=”text” gutter=”false”]
insmod char-read-write.ko
mknod /dev/mycdrv1 c 700 0

[/sourcecode]

Just after doing the read to the device OOPs happened and got  following in the in the /var/log/messages file

[sourcecode language=”text” gutter=”false”]
mycdrv1_read() {
raw_local_irq_enable();
………..
find_vma();
bad_area() {
up_read();
…………
is_prefetch.clone.13() {
convert_ip_to_linear();
pagefault_disable();
pagefault_enable();
}
oops_enter() {
[/sourcecode]

Then I showed an example with sched_switch tracer and showed how we can trace all the function of a particular module.

[sourcecode language=”text” gutter=”false”]</pre>
$ echo sched_switch > /sys/kernel/debug/tracing/current_tracer

$ echo :mod:zfs > /sys/kernel/debug/tracing/set_ftrace_filter
[/sourcecode]

I also also showed how to look at the stack usage.  To enable stack strace

[sourcecode language=”text” gutter=”false”]
echo 1 > /proc/sys/kernel/stack_tracer_enabled
[/sourcecode]

and  look at /sys/kernel/debug/tracing/stack_trace file, which will have something like.

[sourcecode language=”text” gutter=”false”]
Depth    Size   Location    (15 entries)
—–    —-   ——–
0)     1544     352   ext3_get_blocks_handle+0xa0/0x920
1)     1192       0   return_to_handler+0x0/0x2f
2)     1192      96   ext3_get_block+0xbb/0xf8
3)     1096       0   return_to_handler+0x0/0x2f
4)     1096     128   generic_block_bmap+0x3c/0x42
[/sourcecode]

It tells you how much kernel stack is used and usage from  each function. This was very helpful for me while doing the port

of ZFS on Linux. We have limited kernel stack on Linux but this not the case in Solaris.

I then talked about trace-cmd and kernelshark.