Debugging kernel with dynamic debug
Dynamic debug is a great feature for kernel debugging, kernel must be
compiled with CONFIG_DYNAMIC_DEBUG option, if it was enabled, all pr_debug(),
dev_dbg(), netdev_dbg() and friends can be enabled when needed, to see if kernel
support this, checkout with:
# cat /proc/config.gz | gunzip | grep DYNAMIC_DEBUG
CONFIG_DYNAMIC_DEBUG=y
With dyndbg enabled the kernel image size is slightly bigger than before:
-rwxrwxrwx 1 root root 20148736 2019-08-02 23:13 kernel8.img
-rwxrwxrwx 1 root root 19393024 2019-08-02 23:08 kernel8.img.orig
Enable/disable Dynamic Debug Messages
Debug messages can be enabled/disabled per-callsite by echoing control string to
/sys/kernel/debug/dynamic_debug/control, for example, we want to debug network
card module driver lan78xx, by issue the follow command, all debug messages in
file lan78xx.c will be enabled if the message is print with netdev_dbg:
echo 'file lan78xx.c +p' > /sys/kernel/debug/dynamic_debug/control
When the network disconnected or connected, there will be the following message respectively:
# disconnected
[ 285.446634] lan78xx 1-1.1.1:1.0 eth0: PHY INTR: 0x00020000
[ 285.465333] lan78xx 1-1.1.1:1.0 eth0: receive multicast hash filter
[ 285.471837] lan78xx 1-1.1.1:1.0 eth0: deferred multicast write 0x00007ca2
[ 285.485631] lan78xx 1-1.1.1:1.0 eth0: receive multicast hash filter
[ 285.495886] lan78xx 1-1.1.1:1.0 eth0: receive multicast hash filter
[ 285.502655] lan78xx 1-1.1.1:1.0 eth0: receive multicast hash filter
[ 285.539599] lan78xx 1-1.1.1:1.0 eth0: deferred multicast write 0x00007ca2
# connected
[ 286.470634] lan78xx 1-1.1.1:1.0 eth0: PHY INTR: 0x00020000
[ 286.487174] lan78xx 1-1.1.1:1.0 eth0: speed: 100 duplex: 1 anadv: 0x05e1 anlpa: 0x45e1
[ 286.495317] lan78xx 1-1.1.1:1.0 eth0: rx pause enabled, tx pause enabled
[ 286.523117] lan78xx 1-1.1.1:1.0 eth0: receive multicast hash filter
[ 286.529662] lan78xx 1-1.1.1:1.0 eth0: deferred multicast write 0x00007ca2
[ 286.534029] lan78xx 1-1.1.1:1.0 eth0: receive multicast hash filter
[ 286.573682] lan78xx 1-1.1.1:1.0 eth0: deferred multicast write 0x00007ca2
[ 286.597377] lan78xx 1-1.1.1:1.0 eth0: receive multicast hash filter
[ 286.604773] lan78xx 1-1.1.1:1.0 eth0: receive multicast hash filter
[ 286.634334] lan78xx 1-1.1.1:1.0 eth0: deferred multicast write 0x00007ca2
You should change kernel message level to see the above messages either by dmesg
-n 8 or echo 8 > /proc/sys/kernel/printk.
To disable the dynamic debug message just replace the + symbol with -.
List Dynamic Debug Messages
Do cat on file /sys/kernel/debug/dynamic_debug/control will show a full list of dynamic debug messages, here is a part of them, first line shows the format:
# cat /sys/kernel/debug/dynamic_debug/control
# filename:lineno [module]function flags format
init/main.c:743 [main]initcall_blacklist =p "blacklisting initcall %s\012"
init/main.c:774 [main]initcall_blacklisted =p "initcall %s blacklisted\012"
...
lib/kobject_uevent.c:372 [kobject_uevent]kobject_uevent_env =_ "kobject: '%s' (%p): %s: uevent_suppress caused the event to drop!\012"
lib/kobject_uevent.c:380 [kobject_uevent]kobject_uevent_env =_ "kobject: '%s' (%p): %s: filter function caused the event to drop!\012"
lib/kobject_uevent.c:392 [kobject_uevent]kobject_uevent_env =_ "kobject: '%s' (%p): %s: unset subsystem caused the event to drop!\012"
lib/kobject_uevent.c:434 [kobject_uevent]kobject_uevent_env =_ "kobject: '%s' (%p): %s: uevent() returned %d\012"
There are two types of flags in the above entries, here is the meaning of them:
| p | enables the pr_debug() callsite. |
| f | Include the function name in the printed message |
| l | Include line number in the printed message |
| m | Include module name in the printed message |
| t | Include thread ID in messages not generated from interrupt context |
| _ | No flags are set. (Or’d with others on input) |
So we can search all the currently enabled messages by issuing:
# awk '$3 != "=_"' /sys/kernel/debug/dynamic_debug/control
# filename:lineno [module]function flags format
init/main.c:743 [main]initcall_blacklist =p "blacklisting initcall %s\012"
init/main.c:774 [main]initcall_blacklisted =p "initcall %s blacklisted\012"
mm/cma.c:259 [cma]cma_declare_contiguous =p "%s(size %pa, base %pa, limit %pa alignment %pa)\012"
mm/cma.c:418 [cma]cma_alloc =p "%s(cma %p, count %zu, align %d)\012"
mm/cma.c:463 [cma]cma_alloc =p "%s(): memory range at %p is busy, retrying\012"
mm/cma.c:476 [cma]cma_alloc =p "%s(): returned %p\012"
mm/cma.c:497 [cma]cma_release =p "%s(page %p)\012"
drivers/base/dma-contiguous.c:56 [dma_contiguous]early_cma =p "%s(%s)\012"
drivers/base/dma-contiguous.c:114 [dma_contiguous]dma_contiguous_reserve =p "%s(limit %08lx)\012"
drivers/base/dma-contiguous.c:136 [dma_contiguous]dma_contiguous_reserve =p "%s: reserving %ld MiB for global area\012"
Dynamic Debug Enabling During Boot Process
Dynamic debug can be enabled at boot time via kernel bootargs, for rpi 3B, add it to cmdline.txt, add below to enable network module driver:
dyndbg='file lan78xx.c +p'
Enable Dynamic Debug at Load Time
If the module driver was built as a ko, then pass dyndbg as parameter when doing insmod:
insmod lan78xx.ko dyndbg==pmf
The following example also applies, if you do not care much about the module init part.
Examples
// enable all the messages in file lan78xx.c
echo -n 'file lan78xx.c +p' > /sys/kernel/debug/dynamic_debug/control
// enable the message at line 1155 of file lan78xx.c
# echo -n 'file lan78xx.c line 1155 +p' >
/sys/kernel/debug/dynamic_debug/control
// enable all the messages in the lan78xx module
# echo -n 'module lan78xx +p' >
/sys/kernel/debug/dynamic_debug/control
// enable all the messages between line 1000 and 2000 in the lan78xx module
# echo -n 'module lan78xx line 1000-2000 +p' >
/sys/kernel/debug/dynamic_debug/control
// enable all the messages before line 2000 in the lan78xx module
# echo -n 'module lan78xx line -2000 +p' >
/sys/kernel/debug/dynamic_debug/control
// enable all the messages after line 1000 in the lan78xx module
# echo -n 'module lan78xx line 1000- +p' >
/sys/kernel/debug/dynamic_debug/control
// enable all messages in the function lan78xx_tx_bh()
# echo -n 'func lan78xx_tx_bh +p' >
/sys/kernel/debug/dynamic_debug/control
// disable all messages in the function lan78xx_tx_bh()
# echo -n 'func lan78xx_tx_bh -p' >
/sys/kernel/debug/dynamic_debug/control
// enable messages that format contains specified string
# echo -n 'format "receive multicast hash filter" +p' >
/sys/kernel/debug/dynamic_debug/control
// enable messages in files of which the paths include string "usb"
# echo -n 'file *usb* +p' > /sys/kernel/debug/dynamic_debug/control
// enable all message in files under specific directory
# echo -n 'file drivers/usb/* +p' >
/sys/kernel/debug/dynamic_debug/control
// enable all messages
# echo -n '+p' > /sys/kernel/debug/dynamic_debug/control
// add module, function to all supported messages (listed in control)
# echo -n '+mf' > /sys/kernel/debug/dynamic_debug/control
// multiple enablement separated by ';' or '\n'
# echo -n 'func lan78xx_tx_bh +p; format "receive multicast hash filter" +p' >
/sys/kernel/debug/dynamic_debug/control
// multiple enablement with batch file
# cat query-batch-file
func lan78xx_tx_bh +p
format "receive multicast hash filter" +
# cat query-batch-file > /sys/kernel/debug/dynamic_debug/control
Performance
The author of dynamic debug Jason has presented a performance benchmark, tested
against an Intel quad core machine running at 1.6 GHz with tbench, the result
show the cost is negligible with CONFIG_DYNAMIC_DEBUG configured but none of
the debug statement enabled:
| test case | tbench throughput |
| CONFIG_DYNAMIC_DEBUG disabled | 773.054 MB/sec |
| CONFIG_DYNAMIC_DEBUG enabled | 773.913 MB/sec |
| CONFIG_DYNAMIC_DEBUG enabled and all debug statements enabled | 79.664 MB/sec |
Kernel doc correction
There is an error in dynamic debug howto’s example section, an error message shown
below when I am trying echo -n '*usb* +p' > <debugfs>/dynamic_debug/control:
[ 772.355613] dynamic_debug:ddebug_parse_query: expecting pairs of match-spec <value>
[ 772.363611] dynamic_debug:ddebug_exec_query: query parse failed
I think this should be an error, it missing the keyword as expected in the Command
Language Reference section:
match-spec ::= 'func' string |
'file' string |
'module' string |
'format' string |
'line' line-range
line-range ::= lineno |
'-'lineno |
lineno'-' |
lineno'-'lineno
lineno ::= unsigned-int