From: Bharata B Rao <hidden> Date: 2021-06-24 15:55:26
Hi,
A PowerPC KVM guest gets the following BUG message when booting
linux-next-20210623:
smp: Bringing up secondary CPUs ...
BUG: scheduling while atomic: swapper/1/0/0x00000000
no locks held by swapper/1/0.
Modules linked in:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.13.0-rc7-next-20210623
Call Trace:
[c00000000ae5bc20] [c000000000badc64] dump_stack_lvl+0x98/0xe0 (unreliable)
[c00000000ae5bc60] [c000000000210200] __schedule_bug+0xb0/0xe0
[c00000000ae5bcd0] [c000000001609e28] __schedule+0x1788/0x1c70
[c00000000ae5be20] [c00000000160a8cc] schedule_idle+0x3c/0x70
[c00000000ae5be50] [c00000000022984c] do_idle+0x2bc/0x420
[c00000000ae5bf00] [c000000000229d88] cpu_startup_entry+0x38/0x40
[c00000000ae5bf30] [c0000000000666c0] start_secondary+0x290/0x2a0
[c00000000ae5bf90] [c00000000000be54] start_secondary_prolog+0x10/0x14
<The above repeats for all the secondary CPUs>
smp: Brought up 2 nodes, 16 CPUs
numa: Node 0 CPUs: 0-7
numa: Node 1 CPUs: 8-15
This seems to have started from next-20210521 and isn't seen on
next-20210511.
Regards,
Bharata.
* Bharata B Rao [off-list ref] [2021-06-24 21:25:09]:
A PowerPC KVM guest gets the following BUG message when booting
linux-next-20210623:
smp: Bringing up secondary CPUs ...
BUG: scheduling while atomic: swapper/1/0/0x00000000
no locks held by swapper/1/0.
Modules linked in:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.13.0-rc7-next-20210623
Call Trace:
[c00000000ae5bc20] [c000000000badc64] dump_stack_lvl+0x98/0xe0 (unreliable)
[c00000000ae5bc60] [c000000000210200] __schedule_bug+0xb0/0xe0
[c00000000ae5bcd0] [c000000001609e28] __schedule+0x1788/0x1c70
[c00000000ae5be20] [c00000000160a8cc] schedule_idle+0x3c/0x70
[c00000000ae5be50] [c00000000022984c] do_idle+0x2bc/0x420
[c00000000ae5bf00] [c000000000229d88] cpu_startup_entry+0x38/0x40
[c00000000ae5bf30] [c0000000000666c0] start_secondary+0x290/0x2a0
[c00000000ae5bf90] [c00000000000be54] start_secondary_prolog+0x10/0x14
<The above repeats for all the secondary CPUs>
smp: Brought up 2 nodes, 16 CPUs
numa: Node 0 CPUs: 0-7
numa: Node 1 CPUs: 8-15
This seems to have started from next-20210521 and isn't seen on
next-20210511.
Bharata,
I think the regression is due to Commit f1a0a376ca0c ("sched/core:
Initialize the idle task with preemption disabled")
Can you please try with the above commit reverted?
--
Thanks and Regards
Srikar Dronamraju
From: Bharata B Rao <hidden> Date: 2021-06-25 05:50:31
On Fri, Jun 25, 2021 at 11:16:08AM +0530, Srikar Dronamraju wrote:
* Bharata B Rao [off-list ref] [2021-06-24 21:25:09]:
quoted
A PowerPC KVM guest gets the following BUG message when booting
linux-next-20210623:
smp: Bringing up secondary CPUs ...
BUG: scheduling while atomic: swapper/1/0/0x00000000
no locks held by swapper/1/0.
Modules linked in:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.13.0-rc7-next-20210623
Call Trace:
[c00000000ae5bc20] [c000000000badc64] dump_stack_lvl+0x98/0xe0 (unreliable)
[c00000000ae5bc60] [c000000000210200] __schedule_bug+0xb0/0xe0
[c00000000ae5bcd0] [c000000001609e28] __schedule+0x1788/0x1c70
[c00000000ae5be20] [c00000000160a8cc] schedule_idle+0x3c/0x70
[c00000000ae5be50] [c00000000022984c] do_idle+0x2bc/0x420
[c00000000ae5bf00] [c000000000229d88] cpu_startup_entry+0x38/0x40
[c00000000ae5bf30] [c0000000000666c0] start_secondary+0x290/0x2a0
[c00000000ae5bf90] [c00000000000be54] start_secondary_prolog+0x10/0x14
<The above repeats for all the secondary CPUs>
smp: Brought up 2 nodes, 16 CPUs
numa: Node 0 CPUs: 0-7
numa: Node 1 CPUs: 8-15
This seems to have started from next-20210521 and isn't seen on
next-20210511.
Bharata,
I think the regression is due to Commit f1a0a376ca0c ("sched/core:
Initialize the idle task with preemption disabled")
Can you please try with the above commit reverted?
Yes, reverting that commit helps.
Regards,
Bharata.
From: Peter Zijlstra <peterz@infradead.org> Date: 2021-06-25 07:28:24
On Fri, Jun 25, 2021 at 11:16:08AM +0530, Srikar Dronamraju wrote:
* Bharata B Rao [off-list ref] [2021-06-24 21:25:09]:
quoted
A PowerPC KVM guest gets the following BUG message when booting
linux-next-20210623:
smp: Bringing up secondary CPUs ...
BUG: scheduling while atomic: swapper/1/0/0x00000000
'funny', your preempt_count is actually too low. The check here is for
preempt_count() == DISABLE_OFFSET (aka. 1 when PREEMPT=y), but you have
0.
quoted
no locks held by swapper/1/0.
Modules linked in:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.13.0-rc7-next-20210623
Call Trace:
[c00000000ae5bc20] [c000000000badc64] dump_stack_lvl+0x98/0xe0 (unreliable)
[c00000000ae5bc60] [c000000000210200] __schedule_bug+0xb0/0xe0
[c00000000ae5bcd0] [c000000001609e28] __schedule+0x1788/0x1c70
[c00000000ae5be20] [c00000000160a8cc] schedule_idle+0x3c/0x70
[c00000000ae5be50] [c00000000022984c] do_idle+0x2bc/0x420
[c00000000ae5bf00] [c000000000229d88] cpu_startup_entry+0x38/0x40
[c00000000ae5bf30] [c0000000000666c0] start_secondary+0x290/0x2a0
[c00000000ae5bf90] [c00000000000be54] start_secondary_prolog+0x10/0x14
<The above repeats for all the secondary CPUs>
smp: Brought up 2 nodes, 16 CPUs
numa: Node 0 CPUs: 0-7
numa: Node 1 CPUs: 8-15
This seems to have started from next-20210521 and isn't seen on
next-20210511.
Bharata,
I think the regression is due to Commit f1a0a376ca0c ("sched/core:
Initialize the idle task with preemption disabled")
So that extra preempt_disable() that got removed would've incremented it
to 1 and then things would've been fine.
Except.. Valentin changed things such that preempt_count() should've
been inittialized to 1, instead of 0, but for some raisin that didn't
stick.. what gives.
So we have init_idle(p) -> init_idle_preempt_count(p) ->
task_thread_info(p)->preempt_count = PREEMPT_DISABLED;
But somehow, by the time you're running start_secondary(), that's gotten
to be 0 again. Does DEBUG_PREEMPT give more clues?
From: Bharata B Rao <hidden> Date: 2021-06-25 08:53:37
On Fri, Jun 25, 2021 at 09:28:09AM +0200, Peter Zijlstra wrote:
On Fri, Jun 25, 2021 at 11:16:08AM +0530, Srikar Dronamraju wrote:
quoted
* Bharata B Rao [off-list ref] [2021-06-24 21:25:09]:
quoted
A PowerPC KVM guest gets the following BUG message when booting
linux-next-20210623:
smp: Bringing up secondary CPUs ...
BUG: scheduling while atomic: swapper/1/0/0x00000000
'funny', your preempt_count is actually too low. The check here is for
preempt_count() == DISABLE_OFFSET (aka. 1 when PREEMPT=y), but you have
0.
quoted
quoted
no locks held by swapper/1/0.
Modules linked in:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.13.0-rc7-next-20210623
Call Trace:
[c00000000ae5bc20] [c000000000badc64] dump_stack_lvl+0x98/0xe0 (unreliable)
[c00000000ae5bc60] [c000000000210200] __schedule_bug+0xb0/0xe0
[c00000000ae5bcd0] [c000000001609e28] __schedule+0x1788/0x1c70
[c00000000ae5be20] [c00000000160a8cc] schedule_idle+0x3c/0x70
[c00000000ae5be50] [c00000000022984c] do_idle+0x2bc/0x420
[c00000000ae5bf00] [c000000000229d88] cpu_startup_entry+0x38/0x40
[c00000000ae5bf30] [c0000000000666c0] start_secondary+0x290/0x2a0
[c00000000ae5bf90] [c00000000000be54] start_secondary_prolog+0x10/0x14
<The above repeats for all the secondary CPUs>
smp: Brought up 2 nodes, 16 CPUs
numa: Node 0 CPUs: 0-7
numa: Node 1 CPUs: 8-15
This seems to have started from next-20210521 and isn't seen on
next-20210511.
Bharata,
I think the regression is due to Commit f1a0a376ca0c ("sched/core:
Initialize the idle task with preemption disabled")
So that extra preempt_disable() that got removed would've incremented it
to 1 and then things would've been fine.
Except.. Valentin changed things such that preempt_count() should've
been inittialized to 1, instead of 0, but for some raisin that didn't
stick.. what gives.
So we have init_idle(p) -> init_idle_preempt_count(p) ->
task_thread_info(p)->preempt_count = PREEMPT_DISABLED;
But somehow, by the time you're running start_secondary(), that's gotten
to be 0 again. Does DEBUG_PREEMPT give more clues?
On Fri, Jun 25, 2021 at 11:16:08AM +0530, Srikar Dronamraju wrote:
quoted
Bharata,
I think the regression is due to Commit f1a0a376ca0c ("sched/core:
Initialize the idle task with preemption disabled")
So that extra preempt_disable() that got removed would've incremented it
to 1 and then things would've been fine.
Except.. Valentin changed things such that preempt_count() should've
been inittialized to 1, instead of 0, but for some raisin that didn't
stick.. what gives.
So we have init_idle(p) -> init_idle_preempt_count(p) ->
task_thread_info(p)->preempt_count = PREEMPT_DISABLED;
But somehow, by the time you're running start_secondary(), that's gotten
to be 0 again. Does DEBUG_PREEMPT give more clues?
Given the preempt_count isn't reset between hotplugs anymore, you might be
able to find the culprit with a hotplug cycle and ftrace with
trace_prempt_off and trace_preempt_on events (requires PREEMPT_TRACER
IIRC).
It's doable at boot time too, but that will mean sifting through many more
events than you'd like...
From: Peter Zijlstra <peterz@infradead.org> Date: 2021-06-25 10:17:57
On Fri, Jun 25, 2021 at 02:23:16PM +0530, Bharata B Rao wrote:
On Fri, Jun 25, 2021 at 09:28:09AM +0200, Peter Zijlstra wrote:
quoted
On Fri, Jun 25, 2021 at 11:16:08AM +0530, Srikar Dronamraju wrote:
quoted
* Bharata B Rao [off-list ref] [2021-06-24 21:25:09]:
quoted
A PowerPC KVM guest gets the following BUG message when booting
linux-next-20210623:
smp: Bringing up secondary CPUs ...
BUG: scheduling while atomic: swapper/1/0/0x00000000
'funny', your preempt_count is actually too low. The check here is for
preempt_count() == DISABLE_OFFSET (aka. 1 when PREEMPT=y), but you have
0.
quoted
quoted
no locks held by swapper/1/0.
Modules linked in:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.13.0-rc7-next-20210623
Call Trace:
[c00000000ae5bc20] [c000000000badc64] dump_stack_lvl+0x98/0xe0 (unreliable)
[c00000000ae5bc60] [c000000000210200] __schedule_bug+0xb0/0xe0
[c00000000ae5bcd0] [c000000001609e28] __schedule+0x1788/0x1c70
[c00000000ae5be20] [c00000000160a8cc] schedule_idle+0x3c/0x70
[c00000000ae5be50] [c00000000022984c] do_idle+0x2bc/0x420
[c00000000ae5bf00] [c000000000229d88] cpu_startup_entry+0x38/0x40
[c00000000ae5bf30] [c0000000000666c0] start_secondary+0x290/0x2a0
[c00000000ae5bf90] [c00000000000be54] start_secondary_prolog+0x10/0x14
<The above repeats for all the secondary CPUs>
smp: Brought up 2 nodes, 16 CPUs
numa: Node 0 CPUs: 0-7
numa: Node 1 CPUs: 8-15
This seems to have started from next-20210521 and isn't seen on
next-20210511.
Bharata,
I think the regression is due to Commit f1a0a376ca0c ("sched/core:
Initialize the idle task with preemption disabled")
So that extra preempt_disable() that got removed would've incremented it
to 1 and then things would've been fine.
Except.. Valentin changed things such that preempt_count() should've
been inittialized to 1, instead of 0, but for some raisin that didn't
stick.. what gives.
So we have init_idle(p) -> init_idle_preempt_count(p) ->
task_thread_info(p)->preempt_count = PREEMPT_DISABLED;
But somehow, by the time you're running start_secondary(), that's gotten
to be 0 again. Does DEBUG_PREEMPT give more clues?
PREEMPTION is off here.
You mean: CONFIG_PREEMPTION=n, what about CONFIG_PREEMPT_COUNT?
Because if both are =n, then I don't see how that warning could trigger.
in_atomic_preempt_off() would then result in prempt_count() == 0, and
per the print above, it *is* 0.
From: Bharata B Rao <hidden> Date: 2021-06-25 12:32:53
On Fri, Jun 25, 2021 at 12:16:52PM +0200, Peter Zijlstra wrote:
You mean: CONFIG_PREEMPTION=n, what about CONFIG_PREEMPT_COUNT?
Because if both are =n, then I don't see how that warning could trigger.
in_atomic_preempt_off() would then result in prempt_count() == 0, and
per the print above, it *is* 0.
CONFIG_PREEMPTION isn't set.
Also other PREEMPT related options are as under:
# CONFIG_PREEMPT_NONE is not set
CONFIG_PREEMPT_VOLUNTARY=y
# CONFIG_PREEMPT is not set
CONFIG_PREEMPT_COUNT=y
CONFIG_PREEMPT_NOTIFIERS=y
CONFIG_PREEMPTIRQ_TRACEPOINTS=y
# CONFIG_PREEMPTIRQ_DELAY_TEST is not set
Regards,
Bharata.