Commit 78eef01b0fae087c5fadbd85dd4fe2918c3a015f (on_each_cpu(): disable local interrupts) Breaks SGI IP32

DISCUSSION Kumba 4 participants 11 messages May 27, 2006 – Jun 27, 2006 MIPS

Share & tools

Kumba

author

2006-05-27 21:13 UTC #0 lore raw

Finally managed to track down the git commit causing SGI IP32 (O2) systems to lock up really early in the boot cycle, but I'm at a loss to understand why.

Effect:
It appears the system silently hangs somewhere in the void between function calls when trying to invoke the memset() call in __alloc_bootmem_core() in mm/bootmem.c. This puts the machine hardware in a state such that a simple soft reset doesn't clear it -- the machine has to be cold booted to get it to boot a working kernel again.

Determined Cause:
It seems this commit:
78eef01b0fae087c5fadbd85dd4fe2918c3a015f
[PATCH] on_each_cpu(): disable local interrupts

Is the cause. I've verified this by reversing this one change on a 2.6.17-rc4 tree, and it'll boot to a mini-userland (initramfs-based) and appears to function normally.

But this is as far as I can trace this. I'm not sure what this change is doing internally that's triggering this lockup on O2 systems. It doesn't appear to affect Octane (IP30) systems or Origin (IP27). I haven't test-ran it on IP22/IP28 hardware yet, so only IP32 is known to be affected. Unsure about non-SGI MIPS hardware.

Thoughts?

--Kumba

Signature · 4 lines

Gentoo/MIPS Team Lead
Gentoo Foundation Board of Trustees

"Such is oft the course of deeds that move the wheels of the world: small hands do them because they must, while the eyes of the great are elsewhere."  --Elrond

Ralf Baechle

2006-05-28 01:06 UTC #1 lore raw

Quoted 21 lines · Kumba

Finally managed to track down the git commit causing SGI IP32 (O2) systems to lock up really early in the boot cycle, but I'm at a loss to understand why.
Effect:
It appears the system silently hangs somewhere in the void between function calls when trying to invoke the memset() call in __alloc_bootmem_core() in mm/bootmem.c. This puts the machine hardware in a state such that a simple soft reset doesn't clear it -- the machine has to be cold booted to get it to boot a working kernel again.
Determined Cause:
It seems this commit:
78eef01b0fae087c5fadbd85dd4fe2918c3a015f
[PATCH] on_each_cpu(): disable local interrupts
Is the cause. I've verified this by reversing this one change on a 2.6.17-rc4 tree, and it'll boot to a mini-userland (initramfs-based) and appears to function normally.

Quoted 5 lines

But this is as far as I can trace this. I'm not sure what this change is doing internally that's triggering this lockup on O2 systems. It doesn't appear to affect Octane (IP30) systems or Origin (IP27). I haven't test-ran it on IP22/IP28 hardware yet, so only IP32 is known to be affected. Unsure about non-SGI MIPS hardware.

on_each_cpu is re-enabling interrupt. This may crash the system if it happens before interrupt handlers have been installed. A while ago I've fixes all such calls but I may have missed some instances.

Andrew, what was the reason for 78eef01b0fae087c5fadbd85dd4fe2918c3a015f ?

Ralf

Andrew Morton

2006-05-28 02:38 UTC #2 lore raw

Quoted 23 lines · On Sun, 28 May 2006 02:06:03 +0100 Ralf Baechle <[email protected]> wrote:

Quoted 21 lines · Kumba
Finally managed to track down the git commit causing SGI IP32 (O2) systems to lock up really early in the boot cycle, but I'm at a loss to understand why.
Effect:
It appears the system silently hangs somewhere in the void between function calls when trying to invoke the memset() call in __alloc_bootmem_core() in mm/bootmem.c. This puts the machine hardware in a state such that a simple soft reset doesn't clear it -- the machine has to be cold booted to get it to boot a working kernel again.
Determined Cause:
It seems this commit:
78eef01b0fae087c5fadbd85dd4fe2918c3a015f
[PATCH] on_each_cpu(): disable local interrupts
Is the cause. I've verified this by reversing this one change on a 2.6.17-rc4 tree, and it'll boot to a mini-userland (initramfs-based) and appears to function normally.

Quoted 8 lines

