On Sun, 2017-04-30 at 06:20 +0200, Mike Galbraith wrote:
> On Sat, 2017-04-29 at 20:43 -0700, Paul E. McKenney wrote:
> > On Sun, Apr 30, 2017 at 03:21:58AM +0200, Mike Galbraith wrote:
> > > On Sat, 2017-04-29 at 14:45 -0700, Paul E. McKenney wrote:
> > > > On Sat, Apr 29, 2017 at 08:20:33PM +0200, Mike Galbraith wrote:
> > > > > On Sat, 2017-04-29 at 11:06 -0700, Paul E. McKenney wrote:
> > > > >
> > > > > > If someone will either repost a fresh series or point me at
> > > > > > exactly
> > > > > > the set of patches to use, I will run it through rcutorture
> > > > > > again.
> > > > >
> > > > > Patchlet is against x86-tip/master.today.
> > > >
> > > > So today's (as in Saturday April 29) x86-tip/master with the
> > > > following
> > > > patch applied?
> > >
> > > Yeah.
> >
> > OK, will fire it up once the current set of overnight tests
> > complete.
>
> I certainly don't want to discourage you from beating hell outta tip,
> just want to make sure you know that I'm seeing zero RCU woes, only
> late timer expiry (sharpening rocks/sticks to focus trace).
Ah, seems a cpu shutting down the tick can race with add_timer_on(),
leaving the timer stranded until some other event kicks the cpu awake.
<idle>-0 [025] d..4 92.087954: tmigr_group_set_cpu_active:
group=ffff88017d03d000 lvl=1 numa=-1 active=1 migrator=25 num_childs=8 parent=
(null) nextevt=125916000000 evtcpu=2
<idle>-0 [025] d..4 92.087956: tmigr_group_removeevt:
group=ffff88017d03d000 lvl=1 numa=-1 active=1 migrator=25 num_childs=8 parent=
(null) nextevt=125916000000 evtcpu=2
<idle>-0 [025] d..3 92.087956: tmigr_group_set_cpu_active:
group=ffff880179cd1000 lvl=0 numa=3 active=1 migrator=25 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [025] d..3 92.087957: tmigr_group_removeevt:
group=ffff880179cd1000 lvl=0 numa=3 active=1 migrator=25 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [025] d.h3 92.087959: hrtimer_cancel:
hrtimer=ffff880277455d20
<idle>-0 [025] d.h2 92.087959: hrtimer_expire_entry:
hrtimer=ffff880277455d20 function=tick_sched_timer now=91100168287
<idle>-0 [025] d.h2 92.087964: hrtimer_expire_exit:
hrtimer=ffff880277455d20
<idle>-0 [025] d.s3 92.087968: timer_cancel:
timer=ffffffff820dd640
<idle>-0 [025] ..s2 92.087969: timer_expire_entry:
timer=ffffffff820dd640 function=clocksource_watchdog now=4294915072
<idle>-0 [025] d.s4 92.087971: timer_start:
timer=ffffffff820dd640 function=clocksource_watchdog expires=4294915197
[timeout=125] cpu=26 idx=218 flags=
<idle>-0 [025] d.s3 92.087974: wake_up_idle_cpu: NO KICK 26 -
!set_nr_and_not_polling(rq->idle)
<idle>-0 [025] ..s2 92.087974: timer_expire_exit:
timer=ffffffff820dd640
<idle>-0 [025] .Ns2 92.087982: tmigr_handle_remote:
group=ffff880179cd1000 lvl=0 numa=3 active=1 migrator=25 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27 cpu=25
<idle>-0 [025] .Ns2 92.087982: tmigr_handle_remote:
group=ffff88017d03d000 lvl=1 numa=-1 active=1 migrator=25 num_childs=8 parent=
(null) nextevt=125916000000 evtcpu=2 cpu=25
<idle>-0 [025] dN.3 92.087995: hrtimer_start:
hrtimer=ffff880277455d20 function=tick_sched_timer expires=91104000000
softexpires=91104000000
<idle>-0 [026] dN.3 92.088009: tmigr_group_set_cpu_active:
group=ffff880179cd1000 lvl=0 numa=3 active=2 migrator=25 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [026] dN.3 92.088011: tmigr_group_removeevt:
group=ffff880179cd1000 lvl=0 numa=3 active=2 migrator=25 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [025] d..4 92.088016: tmigr_group_addevt:
group=ffff880179cd1000 lvl=0 numa=3 active=1 migrator=25 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [026] dN.3 92.088016: hrtimer_start:
hrtimer=ffff880277495d20 function=tick_sched_timer expires=91104000000
softexpires=91104000000
<idle>-0 [025] d..5 92.088017: tmigr_group_set_cpu_inactive:
group=ffff88017d03d000 lvl=1 numa=-1 active=1 migrator=26 num_childs=8 parent=
(null) nextevt=125916000000 evtcpu=2
<idle>-0 [025] d..4 92.088017: tmigr_group_set_cpu_inactive:
group=ffff880179cd1000 lvl=0 numa=3 active=1 migrator=26 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [025] d..2 92.088018: tick_stop: success=1
dependency=NONE
<idle>-0 [025] d..3 92.088018: hrtimer_cancel:
hrtimer=ffff880277455d20
<idle>-0 [025] d..3 92.088020: hrtimer_start:
hrtimer=ffff880277455d20 function=tick_sched_timer expires=125916000000
softexpires=125916000000
<idle>-0 [026] d..4 92.088022: tmigr_group_addevt:
group=ffff880179cd1000 lvl=0 numa=3 active=0 migrator=26 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [026] d..5 92.088023: tmigr_group_addevt:
group=ffff88017d03d000 lvl=1 numa=-1 active=0 migrator=26 num_childs=8 parent=
(null) nextevt=125916000000 evtcpu=2
<idle>-0 [026] d..5 92.088024: tmigr_group_set_cpu_inactive:
group=ffff88017d03d000 lvl=1 numa=-1 active=0 migrator=-1 num_childs=8 parent=
(null) nextevt=125916000000 evtcpu=2
<idle>-0 [026] d..4 92.088025: tmigr_group_set_cpu_inactive:
group=ffff880179cd1000 lvl=0 numa=3 active=0 migrator=-1 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [026] d..2 92.088025: tick_stop: success=1
dependency=NONE
<idle>-0 [026] d..3 92.088026: hrtimer_cancel:
hrtimer=ffff880277495d20
<idle>-0 [026] d..3 92.088027: hrtimer_start:
hrtimer=ffff880277495d20 function=tick_sched_timer expires=93148000000
softexpires=93148000000
<idle>-0 [026] d..4 94.135877: tmigr_group_set_cpu_active:
group=ffff88017d03d000 lvl=1 numa=-1 active=2 migrator=1 num_childs=8 parent=
(null) nextevt=316380000000 evtcpu=56
<idle>-0 [026] d..4 94.135879: tmigr_group_removeevt:
group=ffff88017d03d000 lvl=1 numa=-1 active=2 migrator=1 num_childs=8 parent=
(null) nextevt=316380000000 evtcpu=56
<idle>-0 [026] d..3 94.135879: tmigr_group_set_cpu_active:
group=ffff880179cd1000 lvl=0 numa=3 active=1 migrator=26 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [026] d..3 94.135880: tmigr_group_removeevt:
group=ffff880179cd1000 lvl=0 numa=3 active=1 migrator=26 num_childs=8
parent=ffff88017d03d000 nextevt=316380000000 evtcpu=27
<idle>-0 [026] d.h3 94.135881: hrtimer_cancel:
hrtimer=ffff880277495d20
<idle>-0 [026] d.h2 94.135882: hrtimer_expire_entry:
hrtimer=ffff880277495d20 function=tick_sched_timer now=93148247903
<idle>-0 [026] d.h2 94.136137: hrtimer_expire_exit:
hrtimer=ffff880277495d20
<idle>-0 [026] d.s3 94.136141: timer_cancel:
timer=ffffffff820dd640
<idle>-0 [026] ..s2 94.136141: timer_expire_entry:
timer=ffffffff820dd640 function=clocksource_watchdog now=4294915584
<idle>-0 [026] d.s4 94.136144: timer_start:
timer=ffffffff820dd640 function=clocksource_watchdog expires=4294915709
[timeout=125] cpu=27 idx=219 flags=
<idle>-0 [026] d.s3 94.136146: wake_up_idle_cpu: KICK 27
<idle>-0 [026] ..s1 94.136148: clocksource_watchdog: LATE by
387 ticks
