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

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

[Frederic Weisbecker]

Now that we've understood the issue that Pavel and Tim have reported,
here's the new version of 24b91e360ef521a2808771633d76ebc68bd5604b that
Linus reverted. I took extra care on CPU hotplug as well. Hopefully this
time the fix doesn't introduce a new bug. The second patch should warn
when such an issue arise.

Thanks.

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 | 28 ++++++++++++++++++++++++++--
 kernel/time/tick-sched.h |  2 ++
 2 files changed, 28 insertions(+), 2 deletions(-)

-- 
2.7.4

[PATCH 1/2] nohz: Fix again collision between tick and other hrtimers

[Frederic Weisbecker]

(This restores commit 24b91e360ef521a2808771633d76ebc68bd5604b that got
reverted by commit 558e8e27e73f53f8a512485be538b07115fe5f3c due to a
regression where CPUs spuriously stopped ticking. The issue happened
when a tick fired too early past its expected expiration: on IRQ exit
the tick was scheduled again to the same deadline but skipped
reprogramming because ts->next_tick still kept in cache the deadline.
This has been fixed now with resetting ts->next_tick from the tick
itself. Extra care has also been taken to prevent from obsolete values
throughout CPU hotplug operations.)

When the tick is stopped and an interrupt occurs afterward, we check on
that interrupt exit if the next tick needs to be rescheduled. If it
doesn't need any update, we don't want to do anything.

In order to check if the tick needs an update, we compare it against the
clockevent device deadline. Now that's a problem because the clockevent
device is at a lower level than the tick itself if it is implemented
on top of hrtimer.

Every hrtimer share this clockevent device. So comparing the next tick
deadline against the clockevent device deadline is wrong because the
device may be programmed for another hrtimer whose deadline collides
with the tick. As a result we may end up not reprogramming the tick
accidentally.

In a worst case scenario under full dynticks mode, the tick stops firing
as it is supposed to every 1hz, leaving /proc/stat stalled:

      Task in a full dynticks CPU
      ----------------------------

      * hrtimer A is queued 2 seconds ahead
      * the tick is stopped, scheduled 1 second ahead
      * tick fires 1 second later
      * on tick exit, nohz schedules the tick 1 second ahead but sees
        the clockevent device is already programmed to that deadline,
        fooled by hrtimer A, the tick isn't rescheduled.
      * hrtimer A is cancelled before its deadline
      * tick never fires again until an interrupt happens...

In order to fix this, store the next tick deadline to the tick_sched
local structure and reuse that value later to check whether we need to
reprogram the clock after an interrupt.

On the other hand, ts->sleep_length still wants to know about the next
clock event and not just the tick, so we want to improve the related
comment to avoid confusion.

Reported-and-tested-by: Tim Wright <tim@binbash.co.uk>
Reported-and-tested-by: Pavel Machek <pavel@ucw.cz>
Reported-by: James Hartsock <hartsjc@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Rik van Riel <riel@redhat.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: stable@vger.kernel.org
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/time/tick-sched.c | 26 ++++++++++++++++++++++++--
 kernel/time/tick-sched.h |  2 ++
 2 files changed, 26 insertions(+), 2 deletions(-)

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 7fe53be..502b320 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -150,6 +150,12 @@ static void tick_sched_handle(struct tick_sched *ts, struct pt_regs *regs)
 		touch_softlockup_watchdog_sched();
 		if (is_idle_task(current))
 			ts->idle_jiffies++;
+		/*
+		 * In case the current tick fired too early past its expected
+		 * expiration, make sure we don't bypass the next clock reprogramming
+		 * to the same deadline.
+		 */
+		ts->next_tick = 0;
 	}
 #endif
 	update_process_times(user_mode(regs));
@@ -660,6 +666,12 @@ static void tick_nohz_restart(struct tick_sched *ts, ktime_t now)
 		hrtimer_start_expires(&ts->sched_timer, HRTIMER_MODE_ABS_PINNED);
 	else
 		tick_program_event(hrtimer_get_expires(&ts->sched_timer), 1);
+
+	/*
+	 * Reset to make sure next tick stop doesn't get fooled by past
+	 * cached clock deadline.
+	 */
+	ts->next_tick = 0;
 }
 
 static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
@@ -771,7 +783,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	tick = expires;
 
 	/* Skip reprogram of event if its not changed */
