[BUG] 2.6.25-rc1-git1 softlockup while bootup on powerpc

3 messages, 2 authors, 2008-02-14 · open the first message on its own page

[BUG] 2.6.25-rc1-git1 softlockup while bootup on powerpc

From: Kamalesh Babulal <hidden>
Date: 2008-02-12 07:10:16

Hi,

While booting with the 2.6.25-rc1-git1 kernel on the powerbox
the softlockup is seen, with following trace. 

insmod used greatest stack depth: 5568 bytes left
Loading st.ko module
BUG: soft lockup - CPU#1 stuck for 61s! [insmod:377]
NIP: c0000000001b172c LR: c0000000001a6f00 CTR: 0000000000000034
REGS: c00000077cb2b8a0 TRAP: 0901   Not tainted  (2.6.25-rc1-git1-autotest)
MSR: 8000000000009032 <EE,ME,IR,DR>  CR: 84004084  XER: 20000000
TASK = c00000077cb2f0e0[377] 'insmod' THREAD: c00000077cb28000 CPU: 1
GPR00: c00000077e1a0460 c00000077cb2bb20 c00000000053ba08 0000000000000002 
GPR04: f000000000000000 c00000077c880240 000000000000003c 000000000000000b 
GPR08: 1000000000000000 c00000077e1a0708 0000000000000002 000000000000000c 
GPR12: c00000077e1a0690 c000000000484d00 
NIP [c0000000001b172c] .radix_tree_gang_lookup+0xdc/0x1e4
LR [c0000000001a6f00] .call_for_each_cic+0x50/0x10c
Call Trace:
[c00000077cb2bb20] [c0000000001a6f60] .call_for_each_cic+0xb0/0x10c (unreliable)
[c00000077cb2bc60] [c00000000019ecd8] .exit_io_context+0xf0/0x110
[c00000077cb2bcf0] [c00000000006254c] .do_exit+0x820/0x850
[c00000077cb2bda0] [c000000000062648] .do_group_exit+0xcc/0xe8
[c00000077cb2be30] [c00000000000872c] syscall_exit+0x0/0x40
Instruction dump:
4800007c 7cc007b4 7ca90436 7f680036 792b06a0 7c8800d0 79691f24 200b0040 
7c0903a6 7d296214 39290018 e8090000 <7caa2038> 39290008 2fa00000 409e0018 
INFO: task insmod:385 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
insmod        D 000000001000e144 12144   385      1
Call Trace:
[c00000077cb97600] [c0000000008fc600] 0xc0000000008fc600 (unreliable)
[c00000077cb977d0] [c000000000010c7c] .__switch_to+0x11c/0x154
[c00000077cb97860] [c0000000003455e0] .schedule+0x5d0/0x6b0
[c00000077cb97950] [c000000000345920] .schedule_timeout+0x3c/0xe8
[c00000077cb97a20] [c000000000344e7c] .wait_for_common+0x150/0x22c
[c00000077cb97ae0] [c00000000008f5ac] .__stop_machine_run+0xbc/0xf0
[c00000077cb97bb0] [c00000000008f61c] .stop_machine_run+0x3c/0x80
[c00000077cb97c50] [c00000000008989c] .sys_init_module+0x14e4/0x1af4
[c00000077cb97e30] [c00000000000872c] syscall_exit+0x0/0x40
-- 0:conmux-control -- time-stamp -- Feb/11/08 14:30:10 --
INFO: task insmod:385 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
insmod        D 000000001000e144 12144   385      1
Call Trace:
[c00000077cb97600] [c0000000008fc600] 0xc0000000008fc600 (unreliable)
[c00000077cb977d0] [c000000000010c7c] .__switch_to+0x11c/0x154
[c00000077cb97860] [c0000000003455e0] .schedule+0x5d0/0x6b0
[c00000077cb97950] [c000000000345920] .schedule_timeout+0x3c/0xe8
[c00000077cb97a20] [c000000000344e7c] .wait_for_common+0x150/0x22c
[c00000077cb97ae0] [c00000000008f5ac] .__stop_machine_run+0xbc/0xf0
[c00000077cb97bb0] [c00000000008f61c] .stop_machine_run+0x3c/0x80
[c00000077cb97c50] [c00000000008989c] .sys_init_module+0x14e4/0x1af4
[c00000077cb97e30] [c00000000000872c] syscall_exit+0x0/0x40
-- 0:conmux-control -- time-stamp -- Feb/11/08 14:32:19 --
INFO: task insmod:385 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
insmod        D 000000001000e144 12144   385      1
Call Trace:
[c00000077cb97600] [c0000000008fc600] 0xc0000000008fc600 (unreliable)
[c00000077cb977d0] [c000000000010c7c] .__switch_to+0x11c/0x154
[c00000077cb97860] [c0000000003455e0] .schedule+0x5d0/0x6b0
[c00000077cb97950] [c000000000345920] .schedule_timeout+0x3c/0xe8
[c00000077cb97a20] [c000000000344e7c] .wait_for_common+0x150/0x22c
[c00000077cb97ae0] [c00000000008f5ac] .__stop_machine_run+0xbc/0xf0
[c00000077cb97bb0] [c00000000008f61c] .stop_machine_run+0x3c/0x80
[c00000077cb97c50] [c00000000008989c] .sys_init_module+0x14e4/0x1af4
[c00000077cb97e30] [c00000000000872c] syscall_exit+0x0/0x40
-- 0:conmux-control -- time-stamp -- Feb/11/08 14:34:28 --
INFO: task insmod:385 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
insmod        D 000000001000e144 12144   385      1
Call Trace:
[c00000077cb97600] [c0000000008fc600] 0xc0000000008fc600 (unreliable)
[c00000077cb977d0] [c000000000010c7c] .__switch_to+0x11c/0x154
[c00000077cb97860] [c0000000003455e0] .schedule+0x5d0/0x6b0
[c00000077cb97950] [c000000000345920] .schedule_timeout+0x3c/0xe8
[c00000077cb97a20] [c000000000344e7c] .wait_for_common+0x150/0x22c
[c00000077cb97ae0] [c00000000008f5ac] .__stop_machine_run+0xbc/0xf0
[c00000077cb97bb0] [c00000000008f61c] .stop_machine_run+0x3c/0x80
[c00000077cb97c50] [c00000000008989c] .sys_init_module+0x14e4/0x1af4
[c00000077cb97e30] [c00000000000872c] syscall_exit+0x0/0x40
-- 0:conmux-control -- time-stamp -- Feb/11/08 14:36:37 --
INFO: task insmod:385 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
insmod        D 000000001000e144 12144   385      1
Call Trace:
[c00000077cb97600] [c0000000008fc600] 0xc0000000008fc600 (unreliable)
[c00000077cb977d0] [c000000000010c7c] .__switch_to+0x11c/0x154
[c00000077cb97860] [c0000000003455e0] .schedule+0x5d0/0x6b0
[c00000077cb97950] [c000000000345920] .schedule_timeout+0x3c/0xe8
[c00000077cb97a20] [c000000000344e7c] .wait_for_common+0x150/0x22c
[c00000077cb97ae0] [c00000000008f5ac] .__stop_machine_run+0xbc/0xf0
[c00000077cb97bb0] [c00000000008f61c] .stop_machine_run+0x3c/0x80
[c00000077cb97c50] [c00000000008989c] .sys_init_module+0x14e4/0x1af4
[c00000077cb97e30] [c00000000000872c] syscall_exit+0x0/0x40
-- 0:conmux-control -- time-stamp -- Feb/11/08 14:38:46 --
INFO: task insmod:385 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
insmod        D 000000001000e144 12144   385      1
Call Trace:
[c00000077cb97600] [c0000000008fc600] 0xc0000000008fc600 (unreliable)
[c00000077cb977d0] [c000000000010c7c] .__switch_to+0x11c/0x154
[c00000077cb97860] [c0000000003455e0] .schedule+0x5d0/0x6b0
[c00000077cb97950] [c000000000345920] .schedule_timeout+0x3c/0xe8
[c00000077cb97a20] [c000000000344e7c] .wait_for_common+0x150/0x22c
[c00000077cb97ae0] [c00000000008f5ac] .__stop_machine_run+0xbc/0xf0
[c00000077cb97bb0] [c00000000008f61c] .stop_machine_run+0x3c/0x80
[c00000077cb97c50] [c00000000008989c] .sys_init_module+0x14e4/0x1af4
[c00000077cb97e30] [c00000000000872c] syscall_exit+0x0/0x40
-- 0:conmux-control -- time-stamp -- Feb/11/08 14:40:54 --
INFO: task insmod:385 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
insmod        D 000000001000e144 12144   385      1
Call Trace:
[c00000077cb97600] [c0000000008fc600] 0xc0000000008fc600 (unreliable)
[c00000077cb977d0] [c000000000010c7c] .__switch_to+0x11c/0x154
[c00000077cb97860] [c0000000003455e0] .schedule+0x5d0/0x6b0
[c00000077cb97950] [c000000000345920] .schedule_timeout+0x3c/0xe8
[c00000077cb97a20] [c000000000344e7c] .wait_for_common+0x150/0x22c
[c00000077cb97ae0] [c00000000008f5ac] .__stop_machine_run+0xbc/0xf0
[c00000077cb97bb0] [c00000000008f61c] .stop_machine_run+0x3c/0x80
[c00000077cb97c50] [c00000000008989c] .sys_init_module+0x14e4/0x1af4
[c00000077cb97e30] [c00000000000872c] syscall_exit+0x0/0x40
-- 0:conmux-control -- time-stamp -- Feb/11/08 14:43:04 --
INFO: task insmod:385 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
insmod        D 000000001000e144 12144   385      1
Call Trace:
[c00000077cb97600] [c0000000008fc600] 0xc0000000008fc600 (unreliable)
[c00000077cb977d0] [c000000000010c7c] .__switch_to+0x11c/0x154
[c00000077cb97860] [c0000000003455e0] .schedule+0x5d0/0x6b0
[c00000077cb97950] [c000000000345920] .schedule_timeout+0x3c/0xe8
[c00000077cb97a20] [c000000000344e7c] .wait_for_common+0x150/0x22c
[c00000077cb97ae0] [c00000000008f5ac] .__stop_machine_run+0xbc/0xf0
[c00000077cb97bb0] [c00000000008f61c] .stop_machine_run+0x3c/0x80
[c00000077cb97c50] [c00000000008989c] .sys_init_module+0x14e4/0x1af4
[c00000077cb97e30] [c00000000000872c] syscall_exit+0x0/0x40



