Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1631502 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH 0/2] nohz: Deal with clock reprogram skipping issues v2 Frederic Weisbecker <fweisbec@gmail.com> - 2017-04-26 17:00 +0200
    Re: [PATCH 0/2] nohz: Deal with clock reprogram skipping issues v2 Ingo Molnar <mingo@kernel.org> - 2017-04-26 20:50 +0200
      Re: [PATCH 0/2] nohz: Deal with clock reprogram skipping issues v2 Frederic Weisbecker <fweisbec@gmail.com> - 2017-04-26 23:10 +0200

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

On Mon, Apr 24, 2017 at 04:45:23PM +0200, Ingo Molnar wrote:
> 
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> 
> > On Mon, Apr 24, 2017 at 10:08:35AM +0200, Ingo Molnar wrote:
> > > 
> > > * Frederic Weisbecker <fweisbec@gmail.com> 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;
 	}
 

[toc] | [next] | [standalone]

#1631665

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> On Mon, Apr 24, 2017 at 04:45:23PM +0200, Ingo Molnar wrote:
> > 
> > * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> > 
> > > On Mon, Apr 24, 2017 at 10:08:35AM +0200, Ingo Molnar wrote:
> > > > 
> > > > * Frederic Weisbecker <fweisbec@gmail.com> 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

Sorry, don't have the time for extensive traces this close to the merge window - 
but are you sure you cannot reproduce it?

The warning popped up on all 3 test systems I tried (two Intel servers, one AMD 
server), and it also hit Mike's server - with a fairly regular distro-ish config.

Thanks,

	Ingo

[toc] | [prev] | [next] | [standalone]

#1631726

On Wed, Apr 26, 2017 at 08:49:13PM +0200, Ingo Molnar wrote:
> Sorry, don't have the time for extensive traces this close to the merge window - 
> but are you sure you cannot reproduce it?
> 
> The warning popped up on all 3 test systems I tried (two Intel servers, one AMD 
> server), and it also hit Mike's server - with a fairly regular distro-ish config.

Fair point, I'll try on other machines than my main one.

Thanks.

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web