Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17

["Paul E. McKenney" <paulmck@linux.vnet.ibm.com>]

On Sat, Mar 26, 2016 at 12:29:31PM +0000, Mathieu Desnoyers wrote:
> ----- On Mar 25, 2016, at 5:46 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com wrote:
> 
> > On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote:
> >> Hi  Paul,
> >> 
> >> On 2016-03-23, Paul E. McKenney wrote:
> >> > Please boot with the following parameters:
> >> > 
> >> > 	rcu_tree.rcu_kick_kthreads ftrace
> >> > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi
> >> 
> >> With these parameters I expected more details to show up in the kernel logs but
> >> cannot find any. Even so, today I left the machine running again and when this
> >> happened I think I was able to capture the trace data for the event. Please
> >> find attached the trace information for the kernel message below. Since the
> >> complete trace file is very big I trimmed it to show the time around this event
> >> - hopefully this will contain the information you need. I would also like to
> >> provide some additional information. The system on which I see these events had
> >> a time that was _very_ wrong. I noticed that this issue occurs when
> >> system-timesynd was one of the tasks calling the functions of interest to your
> >> tracing and am wondering if a very out of sync time in process of being
> >> corrected could be the cause of this issue? As an experiment I ensured the
> >> system time was accurate before leaving the system idle overnight and I did not
> >> see the issue the next morning.
> > 
> > Ah!  Yes, a sudden jump in time or a disagreement about the time among
> > different components of the system can definitely cause these symptoms.
> > We have sometimes seen these problems occur when a pair of CPUs have
> > wildly different ideas about what time it is, for example.  Please let
> > me know how it goes.
> > 
> > Also, in your trace, there are no sched_waking events for the rcu_preempt
> > process that are not immediately followed by sched_wakeup, so your trace
> > isn't showing the problem that I am seeing.
> 
> This is interesting.
> 
> Perhaps we could try with those commits reverted ?
> 
> commit e3baac47f0e82c4be632f4f97215bb93bf16b342
> Author: Peter Zijlstra <peterz@infradead.org>
> Date:   Wed Jun 4 10:31:18 2014 -0700
> 
>     sched/idle: Optimize try-to-wake-up IPI
> 
> commit fd99f91aa007ba255aac44fe6cf21c1db398243a
> Author: Peter Zijlstra <peterz@infradead.org>
> Date:   Wed Apr 9 15:35:08 2014 +0200
> 
>     sched/idle: Avoid spurious wakeup IPIs
> 
> They appeared in 3.16.

At this point, I am up for trying pretty much anything.  ;-)

Will give it a go.

							Thanx, Paul

> Thanks,
> 
> Mathieu
> 
> > 
> > Still beating up on my stress test, which is not yet proving to be all
> > that stressful.  :-/
> > 
> >							Thanx, Paul
> > 
> >> [  957.396537] INFO: rcu_preempt detected stalls on CPUs/tasks:
> >> [  957.399933]  1-...: (0 ticks this GP) idle=4d6/0/0 softirq=6311/6311 fqs=0
> >> [  957.403661]  (detected by 0, t=60002 jiffies, g=3583, c=3582, q=47)
> >> [  957.407227] Task dump for CPU 1:
> >> [  957.409964] swapper/1       R  running task        0     0      1 0x00200000
> >> [  957.413770]  0000039daa9a7eb9 ffff8801785cfed0 ffffffff818af34c
> >> ffff880100000000
> >> [  957.417696]  0000000600000003 ffff8801785d0000 ffff880072f9ea00
> >> ffffffff822dcf80
> >> [  957.421631]  ffff8801785cc000 ffff8801785cc000 ffff8801785cfee0
> >> ffffffff818af597
> >> [  957.425562] Call Trace:
> >> [  957.428124]  [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310
> >> [  957.431713]  [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20
> >> [  957.435122]  [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40
> >> [  957.438467]  [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360
> >> [  957.441949]  [<ffffffff8108c864>] ? start_secondary+0x114/0x140
> >> [  957.445378] rcu_preempt kthread starved for 60002 jiffies! g3583 c3582 f0x0
> >> RCU_GP_WAIT_FQS(3) ->state=0x1
> >> [  957.449834] rcu_preempt     S ffff8801785b7d68     0     7      2 0x00000000
> >> [  957.453579]  ffff8801785b7d68 ffff88017dc8cc80 ffff88016fe6bb80
> >> ffff8801785abb80
> >> [  957.457428]  ffff8801785b8000 ffff8801785b7da0 ffff88017dc8cc80
> >> ffff88017dc8cc80
> >> [  957.461249]  0000000000000003 ffff8801785b7d80 ffffffff81ab03df
> >> 0000000100373021
> >> [  957.465055] Call Trace:
> >> [  957.467493]  [<ffffffff81ab03df>] schedule+0x3f/0xa0
> >> [  957.470613]  [<ffffffff81ab4397>] schedule_timeout+0x127/0x270
> >> [  957.473976]  [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120
> >> [  957.477387]  [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40
> >> [  957.480659]  [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70
> >> [  957.484123]  [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0
> >> [  957.487392]  [<ffffffff8112f856>] kthread+0xe6/0x100
> >> [  957.490470]  [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190
> >> [  957.493859]  [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70
> >> [  957.497044]  [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190
> >> 
> > > Reinette
> 
> -- 
> Mathieu Desnoyers
> EfficiOS Inc.
> http://www.efficios.com
>