Talk more about backtraces.

[pintos-anon] / doc / debug.texi

@node Debugging Tools, Development Tools, Project Documentation, Top
@appendix Debugging Tools

Many tools lie at your disposal for debugging Pintos.  This appendix
introduces you to a few of them.

@menu
* printf::                      
* ASSERT::                      
* DEBUG::                       
* UNUSED NO_RETURN NO_INLINE PRINTF_FORMAT::  
* Backtraces::                  
* i386-elf-gdb::                
* Debugging by Infinite Loop::  
* Modifying Bochs::             
* Debugging Tips::              
@end menu

@node printf
@section @code{@code{printf()}}

Don't underestimate the value of @func{printf}.  The way
@func{printf} is implemented in Pintos, you can call it from
practically anywhere in the kernel, whether it's in a kernel thread or
an interrupt handler, almost regardless of what locks are held.

@func{printf} isn't useful just because it can print data members.
It can also help figure out when and where something goes wrong, even
when the kernel crashes or panics without a useful error message.  The
strategy is to sprinkle calls to @func{print} with different strings
(e.g.@: @code{"1\n"}, @code{"2\n"}, @dots{}) throughout the pieces of
code you suspect are failing.  If you don't even see @code{1} printed,
then something bad happened before that point, if you see @code{1}
but not @code{2}, then something bad happened between those two
points, and so on.  Based on what you learn, you can then insert more
@func{printf} calls in the new, smaller region of code you suspect.
Eventually you can narrow the problem down to a single statement.

@node ASSERT
@section @code{ASSERT}

Assertions are useful because they can catch problems early, before
they'd otherwise be notices.  Pintos provides a macro for assertions
named @code{ASSERT}, defined in @file{<debug.h>}, that you can use for
this purpose.  Ideally, each function should begin with a set of
assertions that check its arguments for validity.  (Initializers for
functions' local variables are evaluated before assertions are
checked, so be careful not to assume that an argument is valid in an
initializer.)  You can also sprinkle assertions throughout the body of
functions in places where you suspect things are likely to go wrong.

When an assertion proves untrue, the kernel panics.  The panic message
should help you to find the problem.  See the description of
backtraces below for more information.

@node DEBUG
@section @code{DEBUG}

The @code{DEBUG} macro, also defined in @file{<debug.h>}, is a sort of
conditional @func{printf}.  It takes as its arguments the name of a
``message class'' and a @func{printf}-like format string and
arguments.  The message class is used to filter the messages that are
actually displayed.  You select the messages to display on the Pintos
command line using the @option{-d} option.  This allows you to easily
turn different types of messages on and off while you debug, without
the need to recompile.

For example, suppose you want to output thread debugging messages.  To
use a class named @code{thread}, you could invoke @code{DEBUG} like
this:
@example
DEBUG(thread, "thread id: %d\n", id);
@end example
@noindent
and then to start Pintos with @code{thread} messages enable you'd use
a command line like this:
@example
pintos run -d thread
@end example

@node UNUSED NO_RETURN NO_INLINE PRINTF_FORMAT
@section UNUSED, NO_RETURN, NO_INLINE, and PRINTF_FORMAT

These macros defined in @file{<debug.h>} tell the compiler special
attributes of a function or function parameter.  Their expansions are
GCC-specific.

@defmac UNUSED
Appended to a function parameter to tell the compiler that the
parameter might not be used within the function.  It suppresses the
warning that would otherwise appear.
@end defmac

@defmac NO_RETURN
Appended to a function prototype to tell the compiler that the
function never returns.  It allows the compiler to fine-tune its
warnings and its code generation.
@end defmac

@defmac NO_INLINE
Appended to a function prototype to tell the compiler to never emit
the function in-line.  Occasionally useful to improve the quality of
backtraces (see below).
@end defmac

