Difference between revisions of "Kernel Debugging Tips"

From eLinux.org
Jump to: navigation, search
(add a tip for generating preprocessed (.i) output)
(Added links to content consolidated with Debugging_by_printing)
(12 intermediate revisions by 3 users not shown)
Line 4: Line 4:
 
To add your own debug message to the kernel, you can place a "printk()" in the kernel code.
 
To add your own debug message to the kernel, you can place a "printk()" in the kernel code.
  
These messages are logged to an internal buffer, and eventually displayed by the kernel,
+
See [[Debugging_by_printing#Usage| Debugging by printing -> Usage]] for more details.
being emitted to whatever is the active console, at the time of display.  Since the console
 
is not initialized until part-way through the boot sequence, several messages build up in
 
the log until the console is initialize, at which point all buffered messages are displayed
 
at once.
 
 
 
After the messages are displayed on the kernel console, they are left in the log buffer (which
 
is a ring buffer), and they can be (and usually are) retrieved later by various commands.
 
 
 
printk is a variable-argument function, just like printf.  Note that there is no "printf()"
 
function for the kernel.  "printk()" is used to specifically remind kernel developers
 
that the environment is different.
 
 
 
printk can use many standard C-style printf format characters, but not all of them.  See the
 
kernel source for examples of what you can do.
 
  
 
=== Log levels ===
 
=== Log levels ===
 
Each kernel message can be pre-pended with a tag indicating the importance of the message.
 
Each kernel message can be pre-pended with a tag indicating the importance of the message.
The message tags are shown in the file include/linux/kernel.h.  The available tags are:
 
KERN_EMERG, KERN_ALERT, KERN_CRIT, KERN_WARNING, KERN_NOTICE, KERN_INFO, KERN_DEBUG.
 
  
Note that these tags are defined as simple strings, with angle brackets and a number:
+
See [[Debugging_by_printing#Log_Levels| Debugging by printing -> Log_Levels]] for more details.
#define      KERN_INFO      "<6>"
 
 
 
You could place the tag onto front of the string without using the #define, but that is
 
considered very bad form, and is discouraged.
 
 
 
The way the tag is placed on the string is with C string concatenation:
 
printk(KERN_DEBUG "This is a debug message\n");
 
 
 
Note that there is no comma between the tag macro and the message string.
 
  
 
=== Adding timing information ===
 
=== Adding timing information ===
Sometimes, it is useful to add timing information to the printk values, so you
+
Sometimes, it is useful to add timing information to the printk values, so you can see when a particular event occurred.  The kernel includes an feature for doing
can see when a particular event occurred.  The kernel includes an feature for doing
 
 
this called printk times.
 
this called printk times.
  
See the help for CONFIG_PRINTK_TIMES in the file lib/Kconfig.debug for more information on
+
See the help for CONFIG_PRINTK_TIMES in the file lib/Kconfig.debug for more information on this feature.  This option is found on the "Kernel Hacking" menu when configuring the kernel.
this feature.  This option is found on the "Kernel Hacking" menu when configuring the kernel.
 
  
The timestamps which are inserted into the printk output consist of seconds and microseconds,
+
The timestamps which are inserted into the printk output consist of seconds and microseconds, as absolute values from the start of machine operation (or from the start of kernel timekeeping).
as absolute values from the start of machine operation (or from the start of kernel timekeeping).
 
  
There is also tool in the kernel source which will convert the timestamp values to relative
+
There is also tool in the kernel source which will convert the timestamp values to relative values (so you can see the interval between events).  This tools is called show_delta and is located in the kernel 'scripts' directory.
values (so you can see the interval between events).  This tools is called show_delta and is
 
located in the kernel 'scripts' directory.
 
  
 
See [[Printk Times]] for more information.
 
See [[Printk Times]] for more information.
  
 
=== Viewing log messages ===
 
=== Viewing log messages ===
The <tt>klogd</tt> program will extract messages from the kernel log buffer, and send them to the system
+
The <tt>klogd</tt> program will extract messages from the kernel log buffer, and send them to the system log (which winds up in /var/log/messages on most systems).  This command runs in the background on most desktop or server systems, and continually transfers messages from the kernel log buffer to the system log.
log (which winds up in /var/log/messages on most systems).  This command runs in the background
 
on most desktop or server systems, and continually transfers messages from the kernel log
 
buffer to the system log.
 
  
You can view the contents of the log buffer directly, using the <tt>dmesg</tt> command.  Note that by
+
You can view the contents of the log buffer directly, using the <tt>dmesg</tt> command.  Note that by default <tt>dmesg</tt> displays the messages from the buffer, but does not remove them.  So this command can be run multiple times to view the kernel printk messages.  See the dmesg man page for more things you can do with this tool.
default <tt>dmesg</tt> displays the messages from the buffer, but does not remove them.  So this command
 
can be run multiple times to view the kernel printk messages.  See the dmesg man page for more things
 
you can do with this tool.
 
  
 
=== Controlling console output ===
 
=== Controlling console output ===
In order to have the kernel boot be less "noisy", or in order to boot more quickly, it is sometimes
+
In order to have the kernel boot be less "noisy", or in order to boot more quickly, it is sometimes useful to control the amount of messages displayed to the console during boot.  You can do this by setting the kernel log level at boot time via a kernel command line option. See the "loglevel=" argument in <tt>Documentation/kernel-parameters.txt</tt>.
useful to control the amount of messages displayed to the console during boot.  You can do this
 
by setting the kernel log level at boot time via a kernel command line option. See the "loglevel="
 
argument in <tt>Documentation/kernel-parameters.txt</tt>.
 
  
You can turn off all messages using the kernel command line option "quiet".
+
You can turn off all messages using the kernel command line option "quiet". See [[Disable Console]] for information on how much time this can save at boot up.
See [[Disable Console]] for information on how much time this save at boot up.
 
  
Note that even if the log level is changed, or "quiet" is used, although the printk messages
+
Note that even if the log level is changed, or "quiet" is used, although the printk messages are not print to console, they are still entered into the log buffer, and they can still be extracted and displayed later using the <tt>dmesg</tt> command.
are not print to console, they are still entered into the log buffer, and they can still be
 
extracted and displayed later using the <tt>dmesg</tt> command.
 
  
 
=== Changing the size of the printk buffer ===
 
=== Changing the size of the printk buffer ===
The size of the buffer that printk writes to is referred to in the kernel source as the "log buffer".
+
See [[Debugging_by_printing#Internals_.2F_Changing_the_size_of_the_printk_buffer | Debugging by printing -> Internals / Changing the size of the printk buffer ]]
  
You can make the log buffer larger when you build the kernel.
+
== Using kernel symbols ==
This is useful for when additional printk data (such as extra messages inserted
+
You can look up the source code for a function address using your toolchain's addr2line program.
for debugging) is produced by the kernel and it overflows the regular buffer.
+
See [[Find a kernel function line]] or [[Addr2line for kernel debugging]].
The log buffer is a ring buffer, so later messages will overwrite the earliest messages
 
in the buffer if too much data is written before the log buffer is drained (by, e.g. klogd or dmesg)
 
  
Step 1: Change the kernel log buffer size:
+
== Using a kernel debugger ==
 +
You can use the in-kernel debugger: [[KDB]]
  
On the General Setup menu, change "Kernel log buffer size" to a larger number.
+
Also, you can use QEMU and gdb (and a high-level IDE like eclipse).
This corresponds to LOG_BUF_SHIFT, which is the power-of-two size of the log buffer.
 
By default, this is 14, which yeilds a log buffer size of 16KB.  Changing this to
 
17 will yield a log buffer size of 128KB.
 
  
Set the option, then re-build and install the kernel for booting on the target board.
+
See [http://issaris.blogspot.com/2007/12/download-linux-kernel-sourcecode-from.html Debugging the Linux kernel using Eclipse/CDT and Qemu] for a great article on using Eclipse (with the CDT plugin) to debug the Linux kernel.
  
Step 2: Tell dmesg to retrieve the larger buffer:
 
Even though the buffer is larger in the kernel, dmesg will still default to only
 
reading 16K, unless told otherwise.  To read the full buffer, use the '-s' option
 
like so: "dmesg -s 128000"
 
  
 
== Debugging early boot problems ==
 
== Debugging early boot problems ==
=== Accessing the printk buffer after a silent hang on boot ===
+
See [[Debugging_by_printing#Debugging_early_boot_problems]]
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).  Eve though these messages
 
are no printed before the hang, it is still possible in some circumstances
 
to dump the printk buffer and see the messages.
 
 
 
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:
 
 
 
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
 
...
 
 
 
=== 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):
 
<pre>
 
> 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...
 
</pre>
 
  
 
== Triggering a kernel event ==
 
== Triggering a kernel event ==
 
=== Overloading the sync system call ===
 
=== Overloading the sync system call ===
Sometimes, it is nice to trigger an event to happen in the kernel from user space.
+
Sometimes, it is nice to trigger an event to happen in the kernel from user space. Instead of creating infrastructure to handle a /proc event, an ioctl() or making a new syscall, it can be quick and easy to just overload an existing function.  One function not used very often is sync.  (I have found that the sync system call is not normally called by user space programs (or during standard linux booting).
Instead of creating infrastructure to handle a /proc event, an ioctl() or making a new syscall,
+
 
it can be quick and easy to just overload an existing function.  One function not used
+
It is quite easy to put a hook to your own kernel program in the sys_sync() routine (located in fs/sync.c) and cause it to execute by issuing 'sync' from the shell command line. This is handy as a temporary mechanism to test things that you have put in the kernel.  
very often is sync.  (I have found that the sync system call is not normally called by user
 
space programs (or during standard linux booting).  
 
  
It is quite easy to put a hook to your own kernel program in the sys_sync() routine
 
(located in fs/sync.c) and cause it to execute by issuing 'sync' from the shell command line.
 
This is handy as a temporary mechanism to test things that you have put in the kernel.
 
 
[[Category:Development Tools]]
 
[[Category:Development Tools]]
  
Line 215: Line 68:
  
 
== Compilation tricks for the kernel ==
 
== Compilation tricks for the kernel ==
Sometimes, you want to modify how the compiler builds an individual kernel file.  The following are tips
+
Sometimes, you want to modify how the compiler builds an individual kernel file.  The following are tips for doing tasks related to this.
for doing tasks related to this.
 
 
=== Build an individual file ===
 
=== Build an individual file ===
 
You can build an individual output object file, with:
 
You can build an individual output object file, with:
 
  make fs/buffer.o
 
  make fs/buffer.o
  
This will build JUST fs/buffer.o (if it needs rebuilding) and not the entire kernel.  To force it to
+
This will build JUST fs/buffer.o (if it needs rebuilding) and not the entire kernel.  To force it to need re-building, use 'touch' on the associated source file:  
need re-building, use 'touch' on the associated source file:  
 
 
  touch fs/buffer.c
 
  touch fs/buffer.c
  
Line 230: Line 81:
  
 
=== Create the assembly file for an individual source file ===
 
=== Create the assembly file for an individual source file ===
Using the same technique, you can create the assembly file for a C source file.  This is useful to  
+
Using the same technique, you can create the assembly file for a C source file.  This is useful to get an idea what actual machine instructions are generated from the C source code.
get an idea what actual machine instructions are generated from the C source code.
 
 
  make fs/buffer.s
 
  make fs/buffer.s
  
Line 237: Line 87:
 
  objdump -d fs/buffer.o > fs/buffer.disassem
 
  objdump -d fs/buffer.o > fs/buffer.disassem
  
This will produce a disassembly of the object file, which should show how the
+
This will produce a disassembly of the object file, which should show how the assembly was translated into machine instructions.
assembly was translated into machine instructions.
 
  
If the object has been compiled with debug symbols (using '-g'), then you might
+
If the object has been compiled with debug symbols (using '-g'), then you might get more information using the '-S' option with objdump:
get more information using the '-S' option with objdump:
 
 
  objdump -S -d fs/buffer.o >fs/buffer.disassem
 
  objdump -S -d fs/buffer.o >fs/buffer.disassem
  
You can also request that the toolchain show mixed source and assembly, by
+
You can also request that the toolchain show mixed source and assembly, by passing extra flags:
passing extra flags:
 
 
  make EXTRA_CFLAGS="-g -Wa,-a,-ad -fverbose-asm" fs/buffer.o >fs/buffer.mixed
 
  make EXTRA_CFLAGS="-g -Wa,-a,-ad -fverbose-asm" fs/buffer.o >fs/buffer.mixed
  
 
=== Alter the flags for a compilation ===
 
=== Alter the flags for a compilation ===
Sometimes, you need to alter the compilation flags for an individual file.  There are two ways to do this.
+
Sometimes, you need to alter the compilation flags for an individual file.  There are two ways to do this. One is to add the extra flags on the make command line:
One is to add the extra flags on the make command line:
 
  
 
  make EXTRA_CFLAGS="-g -finstrument-functions" fs/buffer.o
 
  make EXTRA_CFLAGS="-g -finstrument-functions" fs/buffer.o
Line 256: Line 102:
 
This will work if the flags can be appended to the regular set of C flags used for compiling the object.
 
This will work if the flags can be appended to the regular set of C flags used for compiling the object.
  
However, if you need to do something more complicated, like removing or modifying flags, then you can
+
However, if you need to do something more complicated, like removing or modifying flags, then you can build your own command line by hand.  To do this, it is easiest to have 'make' produce the default compilation command (which will be several lines long), then copy, paste and edit it, to run on the command line directly.  To see the exact compile commands used to compile a particular object, use the V=1 option with the kernel build system:
build your own command line by hand.  To do this, it is easiest to have 'make' produce the default compilation command (which will be several lines long), then copy, paste and edit it, to run on the command line directly.  To see the exact compile commands used to compile a particular object, use the V=1 option with the kernel build system:
 
  
 
  make V=1 fs/buffer.o
 
  make V=1 fs/buffer.o

Revision as of 14:33, 3 April 2012

Here are some miscellaneous tips for debugging a kernel:

Using printks

To add your own debug message to the kernel, you can place a "printk()" in the kernel code.

See Debugging by printing -> Usage for more details.

Log levels

Each kernel message can be pre-pended with a tag indicating the importance of the message.

See Debugging by printing -> Log_Levels for more details.

Adding timing information

Sometimes, it is useful to add timing information to the printk values, so you can see when a particular event occurred. The kernel includes an feature for doing this called printk times.

See the help for CONFIG_PRINTK_TIMES in the file lib/Kconfig.debug for more information on this feature. This option is found on the "Kernel Hacking" menu when configuring the kernel.

The timestamps which are inserted into the printk output consist of seconds and microseconds, as absolute values from the start of machine operation (or from the start of kernel timekeeping).

There is also tool in the kernel source which will convert the timestamp values to relative values (so you can see the interval between events). This tools is called show_delta and is located in the kernel 'scripts' directory.

See Printk Times for more information.

Viewing log messages

The klogd program will extract messages from the kernel log buffer, and send them to the system log (which winds up in /var/log/messages on most systems). This command runs in the background on most desktop or server systems, and continually transfers messages from the kernel log buffer to the system log.

You can view the contents of the log buffer directly, using the dmesg command. Note that by default dmesg displays the messages from the buffer, but does not remove them. So this command can be run multiple times to view the kernel printk messages. See the dmesg man page for more things you can do with this tool.

Controlling console output

In order to have the kernel boot be less "noisy", or in order to boot more quickly, it is sometimes useful to control the amount of messages displayed to the console during boot. You can do this by setting the kernel log level at boot time via a kernel command line option. See the "loglevel=" argument in Documentation/kernel-parameters.txt.

You can turn off all messages using the kernel command line option "quiet". See Disable Console for information on how much time this can save at boot up.

Note that even if the log level is changed, or "quiet" is used, although the printk messages are not print to console, they are still entered into the log buffer, and they can still be extracted and displayed later using the dmesg command.

Changing the size of the printk buffer

See Debugging by printing -> Internals / Changing the size of the printk buffer

Using kernel symbols

You can look up the source code for a function address using your toolchain's addr2line program. See Find a kernel function line or Addr2line for kernel debugging.

Using a kernel debugger

You can use the in-kernel debugger: KDB

Also, you can use QEMU and gdb (and a high-level IDE like eclipse).

See Debugging the Linux kernel using Eclipse/CDT and Qemu for a great article on using Eclipse (with the CDT plugin) to debug the Linux kernel.


Debugging early boot problems

See Debugging_by_printing#Debugging_early_boot_problems

Triggering a kernel event

Overloading the sync system call

Sometimes, it is nice to trigger an event to happen in the kernel from user space. Instead of creating infrastructure to handle a /proc event, an ioctl() or making a new syscall, it can be quick and easy to just overload an existing function. One function not used very often is sync. (I have found that the sync system call is not normally called by user space programs (or during standard linux booting).

It is quite easy to put a hook to your own kernel program in the sys_sync() routine (located in fs/sync.c) and cause it to execute by issuing 'sync' from the shell command line. This is handy as a temporary mechanism to test things that you have put in the kernel.

Interpreting an Oops message

When the kernel encounters an internal fault, it will print an Oops message. Here are some tips on using the Oops message to find the source of the problem.

Compilation tricks for the kernel

Sometimes, you want to modify how the compiler builds an individual kernel file. The following are tips for doing tasks related to this.

Build an individual file

You can build an individual output object file, with:

make fs/buffer.o

This will build JUST fs/buffer.o (if it needs rebuilding) and not the entire kernel. To force it to need re-building, use 'touch' on the associated source file:

touch fs/buffer.c

Create the preprocessed file for an individual source file

Using the same technique, you can create the preprocessed file for a C source file. This is useful if you're having trouble tracking down macro expansion or where defines/prototypes are coming from exactly.

make fs/buffer.i

Create the assembly file for an individual source file

Using the same technique, you can create the assembly file for a C source file. This is useful to get an idea what actual machine instructions are generated from the C source code.

make fs/buffer.s

Another way to get the raw assembly, is to dump the object file using 'objdump'

objdump -d fs/buffer.o > fs/buffer.disassem

This will produce a disassembly of the object file, which should show how the assembly was translated into machine instructions.

If the object has been compiled with debug symbols (using '-g'), then you might get more information using the '-S' option with objdump:

objdump -S -d fs/buffer.o >fs/buffer.disassem

You can also request that the toolchain show mixed source and assembly, by passing extra flags:

make EXTRA_CFLAGS="-g -Wa,-a,-ad -fverbose-asm" fs/buffer.o >fs/buffer.mixed

Alter the flags for a compilation

Sometimes, you need to alter the compilation flags for an individual file. There are two ways to do this. One is to add the extra flags on the make command line:

make EXTRA_CFLAGS="-g -finstrument-functions" fs/buffer.o

This will work if the flags can be appended to the regular set of C flags used for compiling the object.

However, if you need to do something more complicated, like removing or modifying flags, then you can build your own command line by hand. To do this, it is easiest to have 'make' produce the default compilation command (which will be several lines long), then copy, paste and edit it, to run on the command line directly. To see the exact compile commands used to compile a particular object, use the V=1 option with the kernel build system:

make V=1 fs/buffer.o

For me, this produced something like this:

mipsel-linux-gcc -Wp,-MD,fs/.buffer.o.d -nostdinc -isystem /home/usr/local/mipsel-linux-glibc/bin/../lib/gcc/mipsisa32el-linux/3.4.3/include -D__KERNEL__ -Iinclude -Iinclude2 -I/home/tbird/work/linux/include -I/home/tbird/work/linux/fs -Ifs -Wall -Wstrict-prototypes -Wno-trigraphs -fno-strict-aliasing -fno-common -ffreestanding -O2 -fomit-frame-pointer -g -I/home/tbird/work/linux/ -I /home/tbird/work/linux/include/asm/gcc -G 0 -mno-abicalls -fno-pic -pipe -finline-limit=100000 -mabi=32 -march=mips32r2 -Wa,-32 -Wa,-march=mips32r2 -Wa,-mips32r2 -Wa,--trap -I/home/tbird/work/linux/include/asm-mips/ati -Iinclude/asm-mips/ati -I/home/tbird/work/linux/include/asm-mips/mach-generic -Iinclude/asm-mips/mach-generic -Wdeclaration-after-statement -DKBUILD_BASENAME=buffer -DKBUILD_MODNAME=buffer -c -o fs/buffer.o /home/tbird/work/linux/fs/buffer.c