Basic Eraser support.

[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::                      
* Function and Parameter Attributes::  
* Backtraces::                  
* Automatic Race Detection with Checkbochs::  
* gdb::                         
* Debugging by Infinite Loop::  
* Modifying Bochs::             
* Debugging Tips::              
@end menu

@node printf
@section @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 (but see
@ref{printf Reboots} for a counterexample).

@func{printf} is useful for more than just examining data.
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>"}, @code{"<2>"}, @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.
@xref{Debugging by Infinite Loop}, for a related technique.

@node ASSERT
@section @code{ASSERT}

Assertions are useful because they can catch problems early, before
they'd otherwise be noticed.  Pintos provides the
@code{ASSERT}, defined in @file{<debug.h>}, for assertions.
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.
They are especially useful for checking loop invariants.

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 Function and Parameter Attributes
@section Function and Parameter Attributes

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 the argument numbered
@var{format} (starting from 1) and that the corresponding value
arguments start at the argument numbered @var{first}.  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>}, to print a backtrace at any point in your code.

The addresses in a backtrace are listed as raw hexadecimal numbers,
which are meaningless by themselves.  You can translate them into
function names and source file line numbers using a tool called
@command{addr2line} (80@var{x}86) or @command{i386-elf-addr2line}
(SPARC).

The output format of @command{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.

Sometimes backtraces can be confusing without implying corruption.
Compiler optimizations can cause surprising behavior.  For example, when
a function has called another function as its final action (a @dfn{tail
call}), the calling function may not appear in a backtrace at all.

@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, even though that would overflow our margins here:

@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 panicked.)

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} as 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
(This line was also cited in the assertion failure message.)
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, like
so: (typing the command on a single line, of course):

@example
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 (../../tests/filesys/extended/grow-too-big.c:20)
0x8048a96: main (../../tests/main.c:10)
0x8048ac8: _start (../../lib/user/entry.c:9)
@end example

Here's an extra tip for anyone who read this far: @command{backtrace}
is smart enough to strip the @code{Call stack:} header and @samp{.}
trailer from the command line if you include them.  This can save you
a little bit of trouble in cutting and pasting.  Thus, the following
command prints the same output as the first one we used:

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

@node Automatic Race Detection with Checkbochs
@section Automatic Race Detection with Checkbochs

In the Pintos projects, especially projects 3 and 4, proper
synchronization is essential for avoiding race conditions.  There is
no substitute for good design, but sometimes tools can help with
debugging an implementation.

We provide a tool called Checkbochs to help find race conditions in
your implementation.  Checkbochs is a version of Bochs which has been
modified by Sorav Bansal to implement the Eraser race-detection
algorithm (@bibref{Eraser}).

Before you can use Checkbochs to to detect data races in your code,
you must first apply a patch to your Pintos source tree.  FIXME

Once you have applied the Checkbochs patch, you can use Checkbochs
simply by adding @option{--checkbochs} to the @command{pintos} command
line.  You can usefully use @option{--checkbochs} in conjunction with
@option{--monitor} or @option{--gdb}, but not @option{--qemu} or
@option{--gsx}.  The only immediate effect of @option{--checkbochs} is
that your run will produce an extra log file, called
@file{checkbochs.log} by default (use @option{--logfile} to change
it).  The log file is a plaintext log of accesses to memory locations
shared by multiple threads.

After you have a log file, use @command{checkbochs-trace} to interpret
it.  First run it without any options, which causes it to report how
many potential race conditions were detected.  If any were detected,
it also tells you the address of the data involved in the race and
writes backtraces for access to data for the first race it detected to
@file{btrace}.  If more than one race was detected, you can request
information about the @var{n}th race, instead, using @option{-n
@var{n}}.