Quoted 5 lines
But this is as far as I can trace this. I'm not sure what this change is doing internally that's triggering this lockup on O2 systems. It doesn't appear to affect Octane (IP30) systems or Origin (IP27). I haven't test-ran it on IP22/IP28 hardware yet, so only IP32 is known to be affected. Unsure about non-SGI MIPS hardware.
on_each_cpu is re-enabling interrupt. This may crash the system if it happens before interrupt handlers have been installed.

on_each_cpu() calls smp_call_function(). It is not correct to call smp_call_function() with local interrupts disabled, because it can lead to deadlocks.

Therefore on_each_cpu() also must not be called with local interrupts disabled. Therefore on_each_cpu() may use local_irq_disable()/local_irq_enable().

Quoted 5 lines

A while ago I've
fixes all such calls but I may have missed some instances.
Andrew, what was the reason for 78eef01b0fae087c5fadbd85dd4fe2918c3a015f ?

That change made the various calling environments consistent, as described in the changelog.

If it's really, really not deadlocky to call smp_call_function() with interrupts disabled at that time in the MIPS kernel bringup then I'd suggest you should open-code an smp_call_function() and put a big comment over it explaining why it's done this way, and why it isn't deadlocky.

If CPU A is running smp_call_function() it's waiting for CPU B to run the handler.

But if CPU B is presently _also_ running smp_call_function(), it's waiting for CPU A to run the handler.

If either of those CPUs is waiting for the other with local interrupts disabled, that CPU will never respond to the other CPU's IPI and they'll deadlock.

Kumba

author

2006-05-28 04:20 UTC #3 lore raw

Quoted 28 lines · Andrew Morton

on_each_cpu() calls smp_call_function(). It is not correct to call smp_call_function() with local interrupts disabled, because it can lead to deadlocks.
Therefore on_each_cpu() also must not be called with local interrupts disabled. Therefore on_each_cpu() may use local_irq_disable()/local_irq_enable().
Quoted 5 lines
A while ago I've
fixes all such calls but I may have missed some instances.
Andrew, what was the reason for 78eef01b0fae087c5fadbd85dd4fe2918c3a015f ?
That change made the various calling environments consistent, as described in the changelog.
If it's really, really not deadlocky to call smp_call_function() with interrupts disabled at that time in the MIPS kernel bringup then I'd suggest you should open-code an smp_call_function() and put a big comment over it explaining why it's done this way, and why it isn't deadlocky.
<tries to remember what the deadlock is>
If CPU A is running smp_call_function() it's waiting for CPU B to run the handler.

Quoted 6 lines

But if CPU B is presently _also_ running smp_call_function(), it's waiting for CPU A to run the handler.
If either of those CPUs is waiting for the other with local interrupts disabled, that CPU will never respond to the other CPU's IPI and they'll deadlock.

The catch is, the system being affected here is strictly a UP machine. It's impossible to make an O2 go SMP. It seems that the disable call in the UP version of on_each_cpu() (which I assume is the #define macro) is what's causing this issue, since the machine comes to a halt in the dark void between function calls (i.e., that memset() I alluded to earlier)

So I'm wondering, is there a way to see if the IRQ handlers have been installed already prior to disabling them, or is this more of a machine-specific oddity wherein the IRQ handlers need to be setup earlier (I don't even know if this is even possible/relevant to O2 systems)?

It also seems this was affecting AMD Alchemy-based systems too. Other SGI machines are known to work fine, except Indy and Indigo2, as I haven't tested those yet.

--Kumba

Signature · 4 lines

Gentoo/MIPS Team Lead
Gentoo Foundation Board of Trustees

"Such is oft the course of deeds that move the wheels of the world: small hands do them because they must, while the eyes of the great are elsewhere."  --Elrond

Andrew Morton

2006-05-28 04:27 UTC #4 lore raw

Quoted 11 lines · On Sun, 28 May 2006 00:20:30 -0400 Kumba <[email protected]> wrote:

Quoted 11 lines
suggest you should open-code an smp_call_function() and put a big comment over it explaining why it's done this way, and why it isn't deadlocky.
<tries to remember what the deadlock is>
If CPU A is running smp_call_function() it's waiting for CPU B to run the handler.
But if CPU B is presently _also_ running smp_call_function(), it's waiting for CPU A to run the handler.

