spinlock lockup on CPU#0

spinlock lockup on CPU#0

[Justin Mattock]

Hello, I recorded a .mov of a spinlock, but cant seem to send it out,
so I have to manually write it down:

BUG: spinlock lockup on CPU#0, swapper/0, c17fa6c0
Pid: 0. swapper Not tainted 2.6.25-03562-g3dc5063 #1
[<c0219fbb>]  _raw_spin_lock+0xd5/0xf9
[<c0377c6b>] _spin_lock+0x8/0xa
[<c011cdce>]  task_rq_lock+0x44/0x6b
[<c011cfb4>]   try_to_wake+0x2a/0x1c4
[<co11d159>]  default_wake_function+0xb/0xd
[<co118847>] __wake_up_common+0x2f/0x5a
[<c011bc11>] complete+0x2b/0x3e
[<c02ad79a>] usb_api_blocking_completion+0x13/0x15
[<c02abadc>] usb_hcd_giveback_urb+0x52/0x82
[<f88686c7>] ehci_urb_done+0x6f/0x7c [ehci_hcd]
[<f8869614>] qh_completions+0x2d7/0x348 [ehci_hcd]
[<f8869721>] ehci_work+0x9c [ehci_hcd]
[<c0107c35>] ? sched_clock+0xb/0x1c
[<c0119bec>] ? __update_rq_clock+0x94/0x15a
[<f886c827>] ehci_irq+0x138/0x15f [ehci_hcd]
[<c02abd9> ] usb_hcd_irq+0x23/0x51
[<c0151c43>] handle_IRQ_event+0x2a/0x5a
[<c0152d2c>] handle_fasteoi_irq+0x74/0xb6
[<c01058c5>] do_IRQ+0x71/0x8c
[<c01042f7>] common_interrupt+0x23/0x28
[<c011fb07>] ? sched_clock_idle_wakeup_event+0x5b/0x74
[<c02cc212>] acpi_idle_enter_bm+0x2a4/0x31f    [processor]
[<c02cc212>] cpuidle_idle_call+0x5c/0x8c
[<c02cc1b4>] ? cpuidle_idle_call+0x0/0x8c
[<c0102571>] cpu_idle+0xb1/0xd1
[<c036b371>] reset_init+0x49/0x4b
=====================================================


Hopefully the numbers are right, and hopefully this provides enough
info to help the kernel out
regards;

-- 
Justin P. Mattock

Re: spinlock lockup on CPU#0

[Andrew Morton]

On Thu, 24 Apr 2008 01:41:32 +0000 "Justin Mattock" <justinmattock@gmail.com> wrote:

> Hello, I recorded a .mov of a spinlock, but cant seem to send it out,
> so I have to manually write it down:
> 
> BUG: spinlock lockup on CPU#0, swapper/0, c17fa6c0
> Pid: 0. swapper Not tainted 2.6.25-03562-g3dc5063 #1
> [<c0219fbb>]  _raw_spin_lock+0xd5/0xf9
> [<c0377c6b>] _spin_lock+0x8/0xa
> [<c011cdce>]  task_rq_lock+0x44/0x6b
> [<c011cfb4>]   try_to_wake+0x2a/0x1c4
> [<co11d159>]  default_wake_function+0xb/0xd
> [<co118847>] __wake_up_common+0x2f/0x5a
> [<c011bc11>] complete+0x2b/0x3e
> [<c02ad79a>] usb_api_blocking_completion+0x13/0x15
> [<c02abadc>] usb_hcd_giveback_urb+0x52/0x82
> [<f88686c7>] ehci_urb_done+0x6f/0x7c [ehci_hcd]
> [<f8869614>] qh_completions+0x2d7/0x348 [ehci_hcd]
> [<f8869721>] ehci_work+0x9c [ehci_hcd]
> [<c0107c35>] ? sched_clock+0xb/0x1c
> [<c0119bec>] ? __update_rq_clock+0x94/0x15a
> [<f886c827>] ehci_irq+0x138/0x15f [ehci_hcd]
> [<c02abd9> ] usb_hcd_irq+0x23/0x51
> [<c0151c43>] handle_IRQ_event+0x2a/0x5a
> [<c0152d2c>] handle_fasteoi_irq+0x74/0xb6
> [<c01058c5>] do_IRQ+0x71/0x8c
> [<c01042f7>] common_interrupt+0x23/0x28
> [<c011fb07>] ? sched_clock_idle_wakeup_event+0x5b/0x74
> [<c02cc212>] acpi_idle_enter_bm+0x2a4/0x31f    [processor]
> [<c02cc212>] cpuidle_idle_call+0x5c/0x8c
> [<c02cc1b4>] ? cpuidle_idle_call+0x0/0x8c
> [<c0102571>] cpu_idle+0xb1/0xd1
> [<c036b371>] reset_init+0x49/0x4b
> =====================================================
> 
> 
> Hopefully the numbers are right, and hopefully this provides enough
> info to help the kernel out

Well that's cute.  At a guess I'd say that acpi_processor_idle() managed to
call sched_clock_idle_wakeup_event() with local interrupts enabled.  We
took an interrupt with rq->lock held and things went downhill from there.

Can you add this please, see if it triggers?


--- a/kernel/sched.c~a
+++ a/kernel/sched.c
@@ -811,6 +811,7 @@ void sched_clock_idle_sleep_event(void)
 {
 	struct rq *rq = cpu_rq(smp_processor_id());
 
+	WARN_ON(!irqs_disabled());
 	spin_lock(&rq->lock);
 	__update_rq_clock(rq);
 	spin_unlock(&rq->lock);
@@ -826,6 +827,7 @@ void sched_clock_idle_wakeup_event(u64 d
 	struct rq *rq = cpu_rq(smp_processor_id());
 	u64 now = sched_clock();
 
+	WARN_ON(!irqs_disabled());
 	rq->idle_clock += delta_ns;
 	/*
 	 * Override the previous timestamp and ignore all
_

Re: spinlock lockup on CPU#0

[Justin Mattock]

On Sat, Apr 26, 2008 at 6:29 PM, Andrew Morton
<akpm@linux-foundation.org> wrote:
>
> On Thu, 24 Apr 2008 01:41:32 +0000 "Justin Mattock" <justinmattock@gmail.com> wrote:
>
>  > Hello, I recorded a .mov of a spinlock, but cant seem to send it out,
>  > so I have to manually write it down:
>  >
>  > BUG: spinlock lockup on CPU#0, swapper/0, c17fa6c0
>  > Pid: 0. swapper Not tainted 2.6.25-03562-g3dc5063 #1
>  > [<c0219fbb>]  _raw_spin_lock+0xd5/0xf9
>  > [<c0377c6b>] _spin_lock+0x8/0xa
>  > [<c011cdce>]  task_rq_lock+0x44/0x6b
>  > [<c011cfb4>]   try_to_wake+0x2a/0x1c4
>  > [<co11d159>]  default_wake_function+0xb/0xd
>  > [<co118847>] __wake_up_common+0x2f/0x5a
>  > [<c011bc11>] complete+0x2b/0x3e
>  > [<c02ad79a>] usb_api_blocking_completion+0x13/0x15
>  > [<c02abadc>] usb_hcd_giveback_urb+0x52/0x82
>  > [<f88686c7>] ehci_urb_done+0x6f/0x7c [ehci_hcd]
>  > [<f8869614>] qh_completions+0x2d7/0x348 [ehci_hcd]
>  > [<f8869721>] ehci_work+0x9c [ehci_hcd]
>  > [<c0107c35>] ? sched_clock+0xb/0x1c
>  > [<c0119bec>] ? __update_rq_clock+0x94/0x15a
>  > [<f886c827>] ehci_irq+0x138/0x15f [ehci_hcd]
>  > [<c02abd9> ] usb_hcd_irq+0x23/0x51
>  > [<c0151c43>] handle_IRQ_event+0x2a/0x5a
>  > [<c0152d2c>] handle_fasteoi_irq+0x74/0xb6
>  > [<c01058c5>] do_IRQ+0x71/0x8c
>  > [<c01042f7>] common_interrupt+0x23/0x28
>  > [<c011fb07>] ? sched_clock_idle_wakeup_event+0x5b/0x74
>  > [<c02cc212>] acpi_idle_enter_bm+0x2a4/0x31f    [processor]
>  > [<c02cc212>] cpuidle_idle_call+0x5c/0x8c
>  > [<c02cc1b4>] ? cpuidle_idle_call+0x0/0x8c
>  > [<c0102571>] cpu_idle+0xb1/0xd1
>  > [<c036b371>] reset_init+0x49/0x4b
>  > =====================================================
>  >
>  >
>  > Hopefully the numbers are right, and hopefully this provides enough
>  > info to help the kernel out
>
>  Well that's cute.  At a guess I'd say that acpi_processor_idle() managed to
>  call sched_clock_idle_wakeup_event() with local interrupts enabled.  We
>  took an interrupt with rq->lock held and things went downhill from there.
>
>  Can you add this please, see if it triggers?
>
>
>  --- a/kernel/sched.c~a
>  +++ a/kernel/sched.c
>  @@ -811,6 +811,7 @@ void sched_clock_idle_sleep_event(void)
>   {
>         struct rq *rq = cpu_rq(smp_processor_id());
>
>  +       WARN_ON(!irqs_disabled());
>         spin_lock(&rq->lock);
>         __update_rq_clock(rq);
>         spin_unlock(&rq->lock);
>  @@ -826,6 +827,7 @@ void sched_clock_idle_wakeup_event(u64 d
>         struct rq *rq = cpu_rq(smp_processor_id());
>         u64 now = sched_clock();
>
>  +       WARN_ON(!irqs_disabled());
>         rq->idle_clock += delta_ns;
>         /*
>          * Override the previous timestamp and ignore all
>  _
>
>

Yeah, I dont mind adding this to see what happens.
regards

-- 
Justin P. Mattock

Re: spinlock lockup on CPU#0

[Ingo Molnar]

* Andrew Morton <akpm@linux-foundation.org> wrote:

> > Hopefully the numbers are right, and hopefully this provides enough 
> > info to help the kernel out
> 
> Well that's cute.  At a guess I'd say that acpi_processor_idle() 
> managed to call sched_clock_idle_wakeup_event() with local interrupts 
> enabled.  We took an interrupt with rq->lock held and things went 
> downhill from there.
> 
> Can you add this please, see if it triggers?

there's fixes pending in this area. The main fix would be the one below.

	Ingo

---------------->
Subject: idle (arch, acpi and apm) and lockdep
From: Peter Zijlstra <peterz@infradead.org>
Date: Fri, 25 Apr 2008 17:39:01 +0200

On Fri, 2008-04-25 at 16:59 +0200, Peter Zijlstra wrote:
> 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@chello.nl> 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
> > >  > [   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]  =======================

(I just found out I failed to copy LKML on the last discussion about
these patches)

Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
From: Peter Zijlstra <peterz@infradead.org>

OK, so 25-mm1 gave a lockdep error which made me look into this.

The first thing that I noticed was the horrible mess; the second thing I
saw was hacks like: 71e93d15612c61c2e26a169567becf088e71b8ff

The problem is that arch idle routines are somewhat inconsitent with
their IRQ state handling and instead of fixing _that_, we go paper over
the problem.

So the thing I've tried to do is set a standard for idle routines and
fix them all up to adhere to that. So the rules are:

  idle routines are entered with IRQs disabled
  idle routines will exit with IRQs enabled

Nearly all already did this in one form or another.

Merge the 32 and 64 bit bits so they no longer have different bugs.

As for the actual lockdep warning; __sti_mwait() did a plainly un-annotated
irq-enable.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 arch/x86/kernel/apm_32.c      |    3 +
 arch/x86/kernel/process.c     |  117 +++++++++++++++++++++++++++++++++++++++
 arch/x86/kernel/process_32.c  |  118 +---------------------------------------
 arch/x86/kernel/process_64.c  |  123 +-----------------------------------------
 drivers/acpi/processor_idle.c |   19 +++---
 include/asm-x86/processor.h   |    1 
 6 files changed, 137 insertions(+), 244 deletions(-)

Index: linux/arch/x86/kernel/apm_32.c
===================================================================
--- linux.orig/arch/x86/kernel/apm_32.c
+++ linux/arch/x86/kernel/apm_32.c
@@ -904,6 +904,7 @@ recalc:
 			original_pm_idle();
 		else
 			default_idle();
+		local_irq_disable();
 		jiffies_since_last_check = jiffies - last_jiffies;
 		if (jiffies_since_last_check > idle_period)
 			goto recalc;
@@ -911,6 +912,8 @@ recalc:
 
 	if (apm_idle_done)
 		apm_do_busy();
+
+	local_irq_enable();
 }
 
 /**
Index: linux/arch/x86/kernel/process.c
===================================================================
--- linux.orig/arch/x86/kernel/process.c
+++ linux/arch/x86/kernel/process.c
@@ -4,6 +4,8 @@
 #include <linux/smp.h>
 #include <linux/slab.h>
 #include <linux/sched.h>
+#include <linux/module.h>
+#include <linux/pm.h>
 
 struct kmem_cache *task_xstate_cachep;
 
@@ -42,3 +44,118 @@ void arch_task_cache_init(void)
 				  __alignof__(union thread_xstate),
 				  SLAB_PANIC | SLAB_NOTRACK, NULL);
 }
+
+static void do_nothing(void *unused)
+{
+}
+
+/*
+ * cpu_idle_wait - Used to ensure that all the CPUs discard old value of
+ * pm_idle and update to new pm_idle value. Required while changing pm_idle
+ * handler on SMP systems.
+ *
+ * Caller must have changed pm_idle to the new value before the call. Old
+ * pm_idle value will not be used by any CPU after the return of this function.
+ */
+void cpu_idle_wait(void)
+{
+	smp_mb();
+	/* kick all the CPUs so that they exit out of pm_idle */
+	smp_call_function(do_nothing, NULL, 0, 1);
+}
+EXPORT_SYMBOL_GPL(cpu_idle_wait);
+
+/*
+ * This uses new MONITOR/MWAIT instructions on P4 processors with PNI,
+ * which can obviate IPI to trigger checking of need_resched.
+ * We execute MONITOR against need_resched and enter optimized wait state
+ * through MWAIT. Whenever someone changes need_resched, we would be woken
+ * up from MWAIT (without an IPI).
+ *
+ * New with Core Duo processors, MWAIT can take some hints based on CPU
+ * capability.
+ */
+void mwait_idle_with_hints(unsigned long ax, unsigned long cx)
+{
+	if (!need_resched()) {
+		__monitor((void *)&current_thread_info()->flags, 0, 0);
+		smp_mb();
+		if (!need_resched())
+			__mwait(ax, cx);
+	}
+}
+
+/* Default MONITOR/MWAIT with no hints, used for default C1 state */
+static void mwait_idle(void)
+{
+	if (!need_resched()) {
+		__monitor((void *)&current_thread_info()->flags, 0, 0);
+		smp_mb();
+		if (!need_resched())
+			__sti_mwait(0, 0);
+		else
+			local_irq_enable();
+	} else
+		local_irq_enable();
+}
+
+
+static int __cpuinit mwait_usable(const struct cpuinfo_x86 *c)
+{
+	if (force_mwait)
+		return 1;
+	/* Any C1 states supported? */
+	return c->cpuid_level >= 5 && ((cpuid_edx(5) >> 4) & 0xf) > 0;
+}
+
+/*
+ * On SMP it's slightly faster (but much more power-consuming!)
+ * to poll the ->work.need_resched flag instead of waiting for the
+ * cross-CPU IPI to arrive. Use this option with caution.
+ */
+static void poll_idle(void)
+{
+	local_irq_enable();
+	cpu_relax();
+}
+
+void __cpuinit select_idle_routine(const struct cpuinfo_x86 *c)
+{
+	static int selected;
+
+	if (selected)
+		return;
+#ifdef CONFIG_X86_SMP
+	if (pm_idle == poll_idle && smp_num_siblings > 1) {
+		printk(KERN_WARNING "WARNING: polling idle and HT enabled,"
+			" performance may degrade.\n");
+	}
+#endif
+	if (cpu_has(c, X86_FEATURE_MWAIT) && mwait_usable(c)) {
+		/*
+		 * Skip, if setup has overridden idle.
+		 * One CPU supports mwait => All CPUs supports mwait
+		 */
+		if (!pm_idle) {
+			printk(KERN_INFO "using mwait in idle threads.\n");
+			pm_idle = mwait_idle;
+		}
+	}
+	selected = 1;
+}
+
+static int __init idle_setup(char *str)
+{
+	if (!strcmp(str, "poll")) {
+		printk("using polling idle threads.\n");
+		pm_idle = poll_idle;
+	} else if (!strcmp(str, "mwait"))
+		force_mwait = 1;
+	else
+		return -1;
+
+	boot_option_idle_override = 1;
+	return 0;
+}
+early_param("idle", idle_setup);
+
Index: linux/arch/x86/kernel/process_32.c
===================================================================
--- linux.orig/arch/x86/kernel/process_32.c
+++ linux/arch/x86/kernel/process_32.c
@@ -111,12 +111,10 @@ void default_idle(void)
 		 */
 		smp_mb();
 
-		local_irq_disable();
-		if (!need_resched()) {
+		if (!need_resched())
 			safe_halt();	/* enables interrupts racelessly */
-			local_irq_disable();
-		}
-		local_irq_enable();
+		else
+			local_irq_enable();
 		current_thread_info()->status |= TS_POLLING;
 	} else {
 		local_irq_enable();
@@ -128,17 +126,6 @@ void default_idle(void)
 EXPORT_SYMBOL(default_idle);
 #endif
 
-/*
- * On SMP it's slightly faster (but much more power-consuming!)
- * to poll the ->work.need_resched flag instead of waiting for the
- * cross-CPU IPI to arrive. Use this option with caution.
- */
-static void poll_idle(void)
-{
-	local_irq_enable();
-	cpu_relax();
-}
-
 #ifdef CONFIG_HOTPLUG_CPU
 #include <asm/nmi.h>
 /* We don't actually take CPU down, just spin without interrupts. */
@@ -196,6 +183,7 @@ void cpu_idle(void)
 			if (cpu_is_offline(cpu))
 				play_dead();
 
+			local_irq_disable();
 			__get_cpu_var(irq_stat).idle_timestamp = jiffies;
 			/* Don't trace irqs off for idle */
 			stop_critical_timings();
@@ -209,104 +197,6 @@ void cpu_idle(void)
 	}
 }
 