@defmac PRINTF_FORMAT (@var{format}, @var{first})
Appended to a function prototype to tell the compiler that the
function takes a @func{printf}-like format string as its
@var{format}th argument and that the corresponding value arguments
start at the @var{first}th argument.  This lets the compiler tell you
if you pass the wrong argument types.
@end defmac

@node Backtraces
@section Backtraces

When the kernel panics, it prints a ``backtrace,'' that is, a summary
of how your program got where it is, as a list of addresses inside the
functions that were running at the time of the panic.  You can also
insert a call to @func{debug_backtrace}, prototyped in
@file{<debug.h>}, at any point in your code.

The addresses in a backtrace are listed as raw hexadecimal numbers,
which are meaningless in themselves.  You can translate them into
function names and source file line numbers using a tool called
@command{i386-elf-addr2line}.@footnote{If you're using an 80@var{x}86
system for development, it's probably just called
@command{addr2line}.}

The output format of @command{i386-elf-addr2line} is not ideal, so
we've supplied a wrapper for it simply called @command{backtrace}.
Give it the name of your @file{kernel.o} as the first argument and the
hexadecimal numbers composing the backtrace (including the @samp{0x}
prefixes) as the remaining arguments.  It outputs the function name
and source file line numbers that correspond to each address.  

If the translated form of a backtrace is garbled, or doesn't make
sense (e.g.@: function A is listed above function B, but B doesn't
call A), then it's a good sign that you're corrupting a kernel
thread's stack, because the backtrace is extracted from the stack.
Alternatively, it could be that the @file{kernel.o} you passed to
@command{backtrace} does not correspond to the kernel that produced
the backtrace.

@menu
* Backtrace Example::           
@end menu

@node Backtrace Example
@subsection Example

Here's an example.  Suppose that Pintos printed out this following call
stack, which is taken from an actual Pintos submission for the file
system project:

@example
Call stack: 0xc0106eff 0xc01102fb 0xc010dc22 0xc010cf67 0xc0102319
0xc010325a 0x804812c 0x8048a96 0x8048ac8.
@end example

You would then invoke the @command{backtrace} utility like shown below,
cutting and pasting the backtrace information into the command line.
This assumes that @file{kernel.o} is in the current directory.  You
would of course enter all of the following on a single shell command
line:

@example
backtrace kernel.o 0xc0106eff 0xc01102fb 0xc010dc22 0xc010cf67 0xc0102319
0xc010325a 0x804812c 0x8048a96 0x8048ac8
@end example

The backtrace output would then look something like this:

@example
0xc0106eff: debug_panic (../../lib/debug.c:86)
0xc01102fb: file_seek (../../filesys/file.c:405)
0xc010dc22: seek (../../userprog/syscall.c:744)
0xc010cf67: syscall_handler (../../userprog/syscall.c:444)
0xc0102319: intr_handler (../../threads/interrupt.c:334)
0xc010325a: ?? (threads/intr-stubs.S:1554)
0x804812c: ?? (??:0)
0x8048a96: ?? (??:0)
0x8048ac8: ?? (??:0)
@end example

(You will probably not get the same results if you run the command above
on your own kernel binary, because the source code you compiled from is
different from the source code that emitted the panic message.)

The first line in the backtrace refers to @func{debug_panic}, the
function that implements kernel panics.  Because backtraces commonly
result from kernel panics, @func{debug_panic} will often be the first
function shown in a backtrace.

The second line shows @func{file_seek} to be the function that panicked,
in this case as the result of an assertion failure.  In the source code
tree used for this example, line 405 of @file{filesys/file.c} is the
assertion

@example
ASSERT (file_ofs >= )0;
@end example

@noindent
Thus, @func{file_seek} panicked because it passed a negative file offset
argument.

The third line indicates that @func{seek} called @func{file_seek},
presumably without validating the offset argument.  In this submission,
@func{seek} implements the @code{seek} system call.

The fourth line shows that @func{syscall_handler}, the system call
handler, invoked @func{seek}.

