So there's definitely IRQMASK=0 and no MSR[EE]=0 in this frame, which is
what the warning was.
I'd say either something hasn't set PACA_IRQ_HARD_DIS properly, so EE
doesn't get enabled when irqs are restored, or maybe the change to
arch_local_irq_restore(). Less likely that the stack got messed up.
Can you try run with CONFIG_PPC_IRQ_SOFT_MASK_DEBUG=y ?
Thanks,
Nick
So there's definitely IRQMASK=0 and no MSR[EE]=0 in this frame, which is
what the warning was.
I'd say either something hasn't set PACA_IRQ_HARD_DIS properly, so EE
doesn't get enabled when irqs are restored, or maybe the change to
arch_local_irq_restore(). Less likely that the stack got messed up.
Can you try run with CONFIG_PPC_IRQ_SOFT_MASK_DEBUG=y ?
Nevermind, I think I've found the problem. Some code runs in the
implicit soft-mask region without expecting to be masked. Working
on a fix...
Thanks,
Nick
From: Sachin Sant <hidden> Date: 2021-06-27 11:24:14
On 27-Jun-2021, at 3:36 PM, Nicholas Piggin [off-list ref] wrote:
quoted
So there's definitely IRQMASK=0 and no MSR[EE]=0 in this frame, which is
what the warning was.
I'd say either something hasn't set PACA_IRQ_HARD_DIS properly, so EE
doesn't get enabled when irqs are restored, or maybe the change to
arch_local_irq_restore(). Less likely that the stack got messed up.
Can you try run with CONFIG_PPC_IRQ_SOFT_MASK_DEBUG=y ?
Nevermind, I think I've found the problem. Some code runs in the
implicit soft-mask region without expecting to be masked. Working
on a fix…
:-) . I was able to recreate this after few attempts. It seem the warning isn’t
always triggered during boot. I had to run a kernel compile operation after
boot to trigger this warning again.
In case its helpful here is the additional trace with PPC_IRQ_SOFT_MASK_DEBUG.
[ 92.106731] ------------[ cut here ]------------
[ 92.106738] WARNING: CPU: 45 PID: 12757 at arch/powerpc/kernel/irq.c:255 arch_local_irq_restore+0x1d0/0x200
[ 92.106753] Modules linked in: dm_mod bonding nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_set rfkill nf_tables libcrc32c nfnetlink sunrpc pseries_rng xts vmx_crypto uio_pdrv_genirq uio sch_fq_codel ip_tables ext4 mbcache jbd2 sd_mod t10_pi sg ibmvscsi ibmveth scsi_transport_srp fuse
[ 92.106828] CPU: 45 PID: 12757 Comm: sh Kdump: loaded Tainted: G W 5.13.0-rc7-next-20210625 #1
[ 92.106841] NIP: c0000000000164d0 LR: c000000000cedaa8 CTR: 0000000000000000
[ 92.106849] REGS: c00000008dfeb7e0 TRAP: 0700 Tainted: G W (5.13.0-rc7-next-20210625)
[ 92.106859] MSR: 8000000002823033 <SF,VEC,VSX,FP,ME,IR,DR,RI,LE> CR: 28004222 XER: 00000000
[ 92.106892] CFAR: c00000000001632c IRQMASK: 0
GPR00: c000000000ceda98 c00000008dfeba80 c000000002921e00 0000000000000000
GPR04: 0000000000000000 0000000000000000 0000000000000000 00000000000000ff
GPR08: 0000000000000001 0000000000000000 0000000000000001 0000000000000017
GPR12: 0000000024004822 c000000007fb9200 000000012efd81d4 000000012ee50000
GPR16: 0000000000000001 00000100268a0e00 000001002687ec10 0000000114200c40
GPR20: 00003fffa93f8000 0000000000000000 00003fffa93f9300 000000012efb1988
GPR24: 000000012ee7fe7c 000000012efccba0 000000012ee50000 c00000008d5d7600
GPR28: c0000000314c0bc0 c000000040d9f100 c0000008beb5861c 4b72201a3063fe13
[ 92.107024] NIP [c0000000000164d0] arch_local_irq_restore+0x1d0/0x200
[ 92.107035] LR [c000000000cedaa8] _raw_spin_unlock_irqrestore+0x88/0xb0
[ 92.107047] Call Trace:
[ 92.107052] [c00000008dfeba80] [c00000008dfebb50] 0xc00000008dfebb50 (unreliable)
[ 92.107065] [c00000008dfebab0] [238c5bf052df0858] 0x238c5bf052df0858
[ 92.107076] [c00000008dfebae0] [c0000000008178e8] get_random_u64+0x88/0x100
[ 92.107090] [c00000008dfebb20] [c000000000020134] arch_randomize_brk+0xb4/0xd8
[ 92.107105] [c00000008dfebb50] [c0000000005430b0] load_elf_binary+0xe70/0x1220
[ 92.107119] [c00000008dfebc40] [c00000000047ded0] bprm_execve+0x410/0x800
[ 92.107132] [c00000008dfebd10] [c00000000047e8ec] do_execveat_common.isra.44+0x21c/0x240
[ 92.107145] [c00000008dfebd80] [c00000000047e964] sys_execve+0x54/0x70
[ 92.107157] [c00000008dfebdb0] [c000000000032334] system_call_exception+0x164/0x2e0
[ 92.107169] [c00000008dfebe10] [c00000000000c464] system_call_common+0xf4/0x258
[ 92.107185] --- interrupt: c00 at 0x3fff9bb6b8a8
[ 92.107193] NIP: 00003fff9bb6b8a8 LR: 00003fff9bb6c240 CTR: 0000000000000000
[ 92.107202] REGS: c00000008dfebe80 TRAP: 0c00 Tainted: G W (5.13.0-rc7-next-20210625)
[ 92.107213] MSR: 800000000000f033 <SF,EE,PR,FP,ME,IR,DR,RI,LE> CR: 28004224 XER: 00000000
[ 92.107243] IRQMASK: 0
GPR00: 000000000000000b 00003fffc36a1440 00003fff9bc87300 00000100268a67d0
GPR04: 0000010026887e50 0000010026882c50 fefefefefefefeff 7f7f7f7f7f7f7f7f
GPR08: 00000100268a67d0 0000000000000000 0000000000000000 0000000000000000
GPR12: 0000000000000000 00003fff9bce3780 0000000114200db4 0000000000000000
GPR16: 0000000000000001 00000100268a0e00 000001002687ec10 0000000114200c40
GPR20: 00000001141dd820 0000000000000000 00000001141dd740 0000000114204358
GPR24: 0000000114203948 0000010026876454 0000000000000001 0000010026882c50
GPR28: 0000010026887e50 0000010026882c50 00000100268a67d0 00003fffc36a1440
[ 92.107369] NIP [00003fff9bb6b8a8] 0x3fff9bb6b8a8
[ 92.107378] LR [00003fff9bb6c240] 0x3fff9bb6c240
[ 92.107386] --- interrupt: c00
[ 92.107393] Instruction dump:
[ 92.107400] 7d2000a6 71298000 40820048 39200000 992d0152 39400000 992d0153 614a8002
[ 92.107427] 7d410164 4bfffe6c 60000000 60000000 <0fe00000> 4bfffe5c 60000000 60000000
[ 92.107451] ---[ end trace 5f1d49fb99f3613d ]—
Complete dmesg log attached.
Thanks
-Sachin
From: Nicholas Piggin <npiggin@gmail.com> Date: 2021-06-28 03:52:09
Excerpts from Sachin Sant's message of June 27, 2021 9:23 pm:
quoted
On 27-Jun-2021, at 3:36 PM, Nicholas Piggin [off-list ref] wrote:
quoted
So there's definitely IRQMASK=0 and no MSR[EE]=0 in this frame, which is
what the warning was.
I'd say either something hasn't set PACA_IRQ_HARD_DIS properly, so EE
doesn't get enabled when irqs are restored, or maybe the change to
arch_local_irq_restore(). Less likely that the stack got messed up.
Can you try run with CONFIG_PPC_IRQ_SOFT_MASK_DEBUG=y ?
Nevermind, I think I've found the problem. Some code runs in the
implicit soft-mask region without expecting to be masked. Working
on a fix…
:-) . I was able to recreate this after few attempts. It seem the warning isn’t
always triggered during boot. I had to run a kernel compile operation after
boot to trigger this warning again.
In case its helpful here is the additional trace with PPC_IRQ_SOFT_MASK_DEBUG.
Thanks. I ended up being able to reproduce as well, quite frequently
with some extra debug checks that specifically catch more cases.
I've got a few patches under test right now, very stable so far. I'll
post them out if they survive a nother hour or two stress testing.
The problem is some code (e.g., ret_from_fork) now gets implicitly
soft-masked where that was not expecting to be. A masked interrupt might
hit, and then when it moves out of the implicit soft-mask region it
does not re-enable interrupts. Some types of pending interrupts will
clear MSR[EE], and that ends up causing this bug on the next interrupt
that happens.
Not a wonderful escape :\ thanks for finding it. The fixes aren't too
bad, fortunately.
Thanks,
Nick