-static void do_nothing(void *unused)
-{
-}
-
-/*
- * cpu_idle_wait - Used to ensure that all the CPUs discard old value of
- * pm_idle and update to new pm_idle value. Required while changing pm_idle
- * handler on SMP systems.
- *
- * Caller must have changed pm_idle to the new value before the call. Old
- * pm_idle value will not be used by any CPU after the return of this function.
- */
-void cpu_idle_wait(void)
-{
-	smp_mb();
-	/* kick all the CPUs so that they exit out of pm_idle */
-	smp_call_function(do_nothing, NULL, 0, 1);
-}
-EXPORT_SYMBOL_GPL(cpu_idle_wait);
-
-/*
- * This uses new MONITOR/MWAIT instructions on P4 processors with PNI,
- * which can obviate IPI to trigger checking of need_resched.
- * We execute MONITOR against need_resched and enter optimized wait state
- * through MWAIT. Whenever someone changes need_resched, we would be woken
- * up from MWAIT (without an IPI).
- *
- * New with Core Duo processors, MWAIT can take some hints based on CPU
- * capability.
- */
-void mwait_idle_with_hints(unsigned long ax, unsigned long cx)
-{
-	if (!need_resched()) {
-		__monitor((void *)&current_thread_info()->flags, 0, 0);
-		smp_mb();
-		if (!need_resched())
-			__sti_mwait(ax, cx);
-		else
-			local_irq_enable();
-	} else
-		local_irq_enable();
-}
-
-/* Default MONITOR/MWAIT with no hints, used for default C1 state */
-static void mwait_idle(void)
-{
-	local_irq_enable();
-	mwait_idle_with_hints(0, 0);
-}
-
-static int __cpuinit mwait_usable(const struct cpuinfo_x86 *c)
-{
-	if (force_mwait)
-		return 1;
-	/* Any C1 states supported? */
-	return c->cpuid_level >= 5 && ((cpuid_edx(5) >> 4) & 0xf) > 0;
-}
-
-void __cpuinit select_idle_routine(const struct cpuinfo_x86 *c)
-{
-	static int selected;
-
-	if (selected)
-		return;
-#ifdef CONFIG_X86_SMP
-	if (pm_idle == poll_idle && smp_num_siblings > 1) {
-		printk(KERN_WARNING "WARNING: polling idle and HT enabled,"
-			" performance may degrade.\n");
-	}
-#endif
-	if (cpu_has(c, X86_FEATURE_MWAIT) && mwait_usable(c)) {
-		/*
-		 * Skip, if setup has overridden idle.
-		 * One CPU supports mwait => All CPUs supports mwait
-		 */
-		if (!pm_idle) {
-			printk(KERN_INFO "using mwait in idle threads.\n");
-			pm_idle = mwait_idle;
-		}
-	}
-	selected = 1;
-}
-
-static int __init idle_setup(char *str)
-{
-	if (!strcmp(str, "poll")) {
-		printk("using polling idle threads.\n");
-		pm_idle = poll_idle;
-	} else if (!strcmp(str, "mwait"))
-		force_mwait = 1;
-	else
-		return -1;
-
-	boot_option_idle_override = 1;
-	return 0;
-}
-early_param("idle", idle_setup);
-
 void __show_regs(struct pt_regs *regs, int all)
 {
 	unsigned long cr0 = 0L, cr2 = 0L, cr3 = 0L, cr4 = 0L;
Index: linux/arch/x86/kernel/process_64.c
===================================================================
--- linux.orig/arch/x86/kernel/process_64.c
+++ linux/arch/x86/kernel/process_64.c
@@ -107,26 +107,13 @@ void default_idle(void)
 	 * test NEED_RESCHED:
 	 */
 	smp_mb();
-	local_irq_disable();
-	if (!need_resched()) {
+	if (!need_resched())
 		safe_halt();	/* enables interrupts racelessly */
-		local_irq_disable();
-	}
-	local_irq_enable();
+	else
+		local_irq_enable();
 	current_thread_info()->status |= TS_POLLING;
 }
 
-/*
- * On SMP it's slightly faster (but much more power-consuming!)
- * to poll the ->need_resched flag instead of waiting for the
- * cross-CPU IPI to arrive. Use this option with caution.
- */
-static void poll_idle(void)
-{
-	local_irq_enable();
-	cpu_relax();
-}
-
 #ifdef CONFIG_HOTPLUG_CPU
 DECLARE_PER_CPU(int, cpu_state);
 
@@ -207,110 +194,6 @@ void cpu_idle(void)
 	}
 }
 
