Possible issue with commit 4961b6e11825?

Possible issue with commit 4961b6e11825?

[Paul E. McKenney]

Hello!

Are there any known issues with commit 4961b6e11825 (sched: core: Use
hrtimer_start[_expires]())?

The reason that I ask is that I am about 90% sure that an rcutorture
failure bisects to that commit.  I will be running more tests on
3497d206c4d9 (perf: core: Use hrtimer_start()), which is the predecessor
of 4961b6e11825, and which, unlike 4961b6e11825, passes a 12-hour
rcutorture test with scenario TREE03.  In contrast, 4961b6e11825 gets
131 RCU CPU stall warnings, 132 reports of one of RCU's grace-period
kthreads being starved, and 525 reports of one of rcutorture's kthreads
being starved.  Most of the test runs hang on shutdown, which is no
surprise if an RCU CPU stall is happening at about that time.

But perhaps 3497d206c4d9 was just getting lucky, hence additional testing
over the weekend.

Reproducing this takes some doing.  A multisocket x86 box with significant
background computation noise seems to be able to reproduce this with
high probability in a twelve-hour test.  I -can- make it happen on
a single-socket four-core system (eight hardware threads, and with
significant background computational noise), but I ran the test for
several days before seeing the first error.  In addition, the probability
of hitting this is greatly reduced when running the tests on the
multisocket x86 box without the background computational noise.
(I recently taught some IBMers about ppcmem and herd, and gave them
some problems to solve, which is where the background noise came from,
in case you were wondering.  An unexpected benefit from those tools!)

The starving of RCU's grace-period kthreads is quite surprising, as
diagnostics indicate that they are in a wait_event_interruptible_timeout()
with a three-jiffy timeout.  The starvation is not subtle: 21-second
starvation periods are quite common, and 84-second starvation periods
occur from time to time.  In addition, rcutorture goes idle every few
seconds in order to test ramp-up and ramp-down effects, which should rule
out starvation due to heavy load.  Besides, I never see any softlockup
warnings, which should appear in the heavy-load-starvation case.

The commit log for 4961b6e11825 is as follows:

	sched: core: Use hrtimer_start[_expires]()
	    
	hrtimer_start() now enforces a timer interrupt when an already
	expired timer is enqueued.
		        
	Get rid of the __hrtimer_start_range_ns() invocations and the
	loops around it.

Is it possible that I need to adjust RCU or rcutorture code to account
for these newly enforced timer interrupts?  Or is there a known bug with
this commit whose fix I need to apply when bisecting?  (There were two
other fixes that I needed to do this with, so I figured I should ask.)

							Thanx, Paul

Re: Possible issue with commit 4961b6e11825?

[Paul E. McKenney]

On Fri, Dec 04, 2015 at 03:20:22PM -0800, Paul E. McKenney wrote:
> Hello!
> 
> Are there any known issues with commit 4961b6e11825 (sched: core: Use
> hrtimer_start[_expires]())?
> 
> The reason that I ask is that I am about 90% sure that an rcutorture
> failure bisects to that commit.  I will be running more tests on
> 3497d206c4d9 (perf: core: Use hrtimer_start()), which is the predecessor
> of 4961b6e11825, and which, unlike 4961b6e11825, passes a 12-hour
> rcutorture test with scenario TREE03.  In contrast, 4961b6e11825 gets
> 131 RCU CPU stall warnings, 132 reports of one of RCU's grace-period
> kthreads being starved, and 525 reports of one of rcutorture's kthreads
> being starved.  Most of the test runs hang on shutdown, which is no
> surprise if an RCU CPU stall is happening at about that time.
> 
> But perhaps 3497d206c4d9 was just getting lucky, hence additional testing
> over the weekend.

And it was getting lucky.  In a set of 24 two-hour runs (triple parallel)
on an earlier commit (not 3497d206c4d9, no clue what I was thinking) got
me two failed runs, for a total of 49 reports of one of RCU's grace-period
kthreads being starved, no reports of rcutorture's kthreads being starved,
and no hangs on shutdown.  So much lower failure rate, but still failures.

