[PATCH] nohz: Fix spurious warning when hrtimer and clockevent get out of sync

[PATCH] nohz: Fix spurious warning when hrtimer and clockevent get out of sync

[Frederic Weisbecker]

The sanity check ensuring that the tick expiry cache (ts->next_tick)
is actually in sync with the hardware clock (dev->next_event) makes the
wrong assumption that the clock can't be programmed later than the
hrtimer deadline.

In fact the clock hardware can be programmed later on some conditions
such as:

    * The hrtimer deadline is already in the past.
    * The hrtimer deadline is earlier than the minimum delay supported
      by the hardware.

Such conditions can be met when we program the tick, for example if the
last jiffies update hasn't been seen by the current CPU yet, we may
program the hrtimer to a deadline that is earlier than ktime_get()
because last_jiffies_update is our timestamp base to compute the next
tick.

As a result, we can randomly observe such warning:

	WARNING: CPU: 5 PID: 0 at kernel/time/tick-sched.c:794 tick_nohz_stop_sched_tick kernel/time/tick-sched.c:791 [inline]
	Call Trace:
	 tick_nohz_irq_exit
	 tick_irq_exit
	 irq_exit
	 exiting_irq
	 smp_call_function_interrupt
	 smp_call_function_single_interrupt
	 call_function_single_interrupt

Therefore, let's rather make sure that the tick expiry cache is sync'ed
with the tick hrtimer deadline, against which it is not supposed to
drift away. The clock hardware instead has its own will and can't be
used as a reliable comparison point.

Reported-and-tested-by: Sasha Levin <alexander.levin@verizon.com>
Reported-and-tested-by: Abdul Haleem <abdhalee@linux.vnet.ibm.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Rik van Riel <riel@redhat.com>
Cc: James Hartsock <hartsjc@redhat.com>
Cc: Tim Wright <tim@binbash.co.uk>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/time/tick-sched.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 9d31f1e..83c788e 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -768,7 +768,8 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	/* Skip reprogram of event if its not changed */
 	if (ts->tick_stopped && (expires == ts->next_tick)) {
 		/* Sanity check: make sure clockevent is actually programmed */
-		if (likely(dev->next_event <= ts->next_tick))
+		if (tick == KTIME_MAX ||
+		    ts->next_tick == hrtimer_get_expires(&ts->sched_timer))
 			goto out;
 
 		WARN_ON_ONCE(1);
@@ -806,8 +807,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 		goto out;
 	}
 
+	hrtimer_set_expires(&ts->sched_timer, tick);
+
 	if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
-		hrtimer_start(&ts->sched_timer, tick, HRTIMER_MODE_ABS_PINNED);
+		hrtimer_start_expires(&ts->sched_timer, HRTIMER_MODE_ABS_PINNED);
 	else
 		tick_program_event(tick, 1);
 out:
-- 
2.7.4

[tip:timers/nohz] nohz: Fix spurious warning when hrtimer and clockevent get out of sync

[tip-bot for Frederic Weisbecker]

Commit-ID:  d4af6d933ccffd24286528f04d5c39e702c8580f
Gitweb:     http://git.kernel.org/tip/d4af6d933ccffd24286528f04d5c39e702c8580f
Author:     Frederic Weisbecker <fweisbec@gmail.com>
AuthorDate: Tue, 13 Jun 2017 06:04:14 +0200
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Tue, 13 Jun 2017 08:45:43 +0200

nohz: Fix spurious warning when hrtimer and clockevent get out of sync

The sanity check ensuring that the tick expiry cache (ts->next_tick)
is actually in sync with the hardware clock (dev->next_event) makes the
wrong assumption that the clock can't be programmed later than the
hrtimer deadline.

In fact the clock hardware can be programmed later on some conditions
such as:

    * The hrtimer deadline is already in the past.
    * The hrtimer deadline is earlier than the minimum delay supported
      by the hardware.

Such conditions can be met when we program the tick, for example if the
last jiffies update hasn't been seen by the current CPU yet, we may
program the hrtimer to a deadline that is earlier than ktime_get()
because last_jiffies_update is our timestamp base to compute the next
tick.

As a result, we can randomly observe such warning:

	WARNING: CPU: 5 PID: 0 at kernel/time/tick-sched.c:794 tick_nohz_stop_sched_tick kernel/time/tick-sched.c:791 [inline]
	Call Trace:
	 tick_nohz_irq_exit
	 tick_irq_exit
	 irq_exit
	 exiting_irq
	 smp_call_function_interrupt
	 smp_call_function_single_interrupt
	 call_function_single_interrupt

Therefore, let's rather make sure that the tick expiry cache is sync'ed
with the tick hrtimer deadline, against which it is not supposed to
drift away. The clock hardware instead has its own will and can't be
used as a reliable comparison point.

