1. Persistent Kernel Logging — Solving the Volatility Problem

Since the ring buffer lives in RAM and is erased on every reboot or crash, Linux distributions route kernel messages to disk using a userspace log daemon. The evolution of this mechanism went through two phases:

1.1 Why journald is Superior for Kernel Debugging

With the traditional syslog approach, kernel messages and application messages lived in separate files. If you were debugging a timing-sensitive issue between a kernel driver and a userspace daemon, you had to manually align timestamps from two different files — painful and error-prone.

The systemd journal merges all log sources into a single unified, chronologically ordered stream:

You get a single reverse-chronological timeline of everything that happened on the system — no manual log correlation needed. This is a huge productivity boost for driver developers.

2. Using journalctl to Read Kernel Messages

The journalctl command is the user interface to the systemd journal. For kernel developers, it is the most reliable way to access kernel logs that survive past a dmesg buffer overflow.

2.1 Essential journalctl Commands for Kernel Development

# Show only kernel messages from the current boot
$ journalctl -k

# Show kernel messages, most recent first
$ journalctl -k --reverse

# Follow kernel log in real-time (like dmesg -w)
$ journalctl -k -f

# Show kernel messages from the PREVIOUS boot (very useful after a crash)
$ journalctl -k -b -1

# Show kernel messages from 2 boots ago
$ journalctl -k -b -2

# List all stored boot sessions
$ journalctl --list-boots

# Show all kernel messages since today 09:00
$ journalctl -k --since "09:00"

# Show kernel messages in a specific time window
$ journalctl -k --since "2025-06-18 10:00" --until "2025-06-18 10:30"

# Show only error-level and above kernel messages
$ journalctl -k -p err

# Search kernel log for a specific driver or string
$ journalctl -k | grep "ep_uart"

# Show logs without the pager — useful for piping to grep/awk
$ journalctl -k --no-pager | awk '/ep_uart/ {print}'

2.2 Enabling Persistent Journal Storage

By default, on many distributions, the journal only stores logs in /run/log/journal/ — which is a tmpfs (RAM-backed filesystem) and is also lost on reboot. To enable persistent disk-based storage:

# Create the persistent journal directory
$ sudo mkdir -p /var/log/journal

# Tell systemd to use persistent storage
$ sudo sed -i 's/#Storage=auto/Storage=persistent/' /etc/systemd/journald.conf

# Or simply set it manually:
$ sudo nano /etc/systemd/journald.conf
# Set: Storage=persistent

# Restart journald to apply
$ sudo systemctl restart systemd-journald

# Verify — you should now see a machine-id subdirectory
$ ls /var/log/journal/

2.3 journalctl Output Format

The default journal output for kernel messages follows this format:

You can request richer output formats:

# JSON format — one entry per line, all metadata visible
$ journalctl -k -o json-pretty | head -40

# Short format with microsecond timestamps
$ journalctl -k -o short-monotonic

# Verbose — all journal fields for every entry
$ journalctl -k -o verbose

3. Rate Limiting printk — Preventing Log Storms

Imagine you write a printk inside an interrupt service routine (ISR), or inside a loop that processes thousands of packets per second. Without any protection, you could generate millions of log lines per minute. This would:

• Immediately overflow the 256 KB ring buffer, destroying all other useful log data
• Slow down the kernel significantly — printk is not a zero-cost operation
• Make journald write huge amounts of disk data, potentially stalling I/O

The kernel provides dedicated rate-limiting printk wrappers to prevent this problem.

3.1 pr_ratelimited — Rate-Limited Logging

pr_ratelimited() is a family of macros that internally use the kernel’s printk_ratelimit() mechanism. By default, it allows at most 10 messages in a 5-second window, then suppresses further messages (with a note that messages were dropped) until the window resets.

#include <linux/printk.h>
#include <linux/ratelimit.h>

/* This ISR could be called 50,000 times per second */
static irqreturn_t ep_uart_isr(int irq, void *dev_id)
{
    u32 status = read_uart_status();

    if (status & UART_PARITY_ERR) {
        /*
         * Without rate limiting, this would generate a log storm.
         * With pr_ratelimited, at most 10 messages per 5 seconds.
         */
        pr_ratelimited(KERN_WARNING "ep_uart: Parity error on RX, status=0x%08x\n",
                       status);
    }

    return IRQ_HANDLED;
}