At this point, I am a bit disgusted with bisection, so my next test cycle
(36 two-hour runs on a system capable of doing three concurrently) is on
the most recent -rcu, but with CPU hotplug disabled.  If that shows failures,
then I hammer 3497d206c4d9 hard.

Anyway, if you have any ideas as to what might be happening, please don't
keep them a secret!

							Thanx, Paul

Re: Possible issue with commit 4961b6e11825?

[Viresh Kumar]

On 05-12-15, 11:01, Paul E. McKenney wrote:
> And it was getting lucky.  In a set of 24 two-hour runs (triple parallel)
> on an earlier commit (not 3497d206c4d9, no clue what I was thinking) got
> me two failed runs, for a total of 49 reports of one of RCU's grace-period
> kthreads being starved, no reports of rcutorture's kthreads being starved,
> and no hangs on shutdown.  So much lower failure rate, but still failures.
> 
> At this point, I am a bit disgusted with bisection, so my next test cycle
> (36 two-hour runs on a system capable of doing three concurrently) is on
> the most recent -rcu, but with CPU hotplug disabled.  If that shows failures,
> then I hammer 3497d206c4d9 hard.
> 
> Anyway, if you have any ideas as to what might be happening, please don't
> keep them a secret!

I can be the least helpful here (based on knowledge), but I am not
able to find a reason for this diff in 3497d206c4d9:

-       if (!hrtimer_callback_running(hr))
-               __hrtimer_start_range_ns(hr, cpuctx->hrtimer_interval,
-                                        0, HRTIMER_MODE_REL_PINNED, 0);
+       hrtimer_start(hr, cpuctx->hrtimer_interval, HRTIMER_MODE_REL_PINNED);

The commit talks *only* about s/__hrtimer_start_range_ns/hrtimer_start
but not at all on why !hrtimer_callback_running(hr) was removed.
Perhaps there was a reason :)

-- 
viresh

Re: Possible issue with commit 4961b6e11825?

[Paul E. McKenney]

On Sun, Dec 06, 2015 at 08:06:47AM +0530, Viresh Kumar wrote:
> On 05-12-15, 11:01, Paul E. McKenney wrote:
> > And it was getting lucky.  In a set of 24 two-hour runs (triple parallel)
> > on an earlier commit (not 3497d206c4d9, no clue what I was thinking) got
> > me two failed runs, for a total of 49 reports of one of RCU's grace-period
> > kthreads being starved, no reports of rcutorture's kthreads being starved,
> > and no hangs on shutdown.  So much lower failure rate, but still failures.
> > 
> > At this point, I am a bit disgusted with bisection, so my next test cycle
> > (36 two-hour runs on a system capable of doing three concurrently) is on
> > the most recent -rcu, but with CPU hotplug disabled.  If that shows failures,
> > then I hammer 3497d206c4d9 hard.
> > 
> > Anyway, if you have any ideas as to what might be happening, please don't
> > keep them a secret!
> 
> I can be the least helpful here (based on knowledge), but I am not
> able to find a reason for this diff in 3497d206c4d9:
> 
> -       if (!hrtimer_callback_running(hr))
> -               __hrtimer_start_range_ns(hr, cpuctx->hrtimer_interval,
> -                                        0, HRTIMER_MODE_REL_PINNED, 0);
> +       hrtimer_start(hr, cpuctx->hrtimer_interval, HRTIMER_MODE_REL_PINNED);
> 
> The commit talks *only* about s/__hrtimer_start_range_ns/hrtimer_start
> but not at all on why !hrtimer_callback_running(hr) was removed.
> Perhaps there was a reason :)

It is quite possible that this commit was an innocent bystander.  I will
know more in about 16 hours after the current round of tests complete.
These hammer current -rcu, but with CPU hotplug Kconfig'ed out.

							Thanx, Paul