The fifth and sixth lines are the interrupt handler entry path.

The remaining lines are for addresses below @code{PHYS_BASE}.  This
means that they refer to addresses in the user program, not in the
kernel.  If you know what user program was running when the kernel
panicked, you can re-run @command{backtrace} on the user program.  You
need to have compiled the user program with debug symbols enabled for
this to be useful.  Instructions for doing so are included in
@file{pintos/src/Makefile.userprog}.

In this case, we rerun @command{backtrace} like so (typing the command
on a single line, of course):

@example
~/cs140/pintos/src/utils/backtrace grow-too-big 0xc0106eff 0xc01102fb
0xc010dc22 0xc010cf67 0xc0102319 0xc010325a 0x804812c 0x8048a96
0x8048ac8
@end example

The results look like this:

@example
0xc0106eff: ?? (??:0)
0xc01102fb: ?? (??:0)
0xc010dc22: ?? (??:0)
0xc010cf67: ?? (??:0)
0xc0102319: ?? (??:0)
0xc010325a: ?? (??:0)
0x804812c: test_main (/home/blp/cs140/pintos/grading/filesys/grow-too-big.c:20)
0x8048a96: main (/home/blp/cs140/pintos/grading/filesys/fsmain.c:10)
0x8048ac8: _start (../../src/lib/user/entry.c:9)
@end example

@node i386-elf-gdb
@section @command{i386-elf-gdb}

You can run the Pintos kernel under the supervision of the
@command{i386-elf-gdb} debugger.@footnote{If you're using an
80@var{x}86 system for development, it's probably just called
@command{addr2line}.}  There are two steps in the process.  First,
start Pintos with the @option{--gdb} option, e.g.@: @command{pintos
--gdb run}.  Second, in a second terminal, invoke @command{gdb} on
@file{kernel.o}:
@example
i386-elf-gdb kernel.o
@end example
@noindent and issue the following @command{gdb} command:
@example
target remote localhost:1234
@end example

At this point, @command{gdb} is connected to Bochs over a local
network connection.  You can now issue any normal @command{gdb}
commands.  If you issue the @samp{c} command, the Bochs BIOS will take
control, load Pintos, and then Pintos will run in the usual way.  You
can pause the process at any point with @key{Ctrl+C}.  If you want
@command{gdb} to stop when Pintos starts running, set a breakpoint on
@func{main} with the command @code{break main} before @samp{c}.

You can read the @command{gdb} manual by typing @code{info gdb} at a
terminal command prompt, or you can view it in Emacs with the command
@kbd{C-h i}.  Here's a few commonly useful @command{gdb} commands:

@table @code
@item c
Continue execution until the next breakpoint or until @key{Ctrl+C} is
typed.

@item break @var{function}
@itemx break @var{filename}:@var{linenum}
@itemx break *@var{address}
Sets a breakpoint at the given function, line number, or address.
(Use a @samp{0x} prefix to specify an address in hex.)

@item p @var{expression}
Evaluates the given C expression and prints its value.
If the expression contains a function call, the function will actually
be executed, so be careful.

@item l *@var{address}
Lists a few lines of code around the given address.
(Use a @samp{0x} prefix to specify an address in hex.)

@item bt
Prints a stack backtrace similar to that output by the
@command{backtrace} program described above.

@item p/a @var{address}
Prints the name of the function or variable that occupies the given
address.
(Use a @samp{0x} prefix to specify an address in hex.)
@end table

You might notice that @command{gdb} tends to show code being executed
in an order different from the order in the source.  That is, the
current statement jumps around seemingly randomly.  This is due to
GCC's optimizer, which does tend to reorder code.  If it bothers you,
you can turn off optimization by editing
@file{pintos/src/Make.config}, removing @option{-O3} from the
@code{CFLAGS} definition.

