Debugging by printing - kernel - printk


http://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.

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 logbuffer 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 inDocumentation/printk-formats.txt

However please note: always use %zu, %zd or%zx for printingsize_t and ssize_t values. ssize_t and size_t are quite common values in the kernel, soplease 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 ininclude/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:

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 pr_err
KERN_WARNING "4" A warning, meaning nothing serious by itself but might indicate problems pr_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 initialization pr_info
KERN_DEBUG "7" Debug messages pr_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 characterwhose ASCII value is '\001'. Read the source for more details.


The pr_* macros (with exception of pr_debug) are simple shorthand definitionsin include/linux/printk.hfor 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 wascompiled withDEBUG, 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 toDEFAULT_MESSAGE_LOGLEVEL (usually"4"=KERN_WARNING)which can be set via the CONFIG_DEFAULT_MESSAGE_LOGLEVEL kernel configoption (make menuconfig-> Kernel Hacking -> Default message log level)


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

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

To determine your current console_loglevel you simply enter:

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

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


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

# 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 -nparameter

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

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

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

Author's practical advice:
Of course you should always specify an appropriate log level for your messages,but fordebugging, I guess most developers leave theconsole_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 beforeshipping 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.:

printk(KERN_ERR "Doing something was ");
/* <100 lines of whatever>*/
if (success)
   printk(KERN_CONT "successful\n");
else
   printk(KERN_CONT "NOT successful\n");

-> "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 calledquite often. This not only might have a severe performance impact, it alsocould overwrite and spam your kernel buffer so it should be avoided.

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

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 10times 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 canalways setup your own ratelimit using theDEFINE_RATELIMIT_STATE macro andthe __ratelimit function - see the implementation ofprintk_ratelimited for an example.

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

Both functions have also their pr_* equivalents likepr_info_ratelimited forprintk_ratelimited(KERN_INFO... andpr_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 toinsert some messages in the kernel log buffer in order to annotate what'sgoing 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 thelog level - in this case "2"

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

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

Note: Don't confuse this with printf - we are printing a kernel messagefrom 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) (seekernel/printk.c for details).

You can specify the size of the buffer in your kernel config by settingCONFIG_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 thebuffer fills up, but this is only a minor drawback compared to the robustness of thissolution (i.e. minimum memory footprint, callable from every context, not manyresources wasted if nobody reads the buffer, no filling up of disk space/ram when some kernel process goeswild and spams the buffer, ...).Using a reasonably large buffer size should give you enough time to read yourimportant 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 messagesappear.


Please note - reading from /proc/kmsg consumes the messages in thering buffer so they may not be available for other programs. It is usually agood idea to letklogd or syslog do this job and read the contentof the buffer viadmesg.

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 namedearly_printk, this function writesdirectly to the VGA buffer or a serial line but otherwise works just likeprintk -- you have to enable this function by settingCONFIG_EARLY_PRINTKin 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 circumstancesto 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. Youcan 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:

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 bevery 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:

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

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.

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

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

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 configoption (make menuconfig -> Device Drivers -> Network device support -> Network core driver support -> Network console logging support) andconfigure it appropriately by using the netconsole configuration parameter

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

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

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

# 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

# netcat -u -l -p <port>

e.g.

$ 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 ahigher value (see above) or test the connection via telnet e.g. from the target type

$ telnet 10.0.0.2 6666


Netconsole resources

SeeDocumentation/networking/netconsole.txtfor more details.

See Sarah Sharp's blog entry about using netconsole( http://sarah.thesharps.us/2010/03/26/update-for-netconsole-tutorial/ )

Misc

Dmesg / Clearing the buffer

dmesg -c

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

Printk Timestamps

CONFIG_PRINTK_TIME

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

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

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

Also, there are tools available to use the information to show relative timesbetween printks (scripts/show_delta) and create graphs of durations in thekernel (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 thewheel useprintk_hex_dump_bytes() instead.

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:

Kernel Code:
char mybuf[] = "abcdef";
print_hex_dump_bytes("", DUMP_PREFIX_NONE, mybuf, ARRAY_SIZE(mybuf));

dmesg output:
61 62 63 64 65 66 00                             abcdef.

If you need something more sophisticated and flexible maybe have a look atprint_hex_dump() andhex_dump_to_buffer()

Dynamic Debugging

It is also possible to enable/disable debug information at runtime using thedynamic debug functionality of the kernel.For this theCONFIG_DYNAMIC_DEBUG kernel config option must be set.SeeDocumentation/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 thewhole 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 kernelprintk messages is usually the last thing you do when you are tuning your kernel for size.

References and external links



Some page related to printk:


posted @ 2016-09-02 17:16  张同光  阅读(164)  评论(0)  编辑  收藏  举报