-static void do_nothing(void *unused)
-{
-}
-
-/*
- * cpu_idle_wait - Used to ensure that all the CPUs discard old value of
- * pm_idle and update to new pm_idle value. Required while changing pm_idle
- * handler on SMP systems.
- *
- * Caller must have changed pm_idle to the new value before the call. Old
- * pm_idle value will not be used by any CPU after the return of this function.
- */
-void cpu_idle_wait(void)
-{
-	smp_mb();
-	/* kick all the CPUs so that they exit out of pm_idle */
-	smp_call_function(do_nothing, NULL, 0, 1);
-}
-EXPORT_SYMBOL_GPL(cpu_idle_wait);
-
-/*
- * This uses new MONITOR/MWAIT instructions on P4 processors with PNI,
- * which can obviate IPI to trigger checking of need_resched.
- * We execute MONITOR against need_resched and enter optimized wait state
- * through MWAIT. Whenever someone changes need_resched, we would be woken
- * up from MWAIT (without an IPI).
- *
- * New with Core Duo processors, MWAIT can take some hints based on CPU
- * capability.
- */
-void mwait_idle_with_hints(unsigned long ax, unsigned long cx)
-{
-	if (!need_resched()) {
-		__monitor((void *)&current_thread_info()->flags, 0, 0);
-		smp_mb();
-		if (!need_resched())
-			__mwait(ax, cx);
-	}
-}
-
-/* Default MONITOR/MWAIT with no hints, used for default C1 state */
-static void mwait_idle(void)
-{
-	if (!need_resched()) {
-		__monitor((void *)&current_thread_info()->flags, 0, 0);
-		smp_mb();
-		if (!need_resched())
-			__sti_mwait(0, 0);
-		else
-			local_irq_enable();
-	} else {
-		local_irq_enable();
-	}
-}
-
-
-static int __cpuinit mwait_usable(const struct cpuinfo_x86 *c)
-{
-	if (force_mwait)
-		return 1;
-	/* Any C1 states supported? */
-	return c->cpuid_level >= 5 && ((cpuid_edx(5) >> 4) & 0xf) > 0;
-}
-
-void __cpuinit select_idle_routine(const struct cpuinfo_x86 *c)
-{
-	static int selected;
-
-	if (selected)
-		return;
-#ifdef CONFIG_X86_SMP
-	if (pm_idle == poll_idle && smp_num_siblings > 1) {
-		printk(KERN_WARNING "WARNING: polling idle and HT enabled,"
-			" performance may degrade.\n");
-	}
-#endif
-	if (cpu_has(c, X86_FEATURE_MWAIT) && mwait_usable(c)) {
-		/*
-		 * Skip, if setup has overridden idle.
-		 * One CPU supports mwait => All CPUs supports mwait
-		 */
-		if (!pm_idle) {
-			printk(KERN_INFO "using mwait in idle threads.\n");
-			pm_idle = mwait_idle;
-		}
-	}
-	selected = 1;
-}
-
-static int __init idle_setup(char *str)
-{
-	if (!strcmp(str, "poll")) {
-		printk("using polling idle threads.\n");
-		pm_idle = poll_idle;
-	} else if (!strcmp(str, "mwait"))
-		force_mwait = 1;
-	else
-		return -1;
-
-	boot_option_idle_override = 1;
-	return 0;
-}
-early_param("idle", idle_setup);
-
 /* Prints also some state that isn't saved in the pt_regs */
 void __show_regs(struct pt_regs * regs, int all)
 {
Index: linux/drivers/acpi/processor_idle.c
===================================================================
--- linux.orig/drivers/acpi/processor_idle.c
+++ linux/drivers/acpi/processor_idle.c
@@ -418,13 +418,12 @@ static void acpi_processor_idle(void)
 
 	cx = pr->power.state;
 	if (!cx || acpi_idle_suspend) {
-		if (pm_idle_save)
-			pm_idle_save();
-		else
+		if (pm_idle_save) {
+			pm_idle_save(); /* enables IRQs */
+		} else {
 			acpi_safe_halt();
-
-		if (irqs_disabled())
 			local_irq_enable();
+		}
 
 		return;
 	}
@@ -520,10 +519,12 @@ static void acpi_processor_idle(void)
 		 * Use the appropriate idle routine, the one that would
 		 * be used without acpi C-states.
 		 */
-		if (pm_idle_save)
-			pm_idle_save();
-		else
+		if (pm_idle_save) {
+			pm_idle_save(); /* enables IRQs */
+		} else {
 			acpi_safe_halt();
+			local_irq_enable();
+		}
 
 		/*
 		 * TBD: Can't get time duration while in C1, as resumes
@@ -534,8 +535,6 @@ static void acpi_processor_idle(void)
 		 *       skew otherwise.
 		 */
 		sleep_ticks = 0xFFFFFFFF;
-		if (irqs_disabled())
-			local_irq_enable();
 
 		break;
 
Index: linux/include/asm-x86/processor.h
===================================================================
--- linux.orig/include/asm-x86/processor.h
+++ linux/include/asm-x86/processor.h
@@ -725,6 +725,7 @@ static inline void __mwait(unsigned long
 
 static inline void __sti_mwait(unsigned long eax, unsigned long ecx)
 {
+	trace_hardirqs_on();
 	/* "mwait %eax, %ecx;" */
 	asm volatile("sti; .byte 0x0f, 0x01, 0xc9;"
 		     :: "a" (eax), "c" (ecx));

Re: spinlock lockup on CPU#0

[Justin Mattock]

On Sat, Apr 26, 2008 at 7:14 PM, Ingo Molnar <mingo@elte.hu> wrote:
>
>  * Andrew Morton <akpm@linux-foundation.org> wrote:
>
>
> > > Hopefully the numbers are right, and hopefully this provides enough
>  > > info to help the kernel out
>  >
>  > Well that's cute.  At a guess I'd say that acpi_processor_idle()
>  > managed to call sched_clock_idle_wakeup_event() with local interrupts
>  > enabled.  We took an interrupt with rq->lock held and things went
>  > downhill from there.
>  >
>  > Can you add this please, see if it triggers?
>
>  there's fixes pending in this area. The main fix would be the one below.
>
>         Ingo
>
>  ---------------->
>  Subject: idle (arch, acpi and apm) and lockdep
>  From: Peter Zijlstra <peterz@infradead.org>
>  Date: Fri, 25 Apr 2008 17:39:01 +0200
>
>  On Fri, 2008-04-25 at 16:59 +0200, Peter Zijlstra wrote:
>  > 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@chello.nl> 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
>  > > >  > [   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]  =======================
>
>  (I just found out I failed to copy LKML on the last discussion about
>  these patches)
>
>  Signed-off-by: Ingo Molnar <mingo@elte.hu>
>  ---
>  From: Peter Zijlstra <peterz@infradead.org>
>
>  OK, so 25-mm1 gave a lockdep error which made me look into this.
>
>  The first thing that I noticed was the horrible mess; the second thing I
>  saw was hacks like: 71e93d15612c61c2e26a169567becf088e71b8ff
>
>  The problem is that arch idle routines are somewhat inconsitent with
>  their IRQ state handling and instead of fixing _that_, we go paper over
>  the problem.
>
>  So the thing I've tried to do is set a standard for idle routines and
>  fix them all up to adhere to that. So the rules are:
>
>   idle routines are entered with IRQs disabled
>   idle routines will exit with IRQs enabled
>
>  Nearly all already did this in one form or another.
>
>  Merge the 32 and 64 bit bits so they no longer have different bugs.
>
>  As for the actual lockdep warning; __sti_mwait() did a plainly un-annotated
>  irq-enable.
>
>  Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
>  ---
>   arch/x86/kernel/apm_32.c      |    3 +
>   arch/x86/kernel/process.c     |  117 +++++++++++++++++++++++++++++++++++++++
>   arch/x86/kernel/process_32.c  |  118 +---------------------------------------
>   arch/x86/kernel/process_64.c  |  123 +-----------------------------------------
>   drivers/acpi/processor_idle.c |   19 +++---
>   include/asm-x86/processor.h   |    1
>   6 files changed, 137 insertions(+), 244 deletions(-)
>
>  Index: linux/arch/x86/kernel/apm_32.c
>  ===================================================================
>  --- linux.orig/arch/x86/kernel/apm_32.c
>  +++ linux/arch/x86/kernel/apm_32.c
>  @@ -904,6 +904,7 @@ recalc:
>                         original_pm_idle();
>                 else
>                         default_idle();
>  +               local_irq_disable();
>                 jiffies_since_last_check = jiffies - last_jiffies;
>                 if (jiffies_since_last_check > idle_period)
>                         goto recalc;
>  @@ -911,6 +912,8 @@ recalc:
>
>         if (apm_idle_done)
>                 apm_do_busy();
>  +
>  +       local_irq_enable();
>   }
>
>   /**
>  Index: linux/arch/x86/kernel/process.c
>  ===================================================================
>  --- linux.orig/arch/x86/kernel/process.c
>  +++ linux/arch/x86/kernel/process.c
>  @@ -4,6 +4,8 @@
>   #include <linux/smp.h>
>   #include <linux/slab.h>
>   #include <linux/sched.h>
>  +#include <linux/module.h>
>  +#include <linux/pm.h>
>
>   struct kmem_cache *task_xstate_cachep;
>
>  @@ -42,3 +44,118 @@ void arch_task_cache_init(void)
>                                   __alignof__(union thread_xstate),
>                                   SLAB_PANIC | SLAB_NOTRACK, NULL);
>   }
>  +
>  +static void do_nothing(void *unused)
>  +{
>  +}
>  +
>  +/*
>  + * cpu_idle_wait - Used to ensure that all the CPUs discard old value of
>  + * pm_idle and update to new pm_idle value. Required while changing pm_idle
>  + * handler on SMP systems.
>  + *
>  + * Caller must have changed pm_idle to the new value before the call. Old
>  + * pm_idle value will not be used by any CPU after the return of this function.
>  + */
>  +void cpu_idle_wait(void)
>  +{
>  +       smp_mb();
>  +       /* kick all the CPUs so that they exit out of pm_idle */
>  +       smp_call_function(do_nothing, NULL, 0, 1);
>  +}
>  +EXPORT_SYMBOL_GPL(cpu_idle_wait);
>  +
>  +/*
>  + * This uses new MONITOR/MWAIT instructions on P4 processors with PNI,
>  + * which can obviate IPI to trigger checking of need_resched.
>  + * We execute MONITOR against need_resched and enter optimized wait state
>  + * through MWAIT. Whenever someone changes need_resched, we would be woken
>  + * up from MWAIT (without an IPI).
>  + *
>  + * New with Core Duo processors, MWAIT can take some hints based on CPU
>  + * capability.
>  + */
>  +void mwait_idle_with_hints(unsigned long ax, unsigned long cx)
>  +{
>  +       if (!need_resched()) {
>  +               __monitor((void *)&current_thread_info()->flags, 0, 0);
>  +               smp_mb();
>  +               if (!need_resched())
>  +                       __mwait(ax, cx);
>  +       }
>  +}
>  +
>  +/* Default MONITOR/MWAIT with no hints, used for default C1 state */
>  +static void mwait_idle(void)
>  +{
>  +       if (!need_resched()) {
>  +               __monitor((void *)&current_thread_info()->flags, 0, 0);
>  +               smp_mb();
>  +               if (!need_resched())
>  +                       __sti_mwait(0, 0);
>  +               else
>  +                       local_irq_enable();
>  +       } else
>  +               local_irq_enable();
>  +}
>  +
>  +
>  +static int __cpuinit mwait_usable(const struct cpuinfo_x86 *c)
>  +{
>  +       if (force_mwait)
>  +               return 1;
>  +       /* Any C1 states supported? */
>  +       return c->cpuid_level >= 5 && ((cpuid_edx(5) >> 4) & 0xf) > 0;
>  +}
>  +
>  +/*
>  + * On SMP it's slightly faster (but much more power-consuming!)
>  + * to poll the ->work.need_resched flag instead of waiting for the
>  + * cross-CPU IPI to arrive. Use this option with caution.
>  + */
>  +static void poll_idle(void)
>  +{
>  +       local_irq_enable();
>  +       cpu_relax();
>  +}
>  +
>  +void __cpuinit select_idle_routine(const struct cpuinfo_x86 *c)
>  +{
>  +       static int selected;
>  +
>  +       if (selected)
>  +               return;
>  +#ifdef CONFIG_X86_SMP
>  +       if (pm_idle == poll_idle && smp_num_siblings > 1) {
>  +               printk(KERN_WARNING "WARNING: polling idle and HT enabled,"
>  +                       " performance may degrade.\n");
>  +       }
>  +#endif
>  +       if (cpu_has(c, X86_FEATURE_MWAIT) && mwait_usable(c)) {
>  +               /*
>  +                * Skip, if setup has overridden idle.
>  +                * One CPU supports mwait => All CPUs supports mwait
>  +                */
>  +               if (!pm_idle) {
>  +                       printk(KERN_INFO "using mwait in idle threads.\n");
>  +                       pm_idle = mwait_idle;
>  +               }
>  +       }
>  +       selected = 1;
>  +}
>  +
>  +static int __init idle_setup(char *str)
>  +{
>  +       if (!strcmp(str, "poll")) {
>  +               printk("using polling idle threads.\n");
>  +               pm_idle = poll_idle;
>  +       } else if (!strcmp(str, "mwait"))
>  +               force_mwait = 1;
>  +       else
>  +               return -1;
>  +
>  +       boot_option_idle_override = 1;
>  +       return 0;
>  +}
>  +early_param("idle", idle_setup);
>  +
>  Index: linux/arch/x86/kernel/process_32.c
>  ===================================================================
>  --- linux.orig/arch/x86/kernel/process_32.c
>  +++ linux/arch/x86/kernel/process_32.c
>  @@ -111,12 +111,10 @@ void default_idle(void)
>                  */
>                 smp_mb();
>
>  -               local_irq_disable();
>  -               if (!need_resched()) {
>  +               if (!need_resched())
>                         safe_halt();    /* enables interrupts racelessly */
>  -                       local_irq_disable();
>  -               }
>  -               local_irq_enable();
>  +               else
>  +                       local_irq_enable();
>                 current_thread_info()->status |= TS_POLLING;
>         } else {
>                 local_irq_enable();
>  @@ -128,17 +126,6 @@ void default_idle(void)
>   EXPORT_SYMBOL(default_idle);
>   #endif
>
>  -/*
>  - * On SMP it's slightly faster (but much more power-consuming!)
>  - * to poll the ->work.need_resched flag instead of waiting for the
>  - * cross-CPU IPI to arrive. Use this option with caution.
>  - */
>  -static void poll_idle(void)
>  -{
>  -       local_irq_enable();
>  -       cpu_relax();
>  -}
>  -
>   #ifdef CONFIG_HOTPLUG_CPU
>   #include <asm/nmi.h>
>   /* We don't actually take CPU down, just spin without interrupts. */
>  @@ -196,6 +183,7 @@ void cpu_idle(void)
>                         if (cpu_is_offline(cpu))
>                                 play_dead();
>
>  +                       local_irq_disable();
>                         __get_cpu_var(irq_stat).idle_timestamp = jiffies;
>                         /* Don't trace irqs off for idle */
>                         stop_critical_timings();
>  @@ -209,104 +197,6 @@ void cpu_idle(void)
>         }
>   }
>
>  -static void do_nothing(void *unused)
>  -{
>  -}
>  -
>  -/*
>  - * cpu_idle_wait - Used to ensure that all the CPUs discard old value of
>  - * pm_idle and update to new pm_idle value. Required while changing pm_idle
>  - * handler on SMP systems.
>  - *
>  - * Caller must have changed pm_idle to the new value before the call. Old
>  - * pm_idle value will not be used by any CPU after the return of this function.
>  - */
>  -void cpu_idle_wait(void)
>  -{
>  -       smp_mb();
>  -       /* kick all the CPUs so that they exit out of pm_idle */
>  -       smp_call_function(do_nothing, NULL, 0, 1);
>  -}
>  -EXPORT_SYMBOL_GPL(cpu_idle_wait);
>  -
>  -/*
>  - * This uses new MONITOR/MWAIT instructions on P4 processors with PNI,
>  - * which can obviate IPI to trigger checking of need_resched.
>  - * We execute MONITOR against need_resched and enter optimized wait state
>  - * through MWAIT. Whenever someone changes need_resched, we would be woken
>  - * up from MWAIT (without an IPI).
>  - *
>  - * New with Core Duo processors, MWAIT can take some hints based on CPU
>  - * capability.
>  - */
>  -void mwait_idle_with_hints(unsigned long ax, unsigned long cx)
>  -{
>  -       if (!need_resched()) {
>  -               __monitor((void *)&current_thread_info()->flags, 0, 0);
>  -               smp_mb();
>  -               if (!need_resched())
>  -                       __sti_mwait(ax, cx);
>  -               else
>  -                       local_irq_enable();
>  -       } else
>  -               local_irq_enable();
>  -}
>  -
>  -/* Default MONITOR/MWAIT with no hints, used for default C1 state */
>  -static void mwait_idle(void)
>  -{
>  -       local_irq_enable();
>  -       mwait_idle_with_hints(0, 0);
>  -}
>  -
>  -static int __cpuinit mwait_usable(const struct cpuinfo_x86 *c)
>  -{
>  -       if (force_mwait)
>  -               return 1;
>  -       /* Any C1 states supported? */
>  -       return c->cpuid_level >= 5 && ((cpuid_edx(5) >> 4) & 0xf) > 0;
>  -}
>  -
>  -void __cpuinit select_idle_routine(const struct cpuinfo_x86 *c)
>  -{
>  -       static int selected;
>  -
>  -       if (selected)
>  -               return;
>  -#ifdef CONFIG_X86_SMP
>  -       if (pm_idle == poll_idle && smp_num_siblings > 1) {
>  -               printk(KERN_WARNING "WARNING: polling idle and HT enabled,"
>  -                       " performance may degrade.\n");
>  -       }
>  -#endif
>  -       if (cpu_has(c, X86_FEATURE_MWAIT) && mwait_usable(c)) {
>  -               /*
>  -                * Skip, if setup has overridden idle.
>  -                * One CPU supports mwait => All CPUs supports mwait
>  -                */
>  -               if (!pm_idle) {
>  -                       printk(KERN_INFO "using mwait in idle threads.\n");
>  -                       pm_idle = mwait_idle;
>  -               }
>  -       }
>  -       selected = 1;
>  -}
>  -
>  -static int __init idle_setup(char *str)
>  -{
>  -       if (!strcmp(str, "poll")) {
>  -               printk("using polling idle threads.\n");
>  -               pm_idle = poll_idle;
>  -       } else if (!strcmp(str, "mwait"))
>  -               force_mwait = 1;
>  -       else
>  -               return -1;
>  -
>  -       boot_option_idle_override = 1;
>  -       return 0;
>  -}
>  -early_param("idle", idle_setup);
>  -
>   void __show_regs(struct pt_regs *regs, int all)
>   {
>         unsigned long cr0 = 0L, cr2 = 0L, cr3 = 0L, cr4 = 0L;
>  Index: linux/arch/x86/kernel/process_64.c
>  ===================================================================
>  --- linux.orig/arch/x86/kernel/process_64.c
>  +++ linux/arch/x86/kernel/process_64.c
>  @@ -107,26 +107,13 @@ void default_idle(void)
>          * test NEED_RESCHED:
>          */
>         smp_mb();
>  -       local_irq_disable();
>  -       if (!need_resched()) {
>  +       if (!need_resched())
>                 safe_halt();    /* enables interrupts racelessly */
>  -               local_irq_disable();
>  -       }
>  -       local_irq_enable();
>  +       else
>  +               local_irq_enable();
>         current_thread_info()->status |= TS_POLLING;
>   }
>
>  -/*
>  - * On SMP it's slightly faster (but much more power-consuming!)
>  - * to poll the ->need_resched flag instead of waiting for the
>  - * cross-CPU IPI to arrive. Use this option with caution.
>  - */
>  -static void poll_idle(void)
>  -{
>  -       local_irq_enable();
>  -       cpu_relax();
>  -}
>  -
>   #ifdef CONFIG_HOTPLUG_CPU
>   DECLARE_PER_CPU(int, cpu_state);
>
>  @@ -207,110 +194,6 @@ void cpu_idle(void)
>         }
>   }
>
>  -static void do_nothing(void *unused)
>  -{
>  -}
>  -
>  -/*
>  - * cpu_idle_wait - Used to ensure that all the CPUs discard old value of
>  - * pm_idle and update to new pm_idle value. Required while changing pm_idle
>  - * handler on SMP systems.
>  - *
>  - * Caller must have changed pm_idle to the new value before the call. Old
>  - * pm_idle value will not be used by any CPU after the return of this function.
>  - */
>  -void cpu_idle_wait(void)
>  -{
>  -       smp_mb();
>  -       /* kick all the CPUs so that they exit out of pm_idle */
>  -       smp_call_function(do_nothing, NULL, 0, 1);
>  -}
>  -EXPORT_SYMBOL_GPL(cpu_idle_wait);
>  -
>  -/*
>  - * This uses new MONITOR/MWAIT instructions on P4 processors with PNI,
>  - * which can obviate IPI to trigger checking of need_resched.
>  - * We execute MONITOR against need_resched and enter optimized wait state
>  - * through MWAIT. Whenever someone changes need_resched, we would be woken
>  - * up from MWAIT (without an IPI).
>  - *
>  - * New with Core Duo processors, MWAIT can take some hints based on CPU
>  - * capability.
>  - */
>  -void mwait_idle_with_hints(unsigned long ax, unsigned long cx)
>  -{
>  -       if (!need_resched()) {
>  -               __monitor((void *)&current_thread_info()->flags, 0, 0);
>  -               smp_mb();
>  -               if (!need_resched())
>  -                       __mwait(ax, cx);
>  -       }
>  -}
>  -
>  -/* Default MONITOR/MWAIT with no hints, used for default C1 state */
>  -static void mwait_idle(void)
>  -{
>  -       if (!need_resched()) {
>  -               __monitor((void *)&current_thread_info()->flags, 0, 0);
>  -               smp_mb();
>  -               if (!need_resched())
>  -                       __sti_mwait(0, 0);
>  -               else
>  -                       local_irq_enable();
>  -       } else {
>  -               local_irq_enable();
>  -       }
>  -}
>  -
>  -
>  -static int __cpuinit mwait_usable(const struct cpuinfo_x86 *c)
>  -{
>  -       if (force_mwait)
>  -               return 1;
>  -       /* Any C1 states supported? */
>  -       return c->cpuid_level >= 5 && ((cpuid_edx(5) >> 4) & 0xf) > 0;
>  -}
>  -
>  -void __cpuinit select_idle_routine(const struct cpuinfo_x86 *c)
>  -{
>  -       static int selected;
>  -
>  -       if (selected)
>  -               return;
>  -#ifdef CONFIG_X86_SMP
>  -       if (pm_idle == poll_idle && smp_num_siblings > 1) {
>  -               printk(KERN_WARNING "WARNING: polling idle and HT enabled,"
>  -                       " performance may degrade.\n");
>  -       }
>  -#endif
>  -       if (cpu_has(c, X86_FEATURE_MWAIT) && mwait_usable(c)) {
>  -               /*
>  -                * Skip, if setup has overridden idle.
>  -                * One CPU supports mwait => All CPUs supports mwait
>  -                */
>  -               if (!pm_idle) {
>  -                       printk(KERN_INFO "using mwait in idle threads.\n");
>  -                       pm_idle = mwait_idle;
>  -               }
>  -       }
>  -       selected = 1;
>  -}
>  -
>  -static int __init idle_setup(char *str)
>  -{
>  -       if (!strcmp(str, "poll")) {
>  -               printk("using polling idle threads.\n");
>  -               pm_idle = poll_idle;
>  -       } else if (!strcmp(str, "mwait"))
>  -               force_mwait = 1;
>  -       else
>  -               return -1;
>  -
>  -       boot_option_idle_override = 1;
>  -       return 0;
>  -}
>  -early_param("idle", idle_setup);
>  -
>   /* Prints also some state that isn't saved in the pt_regs */
>   void __show_regs(struct pt_regs * regs, int all)
>   {
>  Index: linux/drivers/acpi/processor_idle.c
>  ===================================================================
>  --- linux.orig/drivers/acpi/processor_idle.c
>  +++ linux/drivers/acpi/processor_idle.c
>  @@ -418,13 +418,12 @@ static void acpi_processor_idle(void)
>
>         cx = pr->power.state;
>         if (!cx || acpi_idle_suspend) {
>  -               if (pm_idle_save)
>  -                       pm_idle_save();
>  -               else
>  +               if (pm_idle_save) {
>  +                       pm_idle_save(); /* enables IRQs */
>  +               } else {
>                         acpi_safe_halt();
>  -
>  -               if (irqs_disabled())
>                         local_irq_enable();
>  +               }
>
>                 return;
>         }
>  @@ -520,10 +519,12 @@ static void acpi_processor_idle(void)
>                  * Use the appropriate idle routine, the one that would
>                  * be used without acpi C-states.
>                  */
>  -               if (pm_idle_save)
>  -                       pm_idle_save();
>  -               else
>  +               if (pm_idle_save) {
>  +                       pm_idle_save(); /* enables IRQs */
>  +               } else {
>                         acpi_safe_halt();
>  +                       local_irq_enable();
>  +               }
>
>                 /*
>                  * TBD: Can't get time duration while in C1, as resumes
>  @@ -534,8 +535,6 @@ static void acpi_processor_idle(void)
>                  *       skew otherwise.
>                  */
>                 sleep_ticks = 0xFFFFFFFF;
>  -               if (irqs_disabled())
>  -                       local_irq_enable();
>
>                 break;
>
>  Index: linux/include/asm-x86/processor.h
>  ===================================================================
>  --- linux.orig/include/asm-x86/processor.h
>  +++ linux/include/asm-x86/processor.h
>  @@ -725,6 +725,7 @@ static inline void __mwait(unsigned long
>
>   static inline void __sti_mwait(unsigned long eax, unsigned long ecx)
>   {
>  +       trace_hardirqs_on();
>         /* "mwait %eax, %ecx;" */
>         asm volatile("sti; .byte 0x0f, 0x01, 0xc9;"
>                      :: "a" (eax), "c" (ecx));
>
O.K.
 I added WARN_ON(!irqs_disabled()); in kernel/sched.c
I'm not experiencing anything different, should I have done this with
a fresh git that was'nt patched with the above?
The numbers were different for me they were at kernel/sched.c line 1123 and 1143
regards;

-- 
Justin P. Mattock

Re: spinlock lockup on CPU#0

[Bob Copeland]

On Sat, Apr 26, 2008 at 3:14 PM, Ingo Molnar <mingo@elte.hu> wrote:
>  > Can you add this please, see if it triggers?
>
>  there's fixes pending in this area. The main fix would be the one below.
>
>         Ingo
>
>  ---------------->
>  Subject: idle (arch, acpi and apm) and lockdep

FWIW, I was seeing the same lockdep trace with eventual hangs, and
this patch (applied with some fuzz) fixed the problem.

-- 
Bob Copeland %% www.bobcopeland.com

Re: spinlock lockup on CPU#0

[Justin Mattock]

On Sat, Apr 26, 2008 at 9:06 PM, Bob Copeland <me@bobcopeland.com> wrote:
> On Sat, Apr 26, 2008 at 3:14 PM, Ingo Molnar <mingo@elte.hu> wrote:
>  >  > Can you add this please, see if it triggers?
>  >
>  >  there's fixes pending in this area. The main fix would be the one below.
>  >
>  >         Ingo
>  >
>  >  ---------------->
>  >  Subject: idle (arch, acpi and apm) and lockdep
>
>  FWIW, I was seeing the same lockdep trace with eventual hangs, and
>  this patch (applied with some fuzz) fixed the problem.
>
>  --
>  Bob Copeland %% www.bobcopeland.com
>

Just out of curiosity I put the kernel back to it's original state,
were the freezing occurs, then booted with nohz=off, then added
WARN_ON(!irqs_disabled()); to sched.c only to the kernel, no other
patches, upon rebooting
I received different results: The screen from what I could tell was
spitting out the spinlock messages, but instead of printing that out,
and going on to the next task it just keep't printing, from what I
could tell something with ehci, uhci, agpgart, ieee1394 etc... too
fast to really make anything out, the numbers on the left side keept
moving upward, the fans started hauling ass, I waitied a few minuetes
hopeing this would stop
so I can grab dmesg, but it would'nt. is there a way to use the boot
param to write date to a file? so I could capture this event.
regards

-- 
Justin P. Mattock

Re: spinlock lockup on CPU#0

[Venki Pallipadi]

On Sat, Apr 26, 2008 at 09:48:55PM +0000, Justin Mattock wrote:
> On Sat, Apr 26, 2008 at 9:06 PM, Bob Copeland <me@bobcopeland.com> wrote:
> > On Sat, Apr 26, 2008 at 3:14 PM, Ingo Molnar <mingo@elte.hu> wrote:
> >  >  > Can you add this please, see if it triggers?
> >  >
> >  >  there's fixes pending in this area. The main fix would be the one below.
> >  >
> >  >         Ingo
> >  >
> >  >  ---------------->
> >  >  Subject: idle (arch, acpi and apm) and lockdep
> >
> >  FWIW, I was seeing the same lockdep trace with eventual hangs, and
> >  this patch (applied with some fuzz) fixed the problem.
> >
> >  --
> >  Bob Copeland %% www.bobcopeland.com
> >
> 
> Just out of curiosity I put the kernel back to it's original state,
> were the freezing occurs, then booted with nohz=off, then added
> WARN_ON(!irqs_disabled()); to sched.c only to the kernel, no other
> patches, upon rebooting
> I received different results: The screen from what I could tell was
> spitting out the spinlock messages, but instead of printing that out,
> and going on to the next task it just keep't printing, from what I
> could tell something with ehci, uhci, agpgart, ieee1394 etc... too
> fast to really make anything out, the numbers on the left side keept
> moving upward, the fans started hauling ass, I waitied a few minuetes
> hopeing this would stop
> so I can grab dmesg, but it would'nt. is there a way to use the boot
> param to write date to a file? so I could capture this event.
> regards
> 

OK. Hunted this bug down to
commit 3b22ec7b13cb31e0d87fbc0aabe14caaaad309e8

which for some reason enables interrupt in mwait_idle_with_hints(), which
eventually causes interrupts to be enabled in acpi idle call, resulting in
sched_clock_idle_wakeup_event() with interrupts enabled. This bug
was only in x86 32 bit version.

Peter's patch below which is already in git fixes this. So we don't need any
additional fixes here...

Thanks,
Venki

Re: spinlock lockup on CPU#0

[Justin Mattock]

On Mon, Apr 28, 2008 at 8:38 PM, Venki Pallipadi
<venkatesh.pallipadi@intel.com> wrote:
> On Sat, Apr 26, 2008 at 09:48:55PM +0000, Justin Mattock wrote:
>  > On Sat, Apr 26, 2008 at 9:06 PM, Bob Copeland <me@bobcopeland.com> wrote:
>  > > On Sat, Apr 26, 2008 at 3:14 PM, Ingo Molnar <mingo@elte.hu> wrote:
>  > >  >  > Can you add this please, see if it triggers?
>  > >  >
>  > >  >  there's fixes pending in this area. The main fix would be the one below.
>  > >  >
>  > >  >         Ingo
>  > >  >
>  > >  >  ---------------->
>  > >  >  Subject: idle (arch, acpi and apm) and lockdep
>  > >
>  > >  FWIW, I was seeing the same lockdep trace with eventual hangs, and
>  > >  this patch (applied with some fuzz) fixed the problem.
>  > >
>  > >  --
>  > >  Bob Copeland %% www.bobcopeland.com
>  > >
>  >
>  > Just out of curiosity I put the kernel back to it's original state,
>  > were the freezing occurs, then booted with nohz=off, then added
>  > WARN_ON(!irqs_disabled()); to sched.c only to the kernel, no other
>  > patches, upon rebooting
>  > I received different results: The screen from what I could tell was
>  > spitting out the spinlock messages, but instead of printing that out,
>  > and going on to the next task it just keep't printing, from what I
>  > could tell something with ehci, uhci, agpgart, ieee1394 etc... too
>  > fast to really make anything out, the numbers on the left side keept
>  > moving upward, the fans started hauling ass, I waitied a few minuetes
>  > hopeing this would stop
>  > so I can grab dmesg, but it would'nt. is there a way to use the boot
>  > param to write date to a file? so I could capture this event.
>  > regards
>  >
>
>  OK. Hunted this bug down to
>  commit 3b22ec7b13cb31e0d87fbc0aabe14caaaad309e8
>
>  which for some reason enables interrupt in mwait_idle_with_hints(), which
>  eventually causes interrupts to be enabled in acpi idle call, resulting in
>  sched_clock_idle_wakeup_event() with interrupts enabled. This bug
>  was only in x86 32 bit version.
>
>  Peter's patch below which is already in git fixes this. So we don't need any
>  additional fixes here...
>
>  Thanks,
>  Venki
>
>

Alright, I was concerned about having additional fixes.
regards;

-- 
Justin P. Mattock

Re: spinlock lockup on CPU#0

[Hugh Dickins]

On Sat, 26 Apr 2008, Ingo Molnar wrote:
> * Andrew Morton <akpm@linux-foundation.org> wrote:
> 
> > > Hopefully the numbers are right, and hopefully this provides enough 
> > > info to help the kernel out
> > 
> > Well that's cute.  At a guess I'd say that acpi_processor_idle() 
> > managed to call sched_clock_idle_wakeup_event() with local interrupts 
> > enabled.  We took an interrupt with rq->lock held and things went 
> > downhill from there.
> > 
> > Can you add this please, see if it triggers?
> 
> there's fixes pending in this area. The main fix would be the one below.
> 
> 	Ingo
> 
> ---------------->
> Subject: idle (arch, acpi and apm) and lockdep
> From: Peter Zijlstra <peterz@infradead.org>
> Date: Fri, 25 Apr 2008 17:39:01 +0200

Oh good, thanks, I see you've just asked Linus to pull that idle fix.

Thanks to Peter for the fix, and to Justin for calling attention to it:
this freeze has been plaguing me on one x86_32 box since I put -git8
on, and I've just verified that it's the same as what's been plaguing
me on that machine since 2.6.25-mm1 came out.

Andrew, here's a belated hotfix for 2.6.25-mm1, running nicely at last:

Peter Zijlstra's "idle (arch, acpi and apm) and lockdep" fix to
recent x86 freezes - adapted to 2.6.25-mm1 by omitting merges
from process_32.c and process_64.c into process.c.

Signed-off-by: Hugh Dickins <hugh@veritas.com>
---

 arch/x86/kernel/apm_32.c      |    3 +++
 arch/x86/kernel/process_32.c  |   27 +++++++++++++++------------
 arch/x86/kernel/process_64.c  |    8 +++-----
 drivers/acpi/processor_idle.c |   19 +++++++++----------
 include/asm-x86/processor.h   |    1 +
 5 files changed, 31 insertions(+), 27 deletions(-)

--- 2.6.25-mm1/arch/x86/kernel/apm_32.c	2008-04-18 12:18:09.000000000 +0100
+++ linux/arch/x86/kernel/apm_32.c	2008-04-26 22:17:06.000000000 +0100
@@ -904,6 +904,7 @@ recalc:
 			original_pm_idle();
 		else
 			default_idle();
+		local_irq_disable();
 		jiffies_since_last_check = jiffies - last_jiffies;
 		if (jiffies_since_last_check > idle_period)
 			goto recalc;
@@ -911,6 +912,8 @@ recalc:
 
 	if (apm_idle_done)
 		apm_do_busy();
+
+	local_irq_enable();
 }
 
 /**
--- 2.6.25-mm1/arch/x86/kernel/process_32.c	2008-04-18 12:18:09.000000000 +0100
+++ linux/arch/x86/kernel/process_32.c	2008-04-26 22:29:36.000000000 +0100
@@ -111,12 +111,10 @@ void default_idle(void)
 		 */
 		smp_mb();
 
-		local_irq_disable();
-		if (!need_resched()) {
+		if (!need_resched())
 			safe_halt();	/* enables interrupts racelessly */
-			local_irq_disable();
-		}
-		local_irq_enable();
+		else
+			local_irq_enable();
 		current_thread_info()->status |= TS_POLLING;
 	} else {
 		local_irq_enable();
@@ -196,6 +194,7 @@ void cpu_idle(void)
 			if (cpu_is_offline(cpu))
 				play_dead();
 
+			local_irq_disable();
 			__get_cpu_var(irq_stat).idle_timestamp = jiffies;
 			/* Don't trace irqs off for idle */
 			stop_critical_timings();
@@ -245,18 +244,22 @@ void mwait_idle_with_hints(unsigned long
 		__monitor((void *)&current_thread_info()->flags, 0, 0);
 		smp_mb();
 		if (!need_resched())
-			__sti_mwait(ax, cx);
-		else
-			local_irq_enable();
-	} else
-		local_irq_enable();
+			__mwait(ax, cx);
+	}
 }
 
 /* Default MONITOR/MWAIT with no hints, used for default C1 state */
 static void mwait_idle(void)
 {
-	local_irq_enable();
-	mwait_idle_with_hints(0, 0);
+	if (!need_resched()) {
+		__monitor((void *)&current_thread_info()->flags, 0, 0);
+		smp_mb();
+		if (!need_resched())
+			__sti_mwait(0, 0);
+		else
+			local_irq_enable();
+	} else
+		local_irq_enable();
 }
 
 static int __cpuinit mwait_usable(const struct cpuinfo_x86 *c)