-	if (ts->tick_stopped && (expires == dev->next_event))
+	if (ts->tick_stopped && (expires == ts->next_tick))
 		goto out;
 
 	/*
@@ -791,6 +803,8 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 		trace_tick_stop(1, TICK_DEP_MASK_NONE);
 	}
 
+	ts->next_tick = tick;
+
 	/*
 	 * If the expiration time == KTIME_MAX, then we simply stop
 	 * the tick timer.
@@ -806,7 +820,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	else
 		tick_program_event(tick, 1);
 out:
-	/* Update the estimated sleep length */
+	/*
+	 * Update the estimated sleep length until the next timer
+	 * (not only the tick).
+	 */
 	ts->sleep_length = ktime_sub(dev->next_event, now);
 	return tick;
 }
@@ -864,6 +881,11 @@ static bool can_stop_idle_tick(int cpu, struct tick_sched *ts)
 	if (unlikely(!cpu_online(cpu))) {
 		if (cpu == tick_do_timer_cpu)
 			tick_do_timer_cpu = TICK_DO_TIMER_NONE;
+		/*
+		 * Make sure the CPU doesn't get fooled by obsolete tick
+		 * deadline if it comes back online later.
+		 */
+		ts->next_tick = 0;
 		return false;
 	}
 
diff --git a/kernel/time/tick-sched.h b/kernel/time/tick-sched.h
index bf38226..075444e 100644
--- a/kernel/time/tick-sched.h
+++ b/kernel/time/tick-sched.h
@@ -27,6 +27,7 @@ enum tick_nohz_mode {
  *			timer is modified for nohz sleeps. This is necessary
  *			to resume the tick timer operation in the timeline
  *			when the CPU returns from nohz sleep.
+ * @next_tick:		Next tick to be fired when in dynticks mode.
  * @tick_stopped:	Indicator that the idle tick has been stopped
  * @idle_jiffies:	jiffies at the entry to idle for idle time accounting
  * @idle_calls:		Total number of idle calls
@@ -44,6 +45,7 @@ struct tick_sched {
 	unsigned long			check_clocks;
 	enum tick_nohz_mode		nohz_mode;
 	ktime_t				last_tick;
+	ktime_t				next_tick;
 	int				inidle;
 	int				tick_stopped;
 	unsigned long			idle_jiffies;
-- 
2.7.4

[PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Frederic Weisbecker]

So far we have run into too much troubles with the optimization path
that skips reprogramming the clock on IRQ exit when the expiration
deadline hasn't changed. If by accident the cached deadline happens to
be out of sync with the hardware deadline, the buggy result and its
cause are hard to investigate. So lets detect and warn about the issue
early.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Tim Wright <tim@binbash.co.uk>
Cc: Pavel Machek <pavel@ucw.cz>
Cc: James Hartsock <hartsjc@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Rik van Riel <riel@redhat.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@kernel.org>
---
 kernel/time/tick-sched.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 502b320..eb1366e 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -783,8 +783,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	tick = expires;
 
 	/* Skip reprogram of event if its not changed */
-	if (ts->tick_stopped && (expires == ts->next_tick))
+	if (ts->tick_stopped && (expires == ts->next_tick)) {
+		WARN_ON_ONCE(dev->next_event > ts->next_tick);
 		goto out;
+	}
 
 	/*
 	 * nohz_stop_sched_tick can be called several times before
-- 
2.7.4

Re: [PATCH 1/2] nohz: Fix again collision between tick and other hrtimers

[Rik van Riel]

On Thu, 2017-04-20 at 17:30 +0200, Frederic Weisbecker wrote:
> (This restores commit 24b91e360ef521a2808771633d76ebc68bd5604b that
> got
> reverted by commit 558e8e27e73f53f8a512485be538b07115fe5f3c due to a
> regression where CPUs spuriously stopped ticking. The issue happened
> when a tick fired too early past its expected expiration: on IRQ exit
> the tick was scheduled again to the same deadline but skipped
> reprogramming because ts->next_tick still kept in cache the deadline.
> This has been fixed now with resetting ts->next_tick from the tick
> itself. Extra care has also been taken to prevent from obsolete
> values
> throughout CPU hotplug operations.)
> 
Acked-by: Rik van Riel <riel@redhat.com>

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Rik van Riel]

On Thu, 2017-04-20 at 17:30 +0200, Frederic Weisbecker wrote:
> So far we have run into too much troubles with the optimization path
> that skips reprogramming the clock on IRQ exit when the expiration
> deadline hasn't changed. If by accident the cached deadline happens
> to
> be out of sync with the hardware deadline, the buggy result and its
> cause are hard to investigate. So lets detect and warn about the
> issue
> early.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Tim Wright <tim@binbash.co.uk>
> Cc: Pavel Machek <pavel@ucw.cz>
> Cc: James Hartsock <hartsjc@redhat.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Rik van Riel <riel@redhat.com>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Ingo Molnar <mingo@kernel.org>

Acked-by: Rik van Riel <riel@redhat.com>

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Thomas Gleixner]

On Thu, 20 Apr 2017, Frederic Weisbecker wrote:

> So far we have run into too much troubles with the optimization path
> that skips reprogramming the clock on IRQ exit when the expiration
> deadline hasn't changed. If by accident the cached deadline happens to
> be out of sync with the hardware deadline, the buggy result and its
> cause are hard to investigate. So lets detect and warn about the issue
> early.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Tim Wright <tim@binbash.co.uk>
> Cc: Pavel Machek <pavel@ucw.cz>
> Cc: James Hartsock <hartsjc@redhat.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Rik van Riel <riel@redhat.com>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Ingo Molnar <mingo@kernel.org>
> ---
>  kernel/time/tick-sched.c | 4 +++-
>  1 file changed, 3 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> index 502b320..eb1366e 100644
> --- a/kernel/time/tick-sched.c
> +++ b/kernel/time/tick-sched.c
> @@ -783,8 +783,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
>  	tick = expires;
>  
>  	/* Skip reprogram of event if its not changed */
> -	if (ts->tick_stopped && (expires == ts->next_tick))
> +	if (ts->tick_stopped && (expires == ts->next_tick)) {
> +		WARN_ON_ONCE(dev->next_event > ts->next_tick);

What about handling it proper ? dev->next_event might be KTIME_MAX,
i.e. no more event for the next 500+ years.

Thanks,

	tglx

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Frederic Weisbecker]

On Thu, Apr 20, 2017 at 07:56:22PM +0200, Thomas Gleixner wrote:
> On Thu, 20 Apr 2017, Frederic Weisbecker wrote:
> 
> > So far we have run into too much troubles with the optimization path
> > that skips reprogramming the clock on IRQ exit when the expiration
> > deadline hasn't changed. If by accident the cached deadline happens to
> > be out of sync with the hardware deadline, the buggy result and its
> > cause are hard to investigate. So lets detect and warn about the issue
> > early.
> > 
> > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> > Cc: Tim Wright <tim@binbash.co.uk>
> > Cc: Pavel Machek <pavel@ucw.cz>
> > Cc: James Hartsock <hartsjc@redhat.com>
> > Cc: Peter Zijlstra <peterz@infradead.org>
> > Cc: Rik van Riel <riel@redhat.com>
> > Cc: Thomas Gleixner <tglx@linutronix.de>
> > Cc: Ingo Molnar <mingo@kernel.org>
> > ---
> >  kernel/time/tick-sched.c | 4 +++-
> >  1 file changed, 3 insertions(+), 1 deletion(-)
> > 
> > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > index 502b320..eb1366e 100644
> > --- a/kernel/time/tick-sched.c
> > +++ b/kernel/time/tick-sched.c
> > @@ -783,8 +783,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> >  	tick = expires;
> >  
> >  	/* Skip reprogram of event if its not changed */
> > -	if (ts->tick_stopped && (expires == ts->next_tick))
> > +	if (ts->tick_stopped && (expires == ts->next_tick)) {
> > +		WARN_ON_ONCE(dev->next_event > ts->next_tick);
> 
> What about handling it proper ? dev->next_event might be KTIME_MAX,
> i.e. no more event for the next 500+ years.

I thought I handled this case, what I'm I missing?

> Thanks,
> 
> 	tglx

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Thomas Gleixner]

On Thu, 20 Apr 2017, Frederic Weisbecker wrote:
> On Thu, Apr 20, 2017 at 07:56:22PM +0200, Thomas Gleixner wrote:
> > >  	/* Skip reprogram of event if its not changed */
> > > -	if (ts->tick_stopped && (expires == ts->next_tick))
> > > +	if (ts->tick_stopped && (expires == ts->next_tick)) {
> > > +		WARN_ON_ONCE(dev->next_event > ts->next_tick);
> > 
> > What about handling it proper ? dev->next_event might be KTIME_MAX,
> > i.e. no more event for the next 500+ years.
> 
> I thought I handled this case, what I'm I missing?

	if (ts->tick_stopped && (expires == ts->next_tick)) {
		WARN_ON_ONCE(dev->next_event > ts->next_tick);
		goto out;
	}

IOW, the WARN_ON yells in dmesg, but despite seing the wreckage it just
leaves it and goes out doing nothing.

Why can't you just do

	if (ts->tick_stopped && (expires == ts->next_tick)) {
	   	if (dev->next_event > ts->next_tick)) {
			WARN_ONCE();
			do_something_sensible();
		}		
		goto out;
	}

Hmm?

	tglx

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Frederic Weisbecker]

On Thu, Apr 20, 2017 at 09:40:12PM +0200, Thomas Gleixner wrote:
> On Thu, 20 Apr 2017, Frederic Weisbecker wrote:
> > On Thu, Apr 20, 2017 at 07:56:22PM +0200, Thomas Gleixner wrote:
> > > >  	/* Skip reprogram of event if its not changed */
> > > > -	if (ts->tick_stopped && (expires == ts->next_tick))
> > > > +	if (ts->tick_stopped && (expires == ts->next_tick)) {
> > > > +		WARN_ON_ONCE(dev->next_event > ts->next_tick);
> > > 
> > > What about handling it proper ? dev->next_event might be KTIME_MAX,
> > > i.e. no more event for the next 500+ years.
> > 
> > I thought I handled this case, what I'm I missing?
> 
> 	if (ts->tick_stopped && (expires == ts->next_tick)) {
> 		WARN_ON_ONCE(dev->next_event > ts->next_tick);
> 		goto out;
> 	}
> 
> IOW, the WARN_ON yells in dmesg, but despite seing the wreckage it just
> leaves it and goes out doing nothing.
> 
> Why can't you just do
> 
> 	if (ts->tick_stopped && (expires == ts->next_tick)) {
> 	   	if (dev->next_event > ts->next_tick)) {
> 			WARN_ONCE();
> 			do_something_sensible();
> 		}		
> 		goto out;
> 	}
> 
> Hmm?

Ah ok, right!

So something like this:

    if (ts->tick_stopped && (expires == ts->next_tick)) {
        if (likely(dev->next_event <= ts->next_tick))
            goto out;
        WARN_ON_ONCE(1);
    }

So that we fall down to clock reprogramming if the sanity check fails.

I'm resending the patches.

Thanks.

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Levin, Alexander (Sasha Levin)]