Quoted 6 lines

Quoted 3 lines
If either of those CPUs is waiting for the other with local interrupts disabled, that CPU will never respond to the other CPU's IPI and they'll deadlock.
The catch is, the system being affected here is strictly a UP machine. It's impossible to make an O2 go SMP.

Yup. But again, the reasons for that change to on_each_cpu() were to make all instances of the the callback function run under the same environment in all cases. That's a good change.

If the platform _knows_ that it's safe to do normally-unsafe things then as I say, it shold special-case that case.

Here, if the call is in O2-only code then we don't need on_each_cpu() at all - just call the function instead.

If the call is in board-neutral MIPS code then things get more complicated. Sure, the code is safe on UP, but it might be deadlocky on SMP. It needs to be thought about and a suitable UP&&SMP fix needs to be found.

Can someone point me at the code we're talking about here? file-n-line?

Kumba

author

2006-05-28 07:42 UTC #5 lore raw

Quoted 8 lines · Andrew Morton

Yup. But again, the reasons for that change to on_each_cpu() were to make all instances of the the callback function run under the same environment in all cases. That's a good change.
If the platform _knows_ that it's safe to do normally-unsafe things then as I say, it shold special-case that case.

Quoted 8 lines

Here, if the call is in O2-only code then we don't need on_each_cpu() at all - just call the function instead.
If the call is in board-neutral MIPS code then things get more complicated. Sure, the code is safe on UP, but it might be deadlocky on SMP. It needs to be thought about and a suitable UP&&SMP fix needs to be found.
Can someone point me at the code we're talking about here? file-n-line?

The farthest I can track the lock up is to line ~290 in mm/bootmem.c, in __alloc_bootmem_core. It's when it goes off to try and invoke that memset() function that the machine hangs, and gets put into a state only a cold boot can recover.

Since discovering the this change that introduces this oddity, I think it's what explains the hang happening in the "dark void between function calls" -- control attempts to pass to the memset(), but never reaches it (a printk() before that memset() will get called, but a printk inside the memset() never gets called, even if it's the very first instruction inside the function). Turning off the IRQs, then calling func() while 'info' contains the pointer to the memset() just goes *poof* as Ralf mentioned.

I tried putting printk()'s in the on_each_cpu() macro, before all three instructions, but none of those fired. So whether control even reaches that point, I'm not sure. Ralf mentioned (I think) it could be a cache flush happening after IRQs are disabled that knocks the machine out or something to that effect.

It's tricky to say -- I ran into the exact same hang back in ~2.6.15.2, but it silently vanished before I could pin it down, so I don't even know if it's related. I'm good at tracking down some problems, but even this one's done a fine job of eluding me up until now :)

--Kumba

Signature · 4 lines

Gentoo/MIPS Team Lead
Gentoo Foundation Board of Trustees

"Such is oft the course of deeds that move the wheels of the world: small hands do them because they must, while the eyes of the great are elsewhere."  --Elrond

Ralf Baechle

2006-05-28 10:50 UTC #6 lore raw

In reply to Kumba

Quoted 4 lines · Kumba

Quoted 4 lines
If it's really, really not deadlocky to call smp_call_function() with interrupts disabled at that time in the MIPS kernel bringup then I'd suggest you should open-code an smp_call_function() and put a big comment over it explaining why it's done this way, and why it isn't deadlocky.

MIPS does on_each_cpu() for cache maintenance. In the early stages before interrupts are enabled there is only one CPU active anyway, so it's perfectly safe - and obvious to the reader I hope - to use the local_* variant of the cacheflushes. smp_call_function will yell loudly anyway if called with interrupts disabled.

Quoted 11 lines

Quoted 11 lines
<tries to remember what the deadlock is>
If CPU A is running smp_call_function() it's waiting for CPU B to run the handler.
But if CPU B is presently _also_ running smp_call_function(), it's waiting for CPU A to run the handler.
If either of those CPUs is waiting for the other with local interrupts disabled, that CPU will never respond to the other CPU's IPI and they'll deadlock.

Circumstances which don't apply during the early startup phase but since the MIPS smp_call_function() does a WARN_ON(irqs_disabled()) I had to clean that.

Quoted 6 lines

