lkml.org 
[lkml]   [2018]   [Apr]   [4]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
Subjectsched_rt_period_timer causing large latencies
Hi,

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
changed?

Thanks,
Nick

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