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

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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



[Index of Archives]     [Linux Kernel]     [Kernel Development Newbies]     [Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Yosemite Hiking]     [Linux Kernel]     [Linux SCSI]