--- 2.6.25-mm1/arch/x86/kernel/process_64.c	2008-04-18 12:18:09.000000000 +0100
+++ linux/arch/x86/kernel/process_64.c	2008-04-26 22:19:29.000000000 +0100
@@ -106,12 +106,10 @@ void default_idle(void)
 	 * test NEED_RESCHED:
 	 */
 	smp_mb();
-	local_irq_disable();
-	if (!need_resched()) {
+	if (!need_resched())
 		safe_halt();	/* enables interrupts racelessly */
-		local_irq_disable();
-	}
-	local_irq_enable();
+	else
+		local_irq_enable();
 	current_thread_info()->status |= TS_POLLING;
 }
 
--- 2.6.25-mm1/drivers/acpi/processor_idle.c	2008-04-18 12:18:10.000000000 +0100
+++ linux/drivers/acpi/processor_idle.c	2008-04-26 22:17:06.000000000 +0100
@@ -436,13 +436,12 @@ static void acpi_processor_idle(void)
 
 	cx = pr->power.state;
 	if (!cx || acpi_idle_suspend) {
-		if (pm_idle_save)
-			pm_idle_save();
-		else
+		if (pm_idle_save) {
+			pm_idle_save(); /* enables IRQs */
+		} else {
 			acpi_safe_halt();
-
-		if (irqs_disabled())
 			local_irq_enable();
+		}
 
 		return;
 	}
