linux/arch
Ingo Molnar 4aae070252 x86: fix "Kernel panic - not syncing: IO-APIC + timer doesn't work!"
this is the tale of a full day spent debugging an ancient but elusive bug.

after booting up thousands of random .config kernels, i finally happened
to generate a .config that produced the following rare bootup failure
on 32-bit x86:

| ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
| ..MP-BIOS bug: 8254 timer not connected to IO-APIC
| ...trying to set up timer (IRQ0) through the 8259A ...  failed.
| ...trying to set up timer as Virtual Wire IRQ... failed.
| ...trying to set up timer as ExtINT IRQ... failed :(.
| Kernel panic - not syncing: IO-APIC + timer doesn't work!  Boot with apic=debug
| and send a report.  Then try booting with the 'noapic' option

this bug has been reported many times during the years, but it was never
reproduced nor fixed.

the bug that i hit was extremely sensitive to .config details.

First i did a .config-bisection - suspecting some .config detail.
That led to CONFIG_X86_MCE: enabling X86_MCE magically made the bug disappear
and the system would boot up just fine.

Debugging my way through the MCE code ended up identifying two unlikely
candidates: the thing that made a real difference to the hang was that
X86_MCE did two printks:

 Intel machine check architecture supported.
 Intel machine check reporting enabled on CPU#1.

Adding the same printks to a !CONFIG_X86_MCE kernel made the bug go away!

this left timing as the main suspect: i experimented with adding various
udelay()s to the arch/x86/kernel/io_apic_32.c:check_timer() function, and
the race window turned out to be narrower than 30 microseconds (!).

That made debugging especially funny, debugging without having printk
ability before the bug hits is ... interesting ;-)

eventually i started suspecting IRQ activities - those are pretty much the
only thing that happen this early during bootup and have the timescale of
a few dozen microseconds. Also, check_timer() changes the IRQ hardware
in various creative ways, so the main candidate became IRQ0 interaction.

i've added a counter to track timer irqs (on which core they arrived, at
what exact time, etc.) and found that no timer IRQ would arrive after the
bug condition hits - even if we re-enable IRQ0 and re-initialize the i8259A,
but that we'd get a small number of timer irqs right around the time when we
call the check_timer() function.

Eventually i got the following backtrace triggered from debug code in the
timer interrupt:

...trying to set up timer as Virtual Wire IRQ... failed.
...trying to set up timer as ExtINT IRQ...
Pid: 1, comm: swapper Not tainted (2.6.24-rc5 #57)
EIP: 0060:[<c044d57e>] EFLAGS: 00000246 CPU: 0
EIP is at _spin_unlock_irqrestore+0x5/0x1c
EAX: c0634178 EBX: 00000000 ECX: c4947d63 EDX: 00000246
ESI: 00000002 EDI: 00010031 EBP: c04e0f2e ESP: f7c41df4
 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
 CR0: 8005003b CR2: ffe04000 CR3: 00630000 CR4: 000006d0
 DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
 DR6: ffff0ff0 DR7: 00000400
  [<c05f5784>] setup_IO_APIC+0x9c3/0xc5c

the spin_unlock() was called from init_8259A(). Wait ... we have an IRQ0
entry while we are in the middle of setting up the local APIC, the i8259A
and the PIT??

That is certainly not how it's supposed to work! check_timer() was supposed
to be called with irqs turned off - but this eroded away sometime in the
past. This code would still work most of the time because this code runs
very quickly, but just the right timing conditions are present and IRQ0
hits in this small, ~30 usecs window, timer irqs stop and the system does
not boot up. Also, given how early this is during bootup, the hang is
very deterministic - but it would only occur on certain machines (and
certain configs).

The fix was quite simple: disable/restore interrupts properly in this
function. With that in place the test-system now boots up just fine.

(64-bit x86 io_apic_64.c had the same bug.)

Phew! One down, only 1500 other kernel bugs are left ;-)

Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
2007-12-18 18:05:58 +01:00
..
alpha alpha: build fixes 2007-12-17 19:28:16 -08:00
arm [ARM] 4694/1: IXP4xx: Update clockevent support for shutdown and resume 2007-12-17 17:18:01 +00:00
avr32 [AVR32] Fix wrong pt_regs in critical exception handler 2007-12-07 14:54:48 +01:00
blackfin Blackfin arch: fix bug when enable uart1 with uart0 disabled => no initial console 2007-11-21 17:04:41 +08:00
cris ide: move CONFIG_IDE_ETRAX to drivers/ide/Kconfig 2007-11-27 21:35:55 +01:00
frv FRV: arrange things such that BRA can reach from the trap table 2007-11-29 09:24:54 -08:00
h8300 Kbuild/doc: fix links to Documentation files 2007-10-30 14:26:30 -07:00
ia64 [IA64] Fix iosapic interrupt delivery mode for CPE 2007-12-07 16:13:03 -08:00
m32r m32r: Update sys_rt_sigsuspend 2007-11-28 01:24:04 +09:00
m68k m68k: export atari_keyb_init 2007-11-26 19:15:31 -08:00
m68knommu m68knommu: mark mem init functions as __init 2007-10-23 20:45:44 -07:00
mips [MIPS] Ensure that ST0_FR is never set on a 32 bit kernel 2007-12-14 17:34:30 +00:00
parisc [PARISC] print more than one character at a time for pdc console 2007-12-06 09:32:15 -08:00
powerpc Merge branch 'for-2.6.24' of master.kernel.org:/pub/scm/linux/kernel/git/galak/powerpc into merge 2007-12-14 16:46:50 +11:00
ppc [POWERPC] virtex bug fix: Use canonical value for AC97 interrupt xparams 2007-12-07 11:43:55 +11:00
s390 [S390] Make sure the restore psw masks are initialized. 2007-12-04 16:09:58 +01:00
sh sh: Support PCI IO access of SH7780 base boards. 2007-11-30 12:36:13 +09:00
sh64 sh64: Kill off duplicate includes. 2007-11-05 12:18:17 +09:00
sparc [SPARC]: Add missing of_node_put 2007-12-05 05:38:00 -08:00
sparc64 [SPARC64]: Fix two kernel linear mapping setup bugs. 2007-12-13 06:13:38 -08:00
um uml: stop gdb from deleting breakpoints when running UML 2007-12-17 19:28:15 -08:00
v850 spelling fixes: arch/v850/ 2007-10-20 01:24:05 +02:00
x86 x86: fix "Kernel panic - not syncing: IO-APIC + timer doesn't work!" 2007-12-18 18:05:58 +01:00
xtensa [XTENSA]: Fix use of skb after netif_rx 2007-12-11 02:45:28 -08:00