Re: Possible issue with commit 4961b6e11825?

[Paul E. McKenney]

On Sat, Dec 05, 2015 at 11:01:24AM -0800, Paul E. McKenney wrote:
> On Fri, Dec 04, 2015 at 03:20:22PM -0800, Paul E. McKenney wrote:
> > Hello!
> > 
> > Are there any known issues with commit 4961b6e11825 (sched: core: Use
> > hrtimer_start[_expires]())?
> > 
> > The reason that I ask is that I am about 90% sure that an rcutorture
> > failure bisects to that commit.  I will be running more tests on
> > 3497d206c4d9 (perf: core: Use hrtimer_start()), which is the predecessor
> > of 4961b6e11825, and which, unlike 4961b6e11825, passes a 12-hour
> > rcutorture test with scenario TREE03.  In contrast, 4961b6e11825 gets
> > 131 RCU CPU stall warnings, 132 reports of one of RCU's grace-period
> > kthreads being starved, and 525 reports of one of rcutorture's kthreads
> > being starved.  Most of the test runs hang on shutdown, which is no
> > surprise if an RCU CPU stall is happening at about that time.
> > 
> > But perhaps 3497d206c4d9 was just getting lucky, hence additional testing
> > over the weekend.
> 
> And it was getting lucky.  In a set of 24 two-hour runs (triple parallel)
> on an earlier commit (not 3497d206c4d9, no clue what I was thinking) got
> me two failed runs, for a total of 49 reports of one of RCU's grace-period
> kthreads being starved, no reports of rcutorture's kthreads being starved,
> and no hangs on shutdown.  So much lower failure rate, but still failures.
> 
> At this point, I am a bit disgusted with bisection, so my next test cycle
> (36 two-hour runs on a system capable of doing three concurrently) is on
> the most recent -rcu, but with CPU hotplug disabled.  If that shows failures,
> then I hammer 3497d206c4d9 hard.

And no failures on current -rcu with CPU hotplug disabled.  So this
seems to be specific to CPU hotplug.  So my next step is to fix some
remaining known CPU-hotplug issues in RCU.

And Thomas, when you get those CPU-hotplug patches ready, I have a testcase
for you!  ;-)

								Thanx, Paul

Re: Possible issue with commit 4961b6e11825?

[Frederic Weisbecker]

On Fri, Dec 04, 2015 at 03:20:22PM -0800, Paul E. McKenney wrote:
> Hello!
> 
> Are there any known issues with commit 4961b6e11825 (sched: core: Use
> hrtimer_start[_expires]())?
> 
> The reason that I ask is that I am about 90% sure that an rcutorture
> failure bisects to that commit.  I will be running more tests on
> 3497d206c4d9 (perf: core: Use hrtimer_start()), which is the predecessor
> of 4961b6e11825, and which, unlike 4961b6e11825, passes a 12-hour
> rcutorture test with scenario TREE03.  In contrast, 4961b6e11825 gets
> 131 RCU CPU stall warnings, 132 reports of one of RCU's grace-period
> kthreads being starved, and 525 reports of one of rcutorture's kthreads
> being starved.  Most of the test runs hang on shutdown, which is no
> surprise if an RCU CPU stall is happening at about that time.

I have no idea what the issue is but maybe you have the RCU stall backtrace
somewhere?

Re: Possible issue with commit 4961b6e11825?

[Paul E. McKenney]

On Mon, Dec 07, 2015 at 08:01:23PM +0100, Frederic Weisbecker wrote:
> On Fri, Dec 04, 2015 at 03:20:22PM -0800, Paul E. McKenney wrote:
> > Hello!
> > 
> > Are there any known issues with commit 4961b6e11825 (sched: core: Use
> > hrtimer_start[_expires]())?
> > 
> > The reason that I ask is that I am about 90% sure that an rcutorture
> > failure bisects to that commit.  I will be running more tests on
> > 3497d206c4d9 (perf: core: Use hrtimer_start()), which is the predecessor
> > of 4961b6e11825, and which, unlike 4961b6e11825, passes a 12-hour
> > rcutorture test with scenario TREE03.  In contrast, 4961b6e11825 gets
> > 131 RCU CPU stall warnings, 132 reports of one of RCU's grace-period
> > kthreads being starved, and 525 reports of one of rcutorture's kthreads
> > being starved.  Most of the test runs hang on shutdown, which is no
> > surprise if an RCU CPU stall is happening at about that time.
> 
> I have no idea what the issue is but maybe you have the RCU stall backtrace
> somewhere?

First, please note that this commit might well be an innocent bystander.

That said, I have lots and lots of them!  ;-)

They look like this:

[ 4135.979013] Call Trace:
[ 4135.979013]  [<ffffffff81336c77>] ? debug_smp_processor_id+0x17/0x20
[ 4135.979013]  [<ffffffff8100dffc>] ? default_idle+0xc/0xe0
[ 4135.979013]  [<ffffffff8100e76a>] ? arch_cpu_idle+0xa/0x10
[ 4135.979013]  [<ffffffff8108b0d7>] ? default_idle_call+0x27/0x30
[ 4135.979013]  [<ffffffff8108b3c4>] ? cpu_startup_entry+0x294/0x310
[ 4135.979013]  [<ffffffff81037aef>] ? start_secondary+0xef/0x100

Which says that they are in the idle loop, so the RCU grace-period
kthread should notice within six jiffies and post a quiescent state on
their behalf.  But the next line is like this:

[ 4135.979013] rcu_preempt kthread starved for 21024 jiffies! g102259 c102258 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1

Which says that RCU's grace-period kthread has not run for the full
duration of the stall (21 seconds), hence its failure to record other
tasks' quiescent states.  Its state is 0x1, which is TASK_INTERRUPTIBLE.
The last thing it did was wait either for all quiescent states to come in,
or for three jiffies to elapse (this is the "RCU_GP_WAIT_FQS(3)" above).
Given that 21024 is a bit larger than six (up to two rounds of RCU GP
kthread execution are required to notice the quiescent state), something
isn't quite right here.

The RCU GP kthread's stack is as follows:

[ 4135.979013] Call Trace:
[ 4135.979013]  [<ffffffff8189ae5a>] schedule+0x3a/0x90
[ 4135.979013]  [<ffffffff8189d608>] schedule_timeout+0x148/0x290
[ 4135.979013]  [<ffffffff810b3800>] ? trace_raw_output_itimer_expire+0x70/0x70
[ 4135.979013]  [<ffffffff810aea04>] rcu_gp_kthread+0x934/0x1010
[ 4135.979013]  [<ffffffff8108ae20>] ? prepare_to_wait_event+0xf0/0xf0
[ 4135.979013]  [<ffffffff810ae0d0>] ? rcu_barrier+0x20/0x20
[ 4135.979013]  [<ffffffff8106f4a4>] kthread+0xc4/0xe0
[ 4135.979013]  [<ffffffff8106f3e0>] ? kthread_create_on_node+0x170/0x170
[ 4135.979013]  [<ffffffff8189ea1f>] ret_from_fork+0x3f/0x70
[ 4135.979013]  [<ffffffff8106f3e0>] ? kthread_create_on_node+0x170/0x170

So it looks to be waiting with a timeout.

Which was why I got excited when my bisection appeared to converge on
timer-related commit.  Except that further testing found failures prior
to that commit, though arguably happening at a much lower rate.

I later learned that even the current kernel runs with no stalls if CPU
hotplug is disabled.  So now I am wondering if there is some race that
can happen when trying to awaken a task that last ran on a CPU that is
just now in the process of going online.  Or that is just in the process
of coming online, for that matter.

Hey, you asked!  ;-)

							Thanx, Paul