@@ -538,10 +537,12 @@ static void acpi_processor_idle(void)
 		 * Use the appropriate idle routine, the one that would
 		 * be used without acpi C-states.
 		 */
-		if (pm_idle_save)
-			pm_idle_save();
-		else
+		if (pm_idle_save) {
+			pm_idle_save(); /* enables IRQs */
+		} else {
 			acpi_safe_halt();
+			local_irq_enable();
+		}
 
 		/*
 		 * TBD: Can't get time duration while in C1, as resumes
@@ -552,8 +553,6 @@ static void acpi_processor_idle(void)
 		 *       skew otherwise.
 		 */
 		sleep_ticks = 0xFFFFFFFF;
-		if (irqs_disabled())
-			local_irq_enable();
 
 		break;
 
--- 2.6.25-mm1/include/asm-x86/processor.h	2008-04-18 12:18:34.000000000 +0100
+++ linux/include/asm-x86/processor.h	2008-04-26 22:17:06.000000000 +0100
@@ -726,6 +726,7 @@ static inline void __mwait(unsigned long
 
 static inline void __sti_mwait(unsigned long eax, unsigned long ecx)
 {
+	trace_hardirqs_on();
 	/* "mwait %eax, %ecx;" */
 	asm volatile("sti; .byte 0x0f, 0x01, 0xc9;"
 		     :: "a" (eax), "c" (ecx));

Re: spinlock lockup on CPU#0

[Bernard Pidoux]

[-- Attachment #1: Type: text/plain, Size: 1264 bytes --]

Hi,

I observed about the same message but after the line
Brought up 2 CPUs in dmesg.
However the system keeps running fine. 
I run a Core2 Duo processor.
dmesg dump is attached. 

------------[ cut here ]------------
WARNING: at kernel/lockdep.c:2662 check_flags+0x18d/0x190()
Modules linked in:
Pid: 0, comm: swapper Not tainted 2.6.25 #2

Call Trace:
 [<ffffffff8022fbff>] warn_on_slowpath+0x5f/0x80
 [<ffffffff80213a77>] ? native_sched_clock+0x57/0x80
 [<ffffffff8022ac1a>] ? hrtick_set+0x3a/0x120
 [<ffffffff80254da5>] ? __lock_acquire+0x245/0x1070
 [<ffffffff8022ac9d>] ? hrtick_set+0xbd/0x120
 [<ffffffff80213a77>] ? native_sched_clock+0x57/0x80
 [<ffffffff8024b0b0>] ? __atomic_notifier_call_chain+0x0/0xa0
 [<ffffffff8025180d>] check_flags+0x18d/0x190
 [<ffffffff80255c33>] lock_acquire+0x63/0xd0
 [<ffffffff8024b101>] __atomic_notifier_call_chain+0x51/0xa0
 [<ffffffff8020b210>] ? mwait_idle+0x0/0x50
 [<ffffffff8020b0a0>] ? default_idle+0x0/0x80
 [<ffffffff8024b161>] atomic_notifier_call_chain+0x11/0x20
 [<ffffffff8020a849>] __exit_idle+0x29/0x30
 [<ffffffff8020b178>] cpu_idle+0x58/0xa0
 [<ffffffff80450b5e>] start_secondary+0x2fe/0x430

---[ end trace ca143223eefdc828 ]---
possible reason: unannotated irqs-on.
irq event stamp: 12


Bernard Pidoux

[-- Attachment #2: dmesg_swapper_Not_tainted_2.6.25 --]
[-- Type: text/plain, Size: 26639 bytes --]


Linux version 2.6.25 (root@f6bvp-7) (gcc version 4.2.3 (4.2.3-6mnb1)) #2 SMP Sat Apr 26 22:26:35 CEST 2008
Command line: BOOT_IMAGE=2.6.25 root=UUID=aaf61075-ffef-44f9-bb0b-9858afcfe990 resume=/dev/hda5 splash=silent vga=788
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 000000000009f000 (usable)
 BIOS-e820: 000000000009f000 - 00000000000a0000 (reserved)
 BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
 BIOS-e820: 0000000000100000 - 000000003fee0000 (usable)
 BIOS-e820: 000000003fee0000 - 000000003fee3000 (ACPI NVS)
 BIOS-e820: 000000003fee3000 - 000000003fef0000 (ACPI data)
 BIOS-e820: 00000000e0000000 - 00000000f0000000 (reserved)
 BIOS-e820: 00000000fec00000 - 0000000100000000 (reserved)
Entering add_active_range(0, 0, 159) 0 entries of 256 used
Entering add_active_range(0, 256, 261856) 1 entries of 256 used
end_pfn_map = 1048576
DMI 2.3 present.
ACPI: RSDP 000F7910, 0014 (r0 P4M890)
ACPI: RSDT 3FEE3040, 0038 (r1 P4M890 AWRDACPI 42302E31 AWRD        0)
ACPI: FACP 3FEE30C0, 0074 (r1 P4M890 AWRDACPI 42302E31 AWRD        0)
ACPI: DSDT 3FEE3180, 6A65 (r1 P4M890 AWRDACPI     1000 MSFT  100000E)
ACPI: FACS 3FEE0000, 0040
ACPI: MCFG 3FEE9D40, 003C (r1 P4M890 AWRDACPI 42302E31 AWRD        0)
ACPI: APIC 3FEE9C40, 0090 (r1 P4M890 AWRDACPI 42302E31 AWRD        0)
ACPI: SSDT 3FEE9DC0, 019E (r1  PmRef  Cpu0Ist     3000 INTL 20041203)
ACPI: SSDT 3FEEA250, 02F1 (r1  PmRef    CpuPm     3000 INTL 20041203)
Entering add_active_range(0, 0, 159) 0 entries of 256 used
Entering add_active_range(0, 256, 261856) 1 entries of 256 used
early res: 0 [0-fff] BIOS data page
early res: 1 [6000-7fff] SMP_TRAMPOLINE
early res: 2 [200000-a56297] TEXT DATA BSS
early res: 3 [37d60000-37fefbf6] RAMDISK
early res: 4 [9f000-aefff] EBDA
early res: 5 [8000-afff] PGTABLE
Zone PFN ranges:
  DMA             0 ->     4096
  DMA32        4096 ->  1048576
  Normal    1048576 ->  1048576
Movable zone start PFN for each node
early_node_map[2] active PFN ranges
    0:        0 ->      159
    0:      256 ->   261856
On node 0 totalpages: 261759
  DMA zone: 56 pages used for memmap
  DMA zone: 2158 pages reserved
  DMA zone: 1785 pages, LIFO batch:0
  DMA32 zone: 3524 pages used for memmap
  DMA32 zone: 254236 pages, LIFO batch:31
  Normal zone: 0 pages used for memmap
  Movable zone: 0 pages used for memmap
ACPI: PM-Timer IO Port: 0x408
ACPI: Local APIC address 0xfee00000
ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
Processor #0 (Bootup-CPU)
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
Processor #1
ACPI: LAPIC (acpi_id[0x02] lapic_id[0x02] disabled)
ACPI: LAPIC (acpi_id[0x03] lapic_id[0x03] disabled)
ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
ACPI: LAPIC_NMI (acpi_id[0x02] high edge lint[0x1])
ACPI: LAPIC_NMI (acpi_id[0x03] high edge lint[0x1])
ACPI: IOAPIC (id[0x04] address[0xfec00000] gsi_base[0])
IOAPIC[0]: apic_id 4, address 0xfec00000, GSI 0-23
ACPI: IOAPIC (id[0x05] address[0xfecc0000] gsi_base[24])
IOAPIC[1]: apic_id 5, address 0xfecc0000, GSI 24-47
ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 low level)
ACPI: IRQ0 used by override.
ACPI: IRQ2 used by override.
ACPI: IRQ9 used by override.
Setting APIC routing to flat
Using ACPI (MADT) for SMP configuration information
Allocating PCI resources starting at 40000000 (gap: 3fef0000:a0110000)
SMP: Allowing 2 CPUs, 0 hotplug CPUs
PERCPU: Allocating 423648 bytes of per cpu data
Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 256021
Kernel command line: BOOT_IMAGE=2.6.25 root=UUID=aaf61075-ffef-44f9-bb0b-9858afcfe990 resume=/dev/hda5 splash=silent vga=788
Initializing CPU#0
PID hash table entries: 4096 (order: 12, 32768 bytes)
TSC calibrated against PM_TIMER
time.c: Detected 2194.494 MHz processor.
Console: colour dummy device 80x25
console [tty0] enabled
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
... MAX_LOCKDEP_SUBCLASSES:    8
... MAX_LOCK_DEPTH:          48
... MAX_LOCKDEP_KEYS:        2048
... CLASSHASH_SIZE:           1024
... MAX_LOCKDEP_ENTRIES:     8192
... MAX_LOCKDEP_CHAINS:      16384
... CHAINHASH_SIZE:          8192
 memory used by lock dependency info: 1712 kB
 per task-struct memory footprint: 3456 bytes
------------------------
| Locking API testsuite:
----------------------------------------------------------------------------
                                 | spin |wlock |rlock |mutex | wsem | rsem |
  --------------------------------------------------------------------------
                     A-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
                 A-B-B-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
             A-B-B-C-C-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
             A-B-C-A-B-C deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
         A-B-B-C-C-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
         A-B-C-D-B-D-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
         A-B-C-D-B-C-D-A deadlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
                    double unlock:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
                  initialize held:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
                 bad unlock order:  ok  |  ok  |  ok  |  ok  |  ok  |  ok  |
  --------------------------------------------------------------------------
              recursive read-lock:             |  ok  |             |  ok  |
           recursive read-lock #2:             |  ok  |             |  ok  |
            mixed read-write-lock:             |  ok  |             |  ok  |
            mixed write-read-lock:             |  ok  |             |  ok  |
  --------------------------------------------------------------------------
     hard-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
     soft-irqs-on + irq-safe-A/12:  ok  |  ok  |  ok  |
     hard-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
     soft-irqs-on + irq-safe-A/21:  ok  |  ok  |  ok  |
       sirq-safe-A => hirqs-on/12:  ok  |  ok  |  ok  |
       sirq-safe-A => hirqs-on/21:  ok  |  ok  |  ok  |
         hard-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
         soft-safe-A + irqs-on/12:  ok  |  ok  |  ok  |
         hard-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
         soft-safe-A + irqs-on/21:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #1/123:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #1/132:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #1/213:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #1/231:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #1/312:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #1/321:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #2/123:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #2/132:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #2/213:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #2/231:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #2/312:  ok  |  ok  |  ok  |
    hard-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
    soft-safe-A + unsafe-B #2/321:  ok  |  ok  |  ok  |
      hard-irq lock-inversion/123:  ok  |  ok  |  ok  |
      soft-irq lock-inversion/123:  ok  |  ok  |  ok  |
      hard-irq lock-inversion/132:  ok  |  ok  |  ok  |
      soft-irq lock-inversion/132:  ok  |  ok  |  ok  |
      hard-irq lock-inversion/213:  ok  |  ok  |  ok  |
      soft-irq lock-inversion/213:  ok  |  ok  |  ok  |
      hard-irq lock-inversion/231:  ok  |  ok  |  ok  |
      soft-irq lock-inversion/231:  ok  |  ok  |  ok  |
      hard-irq lock-inversion/312:  ok  |  ok  |  ok  |
      soft-irq lock-inversion/312:  ok  |  ok  |  ok  |
      hard-irq lock-inversion/321:  ok  |  ok  |  ok  |
      soft-irq lock-inversion/321:  ok  |  ok  |  ok  |
      hard-irq read-recursion/123:  ok  |
      soft-irq read-recursion/123:  ok  |
      hard-irq read-recursion/132:  ok  |
      soft-irq read-recursion/132:  ok  |
      hard-irq read-recursion/213:  ok  |
      soft-irq read-recursion/213:  ok  |
      hard-irq read-recursion/231:  ok  |
      soft-irq read-recursion/231:  ok  |
      hard-irq read-recursion/312:  ok  |
      soft-irq read-recursion/312:  ok  |
      hard-irq read-recursion/321:  ok  |
      soft-irq read-recursion/321:  ok  |
-------------------------------------------------------
Good, all 218 testcases passed! |
---------------------------------
Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
Checking aperture...
Memory: 1018620k/1047424k available (2398k kernel code, 28032k reserved, 1193k data, 628k init)
CPA: page pool initialized 1 of 1 pages preallocated
Calibrating delay using timer specific routine.. 4397.01 BogoMIPS (lpj=8794033)
Security Framework initialized
Capability LSM initialized
Mount-cache hash table entries: 256
CPU: L1 I cache: 32K, L1 D cache: 32K
CPU: L2 cache: 2048K
CPU: Physical Processor ID: 0
CPU: Processor Core ID: 0
CPU0: Thermal monitoring enabled (TM1)
using mwait in idle threads.
ACPI: Core revision 20070126
Using local APIC timer interrupts.
APIC timer calibration result 12468711
Detected 12.468 MHz APIC timer.
lockdep: fixing up alternatives.
Booting processor 1/2 APIC 0x1
Initializing CPU#1
Calibrating delay using timer specific routine.. 4388.98 BogoMIPS (lpj=8777966)
CPU: L1 I cache: 32K, L1 D cache: 32K
CPU: L2 cache: 2048K
CPU: Physical Processor ID: 0
CPU: Processor Core ID: 1
CPU1: Thermal monitoring enabled (TM2)
Intel(R) Core(TM)2 Duo CPU     E4500  @ 2.20GHz stepping 0d
checking TSC synchronization [CPU#0 -> CPU#1]: passed.
Brought up 2 CPUs
------------[ cut here ]------------
WARNING: at kernel/lockdep.c:2662 check_flags+0x18d/0x190()
Modules linked in:
Pid: 0, comm: swapper Not tainted 2.6.25 #2

Call Trace:
 [<ffffffff8022fbff>] warn_on_slowpath+0x5f/0x80
 [<ffffffff80213a77>] ? native_sched_clock+0x57/0x80
 [<ffffffff8022ac1a>] ? hrtick_set+0x3a/0x120
 [<ffffffff80254da5>] ? __lock_acquire+0x245/0x1070
 [<ffffffff8022ac9d>] ? hrtick_set+0xbd/0x120
 [<ffffffff80213a77>] ? native_sched_clock+0x57/0x80
 [<ffffffff8024b0b0>] ? __atomic_notifier_call_chain+0x0/0xa0
 [<ffffffff8025180d>] check_flags+0x18d/0x190
 [<ffffffff80255c33>] lock_acquire+0x63/0xd0
 [<ffffffff8024b101>] __atomic_notifier_call_chain+0x51/0xa0
 [<ffffffff8020b210>] ? mwait_idle+0x0/0x50
 [<ffffffff8020b0a0>] ? default_idle+0x0/0x80
 [<ffffffff8024b161>] atomic_notifier_call_chain+0x11/0x20
 [<ffffffff8020a849>] __exit_idle+0x29/0x30
 [<ffffffff8020b178>] cpu_idle+0x58/0xa0
 [<ffffffff80450b5e>] start_secondary+0x2fe/0x430

---[ end trace ca143223eefdc828 ]---
possible reason: unannotated irqs-on.
irq event stamp: 12
hardirqs last  enabled at (11): [<ffffffff804568c5>] _spin_unlock_irqrestore+0x55/0x60
hardirqs last disabled at (12): [<ffffffff8020b16c>] cpu_idle+0x4c/0xa0
softirqs last  enabled at (0): [<ffffffff8022da82>] copy_process+0x2d2/0x16a0
softirqs last disabled at (0): [<0000000000000000>] 0x0
khelper used greatest stack depth: 5920 bytes left
net_namespace: 1144 bytes
NET: Registered protocol family 16
ACPI: bus type pci registered
PCI: Using MMCONFIG at e0000000 - efffffff
PCI: Using configuration type 1
mtrr: your CPUs had inconsistent fixed MTRR settings
mtrr: probably your BIOS does not setup all CPUs.
mtrr: corrected configuration.
ACPI: EC: Look up EC in DSDT
ACPI: Interpreter enabled
ACPI: (supports S0 S1 S5)
ACPI: Using IOAPIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (0000:00)
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEXG._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEX0._PRT]
ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 6 7 *10 11 12)
ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 6 7 10 *11 12)
ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 6 7 10 *11 12)
ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 6 7 10 11 12) *0, disabled.
ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 6 7 10 11 12) *0, disabled.
ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 6 7 10 11 12) *0
ACPI: PCI Interrupt Link [LNK0] (IRQs 3 4 6 7 10 11 12) *0, disabled.
ACPI: PCI Interrupt Link [LNK1] (IRQs 3 4 6 7 10 11 12) *5
ACPI: PCI Interrupt Link [ALKA] (IRQs *20)
ACPI: PCI Interrupt Link [ALKB] (IRQs *21)
ACPI: PCI Interrupt Link [ALKC] (IRQs *22)
ACPI: PCI Interrupt Link [ALKD] (IRQs *23), disabled.
Linux Plug and Play Support v0.97 (c) Adam Belay
pnp: PnP ACPI init
ACPI: bus type pnp registered
pnp: PnP ACPI: found 15 devices
ACPI: ACPI bus type pnp unregistered
PCI: Using ACPI for IRQ routing
PCI: If a device doesn't work, try "pci=routeirq".  If it helps, post a report
PCI-GART: No AMD northbridge found.
system 00:01: ioport range 0x400-0x47f has been reserved
system 00:01: ioport range 0x500-0x50f has been reserved
system 00:02: ioport range 0x4d0-0x4d1 has been reserved
system 00:02: ioport range 0x290-0x297 has been reserved
system 00:02: ioport range 0x880-0x88f has been reserved
system 00:0d: iomem range 0xe0000000-0xefffffff could not be reserved
system 00:0e: iomem range 0xcec00-0xcffff has been reserved
system 00:0e: iomem range 0xf0000-0xf7fff could not be reserved
system 00:0e: iomem range 0xf8000-0xfbfff could not be reserved
system 00:0e: iomem range 0xfc000-0xfffff could not be reserved
system 00:0e: iomem range 0x3fee0000-0x3fefffff could not be reserved
system 00:0e: iomem range 0xffff0000-0xffffffff has been reserved
system 00:0e: iomem range 0x0-0x9ffff could not be reserved
system 00:0e: iomem range 0x100000-0x3fedffff could not be reserved
system 00:0e: iomem range 0xfec00000-0xfec00fff has been reserved
system 00:0e: iomem range 0xfee00000-0xfee00fff could not be reserved
system 00:0e: iomem range 0xfff80000-0xfffeffff has been reserved
PCI: Bridge: 0000:00:01.0
  IO window: 9000-9fff
  MEM window: 0xdfc00000-0xdfcfffff
  PREFETCH window: 0x00000000dfb00000-0x00000000dfbfffff