The full family of rate-limited macros matches the pr_* family:

pr_info_ratelimited("Periodic event: count=%d\n", count);
pr_warn_ratelimited("Near threshold: level=%d\n", level);
pr_err_ratelimited("I/O error: addr=0x%lx, ret=%d\n", addr, ret);
pr_debug_ratelimited("Debug: iter=%d, val=%u\n", i, val);

3.2 Custom Rate Limit Intervals

If the default 5-second / 10-message window does not fit your use case, you can define a custom rate limit state:

#include <linux/ratelimit.h>

/*
 * Define a custom rate limiter:
 * Allow at most 5 messages per 10-second interval
 * DEFINE_RATELIMIT_STATE(name, interval_jiffies, burst_limit)
 */
static DEFINE_RATELIMIT_STATE(ep_rl, 10 * HZ, 5);

static void ep_process_packet(struct sk_buff *skb)
{
    if (some_error_condition) {
        if (__ratelimit(&ep_rl)) {
            pr_warn("ep_net: Malformed packet dropped, len=%d\n",
                    skb->len);
        }
    }
}

3.3 printk_once — Fire Exactly Once

Sometimes you want a warning to appear only the very first time a condition occurs — never again. This is common for deprecation warnings or one-time hardware detection messages:

static void ep_legacy_interface_used(void)
{
    /*
     * Warn the user the first time this deprecated
     * function is called, regardless of how many
     * times it gets invoked afterwards.
     */
    pr_warn_once("ep_uart: Legacy ioctl interface is deprecated. "
                 "Please migrate to the new netlink API.\n");

    /* Continue with the legacy implementation */
    do_legacy_stuff();
}

The pr_warn_once() macro (and its siblings pr_info_once, pr_err_once) internally use a static boolean flag. The very first time it executes, the flag is false — the message prints and the flag is set to true. All subsequent calls see the flag is true and silently skip. This is both safe and efficient.

4. Writing to the Kernel Log from User Space

There are legitimate scenarios where a user-space program wants to inject a message into the kernel log — for example, to mark a test boundary (“TEST STARTED”), or to correlate a user-space event with kernel activity in the unified journal timeline. Linux provides two standard ways to do this.

4.1 Writing Directly to /dev/kmsg

On Linux 6.x, any process with write permission to /dev/kmsg (typically root, or a process with CAP_SYS_ADMIN) can inject messages directly into the kernel log:

/* User-space C program — writes a message into the kernel log */
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <string.h>

int main(void)
{
    int fd;
    const char *msg = "6EmbeddedPathashala: BLE stack test started\n";
    /*
     * The prefix "6" is the KERN_INFO log level digit.
     * Format: "message\n"
     * Level 3 = KERN_ERR, 4 = KERN_WARNING, 6 = KERN_INFO
     */

    fd = open("/dev/kmsg", O_WRONLY);
    if (fd < 0) {
        perror("open /dev/kmsg");
        return 1;
    }

    write(fd, msg, strlen(msg));
    close(fd);
    return 0;
}

4.2 Using the logger Command

For shell scripts and quick testing, the logger utility provides a convenient command-line interface:

# Write a message into the system log (appears in journalctl)
$ logger -t "ep_test" "BLE advertising test phase 1 started"

# Write to kernel log specifically via /dev/kmsg
$ echo "6ep_test: Phase 2 complete" | sudo tee /dev/kmsg

# Mark test boundaries clearly in the log
$ sudo sh -c 'echo "4ep_test: ===== TEST BOUNDARY =====" > /dev/kmsg'

5. Standardized printk Format in Linux 6.x

Modern Linux kernel printk messages include structured metadata beyond just the text. When you read /dev/kmsg raw, each record has a defined format:

# Raw /dev/kmsg record format (Linux 6.x):
# LEVEL,SEQUENCE,TIMESTAMP_USEC,FLAGS;MESSAGE\n

# Example:
6,12345,1234567890,-;ep_uart: UART driver v1.0 initialized
 SUBSYSTEM=tty
 DEVICE=+tty:ttyS0

The sequence number is particularly useful for detecting dropped messages — if you see sequence numbers jump from 5001 to 5010, it means 8 messages were lost (ring buffer overflow).

5.1 Printk Format Specifiers for Kernel Data Types

The kernel extends the standard C printf format specifiers with kernel-specific ones. Using the wrong specifier causes compiler warnings and potential bugs on different architectures:

