Skip to main content

3.4 Remaining printk Miscellanea and Ultimate Debugging Techniques

At this point, we've actually covered 90% of your day-to-day debugging scenarios. From the most basic printk, to the leveled pr_debug, to the rate-limiting ratelimit that prevents log flooding, and that god-like Dynamic Debug. Your toolbox should now contain a pretty solid set of gear.

But the kernel world is never flat. There are edge cases—what about when the kernel just booted and the console isn't ready yet? What about when the system has completely hung and even the keyboard is unresponsive? Or what if you want to inject markers into the kernel log from userspace?

Then there are a few scattered but extremely useful tricks, like the "print-once" macros, or tools for elegantly dumping memory blocks. If we don't tie up these loose ends, your debugging skill tree will always be missing a few key nodes.

In this section, we'll round up these scattered "ultimate moves."

3.4.1 Shouting Before Console Init — Early printk​

You've definitely encountered this moment: the kernel boots for a few lines, the screen suddenly goes black, and the serial port produces no output. You know perfectly well the problem lies in very early initialization code—maybe a driver probe failed, or something went wrong with memory mapping.

But the problem is, the real console isn't initialized yet. You issued printk, but nobody is listening. These messages sit quietly in the ring buffer in memory, and you have no way to see them.

It's like an engine failure before takeoff, before the black box even started recording.

What Is a Console?​

Before solving this problem, let's clarify what a "console" actually is.

In traditional Linux terminology, the console is the terminal where the kernel directly outputs,也就是那个 /dev/console. In the era before graphical interfaces took over everything, this was the plain-text window where the superuser logged in.

Interestingly, Linux can define multiple types of "consoles":

  • TTY: Such as /dev/ttyS0 serial devices.
  • VGA text mode: The old-school black-and-white-blue monitors.
  • Framebuffer: Graphical consoles.
  • USB serial: Common on embedded development boards.

When you use a USB-to-TTL serial cable to connect a Raspberry Pi to your laptop and connect using minicom or screen, what you're seeing is the tty device. This is the developer's closest friend.

The Early Printing Dilemma​

The problem boils down to "timing."

In the very early stages of kernel boot, the kernel itself is still an infant—it hasn't even learned to walk, let alone operate a GPU or complex serial drivers. If the kernel crashes at this point, a normal printk simply cannot reach the physical device (because the driver hasn't started yet).

You can only watch helplessly as the system freezes, while the only clues—those crucial early error messages—remain locked in a pipeline that isn't connected yet.

The Solution: early_printk()​

This calls for some unconventional measures. The kernel community provides a mechanism called early printk.

The principle sounds very geeky: without relying on any complex drivers, it uses the lowest-level, most primitive hardware operations to "hammer" characters onto the serial line one by one (or write directly to video memory). This is called bit-banging. This is why it's called early_—because it's not only fast, but extremely primitive, requiring very little infrastructure.

To enable it, you need to follow three steps:

1. Configure the Kernel (One-Time)​

