Messages in this thread Patch in this message | | | Date | Wed, 26 Apr 2017 16:55:15 +0200 | From | Frederic Weisbecker <> | Subject | 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; }
| |