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

[Frederic Weisbecker <fweisbec@gmail.com>]

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!