The catch is, the system being affected here is strictly a UP machine. It's impossible to make an O2 go SMP. It seems that the disable call in the UP version of on_each_cpu() (which I assume is the #define macro) is what's causing this issue, since the machine comes to a halt in the dark void between function calls (i.e., that memset() I alluded to earlier)

Quoted 8 lines

So I'm wondering, is there a way to see if the IRQ handlers have been installed already prior to disabling them, or is this more of a machine-specific oddity wherein the IRQ handlers need to be setup earlier (I don't even know if this is even possible/relevant to O2 systems)?
It also seems this was affecting AMD Alchemy-based systems too. Other SGI machines are known to work fine, except Indy and Indigo2, as I haven't tested those yet.

IP27 is fine but it's SMP but I've already cleaned out all the early calls to smp_call_function there were shown by the WARN() ages ago.

You can do it the same way, use this debugging version of on_each_cpu:

#define on_each_cpu(func,info,retry,wait)       \
        ({                                      \
		WARN_ON(irqs_disabled());	\
                func(info);                     \
                0;                              \
        })

Ralf

Domen Puncer

2006-06-21 09:52 UTC #7 lore raw

Hi!

(removed akpm from CC, as he's probably no longer interested)

Quoted 8 lines · Ralf Baechle

Quoted 3 lines · Kumba
It also seems this was affecting AMD Alchemy-based systems too. Other SGI machines are known to work fine, except Indy and Indigo2, as I haven't tested those yet.
IP27 is fine but it's SMP but I've already cleaned out all the early calls to smp_call_function there were shown by the WARN() ages ago.

Quoted 8 lines

You can do it the same way, use this debugging version of on_each_cpu:

#define on_each_cpu(func,info,retry,wait)       \
        ({                                      \
		WARN_ON(irqs_disabled());	\
                func(info);                     \
                0;                              \
        })

On Alchemy au1200 this produces:

[4294667.296000] Synthesized TLB modify handler fastpath (33 instructions).
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<803f0000>] inflate_dynamic+0x634/0x70c
[4294667.296000]  [<803f3630>] trap_init+0x3c/0x440
[4294667.296000]  [<803f3630>] trap_init+0x3c/0x440
[4294667.296000]  [<8025f3dc>] sort_extable+0x24/0x30
[4294667.296000]  [<803ed6d4>] start_kernel+0xc8/0x20c
[4294667.296000]  [<803ed6c4>] start_kernel+0xb8/0x20c
[4294667.296000]  [<803ed12c>] unknown_bootoption+0x0/0x310
[4294667.296000] 
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<8010b16c>] dump_stack+0x14/0x20
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<803f0000>] inflate_dynamic+0x634/0x70c
[4294667.296000]  [<8010cb78>] set_except_vector+0x88/0xa0
[4294667.296000]  [<803f0000>] inflate_dynamic+0x634/0x70c
[4294667.296000]  [<803f3648>] trap_init+0x54/0x440
[4294667.296000]  [<8025f3dc>] sort_extable+0x24/0x30
[4294667.296000]  [<803ed6d4>] start_kernel+0xc8/0x20c
[4294667.296000]  [<803ed6c4>] start_kernel+0xb8/0x20c
[4294667.296000]  [<803ed12c>] unknown_bootoption+0x0/0x310
[4294667.296000] 
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<803f0000>] inflate_dynamic+0x634/0x70c
[4294667.296000]  [<803f395c>] trap_init+0x368/0x440
[4294667.296000]  [<803f395c>] trap_init+0x368/0x440
[4294667.296000]  [<8025f3dc>] sort_extable+0x24/0x30
[4294667.296000]  [<803ed6d4>] start_kernel+0xc8/0x20c
[4294667.296000]  [<803ed6c4>] start_kernel+0xb8/0x20c
[4294667.296000]  [<803ed12c>] unknown_bootoption+0x0/0x310
[4294667.296000] 
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<803f0000>] inflate_dynamic+0x634/0x70c
[4294667.296000]  [<803f38c8>] trap_init+0x2d4/0x440
[4294667.296000]  [<803f39dc>] trap_init+0x3e8/0x440
[4294667.296000]  [<8025f3dc>] sort_extable+0x24/0x30
[4294667.296000]  [<803ed6d4>] start_kernel+0xc8/0x20c
[4294667.296000]  [<803ed6c4>] start_kernel+0xb8/0x20c
[4294667.296000]  [<803ed12c>] unknown_bootoption+0x0/0x310
[4294667.296000] 
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<803f5edc>] flush_tlb_handlers+0x28/0x64
[4294667.296000]  [<803ed6d4>] start_kernel+0xc8/0x20c
[4294667.296000]  [<803ed12c>] unknown_bootoption+0x0/0x310
[4294667.296000] 
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<803f5ef4>] flush_tlb_handlers+0x40/0x64
[4294667.296000]  [<803ed6d4>] start_kernel+0xc8/0x20c
[4294667.296000]  [<803ed12c>] unknown_bootoption+0x0/0x310
[4294667.296000] 
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<803ed6d4>] start_kernel+0xc8/0x20c
[4294667.296000]  [<803ed6d4>] start_kernel+0xc8/0x20c
[4294667.296000]  [<803ed12c>] unknown_bootoption+0x0/0x310
[4294667.296000] 
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<80105580>] handle_reserved+0x0/0xc8
[4294667.296000]  [<8010cb78>] set_except_vector+0x88/0xa0
[4294667.296000]  [<8010b0f4>] show_trace+0x98/0xfc
[4294667.296000]  [<803f0c18>] arch_init_irq+0x44/0x1e0
[4294667.296000]  [<8010b16c>] dump_stack+0x14/0x20
[4294667.296000]  [<803f2620>] init_IRQ+0x90/0x9c
[4294667.296000]  [<803ed6e4>] start_kernel+0xd8/0x20c
[4294667.296000]  [<803ed6d4>] start_kernel+0xc8/0x20c
[4294667.296000]  [<803ed12c>] unknown_bootoption+0x0/0x310
[4294667.296000] 
[4294667.296000] PID hash table entries: 2048 (order: 11, 32768 bytes)

