lkml.org 
[lkml]   [2017]   [Apr]   [26]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
From
SubjectRe: [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;
}

\
 
 \ /
  Last update: 2017-04-26 16:56    [W:0.126 / U:1.436 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site