LWN.net Logo

The dynamic debugging interface

By Jonathan Corbet
March 22, 2011
The kernel's "dynamic debugging" interface saw some minor changes for 2.6.39. As it happens, LWN has never written about how dynamic debug works, so this seems like an opportune time to fill in the gap.

It can be nice to instrument kernel code with abundant print statements that illustrate what is going on inside. The problem, of course, is that those statements can generate vast amounts of output which is usually not of interest. These statements can be left commented out most of the time, but that leads to situations where an edit/rebuild/reboot cycle is needed to get the output. In response, many developers have created mechanisms which enable or disable specific print statements at run time. The dynamic debugging interface was added as a way of providing a uniform control interface for debugging output while avoiding cluttering the kernel with various hand-rolled alternatives.

Dynamic debug operates on print statements written with either of:

    pr_debug(char *format, ...);
    dev_dbg(struct device *dev, char *format, ...);

If the CONFIG_DYNAMIC_DEBUG option is not set, the above functions will be turned into normal printk() statements at the KERN_DEBUG level. If the option is enabled, though, the code sets aside a special descriptor for every call site, noting the module, function, and file names, along with the line number and format string. At system boot, all of these debug statements are turned off, so their output will not appear even if debug-level kernel messages are routed somewhere useful by the syslog daemon.

Turning on dynamic debug causes a new virtual file to appear at /sys/kernel/debug/dynamic_debug/control (modulo any individual preferences for the location of debugfs, naturally). Writing to that file will enable or disable specific debugging functions, as specified by a simple but flexible language.

As an example, drivers/char/tpm/tpm_nsc.c contains the following code at line 346:

    dev_dbg(&pdev->dev, "NSC TPM detected\n");

Turning on that specific line could be done with a line like:

    echo file tpm_nsc.c line 346 +p > .../dynamic_debug/control

(Where the full path to debugfs has been replaced with "..."). As it happens, that dev_dbg() line does not stand alone - there is a long series of them providing information on the newly-detected device. One could enter a series of lines like the above to enable them all individually, but either of the following would also work:

    echo file tpm_nsc.c line 346-373 +p > .../dynamic_debug/control
    echo file tpm_nsc.c function init_nsc +p > .../dynamic_debug/control

Along with selection by file name, line number, and function name, the interface also allows "module name" to select a specific module, and "format fmt" to select any line whose format string contains "fmt". If more than one selector is given, all must match for a given statement to be enabled.

Commands to the control file must end with a "flags" operation telling the system what to do; "+p" turns on printk() output, while "-p" turns it off. There is also a set of flags (new for 2.6.39) controlling information added to each output line: "f" adds the function name, "l" adds the line number, "m" adds the module name, and "t" adds the thread ID. One can use "=" to set the full mask of flags to a specific value - "=plm" will enable printing with line numbers and module names while disabling thread ID and function output regardless of their prior setting. The only way to clear all of the flags is with "-pflmt".

Reading the control file will produce a list of all currently-enabled call sites.

Sometimes the interesting action happens before the system reaches a point where the control file can be accessed. Dynamic debug output can be turned on early in the boot process with the ddebug_query boot parameter.

More information on how to use this facility can be found in Documentation/dynamic-debug-howto.txt. Dynamic debug has been in the kernel since 2.6.30, but it is still common to see code submitted which contains its own, home-brewed mechanism for controlling debug output. Chances are that reviewers will ask for such mechanisms to be taken out before the code is merged. Given the flexibility and ease of use of the in-kernel implementation, it makes sense to use it from the beginning.


(Log in to post comments)

Thanks Jon!