This is architecture-dependent.

  • x86: Enable CONFIG_EARLY_PRINTK=y. The path is usually under Kernel hacking -> x86 Debugging -> Early printk. The documentation will typically warn you: this thing doesn't use proper formatting and will interfere with normal logging, so don't enable it unless you're debugging boot issues.
  • ARM (32-bit): The option is called CONFIG_DEBUG_LL, located at Kernel hacking -> Kernel low-level debugging functions. Entering the submenu, you also need to select the specific debug port (whether it's EmbeddedICE DCC or UART).

2. Boot Parameters​

Compiling it in isn't enough; you need to tell the kernel to use it at boot time. Add this to your bootargs:

earlyprintk=serial,ttyS0,115200

Or the simpler x86 VGA:

earlyprintk=vga

The kernel documentation has a ton of parameter combinations (like sclp, xen, dbgp), but the core idea is: specify a device, specify a baud rate, and tell the kernel "spit the early characters here."

There's also a handy parameter called keep. With this added, even after the real console (like the normal serial driver) takes over, the early early_printk output won't be turned off. This is extremely useful for diagnosing "what happened at the exact moment of handover."

3. Calling It from Code​

The API is very intuitive, called early_printk(), looking exactly like printf.

There are ready-made examples in the kernel code. For instance, in kernel/events/core.c, if the interrupt handling time for performance sampling is too long, it will use early_printk to issue a warning:

// kernel/events/core.c
if (!irq_work_queue(&perf_duration_work)) {
    early_printk("perf: interrupt took too long (%lld > %lld), lowering "
                 "kernel.perf_event_max_sample_rate to %d\n",
                 __report_avg, __report_allowed,
                 sysctl_perf_event_sample_rate);
}

This trick is an absolute lifesaver when debugging those "dies after two steps" bugs.

3.4.2 Tagging printk Messages​

Some errors have a strong sense of identity. If the firmware is written wrong, you should blame the firmware vendor; if the hardware is dead, you should tell people to find the hardware engineer; if I don't want you using a certain API anymore, I need to tell you "this thing is deprecated."

The kernel provides a set of macros specifically for adding these "official prefixes" to printk.

They are defined in include/linux/printk.h:

#define FW_BUG      "[Firmware Bug]: "
#define FW_WARN     "[Firmware Warn]: "
#define FW_INFO     "[Firmware Info]: "

/*
 * HW_ERR
 * Add this to a message for hardware errors, so that user
 * can report it to hardware vendor instead of LKML or software
 * vendor.
 */
#define HW_ERR      "[Hardware Error]: "

/*
 * DEPRECATED
 * Add this to a message whenever you want to warn userspace
 * about the use of a deprecated aspect of an API so they can stop using it
 */
#define DEPRECATED  "[Deprecated]: "

Look at the comment for HW_ERR—you can feel the maintainer's exasperation between the lines: "Don't send this to the Linux Kernel Mailing List (LKML), go argue with the hardware vendor."

Using them is very straightforward, like this:

// drivers/acpi/thermal.c
} else if (tmp <= 2732) {
    pr_warn(FW_BUG "Invalid critical threshold (%llu)\n", tmp);

The output looks like this:

[ 123.456] [Firmware Bug]: Invalid critical threshold (2730)

This kind of prefixed log is especially easy to identify in automated log analysis systems—you can tell at a glance who is responsible.

3.4.3 Saying It Only Once — printk_once()​

Some warnings are very important, but if you print them in a high-frequency interrupt or loop, your console will be instantly flooded, and system performance will plummet.

What you want to say is: "Hey, something's wrong here. I'm telling you once, remember it, but don't make me keep nagging you."

This is when you use printk_once().

It guarantees that this message will only be printed once during the entire system runtime. No matter if you call it ten thousand times, it only spits out the first one.

Naturally, that whole family of pr_* macros all have corresponding _once versions: pr_err_once(), pr_warn_once(), pr_info_once(), and so on.

Let's look at an example. The TCP stack encounters a SYN packet that shouldn't be there—this is definitely an anomaly, but you can't bring down the system because of it:

// net/ipv4/tcp.c
if (unlikely(TCP_SKB_CB(skb)->tcp_flags & TCPHDR_SYN))
    pr_err_once("%s: found a SYN, please report !\n", __func__);

If you're writing a driver, remember to use dev_*_once().

// drivers/rtc/rtc-mxc_v2.c
if (!--timeout) {
    dev_err_once(dev, "SRTC_LPSCLR stuck! Check your hw.\n");
    return;
}

There's also another ultimate move: dev_WARN_ONCE(). This macro not only prints once, but also conveniently dumps a stack trace for you, just like WARN_ON(). This thing is powerful—use it with caution.

3.4.4 Shouting Into the Kernel From Userspace — /dev/kmsg​

Sometimes we're writing automated test scripts. The script runs in userspace, controlling the test flow of a kernel module.

echo "test data 123" > /dev/mydevnode

At this point, you'll see a bunch of output from the kernel module in dmesg. But you have a problem: in this massive pile of logs, which line was triggered by which test case?

If only you could insert a bookmark in the logs. For example, when a test case starts, write a line into the kernel log: my_test_script: start testcase 1.

Actually, you don't need to write kernel code to do this. The kernel provides a special device file: /dev/kmsg.

You can directly use echo to write things into it:

sudo bash -c "echo \"my_test_script: start testcase 1\" > /dev/kmsg"

Messages written this way are treated as KERN_WARNING (level 4) by default. If you want to specify a level, like KERN_INFO (level 6), add angle brackets at the front:

sudo bash -c "echo \"<6>my_test_script: start testcase 1\" > /dev/kmsg"

Then in dmesg, you'll see:

user  :info  : [33561.862960] my_test_script: start testcase 1

Here's an interesting point: once a message enters /dev/kmsg, it looks exactly the same as a printk generated by the kernel itself. You can't tell who is whose parent.

So, we recommend adding a conspicuous prefix (like @US_TEST@), so that when you're scrolling through logs and grepping, you can spot these markers you injected at a glance.

3.4.5 Elegantly Dumping Memory — print_hex_dump_bytes()​

One last common requirement: you want to see the contents of a certain data structure or network packet, but you don't want to write that disgusting loop yourself—what for loop to print hex, whether a character is printable, calculating alignment for half a day...

Don't waste your time. The kernel has it ready for you.

print_hex_dump_bytes() is specifically for this.

Its definition is quite long, but the parameters are explained clearly:

/**
 * print_hex_dump_bytes - shorthand form of print_hex_dump() with default params
 * @prefix_str: string to prefix each line with; caller supplies trailing spaces for alignment if desired
 * @prefix_type: controls whether prefix of an offset, address, or none is printed
 *               (%DUMP_PREFIX_OFFSET, %DUMP_PREFIX_ADDRESS, %DUMP_PREFIX_NONE)
 * @buf: data blob to dump
 * @len: number of bytes in the @buf
 */
#define print_hex_dump_bytes(prefix_str, prefix_type, buf, len) \
        print_hex_dump_debug(prefix_str, prefix_type, 16, 1, buf, len, true)

This macro is essentially a wrapper around print_hex_dump_debug(). Notice anything? It uses the _debug suffix.

What does this mean? It means it's hooked into Dynamic Debug! The more you use it, the more you'll appreciate the power of Dynamic Debug—these hex dumps are normally turned off, don't affect performance, and you just need to enable them in /sys/kernel/debug/dynamic_debug/control at the critical moment.

Let's look at an actual usage in a wireless network driver:

// drivers/net/wireless/ath/ath6kl/debug.c
void ath6kl_dbg_dump(enum ATH6K_DEBUG_MASK mask,
             const char *msg, const char *prefix,
             const void *buf, size_t len)
{
    if (debug_mask & mask) {
        if (msg)
            ath6kl_dbg(mask, "%s\n", msg);
        print_hex_dump_bytes(prefix,
            DUMP_PREFIX_OFFSET, buf, len);
    }
    [...]
}

When this code runs, the output looks roughly like this:

00000000: 00 11 22 33 44 55 66 77 88 99 aa bb cc dd ee ff  ."3DUw........
00000010: 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 10  ................

Clear, aligned, and with ASCII display. When debugging network packets or DMA buffers, this is your eyes.

3.4.6 Survival in Desperate Situations: What to Do When the System Crashes?​

If the system has completely hung, can't even output dmesg, and can't even invoke printk, what do we do?

Here are a few "hardcore" backup plans.

Warm Reset and Bootloader Snooping​

Some advanced techniques involve doing a "warm reset" after the system crashes.

A so-called Warm Reset means restarting the CPU but keeping the RAM contents powered. It's like when your computer freezes, but you haven't pulled the plug—the data in the RAM sticks is still there.

Some boards have dedicated soft reset buttons, or you can trigger this via Magic SysRq (which we'll cover in a dedicated chapter later).

At this point, if you can quickly get into the Bootloader's (like U-Boot) command line, you can use the Bootloader's memory display command (like md - memory display) to read the physical address where the kernel log buffer was located.

There's a catch here: The __log_buf address you find in /proc/kallsyms is a virtual address, and the Bootloader only understands physical addresses. You need to consult the chip manual to translate this virtual address into a physical address.

Once translated successfully, a quick sweep with the md command will let you see the kernel logs from the last few seconds before the crash. Although this trick is obscure, in situations where "reproducing the scene is too hard," it can save your life.

Even more extreme, what if the board doesn't even have a serial port connected, or even the Bootloader has crashed?

Return to the most primitive method: GPIO LED toggling.

This is called the "poor man's printf." You pull a GPIO pin high and low on critical code paths, and the external LED will blink.

  • Blink twice during the initialization phase?
  • Blink three times in the interrupt?
  • Stay solid in a dead loop?

This is exactly how the Raspberry Pi does it—if boot fails, the red LED blinks a specific number of times to represent the error code.

Some people even connect OLED screens via I2C and draw error messages directly on the screen. Although it sounds crude, on black-box devices with no output, this is often the only clue.

Network Console​

Finally, we have to mention netconsole.

This mechanism allows the kernel's printk to be thrown directly to another machine on the LAN via UDP packets.

Even if the local disk is dead or the GPU has crashed, as long as the network card still works, logs can be sent in real-time to a remote server for safekeeping. This is the ultimate tool for debugging server kernel crashes. We'll dive into its detailed configuration in a later chapter.

Chapter Echoes​

We went deep in this chapter, from the simplest instrumentation printing all the way to memory forensics after a system crash.

If you look back, you'll notice a clear path of mental model upgrades:

At first, you just treated printk as a higher-level printf, used to confirm "did the code reach this point."

Then, you started to realize it's part of the kernel's logging system, and began to care about log levels and the ring buffer.

Later, when you encountered performance issues in production environments, you learned about rate limiting and dynamic debugging, understanding how to toggle diagnostic information on demand without rebooting the system.

Finally, in extreme crash scenarios, you learned Early printk and memory dumps—these techniques are no longer just "looking at logs," but directly conversing with the lowest levels of the hardware.

This isn't just an accumulation of tools, but a shift in perspective. Now, you're no longer afraid of that dark console window.

With this set of instrumentation and printing skills under our belt, we can confidently move on to the next, grander topic. In the next chapter, we'll introduce the kernel's Kprobes framework—a magic trick even more powerful than instrumentation, allowing you to dynamically "hook" any kernel function at runtime.

When that time comes, you will truly possess the ability to "see through" the kernel's execution trajectory.

Exercises​

Exercise 1: Understanding​

Question: In Linux kernel programming, why can't we directly use the standard C library's printf() function, and why must we use printk()? Briefly describe the core differences between the two in terms of runtime environment and availability.

Answer and Analysis

Answer: The Linux kernel does not depend on the standard C library (libc); printf() is a userspace library function. printk() is a native kernel API that can be safely called in any context (such as Interrupt Context or while holding a spinlock), and it writes directly to the kernel ring buffer.

Analysis: This knowledge point tests your understanding of the boundary between the kernel and userspace. printf relies on extensive userspace library support that simply doesn't exist in the kernel environment. printk not only implements formatted output but also handles kernel-specific log levels and buffering mechanisms, and is designed to be safe in any context (SMP-safe)—something a normal printf cannot guarantee.

Exercise 2: Application​

Question: Suppose you are writing a Network Device Driver and need to print debug information in the open() function. To make the logs more identifiable and automatically include device information, which of the following macros would you choose? Explain your reasoning.

A. printk(KERN_DEBUG "device opened\n") B. pr_info("device opened\n") C. dev_dbg(&pdev->dev, "device opened\n")

Answer and Analysis

Answer: C

Analysis: When writing device drivers, the best practice is to use dev_dbg() (or other dev_* macros like dev_info()). Although pr_info is more convenient than printk, the dev_* family of macros takes a struct device * pointer as its first argument. This means the printed logs will automatically include specific device information (such as device name, bus number, etc.), which is extremely useful for distinguishing logs from multiple identical devices in a system. Additionally, dev_dbg is much more powerful when paired with Dynamic Debug.

Exercise 3: Application​

Question: You need to print a kernel-space pointer and the contents of a 16-byte data buffer in a driver. For security reasons, write the correct printk code (assuming the buffer pointer is buf).

Answer and Analysis

Answer: printk("Pointer: %pK, Data: %*ph\n", ptr, 16, buf);

Analysis: This tests your mastery of kernel format specifiers. 1. To prevent security vulnerabilities caused by kernel pointer leaks, you should use %pK (which prints a hashed value) instead of %px (the real address) when printing pointers, unless you are in a debugging phase. 2. For printing a small hex buffer, %*ph is the most efficient approach, where * represents the length, 16 is the length value, h stands for little-endian hex bytes, and buf is the data source.

Exercise 4: Thinking​

Question: Suppose you have a high-frequency interrupt handler in your kernel module, and there's a line of printk(KERN_INFO "IRQ fired\n"); inside it. Analyze the two main negative impacts this might cause, and provide at least one solution.

Answer and Analysis

Answer: Negative impacts: 1. Performance degradation/livelock: High-frequency printing causes the CPU to spend excessive time on I/O, potentially leading to slow system response or deadlocks. 2. Log flooding: Useful information gets buried, and it easily causes the log buffer to overwrite old data too quickly (syslog explosion). Solution: Use pr_info_ratelimited() or remove/replace it with trace_printk() on non-critical paths.

Analysis: This is a comprehensive engineering problem. Although printk is synchronous, executing it frequently in Interrupt Context will severely slow down the system. The question tests your awareness of the costs of printk and your understanding of "rate limiting" and "tracing" mechanisms. The printk_ratelimit mechanism (through macro wrappers) can limit the number of prints per second, while trace_printk is specifically designed for high-frequency paths with extremely low overhead and no blocking.

Key Takeaways​

Debugging mechanisms in the kernel environment are far more complex than in userspace. The core tool, printk, is not a simple printf replacement. It temporarily stores logs in a ring buffer and determines whether messages are output to the console based on log levels 0-7 (such as KERN_EMERG to KERN_DEBUG). Developers should prioritize using wrapper macros like pr_info() to keep code clean. Using pr_fmt() automatically adds module name, function name, and line number prefixes to all logs, which greatly improves information filtering efficiency when debugging multiple modules concurrently.

To prevent debug printing in high-frequency paths from causing system "livelocks" or log flooding, the kernel provides the pr_*_ratelimited() family of macros for rate-limiting protection. This mechanism drops excess messages based on a /proc/sys/kernel/printk_ratelimit (time window) and burst (burst threshold) to prevent critical information from being overwritten. If you need to trace in extremely high-frequency scenarios, consider using trace_printk(), which writes directly to the trace buffer with a performance overhead far lower than printk.

The most powerful debugging technique is Dynamic Debug, which allows you to dynamically enable or disable any pr_debug() or dev_dbg() call site at runtime without recompiling the kernel. By writing match specifications and flags (such as module misc +p) to /proc/dynamic_debug/control or debugfs, developers can precisely control log output for specific modules, files, or even line numbers, achieving "zero-overhead" on-demand debugging in production environments.

For driver development, you must use the dev_*() family of functions (like dev_dbg()) instead of generic pr_*(). These functions not only automatically carry device context information (such as device name and bus number) but also allow you to pinpoint the source of a problem in systems with multiple identical devices. When paired with Dynamic Debug, dev_dbg() can provide extremely detailed hardware interaction logs without impacting performance.

When the system is in the early boot stage and the console hasn't been initialized yet, a normal printk cannot output anything. In this case, you need to rely on Early printk. This mechanism bypasses complex driver layers and writes characters directly to the serial port or VGA video memory through low-level hardware operations. It is a critical lifesaver for diagnosing "black screen" issues like kernel boot crashes and memory initialization failures. Enabling it typically requires specific kernel configuration options (like CONFIG_EARLY_PRINTK) and boot parameters.