Linux Kernel Logging Internals: printk() & pr_fmt() Explained

Linux Kernel Logging Internals
How printk() and pr_fmt() shape every kernel log message — Linux 6.x Edition
Skill Level
Beginner → Intermediate
Kernel
Linux 6.x
Part
1 of 3
Series: PREV_LEC NEXT_LEC
Topics Covered:
printk kernel pr_fmt macro kernel module logging KBUILD_MODNAME kernel log prefix free linux kernel programming course linux device driver logging LKM init cleanup

When your kernel module prints something, you need to know which module and which function produced that line — especially when the kernel log contains thousands of entries from dozens of subsystems all mixed together.

This tutorial explains how the Linux kernel’s logging system gives you automatic, consistent prefixes on every log line, using two key tools: the printk() function and the pr_fmt() macro. We cover the Linux 6.x behaviour throughout.

1. What Is printk() and Why Does It Exist?

In user-space C programs you call printf() to write text to a terminal. The kernel runs long before any terminal exists, so it has its own equivalent: printk(). The name is short for print kernel.

Every kernel subsystem, every driver, and every loadable module uses printk() to write diagnostic and status messages. Those messages go into a ring buffer inside the kernel called the kernel log buffer. You can read it at any time with the dmesg command.

Key difference from printf(): printk() accepts a log-level prefix that tells the kernel how urgent the message is. This lets the kernel decide whether to also send the message to the system console, depending on the current console log-level setting.

In Linux 6.x the log-level macros available to you are:

/* Log level constants defined in <linux/kern_levels.h> */
KERN_EMERG    /* system is unusable                         */
KERN_ALERT    /* action must be taken immediately           */
KERN_CRIT     /* critical conditions                        */
KERN_ERR      /* error conditions                           */
KERN_WARNING  /* warning conditions                        */
KERN_NOTICE   /* normal but significant condition           */
KERN_INFO     /* informational                              */
KERN_DEBUG    /* debug-level messages                       */

Instead of embedding these raw strings into every printk() call, the kernel provides convenience wrappers like pr_info(), pr_err(), pr_warn(), and pr_debug(). These automatically attach the right log-level prefix for you.

How a printk() message travels from your module to dmesg
Your LKM calls pr_info(“Module loaded”)
pr_fmt() macro prepends module name + function name
printk() attaches log-level (KERN_INFO) and timestamp
Kernel writes message to ring buffer (/dev/kmsg)
dmesg reads and displays: [12345.678901] mymodule:my_init(): Module loaded

2. The Problem With Raw printk() Calls

Imagine you are debugging a kernel module called mydriver and it loads fine but something goes wrong after a few seconds. You run dmesg and see hundreds of log lines from multiple subsystems. How do you quickly find which lines came from your module?

If you wrote bare pr_info("init done\n") calls, the kernel log only shows the log-level and timestamp. Nothing identifies your module or the specific function that printed the message. Finding the relevant lines becomes a slow, manual process.

Real problem: In production systems running Linux 6.x, dmesg output can contain tens of thousands of lines during boot. A message that does not carry its source module name is almost impossible to trace quickly.

The Linux kernel community solved this long ago with a simple macro you define once at the top of each source file.

3. Introducing pr_fmt() — Your Automatic Log Prefix

The pr_fmt() macro acts as a format string preprocessor. Every time a pr_*() convenience function (like pr_info() or pr_err()) is called, it first passes the format string through pr_fmt(). Whatever pr_fmt() returns becomes the actual format string used in the log entry.

By defining pr_fmt() at the top of your source file, before any includes, you inject a consistent prefix into every single log message your file emits — with zero repetition in individual pr_info() calls.

/* Define pr_fmt() at the very top of your .c file,
   BEFORE any #include statements */

#define pr_fmt(fmt)  KBUILD_MODNAME ": " __func__ ": " fmt

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

MODULE_LICENSE("GPL");

static int __init my_driver_init(void)
{
    pr_info("driver inserted\n");
    /* The kernel log will show:
       [  123.456789] mydriver: my_driver_init: driver inserted */
    return 0;
}

static void __exit my_driver_exit(void)
{
    pr_info("driver removed\n");
    /* The kernel log will show:
       [  456.789012] mydriver: my_driver_exit: driver removed */
}

module_init(my_driver_init);
module_exit(my_driver_exit);
Why BEFORE the includes? The kernel headers themselves already contain a default fallback definition for pr_fmt(). If you place your #define after the includes, the header’s definition takes effect first and your custom definition either has no effect or causes a redefinition error, depending on how the compiler sees it.
How pr_fmt() expands at compile time
What you write What the compiler sees after macro expansion
pr_info(“loaded\n”) printk(KERN_INFO “mydriver: my_init: loaded\n”)
pr_err(“failed\n”) printk(KERN_ERR “mydriver: my_init: failed\n”)
pr_warn(“retry\n”) printk(KERN_WARNING “mydriver: my_init: retry\n”)

4. KBUILD_MODNAME and __func__ — The Two Pillars

KBUILD_MODNAME

This is a string constant the Kbuild build system automatically defines for you during compilation. Its value is the name of the kernel module being built — exactly the name of your .ko file without the extension. You never have to hard-code your module name in a string; the build system does it for you.

If your module file is serial_gpio_driver.c and the Makefile builds it as serial_gpio_driver.ko, then KBUILD_MODNAME expands to the string "serial_gpio_driver" at compile time.

__func__

This is a standard C99 predefined identifier. The compiler replaces it with a string literal containing the name of the current function. It is not a macro — it is a language feature, so it correctly resolves to the right function name even when the same header is included from many places.

