Skip to main content

3.3 Debugging with printk

You might think sending a debug message to the kernel log is simple—just fire off a printk at KERN_DEBUG level. Your intuition isn't wrong, but reality is far more complex.

In the eyes of kernel developers, printk is just the tip of the iceberg. The real power tools are pr_debug() and dev_dbg(). When the kernel's "dynamic debug" feature is enabled, these two macros are no longer simple print statements—they become controllable debug switches. We'll see just how powerful this feature is in later chapters.

But before diving into that "killer" feature, we need to solidify the basics: how do we correctly issue a debug print? What advanced techniques can double our debugging efficiency?

Basic Debug Printing: pr_debug and pr_devel​

Going back to the printk_loglevels kernel module from the previous section, you might have noticed these two lines:

pr_debug("Hello, debug world @ log-level KERN_DEBUG   [%d]\n", LOGLEVEL_DEBUG);
pr_devel("Hello, debug world via the pr_devel() macro (eff @ KERN_DEBUG) [%d]\n", LOGLEVEL_DEBUG);

These two macros look similar, and they do both send messages to the kernel log at KERN_DEBUG level. But there's a massive prerequisite: they only actually output anything when the DEBUG symbol is defined at compile time; otherwise, they're like thin air—completely silent.

This is exactly what we want:

  • During development, define DEBUG, and the messages flood in.
  • For release, remove DEBUG, and the kernel stays quiet. The binary won't even retain traces of these strings.

⚠️ Warning The pr_devel() macro is primarily intended for in-kernel development. Module authors should prefer using pr_debug(). The design intent of pr_devel() is that these messages should never appear in a production environment.

Where is that DEBUG symbol defined?​

If you scour the source code but can't find the definition of DEBUG, don't panic. It's usually not in the code itself, but in the Makefile.

Open the Makefile for our example module, and the answer is right there (key parts highlighted):

$ cd ch3/printk_loglevels ; cat Makefile
[ ... ]
FNAME_C := printk_loglevels
PWD            := $(shell pwd)
obj-m          += ${FNAME_C}.o
# EXTRA_CFLAGS deprecated; use ccflags-y
  ccflags-y   += -DDEBUG -g -ggdb -gdwarf-4 -Og -Wall -fno-omit-frame-pointer -fvar-tracking-assignments
[ ... ]

Look at this line: ccflags-y += -DDEBUG ....

  • -DDEBUG: tells the compiler, "define the DEBUG symbol."
  • -UDEBUG: conversely, if you see this, it means "undefine DEBUG."

This is the switch. When you're ready to release the module, just remove -DDEBUG, or control it through a variable (like MYDEBUG) as I did in the Makefile.

Debug Build vs. Production Build​

Here's an easy trap to fall into.

How your module is built depends heavily on the DEBUG_CFLAGS in the kernel's top-level Makefile. This variable's value, in turn, relies on the kernel configuration option CONFIG_DEBUG_INFO.

  • On a debug kernel: If you're booting a kernel with debug info enabled, compiling the module will automatically include various symbol information, KASAN instrumentation, and more.
  • On a production kernel: If you build against a production kernel, all of that gets stripped out.

The data doesn't lie. For the same printk_loglevels.ko:

  • Built on a debug kernel: 221 KB.
  • Built on a production kernel: less than 8 KB! (The massive size difference comes from the stripped debug symbols and instrumentation.)

💡 Tip

  • make V=1: Want to see exactly what parameters are being passed to the compiler? Run this command—it's incredibly informative.

  • readelf: Want to confirm what debug information your module actually carries? Take a look with this tool:

    readelf --debug-dump <module_dbg.ko> | grep producer

    (Note: In a cross-compilation environment, remember to use the ${CROSS_COMPILE}readelf from your toolchain.)

A Driver Developer's Favorite: dev_dbg()​

Now, suppose you're writing a real device driver.

There's a golden rule: stop using pr_debug(), use dev_dbg().

Why? The first argument to dev_dbg() is a struct device *dev. This pointer doesn't just tell the kernel which device is speaking—it also automatically attaches context like the device name and bus information to the log. This is a lifesaver in systems with multiple devices of the same type.

Take the SSD1307 OLED screen driver in the kernel as an example (these screens are typically connected via an I2C bus):

// drivers/video/fbdev/ssd1307fb.c
static int ssd1307fb_init(struct ssd1307fb_par *par)
{
  [...]
        /* Enable the PWM */
        pwm_enable(par->pwm);
        dev_dbg(&par->client->dev, "Using PWM%d with a %lluns period.\n",
            par->pwm->pwm, pwm_get_period(par->pwm));
}

See? par->client->dev is the device pointer. The log will naturally include information about "this I2C device."

Here's another real example from the kernel's network block device driver:

// drivers/block/nbd.c
dev_dbg(nbd_to_dev(nbd), "request %p: got reply\n", req);

Here, nbd_to_dev() is an inline function specifically designed to extract the embedded device structure pointer from a nbd_device structure.

⚠️ Emphasis Again When writing drivers, replace all your pr_*() calls with their dev_*() counterparts: dev_emerg(), dev_err(), dev_warn(), dev_notice(), dev_info(), dev_dbg().

The "Closed Door" in Production​

Let's run an experiment. Boot up the "hardcore" production kernel we built in Chapter 1, and try loading that debug module:

# make
[...]
# dmesg -C; insmod ./printk_loglevels.ko ; dmesg
insmod: ERROR: could not insert module ./printk_loglevels.ko: Operation not permitted
[ 1933.232266] Lockdown: insmod: unsigned module loading is restricted; see man kernel_lockdown.7

