Usage

printk works more or less the same way as printf in userspace, so if you ever debugged your userspace program using printf, you are ready to do the same with your kernel code, e.g. by adding:

printk("My Debugger is Printk\n");

This wasn't that difficult, was it?

Usually you would print out some more interesting information like

printk("Var1 %d var2 %d\n", var1, var2);

just like in userspace.

In order to see the kernel messages, just use the

$ dmesg

command in one of your shells - this one will print out the whole kernel log
buffer to you.

Most of the conversion specifiers supported by the user-space library routine printf() are also available in the kernel; there are some notable additions, including "%pf", which will print the symbol name in place of the numeric pointer value, if available.

However please note: always use %zu, %zd or %zx for printing
size_t and ssize_t values. ssize_t and size_t are quite common values in the kernel, so
please use the %z to avoid annoying compile warnings.

Author's practical advice:
If you want to debug an oops (e.g caused by releasing a resource twice) in your driver and you don't have a clue where the oops happens, simply add this line

printk(KERN_ALERT "DEBUG: Passed %s %d \n",__FUNCTION__,__LINE__);

after each possibly offending statement.
Recompile and (re-)load the module and trigger the error condition - your log now shows you the last line that was successfully executed before the oops happened.

Of course you should remove these 'rude' statements before shipping your module ;)

Log Levels

If you look into real kernel code you will always see something like:

printk(KERN_ERR "something went wrong, return code: %d\n",ret);

where "KERN_ERR" is one of the eight different log levels defined in
include/linux/printk.h and specifes the severity of the error message.

Note that there is NO comma between the KERN_ERR and the format string (as the preprocessor concatenates both strings)

The log levels are:

Name

String

Meaning

alias function

KERN_EMERG

"<0>"

Emergency messages, system is about to crash or is unstable

pr_emerg

KERN_ALERT

"<1>"

Something bad happened and action must be taken immediately

pr_alert

KERN_CRIT

"<2>"

A critical condition occurred like a serious hardware/software failure

pr_crit

KERN_ERR

"<3>"

An error condition, often used by drivers to indicate difficulties with the hardware

"continued" line of log printout (only done after a line that had no enclosing \n) [1]

pr_cont

The pr_* macros (with exception of pr_debug) are simple shorthand definitions
in include/linux/printk.h
for their respective printk call and should probably be used in newer drivers.

