errors when booting with SDCard present (2.6.31-rc1 and others)

[Jake Edge]

I am getting some strange (to me anyway) errors in /var/log/messages
when I boot with an SD Card present in the card reader on my laptop ... 'irq 20: nobody cared' and 'inconsistent lock state' ... so far, I have reproduced similar behavior on 2.6.31-rc1, 2.6.30, 2.6.29, and a (slightly old) Fedora 11 kernel: 2.6.29.2-126.fc11.i586

(from 2.6.31-rc1)

It starts with an:

irq 20: nobody cared (try booting with the "irqpoll" option)

(irq 20 corresponds to a USB host controller) with the following backtrace:

Jun 25 15:42:19 ouzel kernel: Pid: 1093, comm: plymouthd Not tainted 2.6.31-rc1-jake #27
Jun 25 15:42:19 ouzel kernel: Call Trace:
Jun 25 15:42:19 ouzel kernel: [<c047db7c>] __report_bad_irq+0x33/0x74
Jun 25 15:42:19 ouzel kernel: [<c047dcb7>] note_interrupt+0xfa/0x153
Jun 25 15:42:19 ouzel kernel: [<c047e23d>] handle_fasteoi_irq+0x92/0xb5
Jun 25 15:42:19 ouzel kernel: [<c047e1ab>] ? handle_fasteoi_irq+0x0/0xb5
Jun 25 15:42:19 ouzel kernel: <IRQ>  [<c0404ad4>] ? do_IRQ+0x49/0x9c
Jun 25 15:42:19 ouzel kernel: [<c043df85>] ? __do_softirq+0x0/0x1bc
Jun 25 15:42:19 ouzel kernel: [<c0403aae>] ? common_interrupt+0x2e/0x34
Jun 25 15:42:19 ouzel kernel: [<c043df85>] ? __do_softirq+0x0/0x1bc
Jun 25 15:42:19 ouzel kernel: [<c045007b>] ? down_interruptible+0x19/0x3c
Jun 25 15:42:19 ouzel kernel: [<c043dfda>] ? __do_softirq+0x55/0x1bc
Jun 25 15:42:19 ouzel kernel: [<c043df85>] ? __do_softirq+0x0/0x1bc
Jun 25 15:42:19 ouzel kernel: <IRQ>  [<c043e405>] ? irq_exit+0x3d/0x75
Jun 25 15:42:19 ouzel kernel: [<c0417abd>] ? smp_apic_timer_interrupt+0x6c/0x7a
Jun 25 15:42:19 ouzel kernel: [<c049b888>] ? perf_swcounter_event+0xca/0x18a
Jun 25 15:42:19 ouzel kernel: [<c0403dbb>] ? apic_timer_interrupt+0x2f/0x34
Jun 25 15:42:19 ouzel kernel: [<c049b888>] ? perf_swcounter_event+0xca/0x18a
Jun 25 15:42:19 ouzel kernel: [<c045cc1b>] ? lock_acquire+0xce/0xdd
Jun 25 15:42:19 ouzel kernel: [<c049b888>] ? perf_swcounter_event+0xca/0x18a
Jun 25 15:42:19 ouzel kernel: [<c049b8c5>] ? perf_swcounter_event+0x107/0x18a
Jun 25 15:42:19 ouzel kernel: [<c049b888>] ? perf_swcounter_event+0xca/0x18a
Jun 25 15:42:19 ouzel kernel: [<c074d8d1>] ? do_page_fault+0x262/0x2d0
Jun 25 15:42:19 ouzel kernel: [<c074d66f>] ? do_page_fault+0x0/0x2d0
Jun 25 15:42:19 ouzel kernel: [<c074be4b>] ? error_code+0x6b/0x70
Jun 25 15:42:19 ouzel kernel: [<c074d66f>] ? do_page_fault+0x0/0x2d0
Jun 25 15:42:19 ouzel kernel: handlers:
Jun 25 15:42:19 ouzel kernel: [<c0667e65>] (usb_hcd_irq+0x0/0x8d)
Jun 25 15:42:19 ouzel kernel: [<c0667e65>] (usb_hcd_irq+0x0/0x8d)
Jun 25 15:42:19 ouzel kernel: Disabling IRQ #20

Then there are messages about an 'inconsistent lock state':

