Wednesday, April 1, 2015

Tracing Linux kernel function entries/returns

Here is a neat ftrace recipe for tracing execution while the Linux kernel is inside a particular function.  This helps when a kernel function or its children are failing but you don't know where or why.

ftrace will trigger on particular functions if you give it  set_graph_function values.  That way you only see traces from the functions you are interested in.  This eliminates the noise you get when tracing all function entries/returns without a filter.

Let's trace virtio_dev_probe() and all its children:

echo virtio_dev_probe >/sys/kernel/debug/tracing/set_graph_function
echo function_graph >/sys/kernel/debug/tracing/current_tracer
echo 1 >/sys/kernel/debug/tracing/tracing_on

modprobe transport_virtio

echo 0 >/sys/kernel/debug/tracing/tracing_on
echo >/sys/kernel/debug/tracing/current_tracer
echo >/sys/kernel/debug/tracing/set_graph_function
cat /sys/kernel/debug/tracing/trace

Here is some example output:

...
 0)               |        virtqueue_kick [virtio_ring]() {
 0) + 30.207 us   |          virtqueue_kick_prepare [virtio_ring]();
 0) + 13.342 us   |          vp_notify [virtio_pci]();
 0) + 90.315 us   |        }
 0) # 61946.45 us |      }
 0)   1.046 us    |      mutex_unlock();
 0) # 102833.9 us |    }
 0)   2.411 us    |    vp_get_status [virtio_pci]();
 0)   0.826 us    |    vp_get_status [virtio_pci]();
 0) ! 130.773 us  |    vp_set_status [virtio_pci]();
 0)               |    virtio_config_enable [virtio]() {
 0)   0.689 us    |      _raw_spin_lock_irq();
 0) + 33.796 us   |    }
 0) # 105349.9 us |  }

I haven't figured out whether set_graph_function can be used on functions whose kernel module has not been loaded yet.  I think the answer is no, but please let me know in the comments if there is a way to do it.