Reported-and-tested-by: Sasha Levin <alexander.levin@verizon.com>
Reported-and-tested-by: Abdul Haleem <abdhalee@linux.vnet.ibm.com>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: James Hartsock <hartsjc@redhat.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
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/1497326654-14122-1-git-send-email-fweisbec@gmail.com
[ Minor readability edit. ]
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 kernel/time/tick-sched.c | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 9d31f1e..2046009 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -768,7 +768,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	/* Skip reprogram of event if its not changed */
 	if (ts->tick_stopped && (expires == ts->next_tick)) {
 		/* Sanity check: make sure clockevent is actually programmed */
-		if (likely(dev->next_event <= ts->next_tick))
+		if (tick == KTIME_MAX || ts->next_tick == hrtimer_get_expires(&ts->sched_timer))
 			goto out;
 
 		WARN_ON_ONCE(1);
@@ -806,8 +806,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 		goto out;
 	}
 
+	hrtimer_set_expires(&ts->sched_timer, tick);
+
 	if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
-		hrtimer_start(&ts->sched_timer, tick, HRTIMER_MODE_ABS_PINNED);
+		hrtimer_start_expires(&ts->sched_timer, HRTIMER_MODE_ABS_PINNED);
 	else
 		tick_program_event(tick, 1);
 out:

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

[Frederic Weisbecker]

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

[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

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

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

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

[PATCH] nohz: Fix spurious warning when hrtimer and clockevent get out of sync

[Frederic Weisbecker]

On Wed, Jun 07, 2017 at 09:36:45PM +0000, Levin, Alexander (Sasha Levin) wrote:
> 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 ;)

Duly noted ;-)

> 
> 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.

Awesome, these traces have been very helpful! So now I think I get what's going on.
Can you please test the following fix?

Thanks a lot!

---
>From 604a46c3e821c61411cee2205fa1cb65e5b04174 Mon Sep 17 00:00:00 2001
From: Frederic Weisbecker <fweisbec@gmail.com>
Date: Thu, 8 Jun 2017 16:32:58 +0200
Subject: [PATCH] nohz: Fix spurious warning when hrtimer and clockevent get
 out of sync

The sanity check ensuring that the tick expiry cache (ts->next_tick)
is actually in sync with the hardware clock (dev->next_event) makes the
wrong assumption that the clock can't be programmed later than the
hrtimer deadline.

In fact the clock hardware can be programmed later on some conditions
such as:

    * The hrtimer deadline is already in the past.
    * The hrtimer deadline is earlier than the minimum delay supported
      by the hardware.

Such conditions can be met when we program the tick, for example if the
last jiffies update hasn't been seen by the current CPU yet, we may
program the hrtimer to a deadline that is earlier than ktime_get()
because last_jiffies_update is our timestamp base to compute the next
tick.

As a result, we can randomly observe such warning:

	WARNING: CPU: 5 PID: 0 at kernel/time/tick-sched.c:794 tick_nohz_stop_sched_tick kernel/time/tick-sched.c:791 [inline]
	Call Trace:
	 tick_nohz_irq_exit
	 tick_irq_exit
	 irq_exit
	 exiting_irq
	 smp_call_function_interrupt
	 smp_call_function_single_interrupt
	 call_function_single_interrupt

Therefore, let's rather make sure that the tick expiry cache is sync'ed
with the tick hrtimer deadline, against which it is not supposed to
drift away. The clock hardware instead has its own will and can't be
used as a reliable comparison point.

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

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 9d31f1e..b55547f 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -768,7 +768,8 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	/* Skip reprogram of event if its not changed */
 	if (ts->tick_stopped && (expires == ts->next_tick)) {
 		/* Sanity check: make sure clockevent is actually programmed */
-		if (likely(dev->next_event <= ts->next_tick))
+		if (tick != KTIME_MAX &&
+		    ts->next_tick == hrtimer_get_expires(&ts->sched_timer))
 			goto out;
 
 		WARN_ON_ONCE(1);
@@ -806,8 +807,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 		goto out;
 	}
 
+	hrtimer_set_expires(&ts->sched_timer, tick);
+
 	if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
-		hrtimer_start(&ts->sched_timer, tick, HRTIMER_MODE_ABS_PINNED);
+		hrtimer_start_expires(&ts->sched_timer, HRTIMER_MODE_ABS_PINNED);
 	else
 		tick_program_event(tick, 1);
 out:
-- 
2.7.4

[PATCH] nohz: Fix spurious warning when hrtimer and clockevent get out of sync

[Levin, Alexander (Sasha Levin)]

On Thu, Jun 08, 2017 at 09:07:05PM +0200, Frederic Weisbecker wrote:
> Awesome, these traces have been very helpful! So now I think I get what's going on.
> Can you please test the following fix?

With the patch, I hit the warning early on boot:

[    1.423727] clocksource: Switched to clocksource kvm-clock
[    1.429326] ------------[ cut here ]------------
[    1.430234] WARNING: CPU: 1 PID: 0 at kernel/time/tick-sched.c:792 __tick_nohz_idle_enter+0xe1c/0x15c0
[    1.430234] Kernel panic - not syncing: panic_on_warn set ...
[    1.430234] 
[    1.430234] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.12.0-rc4-next-20170606+ #85
[    1.430234] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1ubuntu1 04/01/2014
[    1.430234] Call Trace:
[    1.430234]  <IRQ>
[    1.430234]  dump_stack+0x100/0x189
[    1.430234]  ? _atomic_dec_and_lock+0x187/0x187
[    1.430234]  ? __tick_nohz_idle_enter+0xe1c/0x15c0
[    1.430234]  ? __tick_nohz_idle_enter+0xe1c/0x15c0
[    1.430234]  panic+0x1dd/0x489
[    1.430234]  ? copy_mm+0x10eb/0x10eb
[    1.430234]  ? __probe_kernel_read+0x19c/0x2a0
[    1.430234]  ? __tick_nohz_idle_enter+0xe1c/0x15c0
[    1.430234]  __warn+0x1d3/0x220
[    1.430234]  ? __tick_nohz_idle_enter+0xe1c/0x15c0
[    1.430234]  ? __tick_nohz_idle_enter+0xe1c/0x15c0
[    1.430234]  report_bug+0x1fa/0x2b0
[    1.430234]  do_trap+0x3c4/0x500
[    1.430234]  do_error_trap+0x12f/0x240
[    1.430234]  ? fixup_bad_iret+0x140/0x140
[    1.430234]  ? check_preemption_disabled+0x3b/0x280
[    1.430234]  ? __tick_nohz_idle_enter+0xe1c/0x15c0
[    1.430234]  ? error_entry+0x7c/0xd0
[    1.430234]  ? __this_cpu_preempt_check+0x1c/0x20
[    1.430234]  ? trace_hardirqs_off_caller+0x13e/0x2f0
[    1.430234]  ? trace_hardirqs_off_thunk+0x1a/0x1c
[    1.430234]  do_invalid_op+0x1b/0x20
[    1.430234]  invalid_op+0x1e/0x30
[    1.430234] RIP: 0010:__tick_nohz_idle_enter+0xe1c/0x15c0
[    1.430234] RSP: 0000:ffff88003ec07e58 EFLAGS: 00010086
[    1.430234] RAX: 0000000000000000 RBX: ffff88003eddcfe0 RCX: 0000000000000001
[    1.430234] RDX: 1ffff10007dbba07 RSI: ffffffff9d86f3e0 RDI: ffff88003eddd0b0
[    1.430234] RBP: ffff88003ec07f38 R08: 0000000000000000 R09: dffffc0000000000
[    1.430234] R10: 1ffff10007d8325a R11: 0000000000000001 R12: 7fffffffffffffff
[    1.430234] R13: 7fffffffffffffff R14: ffff88003eddd038 R15: ffff88003eddd044
[    1.430234]  ? __tick_nohz_idle_enter+0xe1c/0x15c0
[    1.430234]  ? get_cpu_iowait_time_us+0x2c0/0x2c0
[    1.430234]  ? check_preemption_disabled+0x3b/0x280
[    1.430234]  tick_nohz_irq_exit+0xac/0x120
[    1.430234]  irq_exit+0x168/0x1f0
[    1.430234]  scheduler_ipi+0x196/0x7a0
[    1.430234]  smp_reschedule_interrupt+0x66/0x90
[    1.430234]  reschedule_interrupt+0x9d/0xb0
[    1.430234] RIP: 0010:native_safe_halt+0x6/0x10
[    1.430234] RSP: 0000:ffff88003df8fe68 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
[    1.430234] RAX: 0000000000000007 RBX: ffff88003df7c040 RCX: ffff88003df7c040
[    1.430234] RDX: 0000000000000000 RSI: ffffffff9d86f3e0 RDI: ffff88003df7c8f4
[    1.430234] RBP: ffff88003df8fe68 R08: 0000000000000007 R09: 0000000000000000
[    1.430234] R10: ffff88003df7c8f8 R11: 0000000000000006 R12: ffffed0007bef808
[    1.430234] R13: 0000000000000000 R14: ffff88003df7c040 R15: dffffc0000000000
[    1.430234]  </IRQ>
[    1.430234]  ? trace_hardirqs_on+0xd/0x10
[    1.430234]  default_idle+0x1f/0x420
[    1.430234]  arch_cpu_idle+0xa/0x10
[    1.430234]  default_idle_call+0x3b/0x70
[    1.430234]  do_idle+0x1ff/0x2e0
[    1.430234]  cpu_startup_entry+0x18/0x20
[    1.430234]  start_secondary+0x2af/0x3b0
[    1.430234]  secondary_startup_64+0x9f/0x9f
[    1.430234] Dumping ftrace buffer:
[    1.430234] ---------------------------------
[    1.430234] watchdog-16      1d..1 1498773us : hrtimer_start: hrtimer=ffff88003eddd1a0 function=watchdog_timer_fn expires=4176000000 softexpires=4176000000
[    1.430234] watchdog-16      1d..1 1498784us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => watchdog_enable
[    1.430234]  => smpboot_thread_fn
[    1.430234]  => kthread
[    1.430234]  => ret_from_fork
[    1.430234] watchdog-16      1d..4 1498828us : hrtimer_start: hrtimer=ffffffffa3374970 function=sched_rt_period_timer expires=1157000000 softexpires=1157000000
[    1.430234] watchdog-16      1d..4 1498831us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => __enqueue_rt_entity
[    1.430234]  => enqueue_rt_entity
[    1.430234]  => enqueue_task_rt
[    1.430234]  => enqueue_task
[    1.430234]  => __sched_setscheduler
[    1.430234]  => _sched_setscheduler
[    1.430234]  => sched_setscheduler
[    1.430234]  => watchdog_enable
[    1.430234]  => smpboot_thread_fn
[    1.430234]  => kthread
[    1.430234]  => ret_from_fork
[    1.430234] kworker/-19      1d..1 1749551us : hrtimer_start: hrtimer=ffff88003dff7aa0 function=hrtimer_wakeup expires=385000000 softexpires=385000000
[    1.430234] kworker/-19      1d..1 1749559us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => schedule_hrtimeout_range_clock
[    1.430234]  => schedule_hrtimeout
[    1.430234]  => wait_task_inactive
[    1.430234]  => __kthread_bind_mask
[    1.430234]  => kthread_bind_mask
[    1.430234]  => create_worker
[    1.430234]  => worker_thread
[    1.430234]  => kthread
[    1.430234]  => ret_from_fork
[    1.430234]   <idle>-0       1d.h2 1750485us : hrtimer_cancel: hrtimer=ffff88003dff7aa0
[    1.430234]   <idle>-0       1d.h2 1750490us : <stack trace>
[    1.430234]  => hrtimer_run_queues
[    1.430234]  => run_local_timers
[    1.430234]  => update_process_times
[    1.430234]  => tick_periodic
[    1.430234]  => tick_handle_periodic
[    1.430234]  => local_apic_timer_interrupt
[    1.430234]  => smp_apic_timer_interrupt
[    1.430234]  => apic_timer_interrupt
[    1.430234]  => native_safe_halt
[    1.430234]  => default_idle
[    1.430234]  => arch_cpu_idle
[    1.430234]  => default_idle_call
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d.h1 1750495us : hrtimer_expire_entry: hrtimer=ffff88003dff7aa0 function=hrtimer_wakeup now=385000000
[    1.430234]   <idle>-0       1d.h1 1750498us : <stack trace>
[    1.430234]  => hrtimer_run_queues
[    1.430234]  => run_local_timers
[    1.430234]  => update_process_times
[    1.430234]  => tick_periodic
[    1.430234]  => tick_handle_periodic
[    1.430234]  => local_apic_timer_interrupt
[    1.430234]  => smp_apic_timer_interrupt
[    1.430234]  => apic_timer_interrupt
[    1.430234]  => native_safe_halt
[    1.430234]  => default_idle
[    1.430234]  => arch_cpu_idle
[    1.430234]  => default_idle_call
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234] watchdog-16      1d..1 1821936us : hrtimer_cancel: hrtimer=ffff88003eddd1a0
[    1.430234] watchdog-16      1d..1 1821946us : <stack trace>
[    1.430234]  => hrtimer_cancel
[    1.430234]  => watchdog_disable
[    1.430234]  => smpboot_thread_fn
[    1.430234]  => kthread
[    1.430234]  => ret_from_fork
[    1.430234] watchdog-16      1d..1 1840234us : hrtimer_start: hrtimer=ffff88003eddd1a0 function=watchdog_timer_fn expires=4445000000 softexpires=4445000000
[    1.430234] watchdog-16      1d..1 1840240us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => watchdog_enable
[    1.430234]  => smpboot_thread_fn
[    1.430234]  => kthread
[    1.430234]  => ret_from_fork
[    1.430234]   <idle>-0       1d.h2 2720410us : hrtimer_cancel: hrtimer=ffffffffa3374970
[    1.430234]   <idle>-0       1d.h2 2720422us : <stack trace>
[    1.430234]  => hrtimer_run_queues
[    1.430234]  => run_local_timers
[    1.430234]  => update_process_times
[    1.430234]  => tick_periodic
[    1.430234]  => tick_handle_periodic
[    1.430234]  => local_apic_timer_interrupt
[    1.430234]  => smp_apic_timer_interrupt
[    1.430234]  => apic_timer_interrupt
[    1.430234]  => native_safe_halt
[    1.430234]  => default_idle
[    1.430234]  => arch_cpu_idle
[    1.430234]  => default_idle_call
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d.h1 2720429us : hrtimer_expire_entry: hrtimer=ffffffffa3374970 function=sched_rt_period_timer now=1157000000
[    1.430234]   <idle>-0       1d.h1 2720433us : <stack trace>
[    1.430234]  => hrtimer_run_queues
[    1.430234]  => run_local_timers
[    1.430234]  => update_process_times
[    1.430234]  => tick_periodic
[    1.430234]  => tick_handle_periodic
[    1.430234]  => local_apic_timer_interrupt
[    1.430234]  => smp_apic_timer_interrupt
[    1.430234]  => apic_timer_interrupt
[    1.430234]  => native_safe_halt
[    1.430234]  => default_idle
[    1.430234]  => arch_cpu_idle
[    1.430234]  => default_idle_call
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d.h2 3052672us : hrtimer_start: hrtimer=ffff88003eddcfe0 function=tick_sched_timer expires=1424000000 softexpires=1424000000
[    1.430234]   <idle>-0       1d.h2 3052680us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => tick_setup_sched_timer
[    1.430234]  => hrtimer_run_queues
[    1.430234]  => run_local_timers
[    1.430234]  => update_process_times
[    1.430234]  => tick_periodic
[    1.430234]  => tick_handle_periodic
[    1.430234]  => local_apic_timer_interrupt
[    1.430234]  => smp_apic_timer_interrupt
[    1.430234]  => apic_timer_interrupt
[    1.430234]  => native_safe_halt
[    1.430234]  => default_idle
[    1.430234]  => arch_cpu_idle
[    1.430234]  => default_idle_call
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d..2 3052735us : hrtimer_cancel: hrtimer=ffff88003eddcfe0
[    1.430234]   <idle>-0       1d..2 3052738us : <stack trace>
[    1.430234]  => __tick_nohz_idle_enter
[    1.430234]  => tick_nohz_irq_exit
[    1.430234]  => irq_exit
[    1.430234]  => smp_apic_timer_interrupt
[    1.430234]  => apic_timer_interrupt
[    1.430234]  => native_safe_halt
[    1.430234]  => default_idle
[    1.430234]  => arch_cpu_idle
[    1.430234]  => default_idle_call
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d..2 3052747us : hrtimer_start: hrtimer=ffff88003eddcfe0 function=tick_sched_timer expires=1426000000 softexpires=1426000000
[    1.430234]   <idle>-0       1d..2 3052750us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => __tick_nohz_idle_enter
[    1.430234]  => tick_nohz_irq_exit
[    1.430234]  => irq_exit
[    1.430234]  => smp_apic_timer_interrupt
[    1.430234]  => apic_timer_interrupt
[    1.430234]  => native_safe_halt
[    1.430234]  => default_idle
[    1.430234]  => arch_cpu_idle
[    1.430234]  => default_idle_call
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1dN.2 3054068us : hrtimer_cancel: hrtimer=ffff88003eddcfe0
[    1.430234]   <idle>-0       1dN.2 3054075us : <stack trace>
[    1.430234]  => hrtimer_cancel
[    1.430234]  => tick_nohz_restart
[    1.430234]  => tick_nohz_idle_exit
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1dN.2 3054088us : hrtimer_start: hrtimer=ffff88003eddcfe0 function=tick_sched_timer expires=1425000000 softexpires=1425000000
[    1.430234]   <idle>-0       1dN.2 3054091us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => tick_nohz_restart
[    1.430234]  => tick_nohz_idle_exit
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d..2 3054214us : hrtimer_cancel: hrtimer=ffff88003eddcfe0
[    1.430234]   <idle>-0       1d..2 3054217us : <stack trace>
[    1.430234]  => __tick_nohz_idle_enter
[    1.430234]  => tick_nohz_idle_enter
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d..2 3054227us : hrtimer_start: hrtimer=ffff88003eddcfe0 function=tick_sched_timer expires=1428000000 softexpires=1428000000
[    1.430234]   <idle>-0       1d..2 3054229us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => __tick_nohz_idle_enter
[    1.430234]  => tick_nohz_idle_enter
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d.h2 3057833us : hrtimer_cancel: hrtimer=ffff88003eddcfe0
[    1.430234]   <idle>-0       1d.h2 3057840us : <stack trace>
[    1.430234]  => hrtimer_interrupt
[    1.430234]  => local_apic_timer_interrupt
[    1.430234]  => smp_apic_timer_interrupt
[    1.430234]  => apic_timer_interrupt
[    1.430234]  => native_safe_halt
[    1.430234]  => default_idle
[    1.430234]  => arch_cpu_idle
[    1.430234]  => default_idle_call
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d.h1 3057844us : hrtimer_expire_entry: hrtimer=ffff88003eddcfe0 function=tick_sched_timer now=1428247421
[    1.430234]   <idle>-0       1d.h1 3057846us : <stack trace>
[    1.430234]  => hrtimer_interrupt
[    1.430234]  => local_apic_timer_interrupt
[    1.430234]  => smp_apic_timer_interrupt
[    1.430234]  => apic_timer_interrupt
[    1.430234]  => native_safe_halt
[    1.430234]  => default_idle
[    1.430234]  => arch_cpu_idle
[    1.430234]  => default_idle_call
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1dN.2 3057926us : hrtimer_start: hrtimer=ffff88003eddcfe0 function=tick_sched_timer expires=1429000000 softexpires=1429000000
[    1.430234]   <idle>-0       1dN.2 3057929us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => tick_nohz_restart
[    1.430234]  => tick_nohz_idle_exit
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1dn.2 3058002us : hrtimer_cancel: hrtimer=ffff88003eddcfe0
[    1.430234]   <idle>-0       1dn.2 3058005us : <stack trace>
[    1.430234]  => __tick_nohz_idle_enter
[    1.430234]  => tick_nohz_idle_enter
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1dn.2 3058014us : hrtimer_start: hrtimer=ffff88003eddcfe0 function=tick_sched_timer expires=1432000000 softexpires=1432000000
[    1.430234]   <idle>-0       1dn.2 3058017us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => __tick_nohz_idle_enter
[    1.430234]  => tick_nohz_idle_enter
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1dN.2 3058031us : hrtimer_cancel: hrtimer=ffff88003eddcfe0
[    1.430234]   <idle>-0       1dN.2 3058033us : <stack trace>
[    1.430234]  => hrtimer_cancel
[    1.430234]  => tick_nohz_restart
[    1.430234]  => tick_nohz_idle_exit
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1dN.2 3058041us : hrtimer_start: hrtimer=ffff88003eddcfe0 function=tick_sched_timer expires=1429000000 softexpires=1429000000
[    1.430234]   <idle>-0       1dN.2 3058044us : <stack trace>
[    1.430234]  => hrtimer_start_range_ns
[    1.430234]  => tick_nohz_restart
[    1.430234]  => tick_nohz_idle_exit
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234]   <idle>-0       1d..2 3058105us : hrtimer_cancel: hrtimer=ffff88003eddcfe0
[    1.430234]   <idle>-0       1d..2 3058107us : <stack trace>
[    1.430234]  => hrtimer_cancel
[    1.430234]  => __tick_nohz_idle_enter
[    1.430234]  => tick_nohz_idle_enter
[    1.430234]  => do_idle
[    1.430234]  => cpu_startup_entry
[    1.430234]  => start_secondary
[    1.430234]  => verify_cpu
[    1.430234] ---------------------------------


