Kernel Dynamic Debug: Turning On pr_debug at Runtime

Most drivers already contain the debug messages you need. They are written with pr_debug() and dev_dbg(), and they are compiled in but silent. Kernel dynamic debug is the mechanism that makes them speak. Instead of adding printk() lines to a driver and rebuilding the image, you enable exactly the call sites you care about on a running system. On an embedded board where a kernel rebuild and reflash costs you twenty minutes, this is the difference between a five-minute investigation and an afternoon.

This tutorial is written for a normal x86_64 development host running a distribution kernel, but every step works the same way on an ARM board as long as the kernel was configured with dynamic debug support.

What you need

• A Linux machine with root access and the kernel headers for the running kernel installed.
• A kernel built with CONFIG_DYNAMIC_DEBUG=y.
• Basic familiarity with building an out-of-tree kernel module.

Checking that kernel dynamic debug is enabled

Two config symbols matter. CONFIG_DYNAMIC_DEBUG=y builds the catalog of debug call sites and enables the core mechanics. CONFIG_DYNAMIC_DEBUG_CORE=y enables the mechanics only and skips the catalog; it is the option used on space-constrained embedded systems, where you then add ccflags := -DDYNAMIC_DEBUG_MODULE to the Makefile of the specific modules you want to control.

raghu@techveda.org:~$ grep DYNAMIC_DEBUG /boot/config-$(uname -r)
CONFIG_DYNAMIC_DEBUG=y
CONFIG_DYNAMIC_DEBUG_CORE=y

The practical test is simpler: if the control file exists, your kernel has dynamic debug.

raghu@techveda.org:~$ sudo ls -l /proc/dynamic_debug/control
-rw-r--r-- 1 root root 0 Jul 14 09:10 /proc/dynamic_debug/control

If debugfs is enabled and mounted, the same file also appears under the mount directory, usually /sys/kernel/debug/dynamic_debug/control. If it is not mounted:

raghu@techveda.org:~$ sudo mount -t debugfs none /sys/kernel/debug

Reading the catalog

The control file is both the catalog and the command interface. Reading it lists every debug call site in the kernel and every loaded module.

raghu@techveda.org:~$ sudo head -n 4 /proc/dynamic_debug/control
# filename:lineno [module]function flags format
init/main.c:1179 [main]initcall_blacklist =_ "blacklisting initcall %s\n"
init/main.c:1218 [main]initcall_blacklisted =_ "initcall %s blacklisted\n"
init/main.c:1424 [main]run_init_process =_ "  with arguments:\n"

The third column is the flag state. =_ means no flags, that is, the call site is silent. =p means the call site is enabled and will print. That is why grep =p is the standard way to see what is currently switched on. On a freshly booted system the count is usually zero, although a distribution kernel may already have a few call sites enabled through its boot arguments.

raghu@techveda.org:~$ sudo grep '=p' /proc/dynamic_debug/control | wc -l
0

A module to experiment with

Create a directory and put this file in it as tv_dyndbg.c. The pr_fmt macro prefixes every message from this module with the module name, which is the convention used across the kernel.

#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt

#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/init.h>

static int __init tv_dyndbg_init(void)
{
	pr_info("loaded\n");
	pr_debug("init: debug print is active\n");
	pr_debug("init: enable me with 'module %s +p'\n", KBUILD_MODNAME);
	return 0;
}

static void __exit tv_dyndbg_exit(void)
{
	pr_debug("exit: unloading\n");
	pr_info("unloaded\n");
}

module_init(tv_dyndbg_init);
module_exit(tv_dyndbg_exit);

MODULE_LICENSE("GPL");
MODULE_AUTHOR("Raghu Bharadwaj");
MODULE_DESCRIPTION("Dynamic debug demonstration module");

The Makefile (the recipe lines must begin with a real tab character):

obj-m += tv_dyndbg.o

all:
	make -C /lib/modules/$(shell uname -r)/build M=$(PWD) modules

clean:
	make -C /lib/modules/$(shell uname -r)/build M=$(PWD) clean

