[lkml]   [2018]   [Apr]   [4]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
Messages in this thread
Subjectsched_rt_period_timer causing large latencies

I'm seeing some pretty big latencies on a ~idle system when a CPU wakes
out of a nohz idle. Looks like it's due to the taking a lot of remote
locks and cache lines. irqoff trace:

latency: 407 us, #608/608, CPU#3 | (M:server VP:0, KP:0, SP:0 HP:0 #P:176)

<idle>-0 3d... 0us : decrementer_common
<idle>-0 3d... 1us : timer_interrupt <-decrementer_common
<idle>-0 3d... 2us : irq_enter <-timer_interrupt
<idle>-0 3d... 2us : rcu_irq_enter <-irq_enter
<idle>-0 3d... 3us : rcu_nmi_enter <-irq_enter
<idle>-0 3d... 4us : rcu_dynticks_eqs_exit <-rcu_nmi_enter
<idle>-0 3d... 4us : __local_bh_disable_ip <-irq_enter
<idle>-0 3d... 5us : tick_irq_enter <-irq_enter
<idle>-0 3d... 6us : tick_check_oneshot_broadcast_this_cpu <-tick_irq_enter
<idle>-0 3d... 6us : ktime_get <-tick_irq_enter
<idle>-0 3d... 7us : update_ts_time_stats <-tick_irq_enter
<idle>-0 3d... 8us : nr_iowait_cpu <-update_ts_time_stats
<idle>-0 3d... 9us : _local_bh_enable <-irq_enter
<idle>-0 3d... 10us : __local_bh_enable <-irq_enter
<idle>-0 3d.h. 10us : __timer_interrupt <-timer_interrupt
<idle>-0 3d.h. 11us : hrtimer_interrupt <-__timer_interrupt
<idle>-0 3d.h. 12us : _raw_spin_lock_irqsave <-hrtimer_interrupt
<idle>-0 3d.h. 13us : ktime_get_update_offsets_now <-hrtimer_interrupt
<idle>-0 3d.h. 13us : __hrtimer_run_queues <-hrtimer_interrupt
<idle>-0 3d.h. 14us : __remove_hrtimer <-__hrtimer_run_queues
<idle>-0 3d.h. 15us : _raw_spin_unlock_irqrestore <-__hrtimer_run_queues
<idle>-0 3d.h. 16us : tick_sched_timer <-__hrtimer_run_queues
<idle>-0 3d.h. 16us : ktime_get <-tick_sched_timer
<idle>-0 3d.h. 17us : tick_sched_do_timer <-tick_sched_timer
<idle>-0 3d.h. 18us : tick_sched_handle.isra.5 <-tick_sched_timer
<idle>-0 3d.h. 19us : update_process_times <-tick_sched_handle.isra.5
<idle>-0 3d.h. 19us : account_process_tick <-update_process_times
<idle>-0 3d.h. 20us : run_local_timers <-update_process_times
<idle>-0 3d.h. 21us : hrtimer_run_queues <-run_local_timers
<idle>-0 3d.h. 21us : raise_softirq <-run_local_timers
<idle>-0 3d.h. 22us : __raise_softirq_irqoff <-raise_softirq
<idle>-0 3d.h. 23us : rcu_check_callbacks <-update_process_times
<idle>-0 3d.h. 24us : rcu_sched_qs <-rcu_check_callbacks
<idle>-0 3d.h. 25us : rcu_bh_qs <-rcu_check_callbacks
<idle>-0 3d.h. 25us : rcu_segcblist_ready_cbs <-rcu_check_callbacks
<idle>-0 3d.h. 26us : cpu_needs_another_gp <-rcu_check_callbacks
<idle>-0 3d.h. 27us : invoke_rcu_core <-rcu_check_callbacks
<idle>-0 3d.h. 28us : raise_softirq <-invoke_rcu_core
<idle>-0 3d.h. 28us : __raise_softirq_irqoff <-raise_softirq
<idle>-0 3d.h. 29us : scheduler_tick <-update_process_times
<idle>-0 3d.h. 30us : _raw_spin_lock <-scheduler_tick
<idle>-0 3d.h. 31us : update_rq_clock <-scheduler_tick
<idle>-0 3d.h. 31us : task_tick_idle <-scheduler_tick
<idle>-0 3d.h. 32us : cpu_load_update_active <-scheduler_tick
<idle>-0 3d.h. 33us : tick_nohz_tick_stopped <-cpu_load_update_active
<idle>-0 3d.h. 33us : cpu_load_update <-scheduler_tick
<idle>-0 3d.h. 34us : sched_avg_update <-cpu_load_update
<idle>-0 3d.h. 35us : calc_global_load_tick <-scheduler_tick
<idle>-0 3d.h. 36us : trigger_load_balance <-scheduler_tick
<idle>-0 3d.h. 36us : raise_softirq <-trigger_load_balance
<idle>-0 3d.h. 37us : __raise_softirq_irqoff <-raise_softirq
<idle>-0 3d.h. 38us : run_posix_cpu_timers <-update_process_times
<idle>-0 3d.h. 39us : profile_tick <-tick_sched_handle.isra.5
<idle>-0 3d.h. 39us : hrtimer_forward <-tick_sched_timer
<idle>-0 3d.h. 40us : _raw_spin_lock_irq <-__hrtimer_run_queues
<idle>-0 3d.h. 41us : enqueue_hrtimer <-__hrtimer_run_queues
<idle>-0 3d.h. 42us : __remove_hrtimer <-__hrtimer_run_queues
<idle>-0 3d.h. 42us : _raw_spin_unlock_irqrestore <-__hrtimer_run_queues
<idle>-0 3d.h. 44us : sched_rt_period_timer <-__hrtimer_run_queues
<idle>-0 3d.h. 44us : _raw_spin_lock <-sched_rt_period_timer
<idle>-0 3d.h. 45us : ktime_get <-sched_rt_period_timer
<idle>-0 3d.h. 46us : hrtimer_forward <-sched_rt_period_timer
<idle>-0 3d.h. 47us : _raw_spin_lock <-sched_rt_period_timer
<idle>-0 3d.h. 48us : _raw_spin_lock <-sched_rt_period_timer
... 527 more locks snipped ...
<idle>-0 3d.h. 403us : ktime_get <-sched_rt_period_timer
<idle>-0 3d.h. 403us : hrtimer_forward <-sched_rt_period_timer
<idle>-0 3d.h. 404us : _raw_spin_lock_irq <-__hrtimer_run_queues
<idle>-0 3d.h. 404us : __hrtimer_get_next_event <-hrtimer_interrupt
<idle>-0 3d.h. 404us : __hrtimer_next_event_base <-__hrtimer_get_next_event
<idle>-0 3d.h. 405us : __hrtimer_next_event_base <-hrtimer_interrupt
<idle>-0 3d.h. 405us : _raw_spin_unlock_irqrestore <-hrtimer_interrupt
<idle>-0 3d.h. 405us : tick_program_event <-hrtimer_interrupt
<idle>-0 3d.h. 406us : clockevents_program_event <-tick_program_event
<idle>-0 3d.h. 406us : ktime_get <-clockevents_program_event
<idle>-0 3d.h. 406us : decrementer_set_next_event <-clockevents_program_event
<idle>-0 3d.h. 407us : irq_exit <-timer_interrupt
<idle>-0 3d... 407us : __do_softirq <-irq_exit
<idle>-0 3d... 407us : __local_bh_disable_ip <-__do_softirq
<idle>-0 3d.s. 408us : __do_softirq
<idle>-0 3d.s. 408us : trace_hardirqs_on <-__do_softirq
<idle>-0 3d.s. 411us : <stack trace>

This is only a 2 socket system with 176 CPUs, so not huge or extreme
remote latency. I suspect this contributes to significantly higher
occasional latency spikes when it hits some runqueue lock contention.

Any way this can be improved? Any config options or settings should be


 \ /
  Last update: 2018-04-05 01:13    [W:0.086 / U:1.992 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site