The @file{btrace} file lists a backtrace for each access to the data
item implicated in a race.  Each backtrace is listed across several
lines.  Each backtrace line is divided into several columns containing
a source file name, function name, and line number.  The first line in
each backtrace also identifies the thread (as the physical address of
its @struct{thread}, followed by the state transition of the memory
location in the format @samp{<OldState>-><NewState>}. More
information on the state transition can be found in @bibref{Eraser}.

You can save the trouble of reading the backtraces and looking up
their source file location by hand by using the @option{--cscope}
option to @command{checkbochs-trace}.  This brings up the backtrace
info in @command{cscope}, a program for interactively exploring code,
which lets you quickly view the source lines implicated in each
backtrace.

@menu
* Debugging Race Conditions::   
* Checkbochs Limitations::      
@end menu

@node Debugging Race Conditions
@subsection Debugging Race Conditions

Once you know that there is a race condition at memory location
@var{addr}, you need to know at least two things to debug it.  First,
you need to know what data corresponds to @var{addr}.  If it is global
or @code{static} data, then @command{checkbochs-trace} will normally
print the variable's name.  Otherwise, for automatic (local) or
heap-allocated data, you will have to figure it out by looking at the
backtrace.

Second, you need to know the various points in time during code
execution at which the data variable was accessed, and which thread
made each access.  You can figure this out from the backtraces:
@file{btrace} contains both the types of accesses made and the tids of
the accessing threads.

@node Checkbochs Limitations
@subsection Limitations

Checkbochs can be useful for debugging race conditions, but it has
several limitations.

Checkbochs is subject to false negatives, that is, it will not find
all potential races.  For example, Checkbochs will not detect races
that result from failing to recheck a condition that might have
changed while a lock was released.  Suppose that @code{lock} is a lock
that controls acquisition and release of a resource, such as a page of
memory.  The following code then has a race, because @code{owner} is
not re-checked after releasing and re-acquiring @code{lock}.
Checkbochs fails to detect this race because @code{lock} is always
held when @code{owner} is accessed:

@example
struct thread *owner = NULL; /* Initially no owner. */
struct lock lock;            /* Controls changes to @var{owner}. */

@dots{}

lock_acquire (&lock);
if (owner == NULL)
  @{
    lock_release (&lock);
    @dots{}
    lock_acquire (&lock);
    owner = thread_current ();
    lock_release (&lock);
  @}
@end example

Checkbochs is also subject to false positives, that is, not every race
it reports is really a race.  (This is why they have been called
``potential'' races throughout this section.)  This will occur when
accesses to data are synchronized in a way not visible to Checkbochs.
For example, Checkbochs does not understand all uses of semaphores,
so synchronization via semaphores may be reported as races.

Checkbochs is a dynamic checker, meaning that it actually runs the
code that it checks.  This also means that code that doesn't get run
doesn't get checked, so you can also get false negatives that way.

@node gdb
@section @command{gdb}

You can run the Pintos kernel under the supervision of the
@command{gdb} (80@var{x}86) or @command{i386-elf-gdb} (SPARC)
debugger.  First,
start Pintos with the @option{--gdb} option, e.g.@: @command{pintos
--gdb -- run mytest}.  Second, in a separate terminal, invoke @command{gdb} (or
@command{i386-elf-gdb}) on
@file{kernel.o}:
@example
gdb kernel.o
@end example
@noindent and issue the following @command{gdb} command:
@example
target remote localhost:1234
@end example

Now @command{gdb} is connected to the simulator over a local
network connection.  You can now issue any normal @command{gdb}
commands.  If you issue the @samp{c} command, the simulated 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
Continues execution until @key{Ctrl+C} or the next breakpoint.

@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, that function will actually
be executed.

@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.)

@item diassemble @var{function}
Disassembles the specified @var{function}.
@end table

If you notice other strange behavior while using @command{gdb}, there
are three possibilities: a bug in your
modified Pintos, a bug in Bochs's
interface to @command{gdb} or in @command{gdb} itself, or
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.

You can also use @command{gdb} to debug a user program running under
Pintos.  Start by issuing this @command{gdb} command to load the
program's symbol table:
@example
add-symbol-file @var{program}
@end example
@noindent
where @var{program} is the name of the program's executable (in the host
file system, not in the Pintos file system).  After this, you should be
able to debug the user program the same way you would the kernel, by
placing breakpoints, inspecting data, etc.  Your actions apply to every
user program running in Pintos, not just to the one you want to debug,
so be careful in interpreting the results.  Also, a name that appears in
both the kernel and the user program will actually refer to the kernel
name.  (The latter problem can be avoided by giving the user executable
name on the @command{gdb} command line, instead of @file{kernel.o}.)

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

If you get yourself into a situation where the machine reboots in a
loop, that's probably 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
reboot 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/`uname -m`/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} and the block allocator in
@file{threads/malloc.c} both clear all the bytes in pages and blocks 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 or
block.

An assertion failure on the expression @code{sec_no < d->capacity}
indicates that Pintos tried to access a file through an inode that has
been closed and freed.  Freeing an inode clears its starting sector
number to @t{0xcccccccc}, which is not a valid sector number for disks
smaller than about 1.6 TB.