-- 
Thanks & Regards,
Kamalesh Babulal,
Linux Technology Center,
IBM, ISTL.

Re: [BUG] 2.6.25-rc1-git1 softlockup while bootup on powerpc

From: Ingo Molnar <hidden>
Date: 2008-02-12 07:59:00

* Kamalesh Babulal [off-list ref] wrote:
While booting with the 2.6.25-rc1-git1 kernel on the powerbox the 
softlockup is seen, with following trace.
BUG: soft lockup - CPU#1 stuck for 61s! [insmod:377]
TASK = c00000077cb2f0e0[377] 'insmod' THREAD: c00000077cb28000 CPU: 1
NIP [c0000000001b172c] .radix_tree_gang_lookup+0xdc/0x1e4
LR [c0000000001a6f00] .call_for_each_cic+0x50/0x10c
Call Trace:
[c00000077cb2bb20] [c0000000001a6f60] .call_for_each_cic+0xb0/0x10c (unreliable)
[c00000077cb2bc60] [c00000000019ecd8] .exit_io_context+0xf0/0x110
[c00000077cb2bcf0] [c00000000006254c] .do_exit+0x820/0x850
[c00000077cb2bda0] [c000000000062648] .do_group_exit+0xcc/0xe8
[c00000077cb2be30] [c00000000000872c] syscall_exit+0x0/0x40
this call_for_each_cic/radix_tree_gang_lookup locked up, and all other 
CPUs deadlocked in stopmachine, due to this one.

