A Linux Kernel Tracing Tutorial

A Linux Kernel Tracing Tutorial

 

Posted by Cliff Brake on 2012-01-31 | Be the First to Comment

The Linux kernel has a fairly extensive tracing infrastructure that is quite useful for debugging.  There are a number of things you can do with tracing, but the focus of this article will be the traditional printk type debugging we often end up doing to trace initialization issues with a driver.  The following links provide additional information on the linux kernel tracing infrastructure:

• http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=tree;f=Documentation/trace
• Debugging the kernel using Ftrace – part 1: http://lwn.net/Articles/365835/
• Debugging the kernel using Ftrace – part 2: http://lwn.net/Articles/366796/
• Secrets of the Ftrace function tracer: http://lwn.net/Articles/370423/
• http://elinux.org/Kernel_Trace_Systems

In this example, I am working on a new audio driver.  The typical experience with a new driver is that you install it and nothing happens because something is not registered correctly with the Linux driver model.  So, the first thing I do is start with with the platform_device_add() function in my drivers init function.  To observe the kernel activity around the kernel platform code, I can do the following:

cd /sys/kernel/debug/tracing/
echo 0 > tracing_on (keep trace from filling up until we set filter)
echo function_graph > current_tracer
echo platform* > set_ftrace_filter
echo 1 > tracing_on
cat trace_pipe (leave running in a different shell)
<insmod my driver>

After executing the above, we see the following.  For this example, trace_pipe is preferred because the trace is then emptied and only new information is shown.

0) + 30.518 us   |  platform_device_alloc();
0)               |  platform_device_add() {
0)   0.000 us    |    platform_uevent();
0) + 30.518 us   |  platform_uevent();
0)   0.000 us    |  platform_uevent();
0) + 30.518 us   |    platform_match();
0) + 30.518 us   |    platform_match();
0)   0.000 us    |    platform_match();
0)   0.000 us    |    platform_match();

...

0) + 30.518 us   |    platform_match();
0)   0.000 us    |    platform_match();
0)   0.000 us    |    platform_match();
0)   0.000 us    |    platform_match();
0)   0.000 us    |    platform_match();
0) ! 3936.767 us |  }
0) + 30.518 us   |  platform_uevent();
0) + 30.518 us   |  platform_device_alloc();

From the above, I can conclude that the platform_match() is not succeeding, because I would expect some more activity.  At this point I chose to add a printk:

diff --git a/drivers/base/platform.c b/drivers/base/platform.c
index 7a24895..f9ce0c7 100644
--- a/drivers/base/platform.c
+++ b/drivers/base/platform.c
@@ -662,6 +662,8 @@ static int platform_match(struct device *dev, struct device_driver *drv)
        struct platform_device *pdev = to_platform_device(dev);
        struct platform_driver *pdrv = to_platform_driver(drv);

+       trace_printk("pdev->name = %s, drv->name = %s", pdev->name, drv->name);
+
        /* Attempt an OF style match first */
        if (of_driver_match_device(dev, drv))
                return 1;

Now, if I re-run the trace, I see the following:

 0)               |      /* pdev->name = soc_audio, drv->name = davinci_emac */
 0)   0.000 us    |    }
 0)               |    platform_match() {
 0)               |      /* pdev->name = soc_audio, drv->name = snd-soc-dummy */
 0)   0.000 us    |    }
 0)               |    platform_match() {
 0)               |      /* pdev->name = soc_audio, drv->name = soc-audio */
 0)   0.000 us    |    }
 0)               |    platform_match() {
 0)               |      /* pdev->name = soc_audio, drv->name = omap-pcm-audio */
 0)   0.000 us    |    }
 0) ! 4241.943 us |  } /* platform_device_add */

From the above, it looks like we have a simple mismatch between “soc_audio” and “soc-audio.”  Fixing this problem, and re-installing the module, we now have:

 0)               |    platform_match() {
 0)               |      /* pdev->name = soc-audio, drv->name = snd-soc-dummy */
 0)   0.000 us    |    }
 0)               |    platform_match() {
 0)               |      /* pdev->name = soc-audio, drv->name = soc-audio */
 0)   0.000 us    |    }
 0) + 91.553 us   |    platform_drv_probe();
 0) ! 4241.943 us |  } /* platform_device_add */

Now we can see that the names match, and the probe function is now being called.  At this point, we may want to turn on tracing of some additional functions to try to determine what is happening next.

echo "platform* snd* mydriver*" > set_ftrace_filter

And the result:

 0)               |      /* pdev->name = soc-audio, drv->name = snd-soc-dummy */
 0)   0.000 us    |    }
 0)               |    platform_match() {
 0)               |      /* pdev->name = soc-audio, drv->name = soc-audio */
 0) + 30.517 us   |    }
 0)               |    platform_drv_probe() {
 0)               |      snd_soc_register_card() {
 0) + 30.518 us   |        snd_soc_instantiate_cards();
 0) ! 17852.78 us |      }
 0) ! 17883.30 us |    }
 0) ! 22125.24 us |  } /* platform_device_add */

With the above additional information, we can continue to learn more about the flow through the kernel.

While all of the above could have been done with printk’s, it would have been more time consuming.  The kernel function tracing capabilities allow us to quickly get a high level view of the flow through the kernel without manually adding a bunch of printk statements.  The kernel tracing features are completely contained in the kernel without requiring additional user space utilities which makes it very convenient to use in embedded systems.  The low overhead is also important in resource constrained embedded systems.

 

Tags: Embedded Linux,kernel, tools