3.4.0-rc4: ksoftirqd crash on sparc64 after IO errors and RCU stalls

3.4.0-rc4: ksoftirqd crash on sparc64 after IO errors and RCU stalls

[Meelis Roos]

Tetest 3.4.0-rc4 on Sun Fire V240 (SMP sparc64). First the disk got may 
IO errors, the RCU soft lockup warning kicked in, mthen any more IO 
errors - up to this point the kernel behaviour seems OK. But finally, an 
oops from ksoftirqd happened.

Kernel unaligned access at TPC[42c0dc] arch_trigger_all_cpu_backtrace+0x13c/0x1c0
seems to be the culprit for me.

I do not know if this is a new behaviour - hitting IO errors is not a 
normal test case for me. V210 with same type of mainbaord and storage 
worked fine with 3.4-rc4 but it did not hit any IO errors either.

Can not get the start of the log - that's all I have in backlog and the 
disk is quite dead so the machine does not boot up any more.

[  332.200524] Buffer I/O error on device sda2, logical block 128273
[  332.280695] BUG: soft lockup - CPU#1 stuck for 22s! [ksoftirqd/1:3]
[  332.363121] Modules linked in: loop ohci_hcd ehci_hcd usbcore i2c_ali15x3 i2c_ali1535 usb_common flash nls_base i2c_core pata_ali libata tg3
[  332.528952] irq event stamp: 293355
[  332.574710] hardirqs last  enabled at (293354): [<0000000000457de4>] vprintk+0x244/0x4a0
[  332.681088] hardirqs last disabled at (293355): [<0000000000426b50>] valid_addr_bitmap_patch+0xb0/0x260
[  332.804619] softirqs last  enabled at (285672): [<000000000045e57c>] __do_softirq+0x11c/0x160
[  332.916706] softirqs last disabled at (285677): [<000000000045e6f4>] run_ksoftirqd+0x134/0x200
[  333.029944] TSTATE: 0000004480001606 TPC: 0000000000457df4 TNPC: 0000000000457df8 Y: 00000000    Not tainted
[  333.159206] TPC: <vprintk+0x254/0x4a0>
[  333.208470] g0: 0000000000990ed8 g1: 0000000000000000 g2: 0000000000000000 g3: 0000000000000001
[  333.322865] g4: fffff8101f071ec0 g5: fffff80000bf8000 g6: fffff8101f08c000 g7: 0000000000000720
[  333.437348] o0: 0000000000990e80 o1: 0000000000a31344 o2: 0000000000a31348 o3: ffffffffffffffb8
[  333.551829] o4: 000000000000000e o5: 0000000000990e80 sp: fffff8101f08ea61 ret_pc: 0000000000457de4
[  333.670887] RPC: <vprintk+0x244/0x4a0>
[  333.720155] l0: 0000000000a51360 l1: 0000000000990c00 l2: 0000000000990c00 l3: 000000003b9aca00
[  333.834548] l4: 0000000000000001 l5: 0000000000990c00 l6: 0000000000000001 l7: 0000000000000000
[  333.949031] i0: 000000000000004b i1: fffff8101f08f330 i2: 0000000000000003 i3: 0000000000990ecc
[  334.063512] i4: 0000000000a51399 i5: 0000000000a51363 i6: fffff8101f08eb71 i7: 00000000008061f4
[  334.178005] I7: <printk+0x24/0x38>
[  334.222686] Call Trace:
[  334.254713]  [00000000008061f4] printk+0x24/0x38
[  334.315342]  [00000000005af0fc] ext4_end_bio+0x1dc/0x240
[  334.385117]  [0000000000563cc8] bio_endio+0x28/0x60
[  334.449167]  [000000000060e894] req_bio_endio+0x74/0xe0
[  334.517789]  [000000000060ea0c] blk_update_request+0x10c/0x3a0
[  334.594423]  [000000000060fbb0] blk_update_bidi_request+0x10/0x80
[  334.674490]  [0000000000610bf4] blk_end_bidi_request+0x14/0x60
[  334.751122]  [0000000000610c50] blk_end_request+0x10/0x40
[  334.822035]  [0000000000610ca0] blk_end_request_err+0x20/0x60
[  334.897530]  [00000000006aaa30] scsi_io_completion+0x350/0x620
[  334.974166]  [00000000006a1728] scsi_finish_command+0xa8/0x120
[  335.050791]  [00000000006aa5a8] scsi_softirq_done+0x108/0x160
[  335.126282]  [000000000061728c] blk_done_softirq+0x6c/0xa0
[  335.198337]  [000000000045e510] __do_softirq+0xb0/0x160
[  335.266962]  [000000000045e6f4] run_ksoftirqd+0x134/0x200
[  335.337881]  [00000000004792ec] kthread+0x6c/0x80
... (lots of IO errors)
[  366.185589] EXT4-fs warning (device sda2): ext4_end_bio:250: I/O error writing to inode 1441884 (offset 11534336 size 528384 starting block 154017)
[  366.361847] sd 0:0:0:0: [sda] Unhandled sense code
[  366.424852] sd 0:0:0:0: [sda]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[  366.519982] sd 0:0:0:0: [sda]  Sense Key : Hardware Error [current]
[  366.603668] Info fld=0x12ea56
[  366.642566] sd 0:0:0:0: [sda]  Add. Sense: Peripheral device write fault
[  366.730838] sd 0:0:0:0: [sda] CDB: Write(10): 2a 00 00 12 e9 0c 00 04 00 00
[  366.822444] end_request: critical target error, dev sda, sector 1239638
[  366.909501] Buffer I/O error on device sda2, logical block 130816
...
[  375.567682] Buffer I/O error on device sda2, logical block 130924
[  375.647843] Buffer I/O error on device sda2, logical block 130925
[  375.727997] INFO: rcu_sched self-detected stall on CPU
[  375.730097] INFO: rcu_sched detected stalls on CPUs/tasks:
[  375.730122]  1: (286 ticks this GP) idle=8e1/140000000000001/0
[  375.730129]  (detected by 0, t=16253 jiffies)
[  375.730136] INFO: Stall ended before state dump start
[  376.068827]
[  376.088267]  1: (286 ticks this GP) idle=8e1/140000000000001/0
[  376.166048]   (t=16253 jiffies)
[  376.207537] Kernel unaligned access at TPC[42c0dc] arch_trigger_all_cpu_backtrace+0x13c/0x1c0
[  376.319655] Unable to handle kernel paging request in mna handler
[  376.397504]  at virtual address 000007f300000001
[  376.460414] current->{active_,}mm->context = 000000000000086f
[  376.535905] current->{active_,}mm->pgd = fffff8101d5d0000
[  376.606819]               \|/ ____ \|/
[  376.606822]               "@'/ .. \`@"
[  376.606825]               /_| \__/ |_\
[  376.606828]                  \__U_/
[  376.800115] ksoftirqd/1(3): Oops [#1]
[  376.848157] TSTATE: 0000009980e01600 TPC: 000000000042c0dc TNPC: 000000000042c0e0 Y: 00000000    Not tainted
[  376.977422] TPC: <arch_trigger_all_cpu_backtrace+0x13c/0x1c0>
[  377.052999] g0: 0000000000000001 g1: ffffffffffffffff g2: 00000000008f5060 g3: 000007f300000001
[  377.167387] g4: fffff8101f071ec0 g5: fffff80000bf8000 g6: fffff8101f08c000 g7: 0000000000000003
[  377.281766] o0: 000000000000000c o1: 0000000000000020 o2: 0000000000000000 o3: 0000004411001603
[  377.396248] o4: 000000000064e920 o5: 000000000064e924 sp: fffff8101f08e2b1 ret_pc: 000000000042c0a0
[  377.515306] RPC: <arch_trigger_all_cpu_backtrace+0x100/0x1c0>
[  377.590781] l0: 000000000000000e l1: 00000000008f50b0 l2: 00000000008f50e0 l3: 00000000008f5068
[  377.705171] l4: 00000000008f5000 l5: 0000000000a0cfc0 l6: 0000000000000000 l7: 0000000000000000
[  377.819550] i0: 0000000000000001 i1: 0000000000983680 i2: 00000000009847bc i3: 000000000098ac00
[  377.934032] i4: 0000000000a0cfc0 i5: 0000000000000000 i6: fffff8101f08e381 i7: 00000000004cf3b4
[  378.048522] I7: <print_cpu_stall+0x54/0x120>
[  378.104643] Call Trace:
[  378.136671]  [00000000004cf3b4] print_cpu_stall+0x54/0x120
[  378.208735]  [00000000004d0794] __rcu_pending+0xf4/0x220
[  378.278504]  [00000000004d13b0] rcu_check_callbacks+0x130/0x160
[  378.356289]  [0000000000465964] update_process_times+0x24/0x80
[  378.432922]  [00000000004a4c3c] tick_sched_timer+0x5c/0xc0
[  378.504977]  [000000000047dcac] __run_hrtimer.isra.15+0x4c/0x140
[  378.583897]  [000000000047e33c] hrtimer_interrupt+0xbc/0x200
[  378.658242]  [000000000042f7e4] timer_interrupt+0xa4/0xe0
[  378.729154]  [0000000000426b5c] valid_addr_bitmap_patch+0xbc/0x260
[  378.810366]  [0000000000457df4] vprintk+0x254/0x4a0
[  378.874417]  [00000000008061f4] printk+0x24/0x38
[  378.935032]  [00000000005af0fc] ext4_end_bio+0x1dc/0x240
[  379.004805]  [0000000000563cc8] bio_endio+0x28/0x60
[  379.068856]  [000000000060e894] req_bio_endio+0x74/0xe0
[  379.137482]  [000000000060ea0c] blk_update_request+0x10c/0x3a0
[  379.214117]  [000000000060fbb0] blk_update_bidi_request+0x10/0x80
[  379.294179] Disabling lock debugging due to kernel taint
[  379.363951] Caller[00000000004cf3b4]: print_cpu_stall+0x54/0x120
[  379.442872] Caller[00000000004d0794]: __rcu_pending+0xf4/0x220
[  379.519503] Caller[00000000004d13b0]: rcu_check_callbacks+0x130/0x160
[  379.604146] Caller[0000000000465964]: update_process_times+0x24/0x80
[  379.687642] Caller[00000000004a4c3c]: tick_sched_timer+0x5c/0xc0
[  379.766562] Caller[000000000047dcac]: __run_hrtimer.isra.15+0x4c/0x140
[  379.852346] Caller[000000000047e33c]: hrtimer_interrupt+0xbc/0x200
[  379.933553] Caller[000000000042f7e4]: timer_interrupt+0xa4/0xe0
[  380.011329] Caller[0000000000426b5c]: valid_addr_bitmap_patch+0xbc/0x260
[  380.099400] Caller[0000000000457de4]: vprintk+0x244/0x4a0
[  380.170313] Caller[00000000008061f4]: printk+0x24/0x38
[  380.237794] Caller[00000000005af0fc]: ext4_end_bio+0x1dc/0x240
[  380.314431] Caller[0000000000563cc8]: bio_endio+0x28/0x60
[  380.385342] Caller[000000000060e894]: req_bio_endio+0x74/0xe0
[  380.460834] Caller[000000000060ea0c]: blk_update_request+0x10c/0x3a0
[  380.544330] Caller[000000000060fbb0]: blk_update_bidi_request+0x10/0x80
[  380.631258] Caller[0000000000610bf4]: blk_end_bidi_request+0x14/0x60
[  380.714754] Caller[0000000000610c50]: blk_end_request+0x10/0x40
[  380.792528] Caller[0000000000610ca0]: blk_end_request_err+0x20/0x60
[  380.874883] Caller[00000000006aaa30]: scsi_io_completion+0x350/0x620
[  380.958379] Caller[00000000006a1728]: scsi_finish_command+0xa8/0x120
[  381.041872] Caller[00000000006aa5a8]: scsi_softirq_done+0x108/0x160
[  381.124225] Caller[000000000061728c]: blk_done_softirq+0x6c/0xa0
[  381.203145] Caller[000000000045e510]: __do_softirq+0xb0/0x160
[  381.278632] Caller[000000000045e6f4]: run_ksoftirqd+0x134/0x200
[  381.356410] Caller[00000000004792ec]: kthread+0x6c/0x80
[  381.425037] Caller[000000000042b830]: kernel_thread+0x30/0x60
[  381.500527] Caller[000000000047962c]: kthreadd+0x10c/0x180
[  381.572579] Instruction DUMP: d85d6008  02c0c007  da5d6010 <c658c000> 02c0c005  83386000  c200e274  8400e420  83386000 
[  381.714400] Kernel panic - not syncing: Aiee, killing interrupt handler!

-- 
Meelis Roos (mroos@linux.ee)

Re: 3.4.0-rc4: ksoftirqd crash on sparc64 after IO errors and RCU stalls

[David Miller]

From: Meelis Roos <mroos@linux.ee>
Date: Mon, 23 Apr 2012 00:33:07 +0300 (EEST)

> [  376.207537] Kernel unaligned access at TPC[42c0dc] arch_trigger_all_cpu_backtrace+0x13c/0x1c0
> [  376.319655] Unable to handle kernel paging request in mna handler
> [  376.397504]  at virtual address 000007f300000001
> [  376.460414] current->{active_,}mm->context = 000000000000086f
> [  376.535905] current->{active_,}mm->pgd = fffff8101d5d0000
> [  376.606819]               \|/ ____ \|/
> [  376.606822]               "@'/ .. \`@"
> [  376.606825]               /_| \__/ |_\
> [  376.606828]                  \__U_/
> [  376.800115] ksoftirqd/1(3): Oops [#1]
> [  376.848157] TSTATE: 0000009980e01600 TPC: 000000000042c0dc TNPC: 000000000042c0e0 Y: 00000000    Not tainted
> [  376.977422] TPC: <arch_trigger_all_cpu_backtrace+0x13c/0x1c0>
> [  377.052999] g0: 0000000000000001 g1: ffffffffffffffff g2: 00000000008f5060 g3: 000007f300000001
> [  377.167387] g4: fffff8101f071ec0 g5: fffff80000bf8000 g6: fffff8101f08c000 g7: 0000000000000003
> [  377.281766] o0: 000000000000000c o1: 0000000000000020 o2: 0000000000000000 o3: 0000004411001603
> [  377.396248] o4: 000000000064e920 o5: 000000000064e924 sp: fffff8101f08e2b1 ret_pc: 000000000042c0a0
> [  377.515306] RPC: <arch_trigger_all_cpu_backtrace+0x100/0x1c0>
> [  377.590781] l0: 000000000000000e l1: 00000000008f50b0 l2: 00000000008f50e0 l3: 00000000008f5068
> [  377.705171] l4: 00000000008f5000 l5: 0000000000a0cfc0 l6: 0000000000000000 l7: 0000000000000000
> [  377.819550] i0: 0000000000000001 i1: 0000000000983680 i2: 00000000009847bc i3: 000000000098ac00
> [  377.934032] i4: 0000000000a0cfc0 i5: 0000000000000000 i6: fffff8101f08e381 i7: 00000000004cf3b4
> [  378.048522] I7: <print_cpu_stall+0x54/0x120>

The thread pointer stored by one of the cpus is garbage.  It's being
inspected in %g3 at this point on the cpu which triggered the
backtrace.  It just tested it for NULL, which passed, so then we trust
it as a good kernel pointer but it's not, it's 000007f300000001.

And we take the unaligned trap when we try to dereference that thing.

Looking at the code which collects these registers, the bug is clear.
In arch/sparc/mm/ultra.S:xcall_fetch_glob_regs we go:

	sethi		%hi(global_reg_snapshot), %g1
	or		%g1, %lo(global_reg_snapshot), %g1
	__GET_CPUID(%g2)
	sllx		%g2, 6, %g3
	add		%g1, %g3, %g1

so far so good, %g2 holds the current cpu's number, and %g1 now holds
a pointer to the global_reg_snapshot entry we'll fill in.

But later in this routine:

	rdpr		%cwp, %g2
	sub		%g2, 1, %g7
	wrpr		%g7, %cwp
	mov		%i7, %g7
	wrpr		%g2, %cwp
	stx		%g7, [%g1 + GR_SNAP_RPC]

which on the surface looks fine, but the problem is we've clobbered
%g2 and then afterwards we go:

	sethi		%hi(trap_block), %g7
	or		%g7, %lo(trap_block), %g7
	sllx		%g2, TRAP_BLOCK_SZ_SHIFT, %g2
	add		%g7, %g2, %g7
	ldx		[%g7 + TRAP_PER_CPU_THREAD], %g3
	stx		%g3, [%g1 + GR_SNAP_THREAD]

This code assumes %g2 still holds the current cpu's number in it, but
as stated it's been clobbered with the %cwp read above.

That's why we read a garbage thread pointer, the index we use into
trap_block[] is wrong.

I'll work on a fix for this, thanks for the report.