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
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 <[email protected]>
Signed-off-by: Frederic Weisbecker <[email protected]>
Cc: Tim Wright <[email protected]>
Cc: Pavel Machek <[email protected]>
Cc: James Hartsock <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Cc: Ingo Molnar <[email protected]>
---
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
(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 <[email protected]>
Reported-and-tested-by: Pavel Machek <[email protected]>
Reported-by: James Hartsock <[email protected]>
Acked-by: Rik van Riel <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: [email protected]
Signed-off-by: Frederic Weisbecker <[email protected]>
---
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
Commit-ID: d58bd60c773d8b16c19c4b9533bceee3761eb804
Gitweb: http://git.kernel.org/tip/d58bd60c773d8b16c19c4b9533bceee3761eb804
Author: Frederic Weisbecker <[email protected]>
AuthorDate: Fri, 21 Apr 2017 16:00:54 +0200
Committer: Thomas Gleixner <[email protected]>
CommitDate: Sun, 23 Apr 2017 13:33:18 +0200
nohz: Fix again collision between tick and other hrtimers
(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 <[email protected]>
Reported-and-tested-by: Pavel Machek <[email protected]>
Reported-by: James Hartsock <[email protected]>
Signed-off-by: Frederic Weisbecker <[email protected]>
Acked-by: Rik van Riel <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: [email protected]
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Thomas Gleixner <[email protected]>
---
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;
Commit-ID: 22aa2ad45fd8a6ef56eb60038fc0ac7059c0a986
Gitweb: http://git.kernel.org/tip/22aa2ad45fd8a6ef56eb60038fc0ac7059c0a986
Author: Frederic Weisbecker <[email protected]>
AuthorDate: Fri, 21 Apr 2017 16:00:55 +0200
Committer: Thomas Gleixner <[email protected]>
CommitDate: Sun, 23 Apr 2017 13:33:18 +0200
tick: Make sure tick timer is active when bypassing reprogramming
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 <[email protected]>
Acked-by: Rik van Riel <[email protected]>
Cc: James Hartsock <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: [email protected]
Cc: Tim Wright <[email protected]>
Cc: Pavel Machek <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Thomas Gleixner <[email protected]>
---
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
* Frederic Weisbecker <[email protected]> wrote:
> As suggested by Thomas Gleixner, the second patch now integrates
> a fix in case the sanity check fails and the clockevent isn't programmed
> as expected.
>
> Frederic Weisbecker (2):
> nohz: Fix again collision between tick and other hrtimers
> tick: Make sure tick timer is active when bypassing reprogramming
>
> kernel/time/tick-sched.c | 33 ++++++++++++++++++++++++++++++---
> kernel/time/tick-sched.h | 2 ++
> 2 files changed, 32 insertions(+), 3 deletions(-)
So I think one of these is causing a new warning on latest -tip:
[ 333.341756] ------------[ cut here ]------------
[ 333.346404] WARNING: CPU: 0 PID: 0 at kernel/time/tick-sched.c:874 __tick_nohz_idle_enter+0x461/0x490
[ 333.355614] Modules linked in:
[ 333.358679] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.11.0-rc7-00955-g76f8909-dirty #1
[ 333.366761] Hardware name: Supermicro H8DG6/H8DGi/H8DG6/H8DGi, BIOS 2.0b 03/01/2012
[ 333.374935] task: ffffffff81e0e4c0 task.stack: ffffffff81e00000
[ 333.380859] RIP: 0010:__tick_nohz_idle_enter+0x461/0x490
[ 333.386167] RSP: 0018:ffff880417c03f38 EFLAGS: 00010093
[ 333.391395] RAX: 0000004d99348555 RBX: 0000004d7a84b800 RCX: 0000000000000001
[ 333.398527] RDX: 7fffffffffffffff RSI: 0000000000000001 RDI: 0000004d7a84b800
[ 333.405659] RBP: ffff880417c03f90 R08: 000000000004fdfe R09: 0000000000000000
[ 333.412792] R10: ffffffffffffff0a R11: 00000001000082f8 R12: 0000004d9934d4df
[ 333.419926] R13: 0000000000000000 R14: ffff880417c0c740 R15: ffff880417c14880
[ 333.427060] FS: 0000000000000000(0000) GS:ffff880417c00000(0000) knlGS:0000000000000000
[ 333.435145] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 333.440892] CR2: 00007fbb1024b010 CR3: 000000081451a000 CR4: 00000000000406f0
[ 333.448024] Call Trace:
[ 333.450477] <IRQ>
[ 333.452510] tick_nohz_irq_exit+0x25/0x30
[ 333.456523] irq_exit+0xa4/0xc0
[ 333.459667] do_IRQ+0x4f/0xd0
[ 333.462638] common_interrupt+0x90/0x90
[ 333.466478] RIP: 0010:acpi_idle_do_entry+0x31/0x40
[ 333.471296] RSP: 0018:ffffffff81e03d90 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffc1
[ 333.478862] RAX: 0000000000080000 RBX: ffff880c163b1000 RCX: 000000000000001f
[ 333.485995] RDX: 4ec4ec4ec4ec4ec5 RSI: 0000000000000034 RDI: ffff880c163b1064
[ 333.493128] RBP: ffffffff81e03dd8 R08: ffff880417c18324 R09: 0000000000000008
[ 333.500260] R10: ffffffff81e03dc8 R11: 0000000000000002 R12: ffff880c163b1064
[ 333.507386] R13: 0000000000000001 R14: 0000000000000001 R15: 0000000000000001
[ 333.514519] </IRQ>
[ 333.516630] ? acpi_idle_enter+0x10c/0x2c0
[ 333.520728] cpuidle_enter_state+0xfa/0x2a0
[ 333.524911] cpuidle_enter+0x17/0x20
[ 333.528494] call_cpuidle+0x23/0x40
[ 333.532001] do_idle+0x174/0x1b0
[ 333.535236] cpu_startup_entry+0x71/0x80
[ 333.539161] rest_init+0x77/0x80
[ 333.542394] start_kernel+0x429/0x44a
[ 333.546061] x86_64_start_reservations+0x2a/0x2c
[ 333.550706] x86_64_start_kernel+0x168/0x176
[ 333.554980] secondary_startup_64+0x9f/0x9f
[ 333.559163] Code: fd ff ff b9 02 00 00 00 31 d2 48 89 de 4c 89 ff e8 e5 0a ff ff 49 8b 46 18 e9 72 fe ff ff 49 8b 46 18 48 39 c3 0f 8d 65 fe ff ff <0f> ff e9 2b fe ff ff 41 83 7f 48 02 0f 85 4f fe ff ff 4c 89 ff
[ 333.578100] ---[ end trace 782ee3b70f3c99e1 ]---
I saw this warning on Intel and AMD systems as well.
Config attached.
Thanks,
Ingo
On Mon, Apr 24, 2017 at 10:08:35AM +0200, Ingo Molnar wrote:
>
> * Frederic Weisbecker <[email protected]> wrote:
>
> > As suggested by Thomas Gleixner, the second patch now integrates
> > a fix in case the sanity check fails and the clockevent isn't programmed
> > as expected.
> >
> > Frederic Weisbecker (2):
> > nohz: Fix again collision between tick and other hrtimers
> > tick: Make sure tick timer is active when bypassing reprogramming
> >
> > kernel/time/tick-sched.c | 33 ++++++++++++++++++++++++++++++---
> > kernel/time/tick-sched.h | 2 ++
> > 2 files changed, 32 insertions(+), 3 deletions(-)
>
> So I think one of these is causing a new warning on latest -tip:
>
> [ 333.341756] ------------[ cut here ]------------
> [ 333.346404] WARNING: CPU: 0 PID: 0 at kernel/time/tick-sched.c:874 __tick_nohz_idle_enter+0x461/0x490
Oh I'll never be done with that bug :)
Ok I just booted your config with tip/master and didn't see the warning.
But the boot seem to be stalled some time after mounting the root fs.
Can you please try the following patch and tell me what it returns to you?
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index c47d135..6d72e8b 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -872,6 +872,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
goto out;
WARN_ON_ONCE(1);
+ printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
}
/*
* Frederic Weisbecker <[email protected]> wrote:
> On Mon, Apr 24, 2017 at 10:08:35AM +0200, Ingo Molnar wrote:
> >
> > * Frederic Weisbecker <[email protected]> wrote:
> >
> > > As suggested by Thomas Gleixner, the second patch now integrates
> > > a fix in case the sanity check fails and the clockevent isn't programmed
> > > as expected.
> > >
> > > Frederic Weisbecker (2):
> > > nohz: Fix again collision between tick and other hrtimers
> > > tick: Make sure tick timer is active when bypassing reprogramming
> > >
> > > kernel/time/tick-sched.c | 33 ++++++++++++++++++++++++++++++---
> > > kernel/time/tick-sched.h | 2 ++
> > > 2 files changed, 32 insertions(+), 3 deletions(-)
> >
> > So I think one of these is causing a new warning on latest -tip:
> >
> > [ 333.341756] ------------[ cut here ]------------
> > [ 333.346404] WARNING: CPU: 0 PID: 0 at kernel/time/tick-sched.c:874 __tick_nohz_idle_enter+0x461/0x490
>
> Oh I'll never be done with that bug :)
>
> Ok I just booted your config with tip/master and didn't see the warning.
> But the boot seem to be stalled some time after mounting the root fs.
>
> Can you please try the following patch and tell me what it returns to you?
>
> diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> index c47d135..6d72e8b 100644
> --- a/kernel/time/tick-sched.c
> +++ b/kernel/time/tick-sched.c
> @@ -872,6 +872,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> goto out;
>
> WARN_ON_ONCE(1);
> + printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
> }
>
Here's what it prints:
[ 707.251791] basemono: 706016000000 ts->next_tick: 693216000000 dev->next_event: 706016406127
Full bootlog attached.
Thanks,
Ingo
Commit-ID: 098991fccfc7c0dd5fdfc6ed2ed965ad80f14be5
Gitweb: http://git.kernel.org/tip/098991fccfc7c0dd5fdfc6ed2ed965ad80f14be5
Author: Frederic Weisbecker <[email protected]>
AuthorDate: Mon, 24 Apr 2017 16:04:37 +0200
Committer: Ingo Molnar <[email protected]>
CommitDate: Mon, 24 Apr 2017 16:27:09 +0200
nohz: Print more debug info in tick_nohz_stop_sched_tick()
Print more debug info when triggering this warning:
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 0 at kernel/time/tick-sched.c:874 __tick_nohz_idle_enter+0x461/0x490
Signed-off-by: Frederic Weisbecker <[email protected]>
Cc: James Hartsock <[email protected]>
Cc: Linus Torvalds <[email protected]>
Cc: Pavel Machek <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Rik van Riel <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Cc: Tim Wright <[email protected]>
Link: http://lkml.kernel.org/r/20170424140436.GD21353@lerouge
Signed-off-by: Ingo Molnar <[email protected]>
---
kernel/time/tick-sched.c | 1 +
1 file changed, 1 insertion(+)
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index be7ca4d..b2df684 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -789,6 +789,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
goto out;
WARN_ON_ONCE(1);
+ printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
}
/*
On Mon, Apr 24, 2017 at 04:45:23PM +0200, Ingo Molnar wrote:
>
> * Frederic Weisbecker <[email protected]> wrote:
>
> > On Mon, Apr 24, 2017 at 10:08:35AM +0200, Ingo Molnar wrote:
> > >
> > > * Frederic Weisbecker <[email protected]> wrote:
> > >
> > > > As suggested by Thomas Gleixner, the second patch now integrates
> > > > a fix in case the sanity check fails and the clockevent isn't programmed
> > > > as expected.
> > > >
> > > > Frederic Weisbecker (2):
> > > > nohz: Fix again collision between tick and other hrtimers
> > > > tick: Make sure tick timer is active when bypassing reprogramming
> > > >
> > > > kernel/time/tick-sched.c | 33 ++++++++++++++++++++++++++++++---
> > > > kernel/time/tick-sched.h | 2 ++
> > > > 2 files changed, 32 insertions(+), 3 deletions(-)
> > >
> > > So I think one of these is causing a new warning on latest -tip:
> > >
> > > [ 333.341756] ------------[ cut here ]------------
> > > [ 333.346404] WARNING: CPU: 0 PID: 0 at kernel/time/tick-sched.c:874 __tick_nohz_idle_enter+0x461/0x490
> >
> > Oh I'll never be done with that bug :)
> >
> > Ok I just booted your config with tip/master and didn't see the warning.
> > But the boot seem to be stalled some time after mounting the root fs.
> >
> > Can you please try the following patch and tell me what it returns to you?
> >
> > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > index c47d135..6d72e8b 100644
> > --- a/kernel/time/tick-sched.c
> > +++ b/kernel/time/tick-sched.c
> > @@ -872,6 +872,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> > goto out;
> >
> > WARN_ON_ONCE(1);
> > + printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
> > }
> >
>
> Here's what it prints:
>
> [ 707.251791] basemono: 706016000000 ts->next_tick: 693216000000 dev->next_event: 706016406127
So weird...
Ok I'm going to need serious traces. Can you please add this boot option?
trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry
And please also apply the following (on top of tip/tmp.tmp), it would be interesting to see
the resulting trace file from the CPU where the warning triggers.
Thanks Ingo!
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index b2df684..b4a6dda 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -156,6 +156,7 @@ static void tick_sched_handle(struct tick_sched *ts, struct pt_regs *regs)
* to the same deadline.
*/
ts->next_tick = 0;
+ trace_printk("ts->next_tick reset (tick)\n");
}
#endif
update_process_times(user_mode(regs));
@@ -672,6 +673,7 @@ static void tick_nohz_restart(struct tick_sched *ts, ktime_t now)
* cached clock deadline.
*/
ts->next_tick = 0;
+ trace_printk("ts->next_tick reset (tick restart)\n");
}
static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
@@ -789,6 +791,8 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
goto out;
WARN_ON_ONCE(1);
+ trace_printk("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
+ tracing_stop();
printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
}
@@ -810,6 +814,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
}
ts->next_tick = tick;
+ trace_printk("ts->next_tick = %llu\n", ts->next_tick);
/*
* If the expiration time == KTIME_MAX, then we simply stop
@@ -892,6 +897,7 @@ static bool can_stop_idle_tick(int cpu, struct tick_sched *ts)
* deadline if it comes back online later.
*/
ts->next_tick = 0;
+ trace_printk("ts->next_tick reset (offline)\n");
return false;
}
* Frederic Weisbecker <[email protected]> wrote:
> On Mon, Apr 24, 2017 at 04:45:23PM +0200, Ingo Molnar wrote:
> >
> > * Frederic Weisbecker <[email protected]> wrote:
> >
> > > On Mon, Apr 24, 2017 at 10:08:35AM +0200, Ingo Molnar wrote:
> > > >
> > > > * Frederic Weisbecker <[email protected]> wrote:
> > > >
> > > > > As suggested by Thomas Gleixner, the second patch now integrates
> > > > > a fix in case the sanity check fails and the clockevent isn't programmed
> > > > > as expected.
> > > > >
> > > > > Frederic Weisbecker (2):
> > > > > nohz: Fix again collision between tick and other hrtimers
> > > > > tick: Make sure tick timer is active when bypassing reprogramming
> > > > >
> > > > > kernel/time/tick-sched.c | 33 ++++++++++++++++++++++++++++++---
> > > > > kernel/time/tick-sched.h | 2 ++
> > > > > 2 files changed, 32 insertions(+), 3 deletions(-)
> > > >
> > > > So I think one of these is causing a new warning on latest -tip:
> > > >
> > > > [ 333.341756] ------------[ cut here ]------------
> > > > [ 333.346404] WARNING: CPU: 0 PID: 0 at kernel/time/tick-sched.c:874 __tick_nohz_idle_enter+0x461/0x490
> > >
> > > Oh I'll never be done with that bug :)
> > >
> > > Ok I just booted your config with tip/master and didn't see the warning.
> > > But the boot seem to be stalled some time after mounting the root fs.
> > >
> > > Can you please try the following patch and tell me what it returns to you?
> > >
> > > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > > index c47d135..6d72e8b 100644
> > > --- a/kernel/time/tick-sched.c
> > > +++ b/kernel/time/tick-sched.c
> > > @@ -872,6 +872,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> > > goto out;
> > >
> > > WARN_ON_ONCE(1);
> > > + printk_once("basemono: %llu ts->next_tick: %llu dev->next_event: %llu\n", basemono, ts->next_tick, dev->next_event);
> > > }
> > >
> >
> > Here's what it prints:
> >
> > [ 707.251791] basemono: 706016000000 ts->next_tick: 693216000000 dev->next_event: 706016406127
>
> So weird...
>
> Ok I'm going to need serious traces. Can you please add this boot option?
>
> trace_event=hrtimer_cancel,hrtimer_start,hrtimer_expire_entry
Sorry, don't have the time for extensive traces this close to the merge window -
but are you sure you cannot reproduce it?
The warning popped up on all 3 test systems I tried (two Intel servers, one AMD
server), and it also hit Mike's server - with a fairly regular distro-ish config.
Thanks,
Ingo
On Wed, Apr 26, 2017 at 08:49:13PM +0200, Ingo Molnar wrote:
> Sorry, don't have the time for extensive traces this close to the merge window -
> but are you sure you cannot reproduce it?
>
> The warning popped up on all 3 test systems I tried (two Intel servers, one AMD
> server), and it also hit Mike's server - with a fairly regular distro-ish config.
Fair point, I'll try on other machines than my main one.
Thanks.
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
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
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
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))
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
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))
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
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 <[email protected]>
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 <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Rik van Riel <[email protected]>
Cc: James Hartsock <[email protected]>
Cc: Tim Wright <[email protected]>
Signed-off-by: Frederic Weisbecker <[email protected]>
---
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
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
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 <[email protected]>
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 <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Rik van Riel <[email protected]>
Cc: James Hartsock <[email protected]>
Cc: Tim Wright <[email protected]>
Signed-off-by: Frederic Weisbecker <[email protected]>
---
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
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
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/[email protected]
has a very similar splat
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!