Practical benefit: When you combine KBUILD_MODNAME and __func__ in your pr_fmt() definition, every log line from your module automatically carries both its module name and the exact function that emitted it. You can pinpoint the source of any log message in seconds.
Anatomy of a kernel log line produced by pr_info() with pr_fmt()
[ 12345.678901 ]   mydriver:my_driver_init:   driver inserted
Kernel timestamp
seconds since boot
←→ KBUILD_MODNAME
auto-inserted by pr_fmt()
←→ __func__
function name
←→ Your message
the fmt string

5. Including Line Numbers in Log Output

Sometimes a function is long and you want to know not just which function printed a message, but at which exact line inside that function. The C preprocessor provides the __LINE__ macro for this. You can include it inline in your format string using a %d specifier.

/* Logging the line number alongside the message */
pr_info("checkpoint reached at line %d\n", __LINE__);

This produces output like:

[  789.012345] mydriver: my_driver_init: checkpoint reached at line 42
When is __LINE__ actually useful? It shines when you have a long init function with multiple early-return error paths and you want to instantly know which path was taken without stepping through the function in gdb or adding many different string labels.

6. pr_fmt() and dev_<foo>() — Device Driver Logging

For platform and character device drivers, the kernel provides a separate family of logging functions: dev_info(), dev_err(), dev_warn(), and others. These take a pointer to a struct device as their first argument and automatically prepend the device name to the log message.

The pr_fmt() macro also feeds into these functions under the hood. This means your module-level prefix and the device name both appear in the log line, giving you two levels of context at once.

/* Inside a probe function for a platform driver */
static int my_device_probe(struct platform_device *pdev)
{
    dev_info(&pdev->dev, "device probed successfully\n");
    /* Output in kernel log:
       [  100.000001] mydriver mydevice0: device probed successfully */
    return 0;
}
Rule of thumb: Use pr_*() functions in module-level code (init, exit, non-device logic). Use dev_*() functions when you have a valid struct device * pointer available — typically inside probe, remove, and runtime PM callbacks.

7. Reading Kernel Log Messages in Linux 6.x

Linux 6.x changed how /dev/kmsg works compared to older kernels. The structured log format now carries additional metadata fields. Here are the main ways to read kernel log output:

Methods to read the kernel log in Linux 6.x
Command What it shows Best used for
dmesg All messages in the ring buffer Quick inspection after insmod
dmesg -w Live follow mode (like tail -f) Watching messages as your module runs
dmesg | grep mydriver Only lines from your module Isolating your module’s output
journalctl -k Kernel messages via systemd journal Persistent log across reboots
cat /proc/kmsg Raw kernel message stream Advanced tooling and log daemons

8. pr_debug() — Conditional Debug Logging

The pr_debug() function is special. By default, when you call it, it compiles down to a no-op — the message is completely removed from the binary and has zero runtime cost. This means you can leave debug statements in your production code without any performance penalty.

To activate pr_debug() output for a specific module, you enable the DEBUG preprocessor flag when compiling that module. There are two ways to do this:

# Method 1: Add to EXTRA_CFLAGS in your module's Makefile
EXTRA_CFLAGS += -DDEBUG

# Method 2: Define it at the top of the specific .c file
#define DEBUG
#define pr_fmt(fmt) KBUILD_MODNAME ": " __func__ ": " fmt
#include <linux/kernel.h>
Linux 6.x dynamic debug: A more powerful alternative is dynamic debug (CONFIG_DYNAMIC_DEBUG). It lets you enable or disable specific debug messages at runtime through /sys/kernel/debug/dynamic_debug/control — without recompiling. This is the preferred approach for production kernel development.

Interview Questions & Answers

Q1. What is the purpose of defining pr_fmt() before any #include in a kernel module source file?
A: The kernel headers already include a default fallback definition of pr_fmt(). Placing your custom definition before the includes ensures that your version is seen by the compiler first, so all pr_*() calls in that file use your custom format string, which typically includes the module name and function name for easier log tracing.
Q2. What is KBUILD_MODNAME and who defines it?
A: KBUILD_MODNAME is a string constant automatically defined by the Kbuild build system during compilation. Its value equals the name of the kernel module (.ko file) being built. You never hard-code it — the build system injects it so the module name is always accurate even if you rename the file.
Q3. What is the difference between pr_info() and dev_info() and when should each be used?
A: Both log informational messages but at different levels of abstraction. pr_info() is a general-purpose kernel logging macro that uses the module-level prefix defined in pr_fmt(). dev_info() takes a struct device * pointer and automatically includes the device name in the log output, making it more appropriate inside driver probe, remove, and runtime callbacks where a valid device object exists.
Q4. How does pr_debug() achieve zero runtime cost when not in use?
A: When the DEBUG preprocessor symbol is not defined, the compiler expands pr_debug() to a no-op. The format string and arguments are still type-checked at compile time (to catch bugs), but no code is emitted. This means you get the benefits of extensive debug instrumentation in your source without any penalty in production builds.
Q5. What changed in Linux 6.x regarding kernel log reading compared to older kernels?
A: Linux 6.x provides a more structured log format through /dev/kmsg, carrying metadata such as log sequence numbers, facility and priority fields, and timestamps in nanoseconds. The dmesg utility was updated to parse this structured format. Additionally, CONFIG_DYNAMIC_DEBUG is more widely used to control per-callsite debug output at runtime without recompilation.

Continue Learning — Free Linux Kernel Course

Next up: printk format specifiers for writing portable, architecture-independent kernel code.

Next: Format Specifiers → Skip to: Kernel Makefile →
EmbeddedPathashala — Free Linux Kernel & Device Driver Course Next Part →

Leave a Reply

Your email address will not be published. Required fields are marked *