printk: Kernel Logging Internals
The kernel's logging system: log buffer, rate limiting, dev_printk, and dmesg
The printk API
/* Basic usage: */
printk(KERN_INFO "my_driver: initialized, irq=%d\n", irq);
/* Convenience macros (preferred): */
pr_emerg("..."); /* KERN_EMERG = "<0>" */
pr_alert("..."); /* KERN_ALERT = "<1>" */
pr_crit("..."); /* KERN_CRIT = "<2>" */
pr_err("..."); /* KERN_ERR = "<3>" */
pr_warn("..."); /* KERN_WARNING = "<4>" */
pr_notice("..."); /* KERN_NOTICE = "<5>" */
pr_info("..."); /* KERN_INFO = "<6>" */
pr_debug("..."); /* KERN_DEBUG = "<7>" (only if DEBUG defined) */
/* Device-aware wrappers (include dev name/address in output): */
dev_err(&pdev->dev, "failed to map IO: %d\n", ret);
dev_info(&client->dev, "probe OK, addr=0x%02x\n", client->addr);
dev_warn(&pdev->dev, "timeout, retrying\n");
dev_dbg(&pdev->dev, "IRQ status: 0x%08x\n", status);
Log levels and console
/*
* Messages are printed to the console (serial, VT) if their log level
* is below the current console_loglevel:
*/
cat /proc/sys/kernel/printk
# 4 4 1 7
# current default min boot-time-default
/* Levels:
0 EMERG — system unusable
1 ALERT — action must be taken immediately
2 CRIT — critical conditions
3 ERR — error conditions
4 WARNING — warning conditions (console_loglevel default = 4)
5 NOTICE — normal but significant
6 INFO — informational
7 DEBUG — debug messages (never shown at default level)
*/
/* Temporarily show all messages including DEBUG: */
echo 8 > /proc/sys/kernel/printk
Circular log buffer
/* kernel/printk/printk.c */
/*
* The ring buffer stores records with metadata.
* Size controlled by: CONFIG_LOG_BUF_SHIFT (default 17 = 128KB)
* Boot parameter: log_buf_len=4M
*/
struct printk_info {
u64 seq; /* sequence number */
u64 ts_nsec; /* timestamp in nanoseconds */
u16 text_len; /* length of message text */
u8 facility; /* syslog facility */
u8 level; /* 0-7 */
u32 caller_id; /* cpu/task ID */
};
/*
* Ring buffer is a lock-free multi-producer multi-consumer design.
* Readers (dmesg, /dev/kmsg) never block the writer (printk).
* Old messages are overwritten when buffer fills.
*/
printk flow
asmlinkage int vprintk_emit(int facility, int level,
const struct dev_printk_info *dev_info,
const char *fmt, va_list args)
{
/* 1. Format the message into a temporary buffer */
int text_len = vscnprintf(text_buf, sizeof(text_buf), fmt, args);
/* 2. Store in the ring buffer */
if (prb_reserve(&e, prb, &r)) {
r.info->facility = facility;
r.info->level = level & 7;
r.info->ts_nsec = local_clock();
memcpy(r.text_buf, text_buf, text_len);
prb_commit(&e);
}
/* 3. Wake up console writers (klogd, /dev/kmsg readers) */
wake_up_klogd();
/* 4. If in atomic context: direct console write */
if (is_printk_force_console())
console_flush_all(true, &dropped, &panic_dropped);
return text_len;
}
Reading kernel logs
# dmesg: reads /dev/kmsg
dmesg
dmesg -T # human-readable timestamps
dmesg -l err # only errors and above
dmesg -w # follow (like tail -f)
dmesg --clear # clear the ring buffer
# /dev/kmsg: raw structured access
cat /dev/kmsg
# 6,1234,123456789,-;e1000: eth0: Intel(R) PRO/1000 Network Connection
# Format: level,seq,timestamp(us),flags;message
# journalctl reads from journal which captures kernel messages:
journalctl -k # kernel messages since last boot
journalctl -k -b-1 # previous boot kernel messages
journalctl -k -p err # kernel errors
Rate limiting
/* Avoid log flooding: */
printk_ratelimited(KERN_WARNING "my_driver: spurious interrupt\n");
/* Allows one message per 5 seconds, prints suppressed count */
pr_warn_ratelimited("Too many requests, dropping\n");
dev_warn_ratelimited(&dev, "error %d, continuing\n", ret);
/* Controlled by: */
/* /proc/sys/kernel/printk_ratelimit (default 5 seconds) */
/* /proc/sys/kernel/printk_ratelimit_burst (default 10 messages) */
/* Custom rate limit: */
static DEFINE_RATELIMIT_STATE(my_rs, 10 * HZ, 5);
if (__ratelimit(&my_rs))
pr_warn("...");
pr_fmt: module prefix
/* At the top of the source file: */
#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt
/* All subsequent pr_*() calls automatically include module name: */
pr_info("driver loaded\n");
/* Output: "my_module: driver loaded" */
Dynamic debug
# dev_dbg() and pr_debug() are no-ops unless dynamically enabled:
# Enable all debug messages in a file:
echo "file drivers/net/e1000.c +p" > /sys/kernel/debug/dynamic_debug/control
# Enable all debug messages in a module:
echo "module e1000 +p" > /sys/kernel/debug/dynamic_debug/control
# Enable with flags (p=print, f=filename, l=line, m=module, t=thread):
echo "file net/ipv4/tcp.c +pflmt" > /sys/kernel/debug/dynamic_debug/control
# List all dynamic debug sites:
cat /sys/kernel/debug/dynamic_debug/control | grep "e1000"
# drivers/net/ethernet/intel/e1000e/netdev.c:2345 [e1000e]e1000_intr =p
# Boot parameter to enable at startup:
# dyndbg="module e1000 +p"
pstore: persist messages across reboot
# If CONFIG_PSTORE enabled (EFI vars, RAM, MTD):
ls /sys/fs/pstore/ # crash logs from previous boot
cat /sys/fs/pstore/dmesg-ramoops-0
# ramoops: dedicated RAM region for persistent kernel logs
# EFI pstore: saves to UEFI non-volatile storage
# Useful for debugging early boot crashes or panic storms
Observing printk
# Trace all printk calls:
bpftrace -e '
kprobe:vprintk_emit {
printf("printk level=%d: %s\n", (int)arg1,
str(*(char **)arg3));
}'
# Serial console speed bottleneck:
# High-volume logging can stall real-time tasks
# Solution: use async console (ASYNC_CONSOLE) or pstore
Further reading
- Oops Analysis — reading kernel crash output
- kdump — kernel crash dumps
kernel/printk/printk.c— core implementationinclude/linux/printk.h— API macrosDocumentation/admin-guide/dynamic-debug-howto.rst— dynamic debug guide