From: eLinux.org

Debugging by printing

Probably the simplest way to get some debug information from your kernel
code is by printing out various information with the kernel’s equivalent
of printf - the printk function and its derivatives. The k in printk is
used to specifically remind kernel developers that the environment is
different.

Contents

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:

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

This wasn’t that difficult, was it?

Usually you would print out some more interesting information like

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

just like in userspace.

In order to see the kernel messages, just use the

  1. $ 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.

The supported format strings are quite extensively documented in
Documentation/printk-formats.txt

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

  1. 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:

  1. 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/kern_levels.h
and specifies 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:








































































NameStringMeaningalias function
KERN_EMERG"0"Emergency messages, system is about to crash or is unstablepr_emerg
KERN_ALERT"1"Something bad happened and action must be taken immediatelypr_alert
KERN_CRIT"2"A critical condition occurred like a serious hardware/software failurepr_crit
KERN_ERR"3"An error condition, often used by drivers to indicate difficulties with the hardwarepr_err
KERN_WARNING"4"A warning, meaning nothing serious by itself but might indicate problemspr_warning
KERN_NOTICE"5"Nothing serious, but notably nevertheless. Often used to report security events.pr_notice
KERN_INFO"6"Informational message e.g. startup information at driver initializationpr_info
KERN_DEBUG"7"Debug messagespr_debug, pr_devel if DEBUG is defined
KERN_DEFAULT"d"The default kernel loglevel
KERN_CONT"""continued" line of log printout (only done after a line that had no enclosing \n) [1]pr_cont

Note that the actual values of the log levels are prepended by the
KERN_SOH character whose ASCII value is ‘\001’. Read the source for
more details.

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.

To determine your current console_loglevel you simply enter:

  1. $ cat /proc/sys/kernel/printk
  2.     7       4       1       7
  3.     current default minimum boot-time-default

The first integer shows you your current console_loglevel; the second
the default log level that you have seen above.

To change your current console_loglevel simply write to this file, so
in order to get all messages printed to the console do a simple

  1. # echo 8 > /proc/sys/kernel/printk

and every kernel message will appear on your console.

Another way to change the console log level is to use dmesg with the
-n parameter

  1. # #set console_loglevel to print KERN_WARNING (4) or more severe messages
  2. # dmesg -n 5

Only messages with a value lower (not lower equal) than the
console_loglevel will be printed.

You can also specify the console_loglevel at boot time using the
loglevel boot parameter. (see
Documentation/kernel-parameters.txt
for more details)

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.

  1. 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.:

  1. printk(KERN_ERR "Doing something was ");
  2. /* <100 lines of whatever>*/
  3. if (success)
  4.    printk(KERN_CONT "successful\n");
  5. else
  6.    printk(KERN_CONT "NOT successful\n");
  8. -> "Doing something was successful"

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:

  1. printk_ratelimited(...)

and

  1. 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 \ 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

  1. # 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”

  1. # echo "2Writing critical printk messages from userspace" >/dev/kmsg

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.

If /dev/kmsg does not exist, it can be created with: ‘mknod -m 600
/dev/kmsg c 1 11’

Internals / Changing the size of the printk buffer

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)(see
kernel/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.:

  1. ### CONFIG_LOG_BUF_SHIFT 17 = 128k
  2. $ 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:

  1. 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.
  2. 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:

  1. fgrep printk_buf System.map

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

  1. 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:

  1. 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:

  1. grep __log_buf System.map

or

  1. grep __log_buf /proc/kallsyms

These show:

  1. 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:

  1. OMAP5912 OSK # md 10352d88
  2. 10352d88: 4c3e353c 78756e69 72657620 6e6f6973    <5>Linux version
  3. 10352d98: 362e3220 2e32322e 612d3631 6e5f706c     2.6.22.16-alp_n
  4. 10352da8: 7428206c 64726962 6d697440 6b736564    l (tbird@timdesk
  5. 10352db8: 2e6d612e 796e6f73 6d6f632e 67282029    .am.sony.com) (g
  6. 10352dc8: 76206363 69737265 33206e6f 342e342e    cc version 3.4.4
  7. 10352dd8: 34232029 45525020 54504d45 65755420    ) #4 PREEMPT Tue
  8. ...

Grub

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

  1. 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.

To see printks earlier in the boot sequence (before the console is
initialized), set CONFIG_DEBUG_LL=y and CONFIG_EARLY_PRINTK=y.

Alternatively, add your own calls to printascii, printch, and printhex
where you believe the problems are located.

Here is an e-mail exchange seen on the linux-embedded mailing list (with
answer by George
Davis):embedded@vger.kernel.org/msg00223.html">[3]

  1. > When we try to boot a 2.6.21 kernel after uncompressing the kernel the boot process dies somehow.
  2. > We've figured out so far that the kernel dies somewhere between the gunzip and start_kernel.
  4. Try enabling DEBUG_LL to see if it's an machine ID error.  If you see:
  6. Error: unrecognized/unsupported processor variant.
  8. or:
  10. Error: unrecognized/unsupported machine ID...
  12. Then you either don't have proper processor support enabled for your target or your bootloader is passing in the wrong machine number.
  14. 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

  1. netconsole=[src-port]@[src-ip]/[<dev>],[tgt-port]@<tgt-ip>/[tgt-macaddr]
  2.     where
  3.         src-port      source for UDP packets (defaults to 6665)
  4.         src-ip        source IP to use (interface address)
  5.         dev           network interface (eth0)
  6.         tgt-port      port for logging agent (6666)
  7.         tgt-ip        IP address for logging agent
  8.         tgt-macaddr   ethernet MAC address for logging agent (broadcast)

e.g. specify at kernel commandline (in your bootloader)

  1. linux netconsole=4444@10.0.0.1/eth1,9353@10.0.0.2/12:34:56:78:9a:bc

to send messages from 10.0.0.1 port 4444 via eth1 to 10.0.0.2 port 9353
with the MAC 12:34:56:78:9a:bc

or while loading the module e.g

  1. # insmod netconsole netconsole=@/,@10.0.0.2/

to send messages via broadcast to 10.0.0.2 port 6666

On the other machine you can now simply fire up

  1. # netcat -u -l -p <port>

e.g.

  1. $ netcat -u -l -p 6666

and see the printk messages from your target dribbling in.

If you don’t see any messages you might have to set the
console_loglevel to a higher value (see above) or test the connection
via telnet e.g. from the target type

  1. $ telnet 10.0.0.2 6666

Netconsole resources

See
Documentation/networking/netconsole.txt
for more details.

See Sarah Sharp’s blog entry about using
netconsole

Misc

Dmesg / Clearing the buffer

  1. dmesg -c

clears the dmesg buffer. Sometimes it is nice to start with a blank
buffer, so you will only see new messages when you invoke dmesg

Printk Timestamps

  1. CONFIG_PRINTK_TIME

Setting this kernel config option prepends every printk statement with a
timestamp representing the time since boot. This is particularly useful
to get a general idea about the timings of your code.

You can also specify an argument on the kernel command line to enable
this, or you can enable it any time at runtime by doing the following:

  1.  $echo 1 >/sys/module/printk/parameters/time

Also, there are tools available to use the information to show relative
times between printks (scripts/show_delta) and create graphs of
durations in the kernel (scripts/bootgraph.pl)

See Printk Times for more details

Printing buffers as hex

If you want to print a buffer as hex within the kernel, don’t reinvent
the wheel use printk_hex_dump_bytes() instead.

  1. print_hex_dump_bytes(const char *prefix_str, int prefix_type, const void *buf, size_t len)

this function prints a buffer as hex values to the kernel log buffer
(with level KERN_DEBUG) Example:

  1. Kernel Code:
  2. char mybuf[] = "abcdef";
  3. print_hex_dump_bytes("", DUMP_PREFIX_NONE, mybuf, ARRAY_SIZE(mybuf));
  5. dmesg output:
  6. 61 62 63 64 65 66 00                             abcdef.

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.

Some page related to printk:

Categories: