Re: [PATCH 0/2] nohz: Deal with clock reprogram skipping issues v2

[Frederic Weisbecker]

On Mon, Apr 24, 2017 at 04:45:23PM +0200, Ingo Molnar wrote:
> 
> * Frederic Weisbecker <fweisbec@xxxxxxxxx> wrote:
> 
> > On Mon, Apr 24, 2017 at 10:08:35AM +0200, Ingo Molnar wrote:
> > > 
> > > * Frederic Weisbecker <fweisbec@xxxxxxxxx> wrote:
> > > 
> > > > As suggested by Thomas Gleixner, the second patch now integrates
> > > > a fix in case the sanity check fails and the clockevent isn't programmed
> > > > as expected.
> > > > 
> > > > Frederic Weisbecker (2):
> > > >   nohz: Fix again collision between tick and other hrtimers
> > > >   tick: Make sure tick timer is active when bypassing reprogramming
> > > > 
> > > >  kernel/time/tick-sched.c | 33 ++++++++++++++++++++++++++++++---
> > > >  kernel/time/tick-sched.h |  2 ++
> > > >  2 files changed, 32 insertions(+), 3 deletions(-)
> > > 
> > > So I think one of these is causing a new warning on latest -tip:
> > > 
> > > [  333.341756] ------------[ cut here ]------------
> > > [  333.346404] WARNING: CPU: 0 PID: 0 at kernel/time/tick-sched.c:874 __tick_nohz_idle_enter+0x461/0x490
> > 
> > Oh I'll never be done with that bug :)
> > 
> > Ok I just booted your config with tip/master and didn't see the warning.
> > But the boot seem to be stalled some time after mounting the root fs.
> > 
> > Can you please try the following patch and tell me what it returns to you?
> > 
> > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > index c47d135..6d72e8b 100644
> > --- a/kernel/time/tick-sched.c
> > +++ b/kernel/time/tick-sched.c
> > @@ -872,6 +872,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> >  			goto out;
> >  
> >  		WARN_ON_ONCE(1);
> > +		printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
> >  	}
> >  
> 
> Here's what it prints:
> 
> [  707.251791] basemono: 706016000000 ts->next_tick: 693216000000 dev->next_event: 706016406127

So weird...

Ok I'm going to need serious traces. Can you please add this boot option?

    trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry

And please also apply the following (on top of tip/tmp.tmp), it would be interesting to see
the resulting trace file from the CPU where the warning triggers.

Thanks Ingo!

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index b2df684..b4a6dda 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -156,6 +156,7 @@ static void tick_sched_handle(struct tick_sched *ts, struct pt_regs *regs)
 		 * to the same deadline.
 		 */
 		ts->next_tick = 0;
+		trace_printk("ts->next_tick reset (tick)\n");
 	}
 #endif
 	update_process_times(user_mode(regs));
@@ -672,6 +673,7 @@ static void tick_nohz_restart(struct tick_sched *ts, ktime_t now)
 	 * cached clock deadline.
 	 */
 	ts->next_tick = 0;
+	trace_printk("ts->next_tick reset (tick restart)\n");
 }
 
 static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
@@ -789,6 +791,8 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 			goto out;
 
 		WARN_ON_ONCE(1);
+		trace_printk("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
+		tracing_stop();
 		printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
 	}
 
@@ -810,6 +814,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	}
 
 	ts->next_tick = tick;
+	trace_printk("ts->next_tick = %llu\n", ts->next_tick);
 
 	/*
 	 * If the expiration time == KTIME_MAX, then we simply stop
@@ -892,6 +897,7 @@ static bool can_stop_idle_tick(int cpu, struct tick_sched *ts)
 		 * deadline if it comes back online later.
 		 */
 		ts->next_tick = 0;
+		trace_printk("ts->next_tick reset (offline)\n");
 		return false;
 	}