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

Groups > linux.kernel > #1628293 > unrolled thread

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

Back to article view | Back to linux.kernel

Contents

  [PATCH 0/2] nohz: Deal with clock reprogram skipping issues v2 Frederic Weisbecker <fweisbec@gmail.com> - 2017-04-21 16:10 +0200
    Re: [PATCH 0/2] nohz: Deal with clock reprogram skipping issues v2 Frederic Weisbecker <fweisbec@gmail.com> - 2017-04-24 16:10 +0200
      [tip:timers/urgent] nohz: Print more debug info in  tick_nohz_stop_sched_tick() tip-bot for Frederic Weisbecker <tipbot@zytor.com> - 2017-04-24 19:10 +0200
      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

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

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(-)

-- 
2.7.4

[toc] | [next] | [standalone]

#1629598

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);
 	}
 
 	/*

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

#1629796 — [tip:timers/urgent] nohz: Print more debug info in tick_nohz_stop_sched_tick()

Commit-ID:  098991fccfc7c0dd5fdfc6ed2ed965ad80f14be5
Gitweb:     http://git.kernel.org/tip/098991fccfc7c0dd5fdfc6ed2ed965ad80f14be5
Author:     Frederic Weisbecker <fweisbec@gmail.com>
AuthorDate: Mon, 24 Apr 2017 16:04:37 +0200
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Mon, 24 Apr 2017 16:27:09 +0200

nohz: Print more debug info in tick_nohz_stop_sched_tick()

Print more debug info when triggering this warning:

  > ------------[ cut here ]------------
  > WARNING: CPU: 0 PID: 0 at kernel/time/tick-sched.c:874 __tick_nohz_idle_enter+0x461/0x490

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: James Hartsock <hartsjc@redhat.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Pavel Machek <pavel@ucw.cz>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Rik van Riel <riel@redhat.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Tim Wright <tim@binbash.co.uk>
Link: http://lkml.kernel.org/r/20170424140436.GD21353@lerouge
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 kernel/time/tick-sched.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index be7ca4d..b2df684 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -789,6 +789,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);
 	}
 
 	/*

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

#1631502

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] | [prev] | [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