PCI: Bridge: 0000:00:02.0
  IO window: b000-bfff
  MEM window: 0xdc000000-0xdeffffff
  PREFETCH window: 0x00000000c0000000-0x00000000cfffffff
PCI: Bridge: 0000:00:03.0
  IO window: a000-afff
  MEM window: 0xdfe00000-0xdfefffff
  PREFETCH window: 0x00000000dfd00000-0x00000000dfdfffff
PCI: Setting latency timer of device 0000:00:01.0 to 64
ACPI: PCI Interrupt 0000:00:02.0[A] -> GSI 27 (level, low) -> IRQ 27
PCI: Setting latency timer of device 0000:00:02.0 to 64
ACPI: PCI Interrupt 0000:00:03.0[A] -> GSI 31 (level, low) -> IRQ 31
PCI: Setting latency timer of device 0000:00:03.0 to 64
NET: Registered protocol family 2
IP route cache hash table entries: 32768 (order: 6, 262144 bytes)
TCP established hash table entries: 131072 (order: 9, 2097152 bytes)
TCP bind hash table entries: 65536 (order: 10, 4194304 bytes)
TCP: Hash tables configured (established 131072 bind 65536)
TCP reno registered
checking if image is initramfs... it is
Freeing initrd memory: 2622k freed
audit: initializing netlink socket (disabled)
type=2000 audit(1209242386.680:1): initialized
Total HugeTLB memory allocated, 0
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered (default)
PCI: VIA PCI bridge detected. Disabling DAC.
Switched to high resolution mode on CPU 1
Switched to high resolution mode on CPU 0
pci 0000:00:10.4: EHCI: BIOS handoff failed (BIOS bug?) 01010001
pci 0000:00:11.0: Bypassing VIA 8237 APIC De-Assert Message
pci 0000:02:00.0: Boot video device
PCI: Setting latency timer of device 0000:00:02.0 to 64
assign_interrupt_mode Found MSI capability
Allocate Port Service[0000:00:02.0:pcie00]
Allocate Port Service[0000:00:02.0:pcie01]
Allocate Port Service[0000:00:02.0:pcie02]
Allocate Port Service[0000:00:02.0:pcie03]
PCI: Setting latency timer of device 0000:00:03.0 to 64
assign_interrupt_mode Found MSI capability
Allocate Port Service[0000:00:03.0:pcie00]
Allocate Port Service[0000:00:03.0:pcie01]
Allocate Port Service[0000:00:03.0:pcie02]
Allocate Port Service[0000:00:03.0:pcie03]
AER service couldn't init device 0000:00:02.0:pcie01 - no _OSC support
AER service couldn't init device 0000:00:03.0:pcie01 - no _OSC support
vesafb: framebuffer at 0xc0000000, mapped to 0xffffc20010100000, using 1875k, total 262144k
vesafb: mode is 800x600x16, linelength=1600, pages=2
vesafb: scrolling: redraw
vesafb: Truecolor: size=0:5:6:5, shift=0:11:5:0
Console: switching to colour frame buffer device 100x37
fb0: VESA VGA frame buffer device
Linux agpgart interface v0.103
Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing enabled
serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
serial8250: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
00:08: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
00:09: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
brd: module loaded
PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at 0x60,0x64 irq 1,12
serio: i8042 KBD port at 0x60,0x64 irq 1
serio: i8042 AUX port at 0x60,0x64 irq 12
mice: PS/2 mouse device common for all mice
input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
TCP cubic registered
NET: Registered protocol family 1
BIOS EDD facility v0.16 2004-Jun-25, 6 devices found
Freeing unused kernel memory: 628k freed
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
ACPI: PCI Interrupt Link [ALKB] enabled at IRQ 21
ACPI: PCI Interrupt 0000:00:10.4[C] -> Link [ALKB] -> GSI 21 (level, low) -> IRQ 21
ehci_hcd 0000:00:10.4: EHCI Host Controller
ehci_hcd 0000:00:10.4: new USB bus registered, assigned bus number 1
ehci_hcd 0000:00:10.4: irq 21, io mem 0xdfffe000
ehci_hcd 0000:00:10.4: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
usb usb1: configuration #1 chosen from 1 choice
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 8 ports detected
input: PS/2 Logitech Mouse as /devices/platform/i8042/serio1/input/input1
usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb1: Product: EHCI Host Controller
usb usb1: Manufacturer: Linux 2.6.25 ehci_hcd
usb usb1: SerialNumber: 0000:00:10.4
modprobe used greatest stack depth: 4688 bytes left
ohci_hcd: 2006 August 04 USB 1.1 'Open' Host Controller (OHCI) Driver
USB Universal Host Controller Interface driver v3.0
ACPI: PCI Interrupt 0000:00:10.0[A] -> Link [ALKB] -> GSI 21 (level, low) -> IRQ 21
uhci_hcd 0000:00:10.0: UHCI Host Controller
uhci_hcd 0000:00:10.0: new USB bus registered, assigned bus number 2
uhci_hcd 0000:00:10.0: irq 21, io base 0x0000dc00
usb usb2: configuration #1 chosen from 1 choice
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 2 ports detected
usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb2: Product: UHCI Host Controller
usb usb2: Manufacturer: Linux 2.6.25 uhci_hcd
usb usb2: SerialNumber: 0000:00:10.0
ACPI: PCI Interrupt 0000:00:10.1[A] -> Link [ALKB] -> GSI 21 (level, low) -> IRQ 21
uhci_hcd 0000:00:10.1: UHCI Host Controller
uhci_hcd 0000:00:10.1: new USB bus registered, assigned bus number 3
uhci_hcd 0000:00:10.1: irq 21, io base 0x0000d800
usb usb3: configuration #1 chosen from 1 choice
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 2 ports detected
usb usb3: New USB device found, idVendor=1d6b, idProduct=0001
usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb3: Product: UHCI Host Controller
usb usb3: Manufacturer: Linux 2.6.25 uhci_hcd
usb usb3: SerialNumber: 0000:00:10.1
ACPI: PCI Interrupt 0000:00:10.2[B] -> Link [ALKB] -> GSI 21 (level, low) -> IRQ 21
uhci_hcd 0000:00:10.2: UHCI Host Controller
uhci_hcd 0000:00:10.2: new USB bus registered, assigned bus number 4
uhci_hcd 0000:00:10.2: irq 21, io base 0x0000d400
usb usb4: configuration #1 chosen from 1 choice
hub 4-0:1.0: USB hub found
hub 4-0:1.0: 2 ports detected
usb usb4: New USB device found, idVendor=1d6b, idProduct=0001
usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb4: Product: UHCI Host Controller
usb usb4: Manufacturer: Linux 2.6.25 uhci_hcd
usb usb4: SerialNumber: 0000:00:10.2
ACPI: PCI Interrupt 0000:00:10.3[B] -> Link [ALKB] -> GSI 21 (level, low) -> IRQ 21
uhci_hcd 0000:00:10.3: UHCI Host Controller
uhci_hcd 0000:00:10.3: new USB bus registered, assigned bus number 5
uhci_hcd 0000:00:10.3: irq 21, io base 0x0000d000
usb usb5: configuration #1 chosen from 1 choice
hub 5-0:1.0: USB hub found
hub 5-0:1.0: 2 ports detected
usb usb5: New USB device found, idVendor=1d6b, idProduct=0001
usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb5: Product: UHCI Host Controller
usb usb5: Manufacturer: Linux 2.6.25 uhci_hcd
usb usb5: SerialNumber: 0000:00:10.3
modprobe used greatest stack depth: 4672 bytes left
Uniform Multi-Platform E-IDE driver
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
VP_IDE: IDE controller (0x1106:0x0571 rev 0x06) at  PCI slot 0000:00:0f.1
ACPI: PCI Interrupt Link [ALKA] enabled at IRQ 20
ACPI: PCI Interrupt 0000:00:0f.1[A] -> Link [ALKA] -> GSI 20 (level, low) -> IRQ 20
VP_IDE: not 100% native mode: will probe irqs later
VP_IDE: VIA vt8237 (rev 00) IDE UDMA133 controller on pci0000:00:0f.1
    ide0: BM-DMA at 0xe000-0xe007, BIOS settings: hda:DMA, hdb:PIO
    ide1: BM-DMA at 0xe008-0xe00f, BIOS settings: hdc:DMA, hdd:DMA
Probing IDE interface ide0...
hda: ST340016A, ATA DISK drive
hda: host max PIO5 wanted PIO255(auto-tune) selected PIO4
hda: UDMA/100 mode selected
Probing IDE interface ide1...
hdc: PIONEER DVD-RW DVR-112D, ATAPI CD/DVD-ROM drive
hdd: Maxtor 6L080P0, ATA DISK drive
hdc: host max PIO5 wanted PIO255(auto-tune) selected PIO4
hdc: host side 80-wire cable detection failed, limiting max speed to UDMA33
hdc: UDMA/33 mode selected
hdd: host max PIO5 wanted PIO255(auto-tune) selected PIO4
hdd: host side 80-wire cable detection failed, limiting max speed to UDMA33
hdd: UDMA/33 mode selected
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
ide1 at 0x170-0x177,0x376 on irq 15
hda: max request size: 128KiB
hda: 78165360 sectors (40020 MB) w/2048KiB Cache, CHS=65535/16/63
hda: cache flushes not supported
 hda: hda1 hda2 < hda5 hda6 hda7 hda8 >
hdd: max request size: 128KiB
hdd: 160086528 sectors (81964 MB) w/8192KiB Cache, CHS=65535/16/63
hdd: cache flushes supported
 hdd: hdd1 hdd2 < hdd5 >