Posted Mar 24, 2011 2:12 UTC (Thu) by pflugstad (subscriber, #224) [Link]

Once again my LWN subscription has paid for itself in saving me hours of time.

I was debugging some code a few weeks ago and wished I understood how this stuff worked, but was too pressed to figure it out, so I resorted to printk's which I then had to comment out when done. Time to go back and retrofit that code with dev_dbg statements.

Thanks Jon!!!

Thanks Jon!

Posted Mar 24, 2011 9:35 UTC (Thu) by rvfh (subscriber, #31018) [Link]

Same here. Now considering having my company apply for a global subscription (but I shall keep mine as well, no worries!) Is that possible?

Company subscriptions

Posted Mar 24, 2011 13:08 UTC (Thu) by corbet (editor, #1) [Link]

Of course company subscriptions are possible! Some basic information can be found on the group subscription page; we'd love to have your company join the list.

Company subscriptions

Posted Apr 11, 2011 16:23 UTC (Mon) by rvfh (subscriber, #31018) [Link]

Apparently my manager managed to get it approved. Hurray!

Thanks Jon!

Posted Mar 24, 2011 15:10 UTC (Thu) by nix (subscriber, #2304) [Link]

Strongly seconded. I've been wishing for something like this, and somehow never realised that it was already here.

The dynamic debugging interface

Posted Mar 24, 2011 18:24 UTC (Thu) by daney (subscriber, #24551) [Link]

It might be worth mentioning that systems that support the jump_label feature (x86, sparc, mips with GCC-4.5 or later), that the dynamic degugging makes use of dynamic code patching. The result is that for disabled printks, the overhead is quite low.

The dynamic debugging interface

Posted Mar 24, 2011 22:35 UTC (Thu) by giraffedata (subscriber, #1954) [Link]

What does the struct device * argument mean?

I read the Documentation/ file, and didn't find it there either.

The dynamic debugging interface

Posted Mar 24, 2011 23:21 UTC (Thu) by gregkh (subscriber, #8) [Link]

It's the pointer to the 'struct device' that this message corresponds to.

The dynamic debugging interface

Posted Mar 24, 2011 23:34 UTC (Thu) by giraffedata (subscriber, #1954) [Link]

OK, and what if anything does that affect practically? Message content? Filtering?

struct device

Posted Mar 25, 2011 0:02 UTC (Fri) by corbet (editor, #1) [Link]

dev_dbg() (dev_printk(), really) uses the device pointer to add the name of the actual device to the output. That way we get standardized device-related message formats with information that, hopefully, is useful to the system admin.

#define DEBUG

Posted Mar 27, 2011 19:47 UTC (Sun) by tardyp (subscriber, #58715) [Link]

> If the CONFIG_DYNAMIC_DEBUG option is not set, the above functions will be turned
> into normal printk() statements at the KERN_DEBUG level.

this, only if DEBUG is defined... see source code:
http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-...

Usually people type #define DEBUG at beginning of file.
Some subsystems add -DDEBUG for their files if CONFIG_[SUBSYSTEM]_DEBUG is set.

The dynamic debugging interface

Posted Mar 28, 2011 2:15 UTC (Mon) by jcm (subscriber, #18262) [Link]

Random tangent related to debugging. I was writing the latest LKML podcast and noticed the lack of docs on USB target debug. Perhaps you'd like to write about that too, sometime, Jon?

For example, using this cable:

http://www.semiconductorstore.com/cart/pc/viewPrd.asp?idp...

It's possible to do target-target debug with USB DebugPort for $89. Andi Kleen and Mark Lord put me onto this, but I'm sure many others don't know how easy it is to debug e.g. laptops this way.

Just thought I'd mention it.

The dynamic debugging interface

Posted Apr 5, 2011 19:04 UTC (Tue) by jwessel (guest, #63702) [Link]

Speaking as the person who re-wrote the majority of ehci debug port code, what further documentation are you interested in?

It does appear we might be missing an addendum to the documentation to explain about all the different uses of the USB debug port dongle. In recent kernels you can use a USB debug port for early_printk, kdb, kgdb, or even a system level serial console, which has support for sysrq. There is a mention of the configuration arguments in the kernel-parameters.txt, but that doesn't cover anything about the useful ways to use the device.

The document in the kernel which describes the device definitely doesn't seem to elaborate on all that you can do with the device.

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-...

Jason.

The dynamic debugging interface

Posted May 6, 2011 20:38 UTC (Fri) by monster (guest, #74760) [Link]

How and when is the control file created? If I load a kernel module which wasn't available at boot time, how to I update the control file to include the new module and the location of its source code?

The dynamic debugging interface

Posted Apr 9, 2012 23:46 UTC (Mon) by yoduh (guest, #38527) [Link]

RE: How and when is the control file created? If I load a kernel module which wasn't available at boot time, how to I update the control file to include the new module and the location of its source code?

A year late, and youve probably found it, but:

The control file is automatically created if youre mounting dbgfs, appears in <dbgmountpt>/dynamic_debug/control. It contains a line for every pr_debug(etc) call in the kernel and its modules, when you modprobe another, its pr_debug() calls appear too.

Copyright © 2011, Eklektix, Inc.
Comments and public postings are copyrighted by their creators.
Linux is a registered trademark of Linus Torvalds