On Thu, 29 Jun 2017 19:36:14 +1000 Nicholas Piggin <npiggin@xxxxxxxxx> wrote: > I've seen this as well (or something like it) in mambo at boot, but > it's pretty rare to hit. I'm trying to debug it. > > I'm guessing possibly an idle vs interrupt race. > > > [ 4255.151192] Sending NMI from CPU 5 to CPUs 0: > > [ 4255.151246] NMI backtrace for cpu 0 > > [ 4255.151287] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.12.0-rc7-next-20170628 #2 > > [ 4255.151363] task: c0000007f8495600 task.stack: c0000007f842c000 > > [ 4255.151428] NIP: c00000000000adb4 LR: c000000000015584 CTR: c00000000082f4b0 > > [ 4255.151504] REGS: c0000007f842fb60 TRAP: 0e81 Not tainted (4.12.0-rc7-next-20170628) > > [ 4255.151578] MSR: 9000000000009033 <SF,HV,EE,ME,IR,DR,RI,LE> > > [ 4255.151586] CR: 22004884 XER: 00000000 > > [ 4255.151675] CFAR: c00000000062c108 SOFTE: 1 > > [ 4255.151675] GPR00: c00000000082d6c8 c0000007f842fde0 c000000001062b00 0000000028000000 > > [ 4255.151675] GPR04: 0000000000000003 c000000000089830 00003aa8056bc35f 0000000000000001 > > [ 4255.151675] GPR08: 0000000000000002 c000000000d52d80 00000007fe7d0000 9000000000001003 > > [ 4255.151675] GPR12: c00000000082a0c0 c00000000fd40000 > > [ 4255.152217] NIP [c00000000000adb4] .L__replay_interrupt_return+0x0/0x4 > > [ 4255.152334] LR [c000000000015584] arch_local_irq_restore+0x74/0x90 > > [ 4255.152447] Call Trace: > > [ 4255.152499] [c0000007f842fde0] [c00000000017cec0] tick_broadcast_oneshot_control+0x40/0x60 (unreliable) > > [ 4255.152662] [c0000007f842fe00] [c00000000082d6c8] cpuidle_enter_state+0x108/0x3d0 > > [ 4255.152803] [c0000007f842fe60] [c000000000133e94] call_cpuidle+0x44/0x80 > > [ 4255.152921] [c0000007f842fe80] [c000000000134240] do_idle+0x290/0x2f0 > > [ 4255.153037] [c0000007f842fef0] [c000000000134474] cpu_startup_entry+0x34/0x40 > > [ 4255.153176] [c0000007f842ff20] [c000000000041944] start_secondary+0x304/0x360 > > [ 4255.153316] [c0000007f842ff90] [c00000000000b16c] start_secondary_prolog+0x10/0x14 > > [ 4255.153455] Instruction dump: > > [ 4255.153527] 7d200026 618c8000 2c030900 4182e320 2c030500 4182dd68 2c030e80 4182ffa4 > > [ 4255.153668] 2c030ea0 4182f078 2c030e60 4182edb0 <4e800020> 7c781b78 480003c9 480003e1 > > What I think you're seeing here is just the lockup IPI causes the CPU to > wake from idle, and so the backtrace gets recorded from where the interrupt > gets replayed when the cpuidle code returns from the low level idle call > then re-enables interrupts. > > I don't *think* the replay-wakeup-interrupt patch is directly involved, but > it's likely to be one of the idle patches. Although you have this in the backtrace. I wonder if that's a stuck lock in rcu_process_callbacks? [ 5948.345539] CPU: 63 PID: 7360 Comm: rs:main Q:Reg Not tainted \ 4.12.0-rc7-next-20170628 #2 [ 5948.345612] task: c000000f1c14e600 task.stack: \ c000000f1c1e8000 [ 5948.345672] NIP: c0000000009c7a10 LR: c0000000009c7a08 CTR: \ c00000000015eda0 [ 5948.358553] REGS: c000000f1c1eb150 TRAP: 0501 Not tainted \ (4.12.0-rc7-next-20170628) [ 5948.358623] MSR: 9000000000009033 \ <SF,HV,EE,ME,IR,DR,RI,LE> [ 5948.358626] CR: 28082884 XER: 20000000 [ 5948.358706] CFAR: c0000000009c7a28 SOFTE: 1 GPR00: c00000000015f14c c000000f1c1eb3d0 c000000001062b00 0000000000000001 GPR04: c000000fff6e6180 0000000000000000 0000000000000001 00000000000000cc GPR08: 0000000000000001 000000008000004a 0000000000000000 0000000000000000 GPR12: c00000000015eda0 c00000000fd55a80 [ 5948.358986] NIP [c0000000009c7a10] _raw_spin_lock_irqsave+0x90/0x100 [ 5948.359043] LR [c0000000009c7a08] _raw_spin_lock_irqsave+0x88/0x100 [ 5948.359099] Call Trace: [ 5948.359123] [c000000f1c1eb3d0] [0000000000000001] 0x1 (unreliable) [ 5948.359182] [c000000f1c1eb410] [c00000000015f14c] \ rcu_process_callbacks+0x3ac/0x620 [ 5948.359252] [c000000f1c1eb4c0] \ [c0000000000e1e0c] __do_softirq+0x14c/0x3a0 [ 5948.365958] [c000000f1c1eb5b0] \ [c0000000000e2448] irq_exit+0x108/0x120 [ 5948.366016] [c000000f1c1eb5d0] \ [c0000000000232b4] timer_interrupt+0xa4/0xe0 [ 5948.366075] [c000000f1c1eb600] \ [c000000000009208] decrementer_common+0x158/0x160 [ 5948.366149] --- interrupt: 901 \ at start_this_handle+0xd0/0x4b0 LR = jbd2__journal_start+0x17c/0x2b0 [ 5948.366242] [c000000f1c1eb8f0] [c000000f20a5cb00] 0xc000000f20a5cb00 (unreliable) [ 5948.366314] [c000000f1c1eba00] [c00000000040717c] jbd2__journal_start+0x17c/0x2b0 [ 5948.366388] [c000000f1c1eba70] [c00000000038edf4] \ __ext4_journal_start_sb+0x84/0x180 [ 5948.366459] [c000000f1c1ebad0] \ [c0000000003b47dc] ext4_da_write_begin+0x17c/0x520 [ 5948.366532] [c000000f1c1ebb90] \ [c00000000021f9c8] generic_perform_write+0xe8/0x250 [ 5948.366604] [c000000f1c1ebc20] \ [c000000000220d20] __generic_file_write_iter+0x200/0x240 [ 5948.366677] \ [c000000f1c1ebc80] [c00000000039d614] ext4_file_write_iter+0x2e4/0x4d0 [ 5948.373255] \ [c000000f1c1ebd00] [c0000000002e13c0] __vfs_write+0x120/0x200 [ 5948.373313] \ [c000000f1c1ebd90] [c0000000002e2c48] vfs_write+0xc8/0x240 [ 5948.373371] \ [c000000f1c1ebde0] [c0000000002e4940] SyS_write+0x60/0x110 [ 5948.373430] \ [c000000f1c1ebe30] [c00000000000b8e0] system_call+0x38/0xdc [ 5948.373486] \ Instruction dump: [ 5948.373521] 7fe3fb78 e8010010 eba1ffe8 ebc1fff0 ebe1fff8 \ 7c0803a6 4e800020 8bad028a [ 5948.373592] 7fe3fb78 4b64db15 60000000 7c210b78 \ <e92d0000> 89290009 792affe3 40820048 [ 5948.374515] Sending NMI from CPU 74 to CPUs \ -- To unsubscribe from this list: send the line "unsubscribe linux-next" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