Jun 25 15:42:19 ouzel kernel: =================================
Jun 25 15:42:19 ouzel kernel: [ INFO: inconsistent lock state ]
Jun 25 15:42:19 ouzel kernel: 2.6.31-rc1-jake #27
Jun 25 15:42:19 ouzel kernel: ---------------------------------
Jun 25 15:42:19 ouzel kernel: inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
Jun 25 15:42:19 ouzel kernel: swapper/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
Jun 25 15:42:19 ouzel kernel: (&irq_desc_lock_class){?.-...}, at: [<c047d9f8>] try_one_irq+0x1d/0xfa
Jun 25 15:42:19 ouzel kernel: {IN-HARDIRQ-W} state was registered at:
Jun 25 15:42:19 ouzel kernel:  [<c045bb1b>] __lock_acquire+0x20f/0xadc
Jun 25 15:42:19 ouzel kernel:  [<c045cc07>] lock_acquire+0xba/0xdd
Jun 25 15:42:19 ouzel kernel:  [<c074b3c9>] _spin_lock+0x2d/0x5d
Jun 25 15:42:19 ouzel kernel:  [<c047e27c>] handle_level_irq+0x1c/0xb3
Jun 25 15:42:19 ouzel kernel:  [<ffffffff>] 0xffffffff
Jun 25 15:42:19 ouzel kernel: irq event stamp: 435284
Jun 25 15:42:19 ouzel kernel: hardirqs last  enabled at (435284): [<c074ba1c>] _spin_unlock_irq+0x27/0x4f
Jun 25 15:42:19 ouzel kernel: hardirqs last disabled at (435283): [<c074b472>] _spin_lock_irq+0x17/0x68
Jun 25 15:42:19 ouzel kernel: softirqs last  enabled at (435270): [<c043e132>] __do_softirq+0x1ad/0x1bc
Jun 25 15:42:19 ouzel kernel: softirqs last disabled at (435281): [<c040543e>] do_softirq+0x6e/0xcc
Jun 25 15:42:19 ouzel kernel:
Jun 25 15:42:19 ouzel kernel: other info that might help us debug this:
Jun 25 15:42:19 ouzel kernel: 1 lock held by swapper/0:
Jun 25 15:42:19 ouzel kernel: #0:  (kernel/irq/spurious.c:21){+.-...}, at: [<c0441ab4>] run_timer_softirq+0xfc/0x1e6
Jun 25 15:42:19 ouzel kernel:
Jun 25 15:42:19 ouzel kernel: stack backtrace:
Jun 25 15:42:19 ouzel kernel: Pid: 0, comm: swapper Not tainted 2.6.31-rc1-jake #27
Jun 25 15:42:19 ouzel kernel: Call Trace:
Jun 25 15:42:19 ouzel kernel: [<c07490d2>] ? printk+0x14/0x1a
Jun 25 15:42:19 ouzel kernel: [<c045ac3d>] valid_state+0x12a/0x13d
Jun 25 15:42:19 ouzel kernel: [<c045ad41>] mark_lock+0xf1/0x1d9
Jun 25 15:42:19 ouzel kernel: [<c045b426>] ? check_usage_backwards+0x0/0x3f
Jun 25 15:42:19 ouzel kernel: [<c045bb89>] __lock_acquire+0x27d/0xadc
Jun 25 15:42:19 ouzel kernel: [<c047d9f8>] ? try_one_irq+0x1d/0xfa
Jun 25 15:42:19 ouzel kernel: [<c045cc07>] lock_acquire+0xba/0xdd
Jun 25 15:42:19 ouzel kernel: [<c047d9f8>] ? try_one_irq+0x1d/0xfa
Jun 25 15:42:19 ouzel kernel: [<c074b3c9>] _spin_lock+0x2d/0x5d
Jun 25 15:42:19 ouzel kernel: [<c047d9f8>] ? try_one_irq+0x1d/0xfa
Jun 25 15:42:19 ouzel kernel: [<c047d9f8>] try_one_irq+0x1d/0xfa
Jun 25 15:42:19 ouzel kernel: [<c047db05>] poll_all_shared_irqs+0x30/0x43
Jun 25 15:42:19 ouzel kernel: [<c047db25>] poll_spurious_irqs+0xd/0x22
Jun 25 15:42:19 ouzel kernel: [<c0441b29>] run_timer_softirq+0x171/0x1e6
Jun 25 15:42:19 ouzel kernel: [<c0441ab4>] ? run_timer_softirq+0xfc/0x1e6
Jun 25 15:42:19 ouzel kernel: [<c047db18>] ? poll_spurious_irqs+0x0/0x22
Jun 25 15:42:19 ouzel kernel: [<c043e068>] __do_softirq+0xe3/0x1bc
Jun 25 15:42:19 ouzel kernel: [<c043df85>] ? __do_softirq+0x0/0x1bc
Jun 25 15:42:19 ouzel kernel: <IRQ>  [<c043e405>] ? irq_exit+0x3d/0x75
Jun 25 15:42:19 ouzel kernel: [<c0404b13>] ? do_IRQ+0x88/0x9c
Jun 25 15:42:19 ouzel kernel: [<c0403aae>] ? common_interrupt+0x2e/0x34
Jun 25 15:42:19 ouzel kernel: [<c045007b>] ? down_interruptible+0x19/0x3c
Jun 25 15:42:19 ouzel kernel: [<c05f14cb>] ? acpi_idle_enter_simple+0x11e/0x14f
Jun 25 15:42:19 ouzel kernel: [<c06b0ea2>] ? cpuidle_idle_call+0x6a/0xa0
Jun 25 15:42:19 ouzel kernel: [<c0402609>] ? cpu_idle+0x58/0x8b
Jun 25 15:42:19 ouzel kernel: [<c0739884>] ? rest_init+0x6c/0x6e
Jun 25 15:42:19 ouzel kernel: [<c0942838>] ? start_kernel+0x316/0x31b
Jun 25 15:42:19 ouzel kernel: [<c0942071>] ? __init_begin+0x71/0x79

I seem to get none of this behavior when I boot without that card present ... it just has a VFAT filesystem, which seems to be in reasonable shape when I look at it ... the machine seems to run fine, but these messages don't look good ...

apologies if I cast too wide of a net on the email ... it is a Ricoh R5C822 SD/SDIO/MMC/MS/MSPro Host Adapter according to lspci ...

further checking shows that I have CONFIG_MMC_SDRICOH_CS turned off, on my
kernels (not sure why), but that module is available for the Fedora kernel
which seems to have the same behavior.

any thoughts?

thanks,

jake

-- 
Jake Edge - LWN - jake@xxxxxxx - http://lwn.net
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/