/* Always use these kernel-correct format specifiers */

/* size_t and ssize_t */
pr_info("Buffer size: %zu bytes\n", buf_size);    /* size_t */
pr_info("Return value: %zd\n", ssize_val);         /* ssize_t */

/* Pointers — always use %p or its variants */
pr_info("DMA buffer at: %p\n", dma_buf);           /* generic pointer */
pr_info("Physical addr: %pa\n", &phys_addr);       /* phys_addr_t — note: pass address of */

/* Kernel resource addresses — obfuscated for security (KASLR) */
pr_info("Function ptr: %pS\n", func_ptr);          /* prints symbol name + offset */
pr_info("Module mem:   %pK\n", kernel_ptr);        /* obfuscated for unprivileged users */

/* Device names */
pr_info("Device: %pOFn\n", dev->of_node);          /* Device Tree node name */

/* IPv4 and IPv6 addresses */
pr_info("IPv4: %pI4\n", &ip4_addr);
pr_info("IPv6: %pI6c\n", &ip6_addr);              /* compressed IPv6 format */

/* MAC addresses */
pr_info("MAC: %pM\n", mac_addr);                   /* aa:bb:cc:dd:ee:ff format */
pr_info("MAC: %pMR\n", mac_addr);                  /* reversed byte order — Bluetooth */

6. Putting It All Together — Complete Example Module

Here is a complete Linux kernel module demonstrating all the printk best practices covered in both Part 1 and Part 2:

// SPDX-License-Identifier: GPL-2.0
/*
 * ep_logging_demo.c — EmbeddedPathashala
 * Demonstrates printk best practices for Linux 6.x
 */

/* pr_fmt must be defined BEFORE including linux/printk.h */
#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt

#include <linux/module.h>
#include <linux/init.h>
#include <linux/printk.h>
#include <linux/ratelimit.h>

MODULE_LICENSE("GPL");
MODULE_AUTHOR("EmbeddedPathashala");
MODULE_DESCRIPTION("printk best practices demo — Linux 6.x");
MODULE_VERSION("1.0");

/*
 * Custom rate limiter:
 * Allow at most 3 messages per 8 seconds from hot paths
 */
static DEFINE_RATELIMIT_STATE(ep_hotpath_rl, 8 * HZ, 3);

/* Simulated hot path — called very frequently */
static void ep_simulate_hot_path(int iteration)
{
    if (iteration % 100 == 0) {
        /* Rate limited — won't spam the log even if called 10000x/sec */
        if (__ratelimit(&ep_hotpath_rl)) {
            pr_info("Hot path iteration %d processed\n", iteration);
        }
    }
}

static int __init ep_logging_demo_init(void)
{
    int i;

    /* KERN_INFO — normal startup message */
    pr_info("EmbeddedPathashala logging demo loaded (Linux %s)\n",
            UTS_RELEASE);

    /* KERN_DEBUG — only visible if console level is 7 */
    pr_debug("Debug: Module base address %pK, init=%pS\n",
             THIS_MODULE, ep_logging_demo_init);

    /* One-time warning — prints only on first module load */
    pr_warn_once("This is a demonstration module — not for production use\n");

    /* Simulate hot path calls */
    for (i = 0; i < 1000; i++)
        ep_simulate_hot_path(i);

    pr_info("Init complete — %d hot path iterations simulated\n", i);
    return 0;
}

static void __exit ep_logging_demo_exit(void)
{
    pr_info("EmbeddedPathashala logging demo unloaded\n");
}

module_init(ep_logging_demo_init);
module_exit(ep_logging_demo_exit);

# Makefile to build this module
obj-m := ep_logging_demo.o

KDIR := /lib/modules/$(shell uname -r)/build

all:
	make -C $(KDIR) M=$(PWD) modules

clean:
	make -C $(KDIR) M=$(PWD) clean

# Build and test workflow
$ make
$ sudo insmod ep_logging_demo.ko

# Check messages immediately
$ dmesg | tail -20

# Or via journalctl for persistent access
$ journalctl -k --no-pager | tail -20

# Remove module
$ sudo rmmod ep_logging_demo

# Adjust console log level to see pr_debug output
$ sudo sh -c 'echo 7 > /proc/sys/kernel/printk'
$ sudo insmod ep_logging_demo.ko
$ dmesg | tail -20

Interview Questions & Answers