raghu@techveda.org:~$ make
make -C /lib/modules/6.8.0-generic/build M=/home/raghu/tv_dyndbg modules
  CC [M]  /home/raghu/tv_dyndbg/tv_dyndbg.o
  MODPOST /home/raghu/tv_dyndbg/Module.symvers
  CC [M]  /home/raghu/tv_dyndbg/tv_dyndbg.mod.o
  LD [M]  /home/raghu/tv_dyndbg/tv_dyndbg.ko

Enabling the messages at runtime

Load the module first, with no debug enabled.

raghu@techveda.org:~$ sudo insmod ./tv_dyndbg.ko
raghu@techveda.org:~$ sudo dmesg | tail -n 1
[ 4210.118233] tv_dyndbg: loaded

Only the pr_info() line appeared. The two pr_debug() lines ran, but their call sites are disabled, so nothing was printed. They are now in the catalog:

raghu@techveda.org:~$ sudo grep tv_dyndbg /proc/dynamic_debug/control
/home/raghu/tv_dyndbg/tv_dyndbg.c:10 [tv_dyndbg]tv_dyndbg_init =_ "init: debug print is active\n"
/home/raghu/tv_dyndbg/tv_dyndbg.c:11 [tv_dyndbg]tv_dyndbg_init =_ "init: enable me with 'module %s +p'\n"
/home/raghu/tv_dyndbg/tv_dyndbg.c:17 [tv_dyndbg]tv_dyndbg_exit =_ "exit: unloading\n"

Enable every call site in the module. Writing to the control file needs root, so use tee rather than a shell redirect, which would be performed by your unprivileged shell.

raghu@techveda.org:~$ echo 'module tv_dyndbg +p' | sudo tee /proc/dynamic_debug/control
module tv_dyndbg +p
raghu@techveda.org:~$ sudo grep tv_dyndbg /proc/dynamic_debug/control | grep -c '=p'
3

The init function has already run, so nothing new prints yet. Unload the module and watch the exit path:

raghu@techveda.org:~$ sudo rmmod tv_dyndbg
raghu@techveda.org:~$ sudo dmesg | tail -n 2
[ 4288.901447] tv_dyndbg: exit: unloading
[ 4288.901452] tv_dyndbg: unloaded

This is the point that catches people out. Debug messages emitted during module initialisation cannot be recovered by enabling them afterwards. For those you must enable the call sites at load time.

Enabling debug at module load and at boot

Every module tacitly accepts a dyndbg parameter, whether or not it defines one. It is handled by the dynamic debug code, not by the module, and it does not appear under /sys/module/<name>/parameters/.

raghu@techveda.org:~$ sudo insmod ./tv_dyndbg.ko dyndbg=+p
raghu@techveda.org:~$ sudo dmesg | tail -n 3
[ 4351.442810] tv_dyndbg: loaded
[ 4351.442814] tv_dyndbg: init: debug print is active
[ 4351.442815] tv_dyndbg: init: enable me with 'module tv_dyndbg +p'

