Great thanks.
Looks like that commit is in today's linux-next, so hopefully I won't
see any oopses in my boot tests overnight. If I do I'll let you know.
cheers
From: Sachin Sant <hidden> Date: 2017-01-31 11:00:38
Trimming the cc list.
quoted
I assume I should be worried?
=20
Thanks for the report. No need to worry, the bug has existed for a
while, this patch just turns on the warning ;-)
=20
The following commit queued up in tip/sched/core should fix your
issues (assuming you see the same callstack on all your powerpc
machines):
=20
=
From: Mike Galbraith <hidden> Date: 2017-01-31 11:49:22
On Tue, 2017-01-31 at 16:30 +0530, Sachin Sant wrote:
Trimming the cc list.
=20
quoted
quoted
I assume I should be worried?
=20
Thanks for the report. No need to worry, the bug has existed for a
while, this patch just turns on the warning ;-)
=20
The following commit queued up in tip/sched/core should fix your
issues (assuming you see the same callstack on all your powerpc
machines):
=20
https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git/commit/?h=3Ds=
=20
I still see this warning with today=A2s next running inside PowerVM LPAR
on a POWER8 box. The stack trace is different from what Michael had
reported.
=20
Easiest way to recreate this is to Online/offline cpu=A2s.
From: Ross Zwisler <hidden> Date: 2017-01-31 17:24:24
On Tue, Jan 31, 2017 at 4:48 AM, Mike Galbraith [off-list ref] wrote:
On Tue, 2017-01-31 at 16:30 +0530, Sachin Sant wrote:
quoted
Trimming the cc list.
quoted
quoted
I assume I should be worried?
Thanks for the report. No need to worry, the bug has existed for a
while, this patch just turns on the warning ;-)
The following commit queued up in tip/sched/core should fix your
issues (assuming you see the same callstack on all your powerpc
machines):
https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git/commit/?h=3D=
@@ -5670,13 +5672,6 @@ static void migrate_tasks(struct rq *dead_rq)continue;}-/*-*__migrate_task()mayreturnwithadifferent-*rq->lockheldandanewcookiein'rf',butweneed-*topreserverf::clock_update_flagsfor'dead_rq'.-*/-old_rf=rf;-/* Find suitable destination for @next, with force if needed. */dest_cpu=select_fallback_rq(dead_rq->cpu,next);
From: Peter Zijlstra <peterz@infradead.org> Date: 2017-02-03 08:53:56
On Fri, Feb 03, 2017 at 10:03:14AM +0530, Sachin Sant wrote:
quoted
On 02-Feb-2017, at 9:25 PM, Peter Zijlstra [off-list ref] wrote:
On Tue, Jan 31, 2017 at 10:22:47AM -0700, Ross Zwisler wrote:
quoted
On Tue, Jan 31, 2017 at 4:48 AM, Mike Galbraith [off-list ref] wrote:
quoted
On Tue, 2017-01-31 at 16:30 +0530, Sachin Sant wrote:
Could some of you test this? It seems to cure things in my (very)
limited testing.
I ran few cycles of cpu hot(un)plug tests. In most cases it works except one
where I ran into rcu stall:
[ 173.493453] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 173.493473] 8-...: (2 GPs behind) idle=006/140000000000000/0 softirq=0/0 fqs=2996
[ 173.493476] (detected by 0, t=6002 jiffies, g=885, c=884, q=6350)
Right, I actually saw that too, but I don't think that would be related
to my patch. I'll see if I can dig into this though, ought to get fixed
regardless.
Thanks for testing!
From: Sachin Sant <hidden> Date: 2017-02-03 11:04:09
<html><head></head><body dir="auto" style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" class="ApplePlainTextBody"><div class="ApplePlainTextBody"><br><blockquote type="cite"><blockquote type="cite">[ 173.493453] INFO: rcu_sched detected stalls on CPUs/tasks:<br>[ 173.493473] <span class="Apple-tab-span" style="white-space:pre"> </span>8-...: (2 GPs behind) idle=006/140000000000000/0 softirq=0/0 fqs=2996 <br>[ 173.493476] <span class="Apple-tab-span" style="white-space:pre"> </span>(detected by 0, t=6002 jiffies, g=885, c=884, q=6350)<br></blockquote><br>Right, I actually saw that too, but I don't think that would be related<br>to my patch. I'll see if I can dig into this though, ought to get fixed<br>regardless.<br><br></blockquote><br>Thanks. If required I can help test the fix.<br><br><blockquote type="cite">Thanks for testing!<br></blockquote><br></div></body></html>
From: Mike Galbraith <hidden> Date: 2017-02-03 13:00:17
On Fri, 2017-02-03 at 09:53 +0100, Peter Zijlstra wrote:
On Fri, Feb 03, 2017 at 10:03:14AM +0530, Sachin Sant wrote:
quoted
I ran few cycles of cpu hot(un)plug tests. In most cases it works except one
where I ran into rcu stall:
[ 173.493453] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 173.493473] > > > > 8-...: (2 GPs behind) idle=006/140000000000000/0 softirq=0/0 fqs=2996
[ 173.493476] > > > > (detected by 0, t=6002 jiffies, g=885, c=884, q=6350)
Right, I actually saw that too, but I don't think that would be related
to my patch. I'll see if I can dig into this though, ought to get fixed
regardless.
FWIW, I'm not seeing stalls/hangs while beating hotplug up in tip. (so
next grew a wart?)
-Mike
From: Peter Zijlstra <peterz@infradead.org> Date: 2017-02-03 13:38:00
On Fri, Feb 03, 2017 at 01:59:34PM +0100, Mike Galbraith wrote:
On Fri, 2017-02-03 at 09:53 +0100, Peter Zijlstra wrote:
quoted
On Fri, Feb 03, 2017 at 10:03:14AM +0530, Sachin Sant wrote:
quoted
quoted
I ran few cycles of cpu hot(un)plug tests. In most cases it works except one
where I ran into rcu stall:
[ 173.493453] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 173.493473] > > > > 8-...: (2 GPs behind) idle=006/140000000000000/0 softirq=0/0 fqs=2996
[ 173.493476] > > > > (detected by 0, t=6002 jiffies, g=885, c=884, q=6350)
Right, I actually saw that too, but I don't think that would be related
to my patch. I'll see if I can dig into this though, ought to get fixed
regardless.
FWIW, I'm not seeing stalls/hangs while beating hotplug up in tip. (so
next grew a wart?)
I've seen it on tip. It looks like hot unplug goes really slow when
there's running tasks on the CPU being taken down.
What I did was something like:
taskset -p $((1<<1)) $$
for ((i=0; i<20; i++)) do while :; do :; done & done
taskset -p $((1<<0)) $$
echo 0 > /sys/devices/system/cpu/cpu1/online
And with those 20 tasks stuck sucking cycles on CPU1, the unplug goes
_really_ slow and the RCU stall triggers. What I suspect happens is that
hotplug stops participating in the RCU state machine early, but only
tells RCU about it really late, and in between it gets suspicious it
takes too long.
I've yet to dig through the RCU code to figure out the exact sequence of
events, but found the above to be fairly reliable in triggering the
issue.
From: Mike Galbraith <hidden> Date: 2017-02-03 13:53:14
On Fri, 2017-02-03 at 14:37 +0100, Peter Zijlstra wrote:
On Fri, Feb 03, 2017 at 01:59:34PM +0100, Mike Galbraith wrote:
quoted
FWIW, I'm not seeing stalls/hangs while beating hotplug up in tip. (so
next grew a wart?)
I've seen it on tip. It looks like hot unplug goes really slow when
there's running tasks on the CPU being taken down.
What I did was something like:
taskset -p $((1<<1)) $$
for ((i=0; i<20; i++)) do while :; do :; done & done
taskset -p $((1<<0)) $$
echo 0 > /sys/devices/system/cpu/cpu1/online
And with those 20 tasks stuck sucking cycles on CPU1, the unplug goes
_really_ slow and the RCU stall triggers. What I suspect happens is that
hotplug stops participating in the RCU state machine early, but only
tells RCU about it really late, and in between it gets suspicious it
takes too long.
Ah. I wasn't doing a really hard pounding, just running a couple
instances of Steven's script. To beat hell out of it, I add futextest,
stockfish and a small kbuild on a big box.
-Mike
From: Paul E. McKenney <hidden> Date: 2017-02-03 15:44:59
On Fri, Feb 03, 2017 at 02:37:48PM +0100, Peter Zijlstra wrote:
On Fri, Feb 03, 2017 at 01:59:34PM +0100, Mike Galbraith wrote:
quoted
On Fri, 2017-02-03 at 09:53 +0100, Peter Zijlstra wrote:
quoted
On Fri, Feb 03, 2017 at 10:03:14AM +0530, Sachin Sant wrote:
quoted
quoted
I ran few cycles of cpu hot(un)plug tests. In most cases it works except one
where I ran into rcu stall:
[ 173.493453] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 173.493473] > > > > 8-...: (2 GPs behind) idle=006/140000000000000/0 softirq=0/0 fqs=2996
[ 173.493476] > > > > (detected by 0, t=6002 jiffies, g=885, c=884, q=6350)
Right, I actually saw that too, but I don't think that would be related
to my patch. I'll see if I can dig into this though, ought to get fixed
regardless.
FWIW, I'm not seeing stalls/hangs while beating hotplug up in tip. (so
next grew a wart?)
I've seen it on tip. It looks like hot unplug goes really slow when
there's running tasks on the CPU being taken down.
What I did was something like:
taskset -p $((1<<1)) $$
for ((i=0; i<20; i++)) do while :; do :; done & done
taskset -p $((1<<0)) $$
echo 0 > /sys/devices/system/cpu/cpu1/online
And with those 20 tasks stuck sucking cycles on CPU1, the unplug goes
_really_ slow and the RCU stall triggers. What I suspect happens is that
hotplug stops participating in the RCU state machine early, but only
tells RCU about it really late, and in between it gets suspicious it
takes too long.
I've yet to dig through the RCU code to figure out the exact sequence of
events, but found the above to be fairly reliable in triggering the
issue.
If you send me the full splat from the dmesg and the RCU portions of
.config, I will take a look. Is this new behavior, or a new test?
Thanx, Paul
From: Paul E. McKenney <hidden> Date: 2017-02-03 15:55:00
On Fri, Feb 03, 2017 at 07:44:57AM -0800, Paul E. McKenney wrote:
On Fri, Feb 03, 2017 at 02:37:48PM +0100, Peter Zijlstra wrote:
quoted
On Fri, Feb 03, 2017 at 01:59:34PM +0100, Mike Galbraith wrote:
quoted
On Fri, 2017-02-03 at 09:53 +0100, Peter Zijlstra wrote:
quoted
On Fri, Feb 03, 2017 at 10:03:14AM +0530, Sachin Sant wrote:
quoted
quoted
I ran few cycles of cpu hot(un)plug tests. In most cases it works except one
where I ran into rcu stall:
[ 173.493453] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 173.493473] > > > > 8-...: (2 GPs behind) idle=006/140000000000000/0 softirq=0/0 fqs=2996
[ 173.493476] > > > > (detected by 0, t=6002 jiffies, g=885, c=884, q=6350)
Right, I actually saw that too, but I don't think that would be related
to my patch. I'll see if I can dig into this though, ought to get fixed
regardless.
FWIW, I'm not seeing stalls/hangs while beating hotplug up in tip. (so
next grew a wart?)
I've seen it on tip. It looks like hot unplug goes really slow when
there's running tasks on the CPU being taken down.
What I did was something like:
taskset -p $((1<<1)) $$
for ((i=0; i<20; i++)) do while :; do :; done & done
taskset -p $((1<<0)) $$
echo 0 > /sys/devices/system/cpu/cpu1/online
And with those 20 tasks stuck sucking cycles on CPU1, the unplug goes
_really_ slow and the RCU stall triggers. What I suspect happens is that
hotplug stops participating in the RCU state machine early, but only
tells RCU about it really late, and in between it gets suspicious it
takes too long.
I've yet to dig through the RCU code to figure out the exact sequence of
events, but found the above to be fairly reliable in triggering the
issue.
If you send me the full splat from the dmesg and the RCU portions of
.config, I will take a look. Is this new behavior, or a new test?
If new behavior, I would be most suspicious of these commits in -rcu which
recently entered -tip:
19e4d983cda1 rcu: Place guard on rcu_all_qs() and rcu_note_context_switch() actions
913324b1364f rcu: Eliminate flavor scan in rcu_momentary_dyntick_idle()
fcdcfefafa45 rcu: Pull rcu_qs_ctr into rcu_dynticks structure
0919a0b7e7a5 rcu: Pull rcu_sched_qs_mask into rcu_dynticks structure
caa7c8e34293 rcu: Make rcu_note_context_switch() do deferred NOCB wakeups
41e4b159d516 rcu: Make rcu_all_qs() do deferred NOCB wakeups
b457a3356a68 rcu: Make call_rcu() do deferred NOCB wakeups
Does reverting any of these help?
Thanx, Paul
From: Sachin Sant <hidden> Date: 2017-02-06 06:23:31
quoted
quoted
I've seen it on tip. It looks like hot unplug goes really slow when
there's running tasks on the CPU being taken down.
=20
What I did was something like:
=20
taskset -p $((1<<1)) $$
for ((i=3D0; i<20; i++)) do while :; do :; done & done
=20
taskset -p $((1<<0)) $$
echo 0 > /sys/devices/system/cpu/cpu1/online
=20
And with those 20 tasks stuck sucking cycles on CPU1, the unplug =
goes
quoted
quoted
_really_ slow and the RCU stall triggers. What I suspect happens is =
that
quoted
quoted
hotplug stops participating in the RCU state machine early, but only
tells RCU about it really late, and in between it gets suspicious it
takes too long.
=20
I've yet to dig through the RCU code to figure out the exact =
sequence of
quoted
quoted
events, but found the above to be fairly reliable in triggering the
issue.
=20
quoted
If you send me the full splat from the dmesg and the RCU portions of
.config, I will take a look. Is this new behavior, or a new test?
=20
I have sent the required files to you via separate email.
If new behavior, I would be most suspicious of these commits in -rcu =
which
recently entered -tip:
=20
19e4d983cda1 rcu: Place guard on rcu_all_qs() and =
rcu_note_context_switch() actions
913324b1364f rcu: Eliminate flavor scan in =
rcu_momentary_dyntick_idle()
fcdcfefafa45 rcu: Pull rcu_qs_ctr into rcu_dynticks structure
0919a0b7e7a5 rcu: Pull rcu_sched_qs_mask into rcu_dynticks structure
caa7c8e34293 rcu: Make rcu_note_context_switch() do deferred NOCB =
wakeups
41e4b159d516 rcu: Make rcu_all_qs() do deferred NOCB wakeups
b457a3356a68 rcu: Make call_rcu() do deferred NOCB wakeups
=20
Does reverting any of these help?
I tried reverting the above commits. That does not help. I can still =
recreate the issue.
Thanks
-Sachin=
From: Paul E. McKenney <hidden> Date: 2017-02-06 15:10:48
On Mon, Feb 06, 2017 at 11:53:10AM +0530, Sachin Sant wrote:
quoted
quoted
quoted
I've seen it on tip. It looks like hot unplug goes really slow when
there's running tasks on the CPU being taken down.
What I did was something like:
taskset -p $((1<<1)) $$
for ((i=0; i<20; i++)) do while :; do :; done & done
taskset -p $((1<<0)) $$
echo 0 > /sys/devices/system/cpu/cpu1/online
And with those 20 tasks stuck sucking cycles on CPU1, the unplug goes
_really_ slow and the RCU stall triggers. What I suspect happens is that
hotplug stops participating in the RCU state machine early, but only
tells RCU about it really late, and in between it gets suspicious it
takes too long.
I've yet to dig through the RCU code to figure out the exact sequence of
events, but found the above to be fairly reliable in triggering the
issue.
quoted
If you send me the full splat from the dmesg and the RCU portions of
.config, I will take a look. Is this new behavior, or a new test?
I have sent the required files to you via separate email.
quoted
If new behavior, I would be most suspicious of these commits in -rcu which
recently entered -tip:
19e4d983cda1 rcu: Place guard on rcu_all_qs() and rcu_note_context_switch() actions
913324b1364f rcu: Eliminate flavor scan in rcu_momentary_dyntick_idle()
fcdcfefafa45 rcu: Pull rcu_qs_ctr into rcu_dynticks structure
0919a0b7e7a5 rcu: Pull rcu_sched_qs_mask into rcu_dynticks structure
caa7c8e34293 rcu: Make rcu_note_context_switch() do deferred NOCB wakeups
41e4b159d516 rcu: Make rcu_all_qs() do deferred NOCB wakeups
b457a3356a68 rcu: Make call_rcu() do deferred NOCB wakeups
Does reverting any of these help?
I tried reverting the above commits. That does not help. I can still recreate the issue.
Thank you for testing, Sachin!
Could you please try building and testing with CONFIG_RCU_BOOST=y?
You will need to enable CONFIG_RCU_EXPERT=y to see this Kconfig option.
Thanx, Paul
From: Paul E. McKenney <hidden> Date: 2017-02-06 15:14:05
On Mon, Feb 06, 2017 at 07:10:48AM -0800, Paul E. McKenney wrote:
On Mon, Feb 06, 2017 at 11:53:10AM +0530, Sachin Sant wrote:
quoted
quoted
quoted
quoted
I've seen it on tip. It looks like hot unplug goes really slow when
there's running tasks on the CPU being taken down.
What I did was something like:
taskset -p $((1<<1)) $$
for ((i=0; i<20; i++)) do while :; do :; done & done
taskset -p $((1<<0)) $$
echo 0 > /sys/devices/system/cpu/cpu1/online
And with those 20 tasks stuck sucking cycles on CPU1, the unplug goes
_really_ slow and the RCU stall triggers. What I suspect happens is that
hotplug stops participating in the RCU state machine early, but only
tells RCU about it really late, and in between it gets suspicious it
takes too long.
I've yet to dig through the RCU code to figure out the exact sequence of
events, but found the above to be fairly reliable in triggering the
issue.
quoted
If you send me the full splat from the dmesg and the RCU portions of
.config, I will take a look. Is this new behavior, or a new test?
I have sent the required files to you via separate email.
quoted
If new behavior, I would be most suspicious of these commits in -rcu which
recently entered -tip:
19e4d983cda1 rcu: Place guard on rcu_all_qs() and rcu_note_context_switch() actions
913324b1364f rcu: Eliminate flavor scan in rcu_momentary_dyntick_idle()
fcdcfefafa45 rcu: Pull rcu_qs_ctr into rcu_dynticks structure
0919a0b7e7a5 rcu: Pull rcu_sched_qs_mask into rcu_dynticks structure
caa7c8e34293 rcu: Make rcu_note_context_switch() do deferred NOCB wakeups
41e4b159d516 rcu: Make rcu_all_qs() do deferred NOCB wakeups
b457a3356a68 rcu: Make call_rcu() do deferred NOCB wakeups
Does reverting any of these help?
I tried reverting the above commits. That does not help. I can still recreate the issue.
Thank you for testing, Sachin!
Could you please try building and testing with CONFIG_RCU_BOOST=y?
You will need to enable CONFIG_RCU_EXPERT=y to see this Kconfig option.
Ah, but looking ahead to your .config file, you have CONFIG_PREEMPT=n,
which means boosting would not help and is not available in any case.
So it looks like there is a very long loop within an RCU read-side
critical section, and that this critical section needs to be broken
up a bit -- 21 seconds in pretty much any kind of critical section is
a bit excessive, after all.
Thanx, Paul
@@ -5670,13 +5672,6 @@ static void migrate_tasks(struct rq *dead_rq)continue;}-/*-*__migrate_task()mayreturnwithadifferent-*rq->lockheldandanewcookiein'rf',butweneed-*topreserverf::clock_update_flagsfor'dead_rq'.-*/-old_rf=rf;-/* Find suitable destination for @next, with force if needed. */dest_cpu=select_fallback_rq(dead_rq->cpu,next);