-- 

Thanks,
Sasha

Re: [PATCH] nohz: Fix spurious warning when hrtimer and clockevent get out of sync

[Frederic Weisbecker]

On Thu, Jun 08, 2017 at 10:13:38PM +0000, Levin, Alexander (Sasha Levin) wrote:
> On Thu, Jun 08, 2017 at 09:07:05PM +0200, Frederic Weisbecker wrote:
> > Awesome, these traces have been very helpful! So now I think I get what's going on.
> > Can you please test the following fix?
> 
> With the patch, I hit the warning early on boot:
> 
> [    1.423727] clocksource: Switched to clocksource kvm-clock
> [    1.429326] ------------[ cut here ]------------
> [    1.430234] WARNING: CPU: 1 PID: 0 at kernel/time/tick-sched.c:792 __tick_nohz_idle_enter+0xe1c/0x15c0

Oh sorry, I inverted some conditional. It warns as soon as the tick is completely stopped
and not just deferred, which seldom happen on my testbox.

I need to learn programming again.

Here is the fixed version:

---
>From f80041b5209aaf9d02ac25a29a248d0f214ba19f Mon Sep 17 00:00:00 2001
From: Frederic Weisbecker <fweisbec@gmail.com>
Date: Thu, 8 Jun 2017 16:32:58 +0200
Subject: [PATCH] nohz: Fix spurious warning when hrtimer and clocksource get
 out of sync

