I'm hoping for some help investigating a behavior I see when doing cpu
hotplug under load on P9 and P8 LPARs. Occasionally, while coming online
a cpu will seem to get "stuck" in idle, with a pending doorbell
interrupt unserviced (cpu 12 here):
cpuhp/12-70 [012] 46133.602202: cpuhp_enter: cpu: 0012 target: 205 step: 174 (0xc000000000028920s)
load.sh-8201 [014] 46133.602248: sched_waking: comm=cpuhp/12 pid=70 prio=120 target_cpu=012
load.sh-8201 [014] 46133.602251: smp_send_reschedule: (c000000000052868) cpu=12
<idle>-0 [012] 46133.602252: do_idle: (c000000000162e08)
load.sh-8201 [014] 46133.602252: smp_muxed_ipi_message_pass: (c0000000000527e8) cpu=12 msg=1
load.sh-8201 [014] 46133.602253: doorbell_core_ipi: (c00000000004d3e8) cpu=12
<idle>-0 [012] 46133.602257: arch_cpu_idle: (c000000000022d08)
<idle>-0 [012] 46133.602259: pseries_lpar_idle: (c0000000000d43c8)
This leaves the task initiating the online blocked in a state like this:
[<0>] __switch_to+0x2dc/0x430
[<0>] __cpuhp_kick_ap+0x78/0xa0
[<0>] cpuhp_kick_ap+0x60/0xf0
[<0>] cpuhp_invoke_callback+0xf4/0x780
[<0>] _cpu_up+0x138/0x260
[<0>] do_cpu_up+0x130/0x160
[<0>] cpu_subsys_online+0x68/0xe0
[<0>] device_online+0xb4/0x120
[<0>] online_store+0xb4/0xc0
[<0>] dev_attr_store+0x3c/0x60
[<0>] sysfs_kf_write+0x70/0xb0
[<0>] kernfs_fop_write+0x17c/0x250
[<0>] __vfs_write+0x40/0x80
[<0>] vfs_write+0xd4/0x250
[<0>] ksys_write+0x74/0x130
[<0>] system_call+0x5c/0x70
This trace is from a 5.2.10 kernel, and I've observed the problem on a
4.12 vendor kernel as well.
The issue always occurs before the cpu has completed all the cpuhp
callbacks that need to run on that cpu. Often it occurs before it even
runs a task (rcu_sched, migration, or cpuhp kthreads are the first to
run). But sometimes it will have run a task or two, as in this case.
It seems specific to doorbell i.e. intra-core IPIs; I have not observed
IPIs between cores getting dropped.
sysrq-l gets the newly onlined cpu unstuck.
The cpu can get in this state even after servicing doorbells earlier in
the online process.
This is using the default cede offline state, not stop-self (which I
haven't tried).
Ideas?
Nathan Lynch [off-list ref] writes:
I'm hoping for some help investigating a behavior I see when doing cpu
hotplug under load on P9 and P8 LPARs. Occasionally, while coming online
a cpu will seem to get "stuck" in idle, with a pending doorbell
interrupt unserviced (cpu 12 here):
cpuhp/12-70 [012] 46133.602202: cpuhp_enter: cpu: 0012 target: 205 step: 174 (0xc000000000028920s)
load.sh-8201 [014] 46133.602248: sched_waking: comm=cpuhp/12 pid=70 prio=120 target_cpu=012
load.sh-8201 [014] 46133.602251: smp_send_reschedule: (c000000000052868) cpu=12
<idle>-0 [012] 46133.602252: do_idle: (c000000000162e08)
load.sh-8201 [014] 46133.602252: smp_muxed_ipi_message_pass: (c0000000000527e8) cpu=12 msg=1
load.sh-8201 [014] 46133.602253: doorbell_core_ipi: (c00000000004d3e8) cpu=12
<idle>-0 [012] 46133.602257: arch_cpu_idle: (c000000000022d08)
<idle>-0 [012] 46133.602259: pseries_lpar_idle: (c0000000000d43c8)
I should be more explicit that given my tracing configuration I would
expect to see doorbell events etc here e.g.
<idle>-0 [012] 46133.602086: doorbell_entry: pt_regs=0xc000000200e7fb50
<idle>-0 [012] 46133.602087: smp_ipi_demux_relaxed: (c0000000000530f8)
<idle>-0 [012] 46133.602088: scheduler_ipi: (c00000000015e4f8)
<idle>-0 [012] 46133.602091: sched_wakeup: cpuhp/12:70 [120] success=1 CPU:012
<idle>-0 [012] 46133.602092: sched_wakeup: migration/12:71 [0] success=1 CPU:012
<idle>-0 [012] 46133.602093: doorbell_exit: pt_regs=0xc000000200e7fb50
but instead cpu 12 goes to idle.
Nathan Lynch [off-list ref] writes:
Nathan Lynch [off-list ref] writes:
quoted
I'm hoping for some help investigating a behavior I see when doing cpu
hotplug under load on P9 and P8 LPARs. Occasionally, while coming online
a cpu will seem to get "stuck" in idle, with a pending doorbell
interrupt unserviced (cpu 12 here):
cpuhp/12-70 [012] 46133.602202: cpuhp_enter: cpu: 0012 target: 205 step: 174 (0xc000000000028920s)
load.sh-8201 [014] 46133.602248: sched_waking: comm=cpuhp/12 pid=70 prio=120 target_cpu=012
load.sh-8201 [014] 46133.602251: smp_send_reschedule: (c000000000052868) cpu=12
<idle>-0 [012] 46133.602252: do_idle: (c000000000162e08)
load.sh-8201 [014] 46133.602252: smp_muxed_ipi_message_pass: (c0000000000527e8) cpu=12 msg=1
load.sh-8201 [014] 46133.602253: doorbell_core_ipi: (c00000000004d3e8) cpu=12
<idle>-0 [012] 46133.602257: arch_cpu_idle: (c000000000022d08)
<idle>-0 [012] 46133.602259: pseries_lpar_idle: (c0000000000d43c8)
I should be more explicit that given my tracing configuration I would
expect to see doorbell events etc here e.g.
<idle>-0 [012] 46133.602086: doorbell_entry: pt_regs=0xc000000200e7fb50
<idle>-0 [012] 46133.602087: smp_ipi_demux_relaxed: (c0000000000530f8)
<idle>-0 [012] 46133.602088: scheduler_ipi: (c00000000015e4f8)
<idle>-0 [012] 46133.602091: sched_wakeup: cpuhp/12:70 [120] success=1 CPU:012
<idle>-0 [012] 46133.602092: sched_wakeup: migration/12:71 [0] success=1 CPU:012
<idle>-0 [012] 46133.602093: doorbell_exit: pt_regs=0xc000000200e7fb50
but instead cpu 12 goes to idle.
Another clue is that I've occasionaly provoked this warning:
WARNING: CPU: 7 PID: 9045 at arch/powerpc/kernel/irq.c:282 arch_local_irq_restore+0xdc/0x150
Modules linked in:
CPU: 7 PID: 9045 Comm: offliner Not tainted 5.3.0-rc2-00190-g9b123d1ea237-dirty #45
NIP: c00000000001d91c LR: c000000001988210 CTR: 0000000000334ee8
REGS: c00000000e19f390 TRAP: 0700 Not tainted (5.3.0-rc2-00190-g9b123d1ea237-dirty)
MSR: 800000010282b033 <SF,VEC,VSX,EE,FP,ME,IR,DR,RI,LE,TM[E]> CR: 44444424 XER: 20040000
CFAR: c00000000001d884 IRQMASK: 0
GPR00: c000000001988210 c00000000e19f620 c0000000032f6200 0000000000000000
GPR04: c00000000e589f10 0000000000000006 c00000000e19f664 c00000000395f260
GPR08: 000000000000003b 0000000000008000 0000000000000009 0000000000000000
GPR12: 0000000000000001 c00000001eca7780 000000000000005c 00000100106c7de0
GPR16: 0000000000000000 0000000000000000 00000000100c0a48 0000000000000001
GPR20: 00000000100c5748 00000001fc710000 0000000000000078 c000000003345c78
GPR24: c0000003ffd99a00 c000000003349de0 0000000000000000 c0000003fb086c10
GPR28: 0000000000000000 000000000000000f c0000003fb086c10 0000000000000000
NIP [c00000000001d91c] arch_local_irq_restore+0xdc/0x150
LR [c000000001988210] _raw_spin_unlock_irqrestore+0xa0/0xd0
Call Trace:
[c00000000e19f6a0] [c000000001988210] _raw_spin_unlock_irqrestore+0xa0/0xd0
[c00000000e19f6d0] [c0000000001be920] try_to_wake_up+0x330/0xf30
[c00000000e19f7a0] [c0000000001bf5b0] wake_up_q+0x70/0xc0
[c00000000e19f7e0] [c0000000002b5a08] cpu_stop_queue_work+0xc8/0x140
[c00000000e19f850] [c0000000002b5bac] queue_stop_cpus_work+0xdc/0x160
[c00000000e19f8b0] [c0000000002b5c98] __stop_cpus+0x68/0xc0
[c00000000e19f950] [c0000000002b65ec] stop_cpus+0x5c/0x90
[c00000000e19f9a0] [c0000000002b6924] stop_machine_cpuslocked+0x194/0x1f0
[c00000000e19fa10] [c00000000016c768] takedown_cpu+0x98/0x260
[c00000000e19fad0] [c00000000016cea4] cpuhp_invoke_callback+0x114/0xf40
[c00000000e19fb60] [c00000000017194c] _cpu_down+0x19c/0x320
[c00000000e19fbd0] [c00000000016ff58] do_cpu_down+0x68/0xb0
[c00000000e19fc10] [c000000000ccccd4] cpu_subsys_offline+0x24/0x40
[c00000000e19fc30] [c000000000cc2860] device_offline+0x100/0x140
[c00000000e19fc70] [c000000000cc2a00] online_store+0x70/0xf0
[c00000000e19fcb0] [c000000000cbcee8] dev_attr_store+0x38/0x60
[c00000000e19fcd0] [c00000000059c970] sysfs_kf_write+0x70/0xb0
[c00000000e19fd10] [c00000000059afa8] kernfs_fop_write+0xf8/0x280
[c00000000e19fd60] [c0000000004b436c] __vfs_write+0x3c/0x70
[c00000000e19fd80] [c0000000004b8700] vfs_write+0xd0/0x220
[c00000000e19fdd0] [c0000000004b8abc] ksys_write+0x7c/0x140
[c00000000e19fe20] [c00000000000bbd8] system_call+0x5c/0x68
i.e. in arch_local_irq_restore():
/*
* We should already be hard disabled here. We had bugs
* where that wasn't the case so let's dbl check it and
* warn if we are wrong. Only do that when IRQ tracing
* is enabled as mfmsr() can be costly.
*/
if (WARN_ON_ONCE(mfmsr() & MSR_EE))
__hard_irq_disable();
Anyway, I've proposed a fix:
https://patchwork.ozlabs.org/patch/1160572/