[-- Attachment #1: Type: text/plain, Size: 1345 bytes --]

On Wed, Jun 07, 2017 at 04:14:03PM +0200, Frederic Weisbecker wrote:
> On Wed, Jun 07, 2017 at 04:17:41AM +0000, Levin, Alexander (Sasha Levin) wrote:
> > > Thanks Sasha!
> > > 
> > > I couldn't reproduce it, that config boots fine on my kvm.
> > > Would you have the time to dump some traces for me?
> > > 
> > > I'd need you to add this boot option: trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry
> > > And boot your kernel with the below patch. This will dump the timer traces to your console.
> > > I would be very interested in the resulting console dump file.
> > 
> > Attached. Let me know if you need anything else.
> 
> Great! So now I can deduce that the problem doesn't come from the nohz code as
> ts->next_tick matches the hrtimer deadline. But the dev->next_event from the
> clockevent seems to be out of line.
> 
> Sorry to bother you again, but I'm chasing this bug for several weeks now and
> you're one of the rare person who can reproduce it. So I may need some more
> tracing details.

I take payment in beers ;)

But really, not a problem.

> Here is another version of the debugging patch (not a delta), I added more trace_printk,
> namely the places where we set this dev->next_event. Can you please apply the below and do
> the dump again?

Attached.