The same parameter works with modprobe, in /etc/modprobe.d/*.conf as options tv_dyndbg dyndbg=+p, and on the kernel command line as tv_dyndbg.dyndbg="+p". When it is given as module.dyndbg="QUERY", the query must not repeat module tv_dyndbg — the module name is taken from the parameter name.

For built-in code that runs long before userspace exists, use the bare dyndbg= boot parameter. This is how you get debug output from a subsystem that initialises during boot, for example an I2C or PCI controller driver that is failing before the root filesystem is mounted:

dyndbg="file drivers/i2c/busses/i2c-imx.c +p"

Add ignore_loglevel to the command line if the messages are reaching the log but not the console. Debug messages are KERN_DEBUG, and the default console loglevel usually filters them out. They are still visible with dmesg.

Writing more precise queries

Enabling a whole module is a blunt instrument. A busy driver can fill the log and change the timing of the very problem you are chasing. The query language lets you narrow the selection. A query is a set of match specifications followed by a flag change, and all the match specifications are combined with a logical AND.

• func <name> — match the function name, wildcards allowed, for example func *probe*.
• file <path> — match the source file, either the basename or the path relative to the source root, for example file drivers/usb/*.
• module <name> — match the module name as it appears in lsmod.
• format <string> — match any part of the format string of the message.
• line <n> or line <n>-<m> — match a line or a range. The range must not contain spaces.
• class <name> — match a class name declared by the module, for example the DRM debug categories. Wildcards are not supported for class names.

The flag change is + to add flags, - to remove them, and = to set them exactly. The flag p enables the call site. The remaining flags are decorators that add to the message prefix: t for the thread ID, m for the module name, f for the function name, s for the source file, l for the line number, and d for a call trace. =_ clears everything.

raghu@techveda.org:~$ echo 'file tv_dyndbg.c line 10-11 +pfl' | sudo tee /proc/dynamic_debug/control
raghu@techveda.org:~$ echo 'func *probe* module i2c_imx +p' | sudo tee /proc/dynamic_debug/control
raghu@techveda.org:~$ echo 'format "SETATTR" +p' | sudo tee /proc/dynamic_debug/control

Several queries can be written in one go, separated by a semicolon. A common pattern is to clear everything and then enable one narrow set, so that the state of the system is known:

raghu@techveda.org:~$ echo '-p; module tv_dyndbg func tv_dyndbg_exit +pf' | sudo tee /proc/dynamic_debug/control

If a query is rejected, the reason is printed to the kernel log, and the write returns EINVAL. Check dmesg for a line beginning with dyndbg: before assuming the mechanism is broken.

Turning it off again

Leaving debug call sites enabled on a device that is going back into a test rack is a real cost: the log fills up, and timing-sensitive code behaves differently. Disable what you enabled.

raghu@techveda.org:~$ echo 'module tv_dyndbg -p' | sudo tee /proc/dynamic_debug/control
raghu@techveda.org:~$ sudo rmmod tv_dyndbg
raghu@techveda.org:~$ sudo grep -c tv_dyndbg /proc/dynamic_debug/control
0

Once the module is unloaded its call sites leave the catalog. Settings applied through the boot parameter, and messages that were enabled at compile time with -DDEBUG, can also be switched off through the control file once the system is up.

Dynamic debug is one of the first tools we put in front of engineers on the Linux device drivers course, because it changes how a driver problem is approached: read the messages the author already wrote before adding your own.

Key takeaways

• Kernel dynamic debug controls pr_debug(), dev_dbg(), print_hex_dump_debug() and print_hex_dump_bytes() call sites at runtime.
• The control file is /proc/dynamic_debug/control, and also appears under debugfs when that is mounted.
• =p in the third column means enabled; =_ means silent.
• Messages printed during module initialisation need dyndbg=+p at load time, or a module.dyndbg= boot parameter.
• Narrow the query with func, file, line, format or class instead of enabling an entire module.
• Add ignore_loglevel if the messages appear in dmesg but not on the console.

Frequently asked questions

Do I need to rebuild the kernel to use dynamic debug?
No, provided the kernel was configured with CONFIG_DYNAMIC_DEBUG=y. The debug call sites are already compiled in and are switched on by writing a query to the control file.

Why do my module’s initialisation debug messages not appear when I enable them afterwards?
Because the init function has already run by the time you write to the control file. Load the module with insmod ./module.ko dyndbg=+p, or pass module.dyndbg="+p" on the kernel command line, so the call sites are enabled before the code executes.

The control file shows =p but I see nothing on my serial console.
Debug messages are at KERN_DEBUG, which the default console loglevel usually filters. The messages are still in the kernel log, so check dmesg, and add ignore_loglevel or raise loglevel= on the kernel command line if you need them on the console.

How do I enable debug for one function instead of a whole driver?
Use a narrower query, for example echo 'module i2c_imx func *probe* +p' written to the control file. All match specifications in a query are combined with a logical AND.

Further reading

• Dynamic debug — Linux kernel documentation (admin-guide)
• The kernel’s command-line parameters — Linux kernel documentation