pr_devel and pr_debug are replaced with printk(KERN_DEBUG ... if the kernel was
compiled with DEBUG, otherwise replaced with an empty statement.

For drivers the pr_debug should not be used anymore (use dev_dbg instead).

If you don't specify a log level in your message it defaults to
DEFAULT_MESSAGE_LOGLEVEL (usually "<4>"=KERN_WARNING)
which can be set via the CONFIG_DEFAULT_MESSAGE_LOGLEVEL kernel config
option (make menuconfig-> Kernel Hacking -> Default message log level)

The log level is used by the kernel to determine the importance of
a message and to decide whether it should be presented to the user
immediately, by printing it to the current console (where console could also
be a serial line or even a printer, not an xterm).

For this the kernel compares the log level of the message to the
console_loglevel (a kernel variable) and if the priority is higher (i.e. a
lower value) than the console_loglevel the message will be printed to the current console.

Author's practical advice:
Of course you should always specify an appropriate log level for your messages,
but for debugging, I guess most developers leave the
console_loglevel unchanged and simply use KERN_ERR or KERN_CRIT to ensure the message reaches the console.

pr_err("REMOVE ME: my debug statement that I swear to remove when I'm done\");

Please make sure to remove these 'inappropriately' tagged messages before
shipping the module ;)

KERN_CONT and pr_cont are special cases since they do not specify an urgency but rather indicate a 'continued message' e.g.:

Important Note:KERN_CONT and pr_cont should only be used by core/arch code during early bootup (a continued line is not SMP-safe otherwise).[2]

Rate limiting and one time messages

Occasionally you have to insert a message in a section which gets called
quite often. This not only might have a severe performance impact, it also
could overwrite and spam your kernel buffer so it should be avoided.

As always the kernel already provides you with nice functions that solve your
problems:

printk_ratelimited(...)

and

printk_once(...)

printk_once is fairly trivial - no matter how often you call it, it prints once and never again.

printk_ratelimited is a little bit more complicated - it prints by default not more than 10
times in every 5 seconds (for each function it is called in).

If you need other values for the maximum burst count and the timeout, you can
always setup your own ratelimit using the DEFINE_RATELIMIT_STATE macro and
the __ratelimit function - see the implementation of
printk_ratelimited for an example.

Be sure to #include <kernel/ratelimit.h> in order to use
printk_ratelimited()

Both functions have also their pr_* equivalents like
pr_info_ratelimited for printk_ratelimited(KERN_INFO... and
pr_crit_once for printk_once(KERN_CRIT...

Note: both did not work as expected in my tests here, will probably investigate further

Printk from userspace

Sometimes, especially when doing automated testing, it is quite useful to
insert some messages in the kernel log buffer in order to annotate what's
going on.

It is as simple as

# echo "Hello Kernel-World" > /dev/kmsg

Of course this messages gets the default log level assigned, if you want e.g.
to issue a KERN_CRIT message you have to use the string representation of the
log level - in this case "<2>"

The message will appear like any other kernel message - there is no way to distinguish them!

Note: Don't confuse this with printf - we are printing a kernel message
from userspace here.

Internals

Printk is implemented by using a ring buffer in the kernel with a size of
__LOG_BUF_LEN bytes where __LOG_BUF_LEN equals (1 <<
CONFIG_LOG_BUF_SHIFT) (seekernel/printk.c for details).

You can specify the size of the buffer in your kernel config by setting
CONFIG_LOG_BUF_SHIFT to an appropriate value (e.g. 17 for 128Kb) (make menuconfig -> General Setup -> Kernel log buffer size).

Using a ring buffer implies that older messages get overwritten once the
buffer fills up, but this is only a minor drawback compared to the robustness of this
solution (i.e. minimum memory footprint, callable from every context, not many
resources wasted if nobody reads the buffer, no filling up of disk space/ram when some kernel process goes
wild and spams the buffer, ...).
Using a reasonably large buffer size should give you enough time to read your
important messages before they are overwritten.

Note: dmesg reads by default a buffer of max 16392 bytes, so if you use a larger logbuffer you have to invoke dmesg with the -s parameter e.g.:

### CONFIG_LOG_BUF_SHIFT 17 = 128k
$ dmesg -s 128000

The kernel log buffer is accessible for reading from userspace by /proc/kmsg.
/proc/kmsg behaves more or less like a FIFO and blocks until new messages
appear.

Please note - reading from /proc/kmsg consumes the messages in the
ring buffer so they may not be available for other programs. It is usually a
good idea to let klogd or syslog do this job and read the content
of the buffer via dmesg.

Pros and Cons

The main advantage of printk over other debugging solutions is that it requires no sophisticated setup and can be called anywhere from any time.
Printk can be called while holding a lock, from interrupt and process context, is SMP safe and does not need any special preparation. It is just there and just works.
The only precondition is that you have some kind of working console to display the messages.

For the early stages in the boot process, where no console is available yet,
there is a special function named early_printk, this function writes
directly to the VGA buffer or a serial line but otherwise works just like
printk -- you have to enable this function by setting CONFIG_EARLY_PRINTK
in your kernel config (make menuconfig -> Kernel Hacking -> Early printk).

The major drawback is that printk is quite static, so you have to figure out what you want to trace beforehand and if you want to trace something different you have to recompile your code - which can become quite cumbersome. (And of course printk is not interactive at all, so you can't modify any variables or the like.)

The other drawback is that printing usually consumes quite some processing power and io time, so if you're trying to debug a timing critical section or a timing bug, you're probably out of luck.

Debugging early boot problems

Accessing the printk buffer after a silent hang on boot

Sometimes, if the kernel hangs early in the boot process, you get no messages on the console before the hang. However, there may still be messages in the printk buffer, which can give you an idea of where the problem is.

The kernel starts putting messages into the printk buffer as soon as it starts. They stay buffered there until the console code has a chance to initialize the console device (often the serial port for embedded devices). Even though these messages are not printed before the hang, it is still possible in some circumstances
to dump the printk buffer and see the messages.

The tricky parts of doing this are:

using a warm reset (if possible) so the memory contents are not lost when transitioning from the stuck kernel to the bootloader. You can do a cold boot, but if the memory is left unpowered for very long, you will start to see memory corruption.

figuring out the address to use in the bootloader, based on the address of __log_buf in System.map. You will probably need to subtract the value of CONFIG_PAGE_OFFSET from the __log_buf address. However, there may be other offsets present as well (such as TEXT_OFFSET). Sometimes you can find the buffer by dumping the memory in a suspected area and locating the kernel messages visually in the dump. Note that the mapping offset between the kernel map of memory and the bootloader map of memory should not change. So once you figure it out you are set.

Quinn Jensen writes:

Something I've found handy when the console is silent is to dump the printk buffer from the boot loader. To do it you have to know how your boot loader maps memory compared to the kernel.

Redboot example on a Freescale ADS board

Quinn says: Here's what I do with Redboot on i.MX31:

fgrep printk_buf System.map

this shows the linked address of the printk_buf, e.g.:

c02338f0 b printk_buf.16194

The address "c02338f0" is in kernel virtual, which, in the case of i.MX31 ADS, redboot will have mapped to 0x802338f0. So, after resetting the target board, but without letting it try to boot again, at the redboot prompt:

dump -b 0x802338f0 -l 10000

And you see the printk buffer that never got flushed to the UART. Knowing what's there can be very useful in debugging your console.

U-boot example on an OMAP OSK board

Tim Bird tried these steps and they worked:

grep __log_buf System.map

or

grep __log_buf /proc/kallsyms

These show:

c0352d88 B __log_buf

In the case of the OSK, this address maps to 0x10352d88. So I reset the target board and use the following:

Grub

Grub also supports a dump command which you can invoke from the grub prompt.

dump [ -s offset ] [-n length] { FILE | (mem) }

Using CONFIG_DEBUG_LL and printascii() (ARM only)

If the kernel fails before the serial console is enabled, you can use CONFIG_DEBUG_LL to add extra debug output routines to the kernel. These are printascii, printch and printhex. These routines print directly to the serial port, bypassing the console code, and are available earlier in machine initialization.

Here is an e-mail exchange seen on the linux-embedded mailing list (with answer by George Davis):[3]

> When we try to boot a 2.6.21 kernel after uncompressing the kernel the boot process dies somehow.
> We've figured out so far that the kernel dies somewhere between the gunzip and start_kernel.
Try enabling DEBUG_LL to see if it's an machine ID error. If you see:
Error: unrecognized/unsupported processor variant.
or:
Error: unrecognized/unsupported machine ID...
Then you either don't have proper processor support enabled for your target or your bootloader is passing in the wrong machine number.
If you still don't see anything, try hacking printk.c to call printascii() (enabled for the DEBUG_LL case) to print directly to the serial port w/o a driver, etc.,. You can find more details on these low-level debugging hacks via a little googling...

NetConsole

Sometimes you are in the unlucky situation that the machine crashes or hangs and you have no way to access the console afterwards, e.g. the graphic driver hangs and and the kernel dies soon after.
In this case you could either hook up a serial line to your crashing target machine (if a serial port is available) or use the kernels netconsole feature to enable printk logging via UDP.

In order to use it you have to enable the CONFIG_NETCONSOLE kernel config
option (make menuconfig -> Device Drivers -> Network device support -> Network core driver support -> Network console logging support) and
configure it appropriately by using the netconsole configuration parameter

If you need something more sophisticated and flexible maybe have a look at
print_hex_dump() and hex_dump_to_buffer()

Dynamic Debugging

It is also possible to enable/disable debug information at runtime using the
dynamic debug functionality of the kernel.
For this the CONFIG_DYNAMIC_DEBUG kernel config option must be set.
See
Documentation/dynamic-debug-howto.txt for more information.

Disabling printk messages at compile time

There is a configuration option which allows you to turn off all the printk messages in the
whole kernel (CONFIG_PRINTK). This reduces the size the kernel, usually by at least 100k,
since all message strings are not compiled into the kernel binary image.

However, it also means you get absolutely no output from the kernel while it is running. Disabling kernel
printk messages is usually the last thing you do when you are tuning your kernel for size.