-- 

Thanks,
Sasha

[-- Attachment #2: log.txt.gz --]
[-- Type: application/gzip, Size: 46400 bytes --]

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Frederic Weisbecker]

On Wed, Jun 07, 2017 at 04:17:41AM +0000, Levin, Alexander (Sasha Levin) wrote:
> > Thanks Sasha!
> > 
> > I couldn't reproduce it, that config boots fine on my kvm.
> > Would you have the time to dump some traces for me?
> > 
> > I'd need you to add this boot option: trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry
> > And boot your kernel with the below patch. This will dump the timer traces to your console.
> > I would be very interested in the resulting console dump file.
> 
> Attached. Let me know if you need anything else.

Great! So now I can deduce that the problem doesn't come from the nohz code as
ts->next_tick matches the hrtimer deadline. But the dev->next_event from the
clockevent seems to be out of line.

Sorry to bother you again, but I'm chasing this bug for several weeks now and
you're one of the rare person who can reproduce it. So I may need some more
tracing details.

Here is another version of the debugging patch (not a delta), I added more trace_printk,
namely the places where we set this dev->next_event. Can you please apply the below and do
the dump again?

I'm adding a boot option as well for the stacktrace:

trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry trace_options=stacktrace

Thanks a lot!

diff --git a/kernel/time/clockevents.c b/kernel/time/clockevents.c
index 4237e07..e21e929 100644
--- a/kernel/time/clockevents.c
+++ b/kernel/time/clockevents.c
@@ -180,6 +180,7 @@ void clockevents_shutdown(struct clock_event_device *dev)
 {
 	clockevents_switch_state(dev, CLOCK_EVT_STATE_SHUTDOWN);
 	dev->next_event = KTIME_MAX;
+	trace_printk("dev->next_event: %llu\n", dev->next_event);
 }
 
 /**
@@ -214,6 +215,7 @@ static int clockevents_increase_min_delta(struct clock_event_device *dev)
 		printk_deferred(KERN_WARNING
 				"CE: Reprogramming failure. Giving up\n");
 		dev->next_event = KTIME_MAX;
+		trace_printk("dev->next_event: %llu\n", dev->next_event);
 		return -ETIME;
 	}
 
@@ -247,6 +249,7 @@ static int clockevents_program_min_delta(struct clock_event_device *dev)
 	for (i = 0;;) {
 		delta = dev->min_delta_ns;
 		dev->next_event = ktime_add_ns(ktime_get(), delta);
+		trace_printk("dev->next_event: %llu\n", dev->next_event);
 
 		if (clockevent_state_shutdown(dev))
 			return 0;
@@ -284,6 +287,7 @@ static int clockevents_program_min_delta(struct clock_event_device *dev)
 
 	delta = dev->min_delta_ns;
 	dev->next_event = ktime_add_ns(ktime_get(), delta);
+	trace_printk("dev->next_event: %llu\n", dev->next_event);
 
 	if (clockevent_state_shutdown(dev))
 		return 0;
@@ -316,6 +320,7 @@ int clockevents_program_event(struct clock_event_device *dev, ktime_t expires,
 	}
 
 	dev->next_event = expires;
+	trace_printk("dev->next_event: %llu\n", dev->next_event);
 
 	if (clockevent_state_shutdown(dev))
 		return 0;
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 2de9c55..ad1de28 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,
@@ -788,6 +790,11 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 		if (likely(dev->next_event <= ts->next_tick))
 			goto out;
 
+		trace_printk("basemono: %llu ts->next_tick: %llu dev->next_event: %llu timer->active: %d timer->expires: %llu\n",
+			    basemono, ts->next_tick, dev->next_event,
+			    hrtimer_active(&ts->sched_timer), hrtimer_get_expires(&ts->sched_timer));
+		tracing_stop();
+		ftrace_dump(DUMP_ORIG);
 		WARN_ON_ONCE(1);
 		printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu timer->active: %d timer->expires: %llu\n",
 			    basemono, ts->next_tick, dev->next_event,
@@ -812,6 +819,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
@@ -894,6 +902,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;
 	}
 
@@ -1202,8 +1211,10 @@ static enum hrtimer_restart tick_sched_timer(struct hrtimer *timer)
 	 */
 	if (regs)
 		tick_sched_handle(ts, regs);