modprobe used greatest stack depth: 3688 bytes left
EXT3-fs: INFO: recovery required on readonly filesystem.
EXT3-fs: write access will be enabled during recovery.
kjournald starting.  Commit interval 5 seconds
EXT3-fs: recovery complete.
EXT3-fs: mounted filesystem with ordered data mode.
awk used greatest stack depth: 3672 bytes left
8139too Fast Ethernet driver 0.9.28
ACPI: PCI Interrupt 0000:00:0b.0[A] -> GSI 21 (level, low) -> IRQ 21
eth0: RealTek RTL8139 at 0xffffc20000018000, 00:16:17:b3:e9:69, IRQ 21
eth0:  Identified 8139 chip type 'RTL-8100B/8139D'
agpgart: Detected VIA P4M890 chipset
agpgart: AGP aperture is 128M @ 0xd0000000
parport_pc 00:0a: reported by Plug and Play ACPI
parport0: PC-style at 0x378, irq 7 [PCSPP]
hdc: ATAPI 40X DVD-ROM DVD-R CD-R/RW drive, 2000kB Cache
Uniform CD-ROM driver Revision: 3.20
input: Power Button (FF) as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input2
ACPI: Power Button (FF) [PWRF]
input: Power Button (CM) as /devices/LNXSYSTM:00/device:00/PNP0C0C:00/input/input3
ACPI: Power Button (CM) [PWRB]
input: Sleep Button (CM) as /devices/LNXSYSTM:00/device:00/PNP0C0E:00/input/input4
ACPI: Sleep Button (CM) [SLPB]
ACPI: ACPI0007:00 is registered as cooling_device0
ACPI: SSDT 3FEEA1C0, 0087 (r1  PmRef  Cpu1Ist     3000 INTL 20041203)
ACPI: ACPI0007:01 is registered as cooling_device1
ACPI: PCI Interrupt Link [ALKC] enabled at IRQ 22
ACPI: PCI Interrupt 0000:00:11.5[C] -> Link [ALKC] -> GSI 22 (level, low) -> IRQ 22
PCI: Setting latency timer of device 0000:00:11.5 to 64
FDC 0 is a post-1991 82077
No dock devices found.
SCSI subsystem initialized
libata version 3.00 loaded.
sata_via 0000:00:0f.0: version 2.3
ACPI: PCI Interrupt 0000:00:0f.0[B] -> Link [ALKA] -> GSI 20 (level, low) -> IRQ 20
sata_via 0000:00:0f.0: routed to hard irq line 11
scsi0 : sata_via
scsi1 : sata_via
ata1: SATA max UDMA/133 cmd 0xf800 ctl 0xf400 bmdma 0xe800 irq 20
ata2: SATA max UDMA/133 cmd 0xf000 ctl 0xec00 bmdma 0xe808 irq 20
ata1: SATA link down 1.5 Gbps (SStatus 0 SControl 300)
ata2: SATA link down 1.5 Gbps (SStatus 0 SControl 300)
EXT3 FS on hda1, internal journal
kjournald starting.  Commit interval 5 seconds
EXT3 FS on hda7, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
EXT3 FS on hdd1, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
EXT3 FS on hda8, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
EXT3 FS on hdd5, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
EXT3 FS on hda6, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
loop: module loaded
Adding 2747072k swap on /dev/hda5.  Priority:-1 extents:1 across:2747072k
rc.sysinit used greatest stack depth: 3416 bytes left
NET: Registered protocol family 10
lo: Disabled Privacy Extensions
NET: Registered protocol family 17
eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
fuse init (API version 7.9)
warning: `proftpd' uses 32-bit capabilities (legacy support in use)
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
eth0: no IPv6 routers present
Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
NFSD: starting 90-second grace period
netconsole: local port 4444
netconsole: local IP 192.168.0.103
netconsole: interface eth0
netconsole: remote port 5555
netconsole: remote IP 192.168.0.66
netconsole: remote ethernet address 00:00:1c:08:d9:76
console [netcon0] enabled
netconsole: network logging started

Re: spinlock lockup on CPU#0

[Bernard Pidoux]

[-- Attachment #1: Type: text/plain, Size: 95 bytes --]

Hi,

cpu_idle bug is also present in 2.6.24.4 kernel.

I hope this helps.

Bernard Pidoux

 



[-- Attachment #2: lockdep-2.6.24.4.idle.cpu --]
[-- Type: text/plain, Size: 3051 bytes --]


Apr 27 01:13:36 f6bvp-7 kernel: Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
Apr 27 01:13:36 f6bvp-7 kernel: ... MAX_LOCKDEP_SUBCLASSES:    8
Apr 27 01:13:36 f6bvp-7 kernel: ... MAX_LOCK_DEPTH:          30
Apr 27 01:13:36 f6bvp-7 kernel: ... MAX_LOCKDEP_KEYS:        2048
Apr 27 01:13:36 f6bvp-7 kernel: ... CLASSHASH_SIZE:           1024
Apr 27 01:13:36 f6bvp-7 kernel: ... MAX_LOCKDEP_ENTRIES:     8192
Apr 27 01:13:36 f6bvp-7 kernel: ... MAX_LOCKDEP_CHAINS:      16384
Apr 27 01:13:36 f6bvp-7 kernel: ... CHAINHASH_SIZE:          8192
Apr 27 01:13:36 f6bvp-7 kernel:  memory used by lock dependency info: 1712 kB
Apr 27 01:13:36 f6bvp-7 kernel:  per task-struct memory footprint: 2160 bytes
Apr 27 01:13:36 f6bvp-7 kernel: Memory: 1018724k/1047424k available (2307k kernel code, 27920k reserved, 1174k data, 616k init)
Apr 27 01:13:36 f6bvp-7 kernel: Calibrating delay using timer specific routine.. 4396.25 BogoMIPS (lpj=8792506)
Apr 27 01:13:36 f6bvp-7 kernel: Mount-cache hash table entries: 256
Apr 27 01:13:36 f6bvp-7 kernel: lockdep: not fixing up alternatives.
Apr 27 01:13:36 f6bvp-7 kernel: lockdep: not fixing up alternatives.
Apr 27 01:13:36 f6bvp-7 kernel: Initializing CPU#1
Apr 27 01:13:36 f6bvp-7 kernel: Calibrating delay using timer specific routine.. 4388.97 BogoMIPS (lpj=8777957)
Apr 27 01:13:36 f6bvp-7 kernel: Intel(R) Core(TM)2 Duo CPU     E4500  @ 2.20GHz stepping 0d
Apr 27 01:13:36 f6bvp-7 kernel: WARNING: at kernel/lockdep.c:2662 check_flags()
Apr 27 01:13:36 f6bvp-7 kernel: Pid: 0, comm: swapper Not tainted 2.6.24.4patched #7
Apr 27 01:13:36 f6bvp-7 kernel: 
Apr 27 01:13:36 f6bvp-7 kernel: Call Trace:
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff8024d650>] __atomic_notifier_call_chain+0x0/0xa0
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff802537b2>] check_flags+0x1c2/0x1d0
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff80257e35>] lock_acquire+0x65/0xd0
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff8024d6a1>] __atomic_notifier_call_chain+0x51/0xa0
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff8020b510>] mwait_idle+0x0/0x60
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff8020b390>] default_idle+0x0/0x60
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff8024d701>] atomic_notifier_call_chain+0x11/0x20
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff8020ac49>] __exit_idle+0x29/0x30
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff8020b475>] cpu_idle+0x85/0xd0
Apr 27 01:13:36 f6bvp-7 kernel:  [<ffffffff8021eea8>] start_secondary+0x2f8/0x430
Apr 27 01:13:36 f6bvp-7 kernel: 
Apr 27 01:13:36 f6bvp-7 kernel: possible reason: unannotated irqs-on.
Apr 27 01:13:36 f6bvp-7 kernel: irq event stamp: 6
Apr 27 01:13:36 f6bvp-7 kernel: hardirqs last  enabled at (5): [<ffffffff8043fd15>] _spin_unlock_irqrestore+0x55/0x60
Apr 27 01:13:36 f6bvp-7 kernel: hardirqs last disabled at (6): [<ffffffff8020b461>] cpu_idle+0x71/0xd0
Apr 27 01:13:36 f6bvp-7 kernel: softirqs last  enabled at (0): [<ffffffff8022e8ae>] copy_process+0x2de/0x15d0
Apr 27 01:13:36 f6bvp-7 kernel: softirqs last disabled at (0): [<0000000000000000>] 0x0

Re: spinlock lockup on CPU#0

[Justin Mattock]

On Sun, Apr 27, 2008 at 12:15 AM, Bernard Pidoux <bpidoux@free.fr> wrote:
> Hi,
>
>  cpu_idle bug is also present in 2.6.24.4 kernel.
>
>  I hope this helps.
>
>  Bernard Pidoux
>
>
>
>
>

Cool, you're welcome.
I've just pulled the latest update and rebooted, eveything looks good
except for my wireless
just spent two hours trying to tweak it to go, but can't figure out
what is happening
madwifi is   giving me a *** TARGET i386-elf is invalid.
aside from that is there a patch for athk5 for the macbook's?
if not, thats O.K. I'm going to have a look into what I might have
wrong on my part maybee (make) is too old.
regards;

-- 
Justin P. Mattock

Re: spinlock lockup on CPU#0

[Bob Copeland]

On Sat, Apr 26, 2008 at 10:00 PM, Justin Mattock
<justinmattock@gmail.com> wrote:
>  Cool, you're welcome.
>  I've just pulled the latest update and rebooted, eveything looks good
>  except for my wireless

>  madwifi is   giving me a *** TARGET i386-elf is invalid.
>  aside from that is there a patch for athk5 for the macbook's?

Heh, I guess we have the same machine.  There is some support for
macbooks under ath5k with the wireless-testing tree.  I'm not sure if
it's been merged yet.  It's also not quite there -- connections tend
to drop a little too often, but I have used it some.  I'm sure Nick
would be happy to get more traces...

-- 
Bob Copeland %% www.bobcopeland.com

Re: spinlock lockup on CPU#0

[Justin Mattock]

On Sun, Apr 27, 2008 at 2:13 AM, Bob Copeland <me@bobcopeland.com> wrote:
> On Sat, Apr 26, 2008 at 10:00 PM, Justin Mattock
>  <justinmattock@gmail.com> wrote:
>  >  Cool, you're welcome.
>  >  I've just pulled the latest update and rebooted, eveything looks good
>  >  except for my wireless
>
>
> >  madwifi is   giving me a *** TARGET i386-elf is invalid.
>  >  aside from that is there a patch for athk5 for the macbook's?
>
>  Heh, I guess we have the same machine.  There is some support for
>  macbooks under ath5k with the wireless-testing tree.  I'm not sure if
>  it's been merged yet.  It's also not quite there -- connections tend
>  to drop a little too often, but I have used it some.  I'm sure Nick
>  would be happy to get more traces...
>
>  --
>
>
> Bob Copeland %% www.bobcopeland.com
>

I'll have to give that a try, the number for my card is: AR5418
If there is'nt any support, then I'll have to use the ndiswrapper approach
for the time being as a quick solution, or revert to my backup kernel
regards;

-- 
Justin P. Mattock

Re: spinlock lockup on CPU#0

[Bob Copeland]

On Sat, Apr 26, 2008 at 10:20 PM, Justin Mattock
<justinmattock@gmail.com> wrote:
>
>  I'll have to give that a try, the number for my card is: AR5418
>  If there is'nt any support, then I'll have to use the ndiswrapper approach
>  for the time being as a quick solution, or revert to my backup kernel

Ah, I am using AR5006 which is a 5424, so ymmv.

-- 
Bob Copeland %% www.bobcopeland.com

Re: spinlock lockup on CPU#0

[Justin Mattock]

On Sun, Apr 27, 2008 at 2:41 AM, Bob Copeland <me@bobcopeland.com> wrote:
> On Sat, Apr 26, 2008 at 10:20 PM, Justin Mattock
>  <justinmattock@gmail.com> wrote:
>  >
>  >  I'll have to give that a try, the number for my card is: AR5418
>  >  If there is'nt any support, then I'll have to use the ndiswrapper approach
>  >  for the time being as a quick solution, or revert to my backup kernel
>
>  Ah, I am using AR5006 which is a 5424, so ymmv.
>
>  --
>
>
> Bob Copeland %% www.bobcopeland.com
>

After thinking "Youremileagemayvery", sorry I'm a little slow;
I tried, ath5k gives a not supported flag. With this in mind I'm going
to spent a few hours looking at what I had until ath5k is supported
regards;

-- 
Justin P. Mattock