The sanity check ensuring that the tick expiry cache (ts->next_tick)
is actually in sync with the hardware clock (dev->next_event) makes the
wrong assumption that the clock can't be programmed later than the
hrtimer deadline.

In fact the clock hardware can be programmed later on some conditions
such as:

    * The hrtimer deadline is already in the past.
    * The hrtimer deadline is earlier than the minimum delay supported
      by the hardware.

Such conditions can be met when we program the tick, for example if the
last jiffies update hasn't been seen by the current CPU yet, we may
program the hrtimer to a deadline that is earlier than ktime_get()
because last_jiffies_update is our timestamp base to compute the next
tick.

As a result, we can randomly observe such warning:

	WARNING: CPU: 5 PID: 0 at kernel/time/tick-sched.c:794 tick_nohz_stop_sched_tick kernel/time/tick-sched.c:791 [inline]
	Call Trace:
	 tick_nohz_irq_exit
	 tick_irq_exit
	 irq_exit
	 exiting_irq
	 smp_call_function_interrupt
	 smp_call_function_single_interrupt
	 call_function_single_interrupt

Therefore, let's rather make sure that the tick expiry cache is sync'ed
with the tick hrtimer deadline, against which it is not supposed to
drift away. The clock hardware instead has its own will and can't be
used as a reliable comparison point.

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

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 9d31f1e..83c788e 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -768,7 +768,8 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 	/* Skip reprogram of event if its not changed */
 	if (ts->tick_stopped && (expires == ts->next_tick)) {
 		/* Sanity check: make sure clockevent is actually programmed */
-		if (likely(dev->next_event <= ts->next_tick))
+		if (tick == KTIME_MAX ||
+		    ts->next_tick == hrtimer_get_expires(&ts->sched_timer))
 			goto out;
 
 		WARN_ON_ONCE(1);
@@ -806,8 +807,10 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 		goto out;
 	}
 