If you notice other strange behavior while using @command{gdb}, there
are three possibilities.  The first is that there is a bug in your
modified Pintos.  The second is that there is a bug in Bochs's
interface to @command{gdb} or in @command{gdb} itself.  The third is
that there is a bug in the original Pintos code.  The first and second
are quite likely, and you should seriously consider both.  We hope
that the third is less likely, but it is also possible.

@node Debugging by Infinite Loop
@section Debugging by Infinite Loop

If you get yourself into a situation where the machine reboots in a
loop, you've probably hit a ``triple fault.''  In such a situation you
might not be able to use @func{printf} for debugging, because the
reboots might be happening even before everything needed for
@func{printf} is initialized.  In such a situation, you might want to
try what I call ``debugging by infinite loop.''

What you do is pick a place in the Pintos code, insert the statement
@code{for (;;);} there, and recompile and run.  There are two likely
possibilities:

@itemize @bullet
@item
The machine hangs without rebooting.  If this happens, you know that
the infinite loop is running.  That means that whatever caused the
problem must be @emph{after} the place you inserted the infinite loop.
Now move the infinite loop later in the code sequence.

@item
The machine reboots in a loop.  If this happens, you know that the
machine didn't make it to the infinite loop.  Thus, whatever caused the
reboot must be @emph{before} the place you inserted the infinite loop.
Now move the infinite loop earlier in the code sequence.
@end itemize

If you move around the infinite loop in a ``binary search'' fashion, you
can use this technique to pin down the exact spot that everything goes
wrong.  It should only take a few minutes at most.

@node Modifying Bochs
@section Modifying Bochs

An advanced debugging technique is to modify and recompile the
simulator.  This proves useful when the simulated hardware has more
information than it makes available to the OS.  For example, page
faults have a long list of potential causes, but the hardware does not
report to the OS exactly which one is the particular cause.
Furthermore, a bug in the kernel's handling of page faults can easily
lead to recursive faults, but a ``triple fault'' will cause the CPU to
reset itself, which is hardly conducive to debugging.

In a case like this, you might appreciate being able to make Bochs
print out more debug information, such as the exact type of fault that
occurred.  It's not very hard.  You start by retrieving the source
code for Bochs 2.1.1 from @uref{http://bochs.sourceforge.net} and
extracting it into a directory.  Then read
@file{pintos/src/misc/bochs-2.1.1.patch} and apply the patches needed.
Then run @file{./configure}, supplying the options you want (some
suggestions are in the patch file).  Finally, run @command{make}.
This will compile Bochs and eventually produce a new binary
@file{bochs}.  To use your @file{bochs} binary with @command{pintos},
put it in your @env{PATH}, and make sure that it is earlier than
@file{/usr/class/cs140/i386/bochs}.

Of course, to get any good out of this you'll have to actually modify
Bochs.  Instructions for doing this are firmly out of the scope of
this document.  However, if you want to debug page faults as suggested
above, a good place to start adding @func{printf}s is
@func{BX_CPU_C::dtranslate_linear} in @file{cpu/paging.cc}.

@node Debugging Tips
@section Tips

The page allocator in @file{threads/palloc.c} clears all the bytes in
pages to @t{0xcc} when they are freed.  Thus, if you see an attempt to
dereference a pointer like @t{0xcccccccc}, or some other reference to
@t{0xcc}, there's a good chance you're trying to reuse a page that's
already been freed.  Also, byte @t{0xcc} is the CPU opcode for
``invoke interrupt 3,'' so if you see an error like @code{Interrupt
0x03 (#BP Breakpoint Exception)}, Pintos tried to execute code in a
freed page.

Similarly, the block allocator in @file{threads/malloc.c} clears all
the bytes in freed blocks to @t{0xcd}.  The two bytes @t{0xcdcd} are
a CPU opcode for ``invoke interrupt @t{0xcd},'' so @code{Interrupt
0xcd (unknown)} is a good sign that you tried to execute code in a
block freed with @func{free}.