|
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[hide]Usageprintk 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.
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: 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 LevelsIf 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/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:
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.
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).
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: $ 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 the default log level that you have seen above.
# 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 # #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 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: 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 ;)
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 messagesOccasionally 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...
Printk from userspaceSometimes, 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" # 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 bufferPrintk 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.: ### 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.
Pros and ConsThe 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 problemsAccessing the printk buffer after a silent hang on bootSometimes, 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:
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 boardQuinn 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 boardTim 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 ... GrubGrub 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=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):[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... NetConsoleSometimes 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 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 a higher value (see above) or test the connection via telnet e.g. from the target type $ telnet 10.0.0.2 6666
Netconsole resourcesSee Documentation/networking/netconsole.txt for more details. See Sarah Sharp's blog entry about using netconsole ( http://sarah./2010/03/26/update-for-netconsole-tutorial/ ) MiscDmesg / Clearing the bufferdmesg -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 TimestampsCONFIG_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: $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 hexIf you want to print a buffer as hex within the kernel, don't reinvent the wheel use printk_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 at print_hex_dump() and hex_dump_to_buffer() Dynamic DebuggingIt 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 timeThere 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. References and external links
|
|
|