-	else
+	else {
+		trace_printk("ts->next_tick reset (tick)\n");
 		ts->next_tick = 0;
+	}
 
 	/* No need to reprogram if we are in idle or full dynticks mode */
 	if (unlikely(ts->tick_stopped))

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Levin, Alexander (Sasha Levin)]

[-- Attachment #1: Type: text/plain, Size: 2361 bytes --]

On Tue, Jun 06, 2017 at 04:52:29PM +0200, Frederic Weisbecker wrote:
> On Sat, Jun 03, 2017 at 01:00:53PM +0000, Levin, Alexander (Sasha Levin) wrote:
> > On Sat, Jun 03, 2017 at 02:42:43PM +0200, Frederic Weisbecker wrote:
> > > On Sat, Jun 03, 2017 at 08:06:41AM +0000, Levin, Alexander (Sasha Levin) wrote:
> > > > On Fri, Apr 21, 2017 at 04:00:55PM +0200, Frederic Weisbecker wrote:
> > > > > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > > > > index 502b320..be7ca4d 100644
> > > > > --- a/kernel/time/tick-sched.c
> > > > > +++ b/kernel/time/tick-sched.c
> > > > > @@ -783,8 +783,13 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> > > > >  	tick = expires;
> > > > >  
> > > > >  	/* Skip reprogram of event if its not changed */
> > > > > -	if (ts->tick_stopped && (expires == ts->next_tick))
> > > > > -		goto out;
> > > > > +	if (ts->tick_stopped && (expires == ts->next_tick)) {
> > > > > +		/* Sanity check: make sure clockevent is actually programmed */
> > > > > +		if (likely(dev->next_event <= ts->next_tick))
> > > > > +			goto out;
> > > > > +
> > > > > +		WARN_ON_ONCE(1);
> > > > > +	}
> > > > 
> > > > I seem to be hitting that in a KVM vm, even without load (sometimes
> > > > right after boot):
> > > 
> > > Ah, can you tell me which tree you were using? Is it tip/master?
> > 
> > Its next-20170601: https://urldefense.proofpoint.com/v2/url?u=https-3A__git.kernel.org_pub_scm_linux_kernel_git_next_linux-2Dnext.git_commit_-3Fh-3Dnext-2D20170601-26id-3D3ab334ebe84e0dfd1cc3ea2fe77f5ce4406f7370&d=DwIBAg&c=udBTRvFvXC5Dhqg7UHpJlPps3mZ3LRxpb6__0PomBTQ&r=bUtaaC9mlBij4OjEG_D-KMy3t3Ka3bY06suGz7ewY7g&m=0ex_DoQxODGZtsXpFBMXf2fPbFxv2ogjY9fVReKqbpk&s=t0F0_37WnCEpxAZR6WD3d_Q4n0Lp_2HCNOx3b_iOGtI&e= 
> > 
> > > Can you give me its HEAD and your config file?
> > 
> > Attached config.
> 
> Thanks Sasha!
> 
> I couldn't reproduce it, that config boots fine on my kvm.
> Would you have the time to dump some traces for me?
> 
> I'd need you to add this boot option: trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry
> And boot your kernel with the below patch. This will dump the timer traces to your console.
> I would be very interested in the resulting console dump file.

Attached. Let me know if you need anything else.

-- 

Thanks,
Sasha

[-- Attachment #2: log.txt.gz --]
[-- Type: application/gzip, Size: 32672 bytes --]

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Frederic Weisbecker]

On Sat, Jun 03, 2017 at 01:00:53PM +0000, Levin, Alexander (Sasha Levin) wrote:
> On Sat, Jun 03, 2017 at 02:42:43PM +0200, Frederic Weisbecker wrote:
> > On Sat, Jun 03, 2017 at 08:06:41AM +0000, Levin, Alexander (Sasha Levin) wrote:
> > > On Fri, Apr 21, 2017 at 04:00:55PM +0200, Frederic Weisbecker wrote:
> > > > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > > > index 502b320..be7ca4d 100644
> > > > --- a/kernel/time/tick-sched.c
> > > > +++ b/kernel/time/tick-sched.c
> > > > @@ -783,8 +783,13 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> > > >  	tick = expires;
> > > >  
> > > >  	/* Skip reprogram of event if its not changed */
> > > > -	if (ts->tick_stopped && (expires == ts->next_tick))
> > > > -		goto out;
> > > > +	if (ts->tick_stopped && (expires == ts->next_tick)) {
> > > > +		/* Sanity check: make sure clockevent is actually programmed */
> > > > +		if (likely(dev->next_event <= ts->next_tick))
> > > > +			goto out;
> > > > +
> > > > +		WARN_ON_ONCE(1);
> > > > +	}
> > > 
> > > I seem to be hitting that in a KVM vm, even without load (sometimes
> > > right after boot):
> > 
> > Ah, can you tell me which tree you were using? Is it tip/master?
> 
> Its next-20170601: https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git/commit/?h=next-20170601&id=3ab334ebe84e0dfd1cc3ea2fe77f5ce4406f7370
> 
> > Can you give me its HEAD and your config file?
> 
> Attached config.

Thanks Sasha!

I couldn't reproduce it, that config boots fine on my kvm.
Would you have the time to dump some traces for me?

I'd need you to add this boot option: trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry
And boot your kernel with the below patch. This will dump the timer traces to your console.
I would be very interested in the resulting console dump file.

Thanks!

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 2de9c55..ad1de28 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,
@@ -788,6 +790,11 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 		if (likely(dev->next_event <= ts->next_tick))
 			goto out;
 
+		trace_printk("basemono: %llu ts->next_tick: %llu dev->next_event: %llu timer->active: %d timer->expires: %llu\n",
+			    basemono, ts->next_tick, dev->next_event,
+			    hrtimer_active(&ts->sched_timer), hrtimer_get_expires(&ts->sched_timer));
+		tracing_stop();
+		ftrace_dump(DUMP_ORIG);
 		WARN_ON_ONCE(1);
 		printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu timer->active: %d timer->expires: %llu\n",
 			    basemono, ts->next_tick, dev->next_event,
@@ -812,6 +819,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
@@ -894,6 +902,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;
 	}
 