It crashed.

This isn't your fault—our production kernel has Lockdown mode enabled (kernel security lockdown). Starting from kernel 5.4, if CONFIG_SECURITY_LOCKDOWN_LSM=y is enabled, no unsigned module can be loaded—don't even think about it.

This is also why we can't even test on a production kernel. To break the deadlock, we either need to properly sign the module (see kernel documentation Documentation/admin-guide/module-signing.html), or (strictly for debugging) turn off these security restrictions.

Don't forget: The kernel documentation contains a detailed explanation of lockdown; see man kernel_lockdown.7.

The Log Flood Crisis: printk's Rate Limiting​

Debug prints are great, but don't overdo it.

Imagine you put a dev_dbg() in your driver, and it happens to sit on a high-frequency execution path (like an interrupt handler or a timer callback). What are the consequences?

  • Kernel ring buffer overflow: The buffer is only a few dozen to a few hundred KB. It gets instantly flooded, old logs get overwritten, and useful information is lost.
  • System livelock: Serial output is so slow that the CPU spends all its effort printing characters, causing the system to become sluggish or completely freeze.
  • Log spam: The same error gets printed ten thousand times, which doesn't help solve the problem at all.

You might see systemd complaining: /dev/kmsg buffer overrun, some messages lost.

To solve this self-inflicted problem, the kernel community came up with Rate Limiting.

How to Rate Limit?​

The kernel provides two key /proc interfaces to control the thresholds:

  1. /proc/sys/kernel/printk_ratelimit

    • Meaning: The minimum time required between two outputs (unit: jiffies, usually a few seconds).
    • Default value: 5 (seconds). Setting it to 0 disables rate limiting.

  2. /proc/sys/kernel/printk_ratelimit_burst

    • Meaning: The number of messages allowed to "burst" in a short window before rate limiting kicks in.
    • Default value: 10.

Simply put: within 5 seconds, you can burst at most 10 messages. Exceed that number? Everything after gets dropped until the next 5-second window.

Let's see how to use it. The kernel provides these ready-made macros (remember to include <linux/kernel.h>):

  • pr_*_ratelimited(): corresponds to pr_info, pr_err, etc.
  • dev_*_ratelimited(): corresponds to dev_info, dev_err, etc.

⚠️ Warning Never use printk_ratelimited() directly—the kernel documentation explicitly warns against this. Use the wrapper macros.

Rate Limiting in Action​

Let's write a simple module to verify this (only key parts shown):

// ch3/ratelimit_test/ratelimit_test.c
#define pr_fmt(fmt) "%s:%s():%d: " fmt, KBUILD_MODNAME, __func__, __LINE__
[…]
#include <linux/kernel.h>
#include <linux/delay.h>

static int num_burst_prints = 7;
module_param(num_burst_prints, int, 0644);
MODULE_PARM_DESC(num_burst_prints, "Number of printks to generate in a burst (defaults to 7).");

static int __init ratelimit_test_init(void)
{
    int i;
    pr_info("num_burst_prints=%d. Attempting to emit %d printks in a burst:\n", 
            num_burst_prints, num_burst_prints);
    for (i=0; i<num_burst_prints; i++) {
        pr_info_ratelimited("[%d] ratelimited printk @ KERN_INFO [%d]\n", i, LOGLEVEL_INFO);
        mdelay(100); /* 故意加个延迟，把时间轴拉长 */
    }
    return 0;
}

The default parameter is 7, which is fine. Let's push it and set it to 60:

# insmod ./ratelimit_test.ko num_burst_prints=60

You'll see output similar to this:

[ ...] ratelimit_test:ratelimit_test_init:58: num_burst_prints=60. Attempting to emit 60 printks in a burst:
[ ...] ratelimit_test:ratelimit_test_init:61: [0] ratelimited printk @ KERN_INFO [6]
[ ...] ratelimit_test:ratelimit_test_init:61: [1] ratelimited printk @ KERN_INFO [6]
...
[ ...] ratelimit_test:ratelimit_test_init:61: [9] ratelimited printk @ KERN_INFO [6]
[ ...] kernel: __ratelimit: 40 callbacks suppressed

See? When it hits the 10th message (index 9), the rate limiter kicks in. 40 callbacks suppressed means the next 40 prints were ruthlessly swallowed by the kernel.

After another 5 seconds (because we added mdelay(100) in the loop to stretch the time), the rate limiter resets, and a few more of the remaining prints trickle out. Out of 60 total, only a small fraction actually appeared.

That's the power of rate limiting.

The Ultimate Solution: trace_printk()​

If you really need to print in an extremely high-frequency path, and even rate limiting isn't enough, then printk is probably not the right tool.

The kernel's ftrace subsystem (which we'll cover in detail in Chapter 9) provides a trace_printk() API.

  • Syntax: just like printf() (note: not printk).
  • Advantages:
    1. Extremely fast: it only writes to RAM, bypassing complex console logic.
    2. Huge buffer: the trace buffer is large by default, and root can dynamically resize it.

If you truly need to debug in this kind of scenario, consider trace_printk(). It's not just a matter of swapping a function—it represents a different debugging mindset.

Mastering these tools—pr_debug, dev_dbg, and the rate-limiting macros—gives you the ability to "tap into" the kernel and monitor its flow. This might seem sufficient, until you encounter the true "weapon of mass debugging": Dynamic Debug. That is the ultimate form of making kernel printing work for you.

In the next section, we'll break it down.