+	hrtimer_set_expires(&ts->sched_timer, tick);
+
 	if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
-		hrtimer_start(&ts->sched_timer, tick, HRTIMER_MODE_ABS_PINNED);
+		hrtimer_start_expires(&ts->sched_timer, HRTIMER_MODE_ABS_PINNED);
 	else
 		tick_program_event(tick, 1);
 out:
-- 
2.7.4

Re: [PATCH] nohz: Fix spurious warning when hrtimer and clockevent get out of sync

[Levin, Alexander (Sasha Levin)]

On Fri, Jun 09, 2017 at 02:48:57AM +0200, Frederic Weisbecker wrote:
> On Thu, Jun 08, 2017 at 10:13:38PM +0000, Levin, Alexander (Sasha Levin) wrote:
> > On Thu, Jun 08, 2017 at 09:07:05PM +0200, Frederic Weisbecker wrote:
> > > Awesome, these traces have been very helpful! So now I think I get what's going on.
> > > Can you please test the following fix?
> > 
> > With the patch, I hit the warning early on boot:
> > 
> > [    1.423727] clocksource: Switched to clocksource kvm-clock
> > [    1.429326] ------------[ cut here ]------------
> > [    1.430234] WARNING: CPU: 1 PID: 0 at kernel/time/tick-sched.c:792 __tick_nohz_idle_enter+0xe1c/0x15c0
> 
> Oh sorry, I inverted some conditional. It warns as soon as the tick is completely stopped
> and not just deferred, which seldom happen on my testbox.
> 
> I need to learn programming again.
> 
> Here is the fixed version:

These warnings seem to have gone away, but I've started seeing a new one:

------------[ cut here ]------------
WARNING: CPU: 0 PID: 12525 at kernel/time/hrtimer.c:805 hrtimer_forward+0x222/0x3e0 kernel/time/hrtimer.c:805
Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 12525 Comm: syz-executor7 Not tainted 4.12.0-rc4-next-20170608+ #87
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1ubuntu1 04/01/2014
Call Trace:
 __dump_stack lib/dump_stack.c:16 [inline]
 dump_stack+0x100/0x189 lib/dump_stack.c:52
 panic+0x1dd/0x489 kernel/panic.c:180
 __warn+0x1d3/0x220 kernel/panic.c:541
 report_bug+0x1fa/0x2b0 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+0x3c4/0x500 arch/x86/kernel/traps.c:273
 do_error_trap+0x12f/0x240 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:hrtimer_forward+0x222/0x3e0 kernel/time/hrtimer.c:805
RSP: 0018:ffff880064a77b58 EFLAGS: 00010086
RAX: 0000000000010000 RBX: ffff88003b35d4b8 RCX: 0000000000000017
RDX: 1ffff1000766ba9e RSI: 14c6502d37db1b49 RDI: ffff88003b35d4f0
RBP: ffff880064a77ba8 R08: 14c6502d37db1b49 R09: ffff88007ffd7008
R10: ffff88007ffd7010 R11: 0000000000000001 R12: 0000001f39eeff61
R13: 14c6502d37db1b49 R14: 14c6500dfdec1be8 R15: 0000000000000000
 common_hrtimer_forward+0x50/0x70 kernel/time/posix-timers.c:621
 common_timer_get+0x25a/0x690 kernel/time/posix-timers.c:674
 common_timer_set+0x63/0x580 kernel/time/posix-timers.c:779
 SYSC_timer_settime+0x1e4/0x370 kernel/time/posix-timers.c:840
 SyS_timer_settime+0x2c/0x40 kernel/time/posix-timers.c:809
 do_syscall_64+0x1c1/0x5c0 arch/x86/entry/common.c:284
 entry_SYSCALL64_slow_path+0x25/0x25
RIP: 0033:0x451429
RSP: 002b:00007f8ab906cc08 EFLAGS: 00000216 ORIG_RAX: 00000000000000df
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 0000000000451429
RDX: 0000000020002000 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000007180a8 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000020000fe0 R11: 0000000000000216 R12: 00000000ffffffff
R13: 0000000000000000 R14: 00000000000005b9 R15: 00007f8ab906d700
Dumping ftrace buffer:
   (ftrace buffer empty)
Kernel Offset: 0x1de00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
Rebooting in 86400 seconds..

I'm not 100% sure it's related, but that WARN isn't in any new code.

-- 

Thanks,
Sasha

Re: [PATCH] nohz: Fix spurious warning when hrtimer and clockevent get out of sync

[Peter Zijlstra]

On Fri, Jun 09, 2017 at 12:13:49PM +0000, Levin, Alexander (Sasha Levin) wrote:
> On Fri, Jun 09, 2017 at 02:48:57AM +0200, Frederic Weisbecker wrote:
> > On Thu, Jun 08, 2017 at 10:13:38PM +0000, Levin, Alexander (Sasha Levin) wrote:
> > > On Thu, Jun 08, 2017 at 09:07:05PM +0200, Frederic Weisbecker wrote:
> > > > Awesome, these traces have been very helpful! So now I think I get what's going on.
> > > > Can you please test the following fix?
> > > 
> > > With the patch, I hit the warning early on boot:
> > > 
> > > [    1.423727] clocksource: Switched to clocksource kvm-clock
> > > [    1.429326] ------------[ cut here ]------------
> > > [    1.430234] WARNING: CPU: 1 PID: 0 at kernel/time/tick-sched.c:792 __tick_nohz_idle_enter+0xe1c/0x15c0
> > 
> > Oh sorry, I inverted some conditional. It warns as soon as the tick is completely stopped
> > and not just deferred, which seldom happen on my testbox.
> > 
> > I need to learn programming again.
> > 
> > Here is the fixed version:
> 
> These warnings seem to have gone away, but I've started seeing a new one:
> 
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 12525 at kernel/time/hrtimer.c:805 hrtimer_forward+0x222/0x3e0 kernel/time/hrtimer.c:805
> Kernel panic - not syncing: panic_on_warn set ...

