Debugging the undebuggable – live preview of Linux kernel execution

This is a story about two cool features, I’ve developed recently. One of them is quite clever, whereas the other one not so much.

Couple of weeks ago, I’ve came to the point, where I was ready to run Linux. I’ve got this very simple setup, where ao68000 was connected to the memory and uart, via wishbone arbiter, hardcoded to one master, and two slaves, multiplexed by 24th address pin. I managed to obtain and compile Linux Kernel, version 2.6.33.1, that was used by Aleksander O., the founder of ao68000. The compiler was generated by crosstool-ng, vmem image was built by custom shell script.

The uart module was modified to use $write task, every time kernel writes a character to send, so all characters would be displayed in Linux console. I have also written simple asembler code to test, if it is able to print some strings on the linux console.  I ran everything and…. nothing happened.

Shit.

Cool feature #1 – the not very clever one

I started to analyze, what happens during the boot up process. The very first line of code that is executed, lies in arch/m68knommu/platform/ao68000/head-ram.S, line 20. After zeroing the memory, the start_kernel function is called. This is the first function written in C, and also a generic (machine independent) one. It lies in init/main.c. Let’s have a look at what it does.

At the very bootom of the snipped, you can see the console initialization. There are load of things, that can go wrong, before kernel can put any character on the console. Most likely the console initialization in my setup was broken. But how kernel actually does the printk’s, so no string is missing?

Digging into printk(), we can see, that it calls vprintk(), which formats the string, and calls emit_log_char() with one character as a parameter. (the fact is, that in newest kernel, the code for vprintk() was changed, but as far as I read the newest code, the idea remains the same). After the console is initialized, buffered strings are put into the console. Moreover, if any function panicked earlier, it only sets the panic_later variable, in order to have the ability to print the panic reason when the console is available.

What I did, is to put additional code to emit_log_char, so it prints the character to the fake console, resulting in character displayed on my Linux console:

 

Why this is not so clever solution? Because I’ve forgotten about early_printk() 🙂 Anyway, I am now able to debug the kernel, and look for the bugs. And this is what was printed on the console:

Now we  know, what is going on!

Cool feature #2 – the clever one

The other thing that bothered me was the fact, that I had no knowledge of where is the kernel, what is going on inside. I had no hardware debugger. Targeting the softcore into FPGA is not an option, when you have no software working. I thought, it would be awesome, if I could track the instructions that are evaluated by the processor. And, after little investigations, I disovered, it is actually possible!

First of all, one must emit all program counter values. The PC register is kept in registers.v source file. This little block of code emits all pc values to the stderr (stdout is kept for uart). $fwrite‘s first parameter is file handler (which is in fact, an integer). As in C application, first three values are reserved for stdin, stdout, and stderr. Stderr file pointer is 32’b80000002.

Now, running the simulation with $ ./m68k_ram_uart 2> log1.pc, we have a file with all program counter values. But that tells us nothing. We need to convert it to a human readable form.

GNU binutils is equipped which a little tool, called nm. This tool lists all the symbols in the object file.  A symbol might be a function name, variable name, section name and so on. Every symbol value is connected with an address of where it lives. Linux kernel’s build system automatically extracts the symbol table into a file, called System.map. The only thing we need to do, is a tool, that converts the pc value into a symbol. Of course not every pc value will have associated symbol. We need to find the last symbol, that’s value is less than our pc value. This is easly done with bisection search algorithm. The code for the tool is listed below:

The parse_system_map() function reads the whole output of nm and extracts all symbols from text section. Then, with find_function(), we locates proper symbol with bisection. The second value returned by find_function() is the offset from the latest symbol. This way, when particular function is executed instruction by instruction, we can see the offset incrementing.

Now, last hack. We use named pipe to pass the program counter values. This way we can see the translating being done live!

The result is below. On the left side, we see the processed ouput of every Program Counter, converted to appropirate function name. On the right side, there is the simulation with the console output. I’ve recorded one of my development Linux kernel images, so you can see a lot of debugging info.

 

Leave a Reply

Your email address will not be published. Required fields are marked *