Debugging Tools
***************

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

printf()
========

Don't underestimate the value of printf.  The way 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.

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 print with different strings (e.g. "1\n", "2\n", ...) throughout the pieces of code you suspect are failing.  If you don't even see 1 printed, then something bad happened before that point, if you see 1 but not 2, then something bad happened between those two points, and so on.  Based on what you learn, you can then insert more printf calls in the new, smaller region of code you suspect. Eventually you can narrow the problem down to a single statement.

ASSERT
======

Assertions are useful because they can catch problems early, before they'd otherwise be notices.  Pintos provides a macro for assertions named ASSERT, defined in <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.

DEBUG
=====

The DEBUG macro, also defined in <debug.h>, is a sort of conditional printf.  It takes as its arguments the name of a ``message class'' and a 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 -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 thread, you could invoke DEBUG like this:

     DEBUG(thread, "thread id: %d\n", id);

and then to start Pintos with thread messages enable you'd use a command line like this:

     pintos run -d thread

UNUSED, NO_RETURN, NO_INLINE, and PRINTF_FORMAT
===============================================

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

 -- Macro: 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.

 -- Macro: 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.

 -- Macro: 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).

 -- Macro: PRINTF_FORMAT (FORMAT, FIRST)
     Appended to a function prototype to tell the compiler that the function takes a printf-like format string as its FORMATth argument and that the corresponding value arguments start at the FIRSTth argument.  This lets the compiler tell you if you pass the wrong argument types.

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 debug_backtrace, prototyped in <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 i386-elf-addr2line. (If you're using an 80X86 system for development, it's probably just called addr2line.)

The output format of i386-elf-addr2line is not ideal, so we've supplied a wrapper for it simply called backtrace. Give it the name of your kernel.o as the first argument and the hexadecimal numbers composing the backtrace (including the 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 kernel.o you passed to backtrace does not correspond to the kernel that produced the backtrace.

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:

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

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

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

The backtrace output would then look something like this:

     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)

(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 debug_panic, the function that implements kernel panics.  Because backtraces commonly result from kernel panics, debug_panic will often be the first function shown in a backtrace.

The second line shows 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 filesys/file.c is the assertion

     ASSERT (file_ofs >= )0;

Thus, file_seek panicked because it passed a negative file offset argument.

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

The fourth line shows that syscall_handler, the system call handler, invoked seek.

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

The remaining lines are for addresses below 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 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 pintos/src/Makefile.userprog.

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

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

The results look like this:

     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)

i386-elf-gdb
============

You can run the Pintos kernel under the supervision of the i386-elf-gdb debugger. (If you're using an 80X86 system for development, it's probably just called addr2line.)  There are two steps in the process.  First, start Pintos with the --gdb option, e.g. pintos --gdb run.  Second, in a second terminal, invoke gdb on kernel.o:

     i386-elf-gdb kernel.o

and issue the following gdb command:

     target remote localhost:1234

At this point, gdb is connected to Bochs over a local network connection.  You can now issue any normal gdb commands.  If you issue the 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 Ctrl+C.  If you want gdb to stop when Pintos starts running, set a breakpoint on main with the command break main before c.

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

c
     Continue execution until the next breakpoint or until Ctrl+C is typed.

break FUNCTION
break FILENAME:LINENUM
break *ADDRESS
     Sets a breakpoint at the given function, line number, or address. (Use a 0x prefix to specify an address in hex.)

p 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.

l *ADDRESS
     Lists a few lines of code around the given address. (Use a 0x prefix to specify an address in hex.)

bt
     Prints a stack backtrace similar to that output by the backtrace program described above.

p/a ADDRESS
     Prints the name of the function or variable that occupies the given address. (Use a 0x prefix to specify an address in hex.)

You might notice that 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 pintos/src/Make.config, removing -O3 from the CFLAGS definition.

If you notice other strange behavior while using 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 gdb or in 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.

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 printf for debugging, because the reboots might be happening even before everything needed for 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 for (;;); there, and recompile and run.  There are two likely possibilities:

  * 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 after the place you inserted the infinite loop. Now move the infinite loop later in the code sequence.

  * 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 before the place you inserted the infinite loop. Now move the infinite loop earlier in the code sequence.

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.

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 http://bochs.sourceforge.net and extracting it into a directory.  Then read pintos/src/misc/bochs-2.1.1.patch and apply the patches needed. Then run ./configure, supplying the options you want (some suggestions are in the patch file).  Finally, run make. This will compile Bochs and eventually produce a new binary bochs.  To use your bochs binary with pintos, put it in your PATH, and make sure that it is earlier than /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 printfs is BX_CPU_C::dtranslate_linear in cpu/paging.cc.

Tips
====

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

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