Re: [ INFO: iconsistent lock state ]

From: Peter Zijlstra
Date: Fri Apr 25 2008 - 10:59:53 EST


On Fri, 2008-04-25 at 14:47 +0000, Justin Mattock wrote:
> On Fri, Apr 25, 2008 at 12:11 PM, Peter Zijlstra <a.p.zijlstra@xxxxxxxxx> wrote:
> > On Fri, 2008-04-25 at 00:24 +0000, Justin Mattock wrote:
> >
> > > [ 13.269763] =================================
> > > [ 13.270954] [ INFO: inconsistent lock state ]
> > > [ 13.271865] 2.6.25-04569-gb69d398 #3
> >
> > What tree is that? git checkout gb69d398 doesn't want to happen here.

Argh, s/g// so the hash is: b69d398

Could we make that -git-# ?

> > > [ 13.272614] ---------------------------------
> > > [ 13.273521] inconsistent {in-hardirq-W} -> {hardirq-on-W} usage.
> > > [ 13.274745] swapper/0 [HC0[0]:SC0[0]:HE1:SE1] takes:
> > > [ 13.275787] (&rq->rq_lock_key){++..}, at: [<c01208e9>] sched_clock_idle_wakeup_event+0x43/0x74
> > > [ 13.276859] {in-hardirq-W} state was registered at:
> > > [ 13.276859] [<c01423d8>] __lock_acquire+0x419/0xb70
> > > [ 13.276859] [<c0142bae>] lock_acquire+0x7f/0xa6
> > > [ 13.280188] [<c0394132>] _spin_lock+0x1c/0x49
> > > [ 13.280188] [<c0121c44>] scheduler_tick+0x43/0x1bd
> > > [ 13.280188] [<c012d99f>] update_process_times+0x3d/0x49
> > > [ 13.283524] [<c013daf6>] tick_periodic+0x66/0x72
> > > [ 13.283524] [<c013db1b>] tick_handle_periodic+0x19/0x6a
> > > [ 13.283524] [<c0105a87>] timer_interrupt+0x47/0x4e
> > > [ 13.286855] [<c015cf64>] handle_IRQ_event+0x1a/0x4f
> > > [ 13.286855] [<c015e3e9>] handle_level_irq+0x7f/0xca
> > > [ 13.286855] [<c0105a27>] do_IRQ+0x71/0x8a
> > > [ 13.290190] [<c01043fe>] common_interrupt+0x2e/0x34
> > > [ 13.290190] [<c038bd6f>] calibrate_delay+0x8f/0x276
> > > [ 13.290190] [<c04f0883>] start_kernel+0x27c/0x2f8
> > > [ 13.293520] [<c04f0008>] __init_begin+0x8/0xa
> > > [ 13.293520] [<ffffffff>] 0xffffffff
> > > [ 13.293520] irq event stamp: 253965
> > > [ 13.296856] hardirqs last enabled at (253965): [<c0108069>] native_sched_clock+0xe7/0xff
> > > [ 13.296856] hardirqs last disabled at (253964): [<c0107fef>] native_sched_clock+0x6d/0xff
> > > [ 13.300190] softirqs last enabled at (253958): [<c0129cea>] __do_softirq+0xf9/0xff
> > > [ 13.300190] softirqs last disabled at (253953): [<c0129d3d>] do_softirq+0x4d/0x79
> > > [ 13.303522]
> > > [ 13.303522] other info that might help us debug this:
> > > [ 13.303522] no locks held by swapper/0.
> > > [ 13.303522]
> > > [ 13.303522] stack backtrace:
> > > [ 13.306852] Pid: 0, comm: swapper Not tainted 2.6.25-04569-gb69d398 #3
> > > [ 13.336851] [<c01409f9>] print_usage_bug+0x106/0x113
> > > [ 13.340185] [<c0141823>] mark_lock+0x1ed/0x3a5
> > > [ 13.343519] [<c014244d>] __lock_acquire+0x48e/0xb70
> > > [ 13.346852] [<c0142bae>] lock_acquire+0x7f/0xa6
> > > [ 13.350185] [<c01208e9>] ? sched_clock_idle_wakeup_event+0x43/0x74
> > > [ 13.353519] [<c0394132>] _spin_lock+0x1c/0x49
> > > [ 13.360185] [<c01208e9>] ? sched_clock_idle_wakeup_event+0x43/0x74
> > > [ 13.363518] [<c01208e9>] sched_clock_idle_wakeup_event+0x43/0x74

Got it:

acpi_idle_do_entry()
acpi_processor_ffh_cstate_enter()
mwait_idle_with_hints() (32 bit)
local_irq_enable()

sched_clock_idle_wakeup_event()


I think my recent idle patches should address this, no?

> > > [ 13.366851] [<f883919b>] acpi_idle_enter_bm+0x2b3/0x333 [processor]
> > > [ 13.370184] [<c02e5ec1>] cpuidle_idle_call+0x63/0x92
> > > [ 13.373517] [<c02e5e5e>] ? cpuidle_idle_call+0x0/0x92
> > > [ 13.380184] [<c010257d>] cpu_idle+0xb6/0xd6
> > > [ 13.383517] [<c0387071>] rest_init+0x49/0x4b
> > > [ 13.386850] =======================
> >
> > looking at current -linus I'm not directly seeing how we can get there
> > with interrupts enabled.
> >

--
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/