Debugging eines Linux-Treibers

»Incorrect Driver – process HALTed« – diese Meldung während des Bootvorgangs hat Linux schon einige Sympathien gekostet. Während »schlampigere« Betriebssysteme schon mal ein Gerät mittels eines nicht hundertprozentig passenden Treibers zum Laufen kriegen, bestehen sauber programmierte UNIX-Derivate auf...

»Incorrect Driver – process HALTed« – diese Meldung während des Bootvorgangs hat Linux schon einige Sympathien gekostet. Während »schlampigere« Betriebssysteme schon mal ein Gerät mittels eines nicht hundertprozentig passenden Treibers zum Laufen kriegen, bestehen sauber programmierte UNIX-Derivate auf korrekten Versionen. Bei Embedded-Projekten, wo sich oft sowohl Hardware als auch Treiber noch in der Entwicklung befinden, wird es dann schwierig.

Die »Pedanterie« von Betriebssystemen wie Linux hat natürlich viel mehr Vor- als Nachteile, immerhin gefährden unsaubere Treiber die Systemintegrität. Solchen Problemen wird man am besten schon während des Bootvorgangs Herr. So lassen sich mit modernen Debug-Tools Fehler während des Systemstarts über die serielle Schnittstelle beheben, wie ein Beispiel aus der Praxis zeigen soll.

Der Emulator »ZeBu« von Eve bietet kombinierte Softund Hardwareansichten, welche sich für genau solche Probleme eignen. Im konkreten Fall geht es um ein System-on-Chip mit einem Prozessorcore, »Diamond 232L« von Tensilica, einem Speichersubsystem mit RAM und Flash sowie einem UART-Controller, also die Minimalkonfiguration für Linux. Auf der Softwareseite kam eine Distribution von MontaVista zum Einsatz, die auf dem Kernel 2.6 basiert. Die Grundstruktur für den Systemstart fand in einer »initramfs«-Datei Platz, das Hilfsprogramm »BusyBox« stellte speichersparend die wesentlichen Linux-Befehle und eine Shell bereit.

Das SoC wurde auf dem Hardware-Emulator »ZeBu-UF 0.5« emuliert; es verwendete zwei Transaktoren: Ein UART-Transaktor zeigte die Konsole des emulierten SoCs in einem Fenster auf der Host-Workstation an, ein JTAG-Transaktor sorgte für die Anbindung an die Debugger »Xplorer« oder »xt-gdb« von Tensilica. Die Transaktoren kamen für sämtliche Schnittstellen zum Einsatz, sodass sichergestellt war, dass die Emulation vollständig und korrekt war und ein »echtes« System repräsentierte. Mit Hilfe solcher Transaktoren lässt sich jeder Emulationslauf identisch reproduzieren, sodass sich Fehler einfacher isolieren und wiederholen lassen. Das gilt besonders für jene, die »wandern«, wenn sie isoliert werden sollen.

Sobald das Linux-Image auf den emulierten Prozessor geladen wurde, begann Linux zu booten. Als der »init«-Prozess eine Shell starten sollte, erschien eine Fehlermeldung, woraufhin die Ausgabe abbrach (Listing: »Fehler beim Booten«).

Listing 1: Fehler beim Booten

ZeBu-Diamond Console
Linux version 2.6.10_mvl401-xt2000-xtensa_linux_le (alain@
treasure5.us.eve) (gcc version 3.4.3 (MontaVista 3.4.3-25.0.135.0702842
2007-03-23)) #76 Tue May 1 11:02:33 PDT 2007
On node 0 totalpages: 8192
    DMA zone: 8192 pages, LIFO batch:2
    Normal zone: 0 pages, LIFO batch:1
    HighMem zone: 0 pages, LIFO batch:1
Built 1 zonelists
Kernel command line: console=ttyS0 mem=64M debug init=/sbin/init root=/dummy
PID hash table entries: 256 (order: 8, 4096 bytes)
Console: colour dummy device 80x25
Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)
Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)
Memory: 30936k/32768k available (606k kernel code, 1784k reserved, 80k
data, 528k init 0k highmem)
Calibrating delay loop... 15.76 BogoMIPS (lpj=78848)
Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
spawn_desched_task(00000000)
desched cpu_callback 3/00000000
ksoftirqd started up.
desched cpu_callback 2/00000000
desched thread 0 started up.
Linux NoNET1.0 for Linux 2.6
Initializing Cryptographic API
Serial: 8250/16550 driver $Revision: 1.90 $ 6 ports, IRQ sharing disabled
Registering platform device ‘serial8250’. Parent at platform
ttyS0 at MMIO 0x0 (irq = 4) is a ST16650
ttyS1 at MMIO 0x0 (irq = 5) is a ST16650
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered
loop: loaded (max 8 devices)
mice: PS/2 mouse device common for all mice
Freeing unused kernel memory: 528k freed
Laun serial8250: too much work for irq4