@@ -1202,8 +1211,10 @@ static enum hrtimer_restart tick_sched_timer(struct hrtimer *timer)
 	 */
 	if (regs)
 		tick_sched_handle(ts, regs);
-	else
+	else {
+		trace_printk("ts->next_tick reset (tick)\n");
 		ts->next_tick = 0;
+	}
 
 	/* No need to reprogram if we are in idle or full dynticks mode */
 	if (unlikely(ts->tick_stopped))

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Levin, Alexander (Sasha Levin)]

[-- Attachment #1: Type: text/plain, Size: 1368 bytes --]

On Sat, Jun 03, 2017 at 02:42:43PM +0200, Frederic Weisbecker wrote:
> On Sat, Jun 03, 2017 at 08:06:41AM +0000, Levin, Alexander (Sasha Levin) wrote:
> > On Fri, Apr 21, 2017 at 04:00:55PM +0200, Frederic Weisbecker wrote:
> > > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > > index 502b320..be7ca4d 100644
> > > --- a/kernel/time/tick-sched.c
> > > +++ b/kernel/time/tick-sched.c
> > > @@ -783,8 +783,13 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> > >  	tick = expires;
> > >  
> > >  	/* Skip reprogram of event if its not changed */
> > > -	if (ts->tick_stopped && (expires == ts->next_tick))
> > > -		goto out;
> > > +	if (ts->tick_stopped && (expires == ts->next_tick)) {
> > > +		/* Sanity check: make sure clockevent is actually programmed */
> > > +		if (likely(dev->next_event <= ts->next_tick))
> > > +			goto out;
> > > +
> > > +		WARN_ON_ONCE(1);
> > > +	}
> > 
> > I seem to be hitting that in a KVM vm, even without load (sometimes
> > right after boot):
> 
> Ah, can you tell me which tree you were using? Is it tip/master?

Its next-20170601: https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git/commit/?h=next-20170601&id=3ab334ebe84e0dfd1cc3ea2fe77f5ce4406f7370

> Can you give me its HEAD and your config file?

Attached config.

-- 

Thanks,
Sasha

[-- Attachment #2: config-sasha.gz --]
[-- Type: application/gzip, Size: 31104 bytes --]

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Frederic Weisbecker]

On Sat, Jun 03, 2017 at 08:06:41AM +0000, Levin, Alexander (Sasha Levin) wrote:
> On Fri, Apr 21, 2017 at 04:00:55PM +0200, Frederic Weisbecker wrote:
> > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > index 502b320..be7ca4d 100644
> > --- a/kernel/time/tick-sched.c
> > +++ b/kernel/time/tick-sched.c
> > @@ -783,8 +783,13 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> >  	tick = expires;
> >  
> >  	/* Skip reprogram of event if its not changed */
> > -	if (ts->tick_stopped && (expires == ts->next_tick))
> > -		goto out;
> > +	if (ts->tick_stopped && (expires == ts->next_tick)) {
> > +		/* Sanity check: make sure clockevent is actually programmed */
> > +		if (likely(dev->next_event <= ts->next_tick))
> > +			goto out;
> > +
> > +		WARN_ON_ONCE(1);
> > +	}
> 
> I seem to be hitting that in a KVM vm, even without load (sometimes
> right after boot):

Ah, can you tell me which tree you were using? Is it tip/master?
Can you give me its HEAD and your config file?

Thanks

Re: [PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Levin, Alexander (Sasha Levin)]

On Fri, Apr 21, 2017 at 04:00:55PM +0200, Frederic Weisbecker wrote:
> diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> index 502b320..be7ca4d 100644
> --- a/kernel/time/tick-sched.c
> +++ b/kernel/time/tick-sched.c
> @@ -783,8 +783,13 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
>  	tick = expires;
>  
>  	/* Skip reprogram of event if its not changed */
> -	if (ts->tick_stopped && (expires == ts->next_tick))
> -		goto out;
> +	if (ts->tick_stopped && (expires == ts->next_tick)) {
> +		/* Sanity check: make sure clockevent is actually programmed */
> +		if (likely(dev->next_event <= ts->next_tick))
> +			goto out;
> +
> +		WARN_ON_ONCE(1);
> +	}

I seem to be hitting that in a KVM vm, even without load (sometimes
right after boot):

------------[ cut here ]------------
WARNING: CPU: 5 PID: 0 at kernel/time/tick-sched.c:794 tick_nohz_stop_sched_tick kernel/time/tick-sched.c:791 [inline]
WARNING: CPU: 5 PID: 0 at kernel/time/tick-sched.c:794 __tick_nohz_idle_enter+0x11f4/0x1ab0 kernel/time/tick-sched.c:950
Kernel panic - not syncing: panic_on_warn set ...

CPU: 5 PID: 0 Comm: swapper/5 Not tainted 4.12.0-rc3-next-20170601+ #53
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1ubuntu1 04/01/2014
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:16 [inline]
 dump_stack+0x115/0x1d1 lib/dump_stack.c:52
 panic+0x1d8/0x3c4 kernel/panic.c:180
 __warn+0x1d6/0x220 kernel/panic.c:541
 report_bug+0x223/0x310 lib/bug.c:183
 fixup_bug arch/x86/kernel/traps.c:190 [inline]
 do_trap_no_signal arch/x86/kernel/traps.c:224 [inline]
 do_trap+0x34c/0x490 arch/x86/kernel/traps.c:273
 do_error_trap+0x12f/0x390 arch/x86/kernel/traps.c:310
 do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:323
 invalid_op+0x1e/0x30 arch/x86/entry/entry_64.S:844
RIP: 0010:tick_nohz_stop_sched_tick kernel/time/tick-sched.c:791 [inline]
RIP: 0010:__tick_nohz_idle_enter+0x11f4/0x1ab0 kernel/time/tick-sched.c:950
RSP: 0018:ffff88005f407dd8 EFLAGS: 00010082
RAX: 000000000000007e RBX: ffff88005f5dcfe0 RCX: 0000000000000000
RDX: 000000000000007e RSI: 1ffff1000be80f78 RDI: ffffed000be80faf
RBP: ffff88005f407f88 R08: ffff88005f416300 R09: 1ffff1000be82c76
R10: ffff88007ffd915d R11: 0000000000000001 R12: ffff88005f5dcff8
R13: 00000061d944ea40 R14: ffff88005f407ea0 R15: 1ffff1000be80fc8
 tick_nohz_irq_exit+0xac/0x120 kernel/time/tick-sched.c:1009
 tick_irq_exit kernel/softirq.c:386 [inline]
 irq_exit+0x141/0x1b0 kernel/softirq.c:407
 exiting_irq arch/x86/include/asm/apic.h:652 [inline]
 smp_call_function_interrupt+0x70/0xa0 arch/x86/kernel/smp.c:302
 smp_call_function_single_interrupt+0x9/0x10 include/linux/compiler.h:250
 call_function_single_interrupt+0x9d/0xb0 arch/x86/entry/entry_64.S:722
RIP: 0010:native_safe_halt+0x6/0x10 arch/x86/include/asm/irqflags.h:53
RSP: 0018:ffff88005ee7fdb8 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff04
RAX: 0000000000000007 RBX: 1ffff1000bdcffba RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff91672020 RDI: ffff88005ee708f4
RBP: ffff88005ee7fdb8 R08: ffff88005f416060 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff88005ee70040
R13: ffff88005ee7fe70 R14: 0000000000000000 R15: ffff88005ee70040
 </IRQ>
 arch_safe_halt arch/x86/include/asm/paravirt.h:98 [inline]
 default_idle+0x8d/0x600 arch/x86/kernel/process.c:341
 arch_cpu_idle+0xa/0x10 arch/x86/kernel/process.c:332
 default_idle_call+0x4c/0xa0 kernel/sched/idle.c:98
 cpuidle_idle_call kernel/sched/idle.c:156 [inline]
 do_idle+0x287/0x410 kernel/sched/idle.c:245
 cpu_startup_entry+0x18/0x20 kernel/sched/idle.c:350
 start_secondary+0x2d3/0x400 arch/x86/kernel/smpboot.c:275
 secondary_startup_64+0x9f/0x9f arch/x86/kernel/head_64.S:304
Dumping ftrace buffer:
   (ftrace buffer empty)
Kernel Offset: 0xb200000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
Rebooting in 86400 seconds..

-- 

Thanks,
Sasha

[PATCH 2/2] tick: Make sure tick timer is active when bypassing reprogramming

[Frederic Weisbecker]

So far we have run into too much troubles with the optimization path
that skips reprogramming the clock on IRQ exit when the expiration
deadline hasn't changed. If by accident the cached deadline happens to
be out of sync with the hardware deadline, the buggy result and its
cause are hard to investigate. So lets detect and warn about the issue
early.

Acked-by: Rik van Riel <riel@redhat.com>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Tim Wright <tim@binbash.co.uk>
Cc: Pavel Machek <pavel@ucw.cz>
Cc: James Hartsock <hartsjc@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@kernel.org>
---
 kernel/time/tick-sched.c | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 502b320..be7ca4d 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -783,8 +783,13 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	tick = expires;
 
 	/* Skip reprogram of event if its not changed */
-	if (ts->tick_stopped && (expires == ts->next_tick))
-		goto out;
+	if (ts->tick_stopped && (expires == ts->next_tick)) {
+		/* Sanity check: make sure clockevent is actually programmed */
+		if (likely(dev->next_event <= ts->next_tick))
+			goto out;
+
+		WARN_ON_ONCE(1);
+	}
 
 	/*
 	 * nohz_stop_sched_tick can be called several times before
-- 
2.7.4