call_for_each_cic is in ./block/cfq-iosched.c uses RCU, but you've got 
classic-RCU:

  CONFIG_CLASSIC_RCU=y
  # CONFIG_PREEMPT_RCU is not set

so it's not related to the preempt-RCU changes either.

It is this part that locks up:

        do {
...
                nr = radix_tree_gang_lookup(&ioc->radix_root, (void **) cics,
                                                index, CIC_GANG_NR);
...
        } while (nr == CIC_GANG_NR);
...

it seems the radix tree will yield new entries again and again. Either 
it got corrupted, or some other CPU is filling it faster than we can 
deplete it [unlikely i think].

	Ingo

Re: [BUG] 2.6.25-rc1-git1 softlockup while bootup on powerpc

From: Kamalesh Babulal <hidden>
Date: 2008-02-14 10:00:57

Ingo Molnar wrote:
* Kamalesh Babulal [off-list ref] wrote:
quoted
While booting with the 2.6.25-rc1-git1 kernel on the powerbox the 
softlockup is seen, with following trace.
quoted
BUG: soft lockup - CPU#1 stuck for 61s! [insmod:377]
TASK = c00000077cb2f0e0[377] 'insmod' THREAD: c00000077cb28000 CPU: 1
NIP [c0000000001b172c] .radix_tree_gang_lookup+0xdc/0x1e4
LR [c0000000001a6f00] .call_for_each_cic+0x50/0x10c
Call Trace:
[c00000077cb2bb20] [c0000000001a6f60] .call_for_each_cic+0xb0/0x10c (unreliable)
[c00000077cb2bc60] [c00000000019ecd8] .exit_io_context+0xf0/0x110
[c00000077cb2bcf0] [c00000000006254c] .do_exit+0x820/0x850
[c00000077cb2bda0] [c000000000062648] .do_group_exit+0xcc/0xe8
[c00000077cb2be30] [c00000000000872c] syscall_exit+0x0/0x40
this call_for_each_cic/radix_tree_gang_lookup locked up, and all other 
CPUs deadlocked in stopmachine, due to this one.

call_for_each_cic is in ./block/cfq-iosched.c uses RCU, but you've got 
classic-RCU:

  CONFIG_CLASSIC_RCU=y
  # CONFIG_PREEMPT_RCU is not set

so it's not related to the preempt-RCU changes either.

It is this part that locks up:

        do {
...
                nr = radix_tree_gang_lookup(&ioc->radix_root, (void **) cics,
                                                index, CIC_GANG_NR);
...
        } while (nr == CIC_GANG_NR);
...

it seems the radix tree will yield new entries again and again. Either 
it got corrupted, or some other CPU is filling it faster than we can 
deplete it [unlikely i think].

	Ingo
This softlockup is seen with the 2.6.25-rc1-git3 also. Let me know if you
need more details.

-- 
Thanks & Regards,
Kamalesh Babulal,
Linux Technology Center,
IBM, ISTL.
Keyboard shortcuts
hback out one level
jnext message in thread
kprevious message in thread
ldrill in
Escclose help / fold thread tree
?toggle this help