Listing 2: Quellcode des Treibers (Aus den Linux-Quellen, drivers/serial/8250.c):

static irqreturn_t serial8250_interrupt(int irq, void *dev_id, struct
pt_regs *regs)
{
    struct irq_info *i = dev_id;
    struct list_head *l, *end = NULL;
    int pass_counter = 0, handled = 0;
    DEBUG_INTR(“serial8250_interrupt(%d)...”, irq);
    spin_lock(&i->lock);
    l = i->head;
    do {
        struct uart_8250_port *up;
        unsigned int iir;
        up = list_entry(l, struct uart_8250_port, list);
#ifdef CONFIG_TSI108_BRIDGE /* for TSI108_REV_Z1 errata U2 */
        /* read IIR as part of 32-bit word */
        iir = (in_be32((u32 *)(up->port.membase + UART_RX)) > 8) & 0xff;
#else
        iir = serial_in(up, UART_IIR);
#endif
    if (!(iir & UART_IIR_NO_INT)) {
        spin_lock(&up->port.lock);
        serial8250_handle_port(up, regs);
        spin_unlock(&up->port.lock);
        handled = 1;
        end = NULL;
    } else if (end == NULL)
        end = l;
        l = l->next;
    if (l == i->head && pass_counter++ > PASS_LIMIT) {
        /* If we hit this, we’re dead. */
        printk(KERN_ERR “serial8250: too much work for “
        “irq%d\n”, irq);
        break;
    }
} while (l != end);

Listing 3:

proc getDynamicTrigger { } {
global logFile
global selectedTrig ret prog
set prog [ZEBU_Trigger_getExpr $selectedTrig]
set ret 1
set okCmd { global ret
    global prog logFile
    # use system.map
    set simprog “Diamond_PC\[31:0\]==$czrAddFromSym($prog)”

    set ret [ZEBU_Trigger_setExpr $selectedTrig “$simprog”]
    destroy .la.progDynaTrig
    }

Listing 4: Korrekter Bootvorgang

ZeBu-Diamond Console
Linux version 2.6.10_mvl401-xt2000-xtensa_linux_le (alain@treasure5.us.eve)
(gcc version 3.4.3 (MontaVista 3.4.3-25.0.135.0702842 2007-03-23)) #76 Tue
May 1 11:02:33 PDT 2007
On node 0 totalpages: 8192
    DMA zone: 8192 pages, LIFO batch:2
    Normal zone: 0 pages, LIFO batch:1
    HighMem zone: 0 pages, LIFO batch:1
Built 1 zonelists
Kernel command line: console=ttyS0 mem=64M debug init=/sbin/init root=/dummy
PID hash table entries: 256 (order: 8, 4096 bytes)
Console: colour dummy device 80x25
Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)
Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)
Memory: 30936k/32768k available (606k kernel code, 1784k reserved, 80k data,
528k init 0k highmem)
Calibrating delay loop... 15.76 BogoMIPS (lpj=78848)
Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
spawn_desched_task(00000000)
desched cpu_callback 3/00000000
ksoftirqd started up.
desched cpu_callback 2/00000000
desched thread 0 started up.
Linux NoNET1.0 for Linux 2.6
Initializing Cryptographic API
Serial: 8250/16550 driver $Revision: 1.90 $ 6 ports, IRQ sharing disabled
Registering platform device ‘serial8250’. Parent at platform
ttyS0 at MMIO 0x0 (irq = 4) is a ST16650
ttyS1 at MMIO 0x0 (irq = 5) is a ST16650
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered
loop: loaded (max 8 devices)
mice: PS/2 mouse device common for all mice
Freeing unused kernel memory: 528k freed
init started: BusyBox v1.4.2 (2007-04-26 04:18:24 PDT) multi-call binary
Starting pid 15, console /dev/console: ‘/bin/hostname’
Starting pid 16, console /dev/console: ‘/bin/login’
zebudemo login: demo
BusyBox v1.4.2 (2007-04-26 04:18:24 PDT) Built-in shell (ash)
Enter ‘help’ for a list of built-in commands.
$ pwd
/home/demo
$

Sobald ZeBu in der Nähe der interessanten Vorgänge angehalten hatte, kamen dynamische Sonden zum Einsatz, die jedes Signal innerhalb des Prüflings auf ein standardisiertes Wellenformformat abbildeten. Die Entwicklergruppe betrachtete dabei alle Signale im UART-Controller, wobei das IIR und die Interrupt-Leitung besondere Beachtung fanden (Bild 2).

Das Beobachten der Wellenformen machte deutlich, dass die ersten paar Zeichen tatsächlich korrekt über den Datenbus übertragen wurden. Doch auf einmal forderte der Controller keine weiteren Interrupts (Signal »Uart_int_a«) an, sodass keine weiteren Zeichen mehr gesendet werden konnten – dies erklärte die Fehlermeldung des Treibers.