https://lkml.kernel.org/r/20170609104457.GA39907@inn.lkp.intel.com

has a very similar splat

Re: [PATCH] nohz: Fix spurious warning when hrtimer and clockevent get out of sync

[Frederic Weisbecker]

On Fri, Jun 09, 2017 at 12:13:49PM +0000, Levin, Alexander (Sasha Levin) wrote:
> On Fri, Jun 09, 2017 at 02:48:57AM +0200, Frederic Weisbecker wrote:
> > On Thu, Jun 08, 2017 at 10:13:38PM +0000, Levin, Alexander (Sasha Levin) wrote:
> > > On Thu, Jun 08, 2017 at 09:07:05PM +0200, Frederic Weisbecker wrote:
> > > > Awesome, these traces have been very helpful! So now I think I get what's going on.
> > > > Can you please test the following fix?
> > > 
> > > With the patch, I hit the warning early on boot:
> > > 
> > > [    1.423727] clocksource: Switched to clocksource kvm-clock
> > > [    1.429326] ------------[ cut here ]------------
> > > [    1.430234] WARNING: CPU: 1 PID: 0 at kernel/time/tick-sched.c:792 __tick_nohz_idle_enter+0xe1c/0x15c0
> > 
> > Oh sorry, I inverted some conditional. It warns as soon as the tick is completely stopped
> > and not just deferred, which seldom happen on my testbox.
> > 
> > I need to learn programming again.
> > 
> > Here is the fixed version:
> 
> These warnings seem to have gone away,

Cool!

> but I've started seeing a new one:
> 
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 12525 at kernel/time/hrtimer.c:805 hrtimer_forward+0x222/0x3e0 kernel/time/hrtimer.c:805
> Kernel panic - not syncing: panic_on_warn set ...
> 
> CPU: 0 PID: 12525 Comm: syz-executor7 Not tainted 4.12.0-rc4-next-20170608+ #87
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1ubuntu1 04/01/2014
> Call Trace:
>  __dump_stack lib/dump_stack.c:16 [inline]
>  dump_stack+0x100/0x189 lib/dump_stack.c:52
>  panic+0x1dd/0x489 kernel/panic.c:180
>  __warn+0x1d3/0x220 kernel/panic.c:541
>  report_bug+0x1fa/0x2b0 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+0x3c4/0x500 arch/x86/kernel/traps.c:273
>  do_error_trap+0x12f/0x240 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:hrtimer_forward+0x222/0x3e0 kernel/time/hrtimer.c:805
> RSP: 0018:ffff880064a77b58 EFLAGS: 00010086
> RAX: 0000000000010000 RBX: ffff88003b35d4b8 RCX: 0000000000000017
> RDX: 1ffff1000766ba9e RSI: 14c6502d37db1b49 RDI: ffff88003b35d4f0
> RBP: ffff880064a77ba8 R08: 14c6502d37db1b49 R09: ffff88007ffd7008
> R10: ffff88007ffd7010 R11: 0000000000000001 R12: 0000001f39eeff61
> R13: 14c6502d37db1b49 R14: 14c6500dfdec1be8 R15: 0000000000000000
>  common_hrtimer_forward+0x50/0x70 kernel/time/posix-timers.c:621
>  common_timer_get+0x25a/0x690 kernel/time/posix-timers.c:674
>  common_timer_set+0x63/0x580 kernel/time/posix-timers.c:779
>  SYSC_timer_settime+0x1e4/0x370 kernel/time/posix-timers.c:840
>  SyS_timer_settime+0x2c/0x40 kernel/time/posix-timers.c:809
>  do_syscall_64+0x1c1/0x5c0 arch/x86/entry/common.c:284
>  entry_SYSCALL64_slow_path+0x25/0x25
> RIP: 0033:0x451429
> RSP: 002b:00007f8ab906cc08 EFLAGS: 00000216 ORIG_RAX: 00000000000000df
> RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 0000000000451429
> RDX: 0000000020002000 RSI: 0000000000000000 RDI: 0000000000000000
> RBP: 00000000007180a8 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000020000fe0 R11: 0000000000000216 R12: 00000000ffffffff
> R13: 0000000000000000 R14: 00000000000005b9 R15: 00007f8ab906d700
> Dumping ftrace buffer:
>    (ftrace buffer empty)
> Kernel Offset: 0x1de00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
> Rebooting in 86400 seconds..
> 
> I'm not 100% sure it's related, but that WARN isn't in any new code.

It seems that somebody else has also reported it. Anyway it doesn't look like
related. I rather think the recent commits on posix-timers are concerned.

Thanks a lot for your help Sasha!