Domen

Ralf Baechle

2006-06-21 12:11 UTC #8 lore raw

Quoted 7 lines · Domen Puncer

Quoted 6 lines

#define on_each_cpu(func,info,retry,wait)       \
        ({                                      \
		WARN_ON(irqs_disabled());	\
                func(info);                     \
                0;                              \
        })

Quoted 7 lines

On Alchemy au1200 this produces:

[4294667.296000] Synthesized TLB modify handler fastpath (33 instructions).
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<803f0000>] inflate_dynamic+0x634/0x70c
[4294667.296000]  [<803f3630>] trap_init+0x3c/0x440

Pretty much as expected, thanks!

Ralf

Domen Puncer

2006-06-22 06:49 UTC #9 lore raw

Quoted 17 lines · Ralf Baechle

Quoted 7 lines · Domen Puncer

Quoted 6 lines

#define on_each_cpu(func,info,retry,wait)       \
        ({                                      \
		WARN_ON(irqs_disabled());	\
                func(info);                     \
                0;                              \
        })

Quoted 7 lines

On Alchemy au1200 this produces:

[4294667.296000] Synthesized TLB modify handler fastpath (33 instructions).
[4294667.296000] Badness in r4k_flush_icache_range at /home/domen/tmp/linux-2.6.bisecting/linux-mips.git/arch/mips/mm/c-r4k.c:516
[4294667.296000] Call Trace:
[4294667.296000]  [<80113434>] r4k_flush_icache_range+0x144/0x150
[4294667.296000]  [<803f0000>] inflate_dynamic+0x634/0x70c
[4294667.296000]  [<803f3630>] trap_init+0x3c/0x440

Quoted 1 line

Pretty much as expected, thanks!

Guess I forgot to state my simptoms... they don't seem so expected to me :-)

set_c0_status(ALLINTS) causes in_interrupt to be non-zero, which in time causes a hang via kernel/printk.c:acquire_console_sem->BUG().

set_c0_status call trace:
start_kernel->init_IRQ->arch_init_irq->set_c0_status

I'm a bit lost in mipsregs.h, and I can't figure out why it sets preempt_count() to 0x100 (that being HARD_IRQ).

Ideas?

Domen

Domen Puncer

2006-06-27 08:19 UTC #10 lore raw

So... to sum it up... any idea, why (with this patch applied) set_c0_status(ALL_INTS) increases preempt_count?

Any pointers appreaciated!

Domen