Neependra

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:

$ 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

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 :-

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() {

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:-

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

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

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

I had following for the read operation

static ssize_t mycdrv1_read (struct file *file, char __user * buf, size_t lbuf, loff_t * ppos)
{
*(int *)0 = 0;
}

After inserting the module I created the character device

insmod char-read-write.ko
mknod /dev/mycdrv1 c 700 0

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

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() {

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

</pre>
$ echo sched_switch > /sys/kernel/debug/tracing/current_tracer

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

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

echo 1 > /proc/sys/kernel/stack_tracer_enabled

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

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

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.

19. December 2010 by Neependra Khare
Categories: Uncategorized | Tags: fedora, foss, ftrace, kernel | 4 comments