Message-ID: <20150406235126.GA6023@amt.cnet>
Date:	Mon, 6 Apr 2015 20:51:26 -0300
From:	Marcelo Tosatti <mtosatti@...hat.com>
To:	Frederic Weisbecker <fweisbec@...il.com>
Cc:	linux-kernel@...r.kernel.org, Rik van Riel <riel@...hat.com>,
	Thomas Gleixner <tglx@...utronix.de>,
	"Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>,
	Viresh Kumar <viresh.kumar@...aro.org>
Subject: Re: kernel/timer: avoid spurious ksoftirqd wakeups

On Tue, Apr 07, 2015 at 01:34:15AM +0200, Frederic Weisbecker wrote:
> On Thu, Apr 02, 2015 at 06:08:09PM -0300, Marcelo Tosatti wrote:
> > On Thu, Apr 02, 2015 at 04:59:40PM +0200, Frederic Weisbecker wrote:
> > > On Wed, Apr 01, 2015 at 10:44:55PM -0300, Marcelo Tosatti wrote:
> > > > 
> > > > It is only necessary to raise timer softirq
> > > > in case there are active timers or irq work 
> > > > to do.
> > > > 
> > > > Limit the ksoftirqd wakeup to those cases.
> > > > 
> > > > Fixes a latency spike with isolated CPUs and 
> > > > nohz full mode.
> > > > 
> > > > Reported-and-tested-by: Luiz Capitulino <lcapitulino@...hat.com>
> > > > Signed-off-by: Marcelo Tosatti <mtosatti@...hat.com>
> > > > 
> > > > diff --git a/include/linux/timer.h b/include/linux/timer.h
> > > > index 8c5a197..0c065f9 100644
> > > > --- a/include/linux/timer.h
> > > > +++ b/include/linux/timer.h
> > > > @@ -192,7 +192,7 @@ extern void set_timer_slack(struct timer_list *time, int slack_hz);
> > > >   * locks the timer base and does the comparison against the given
> > > >   * jiffie.
> > > >   */
> > > > -extern unsigned long get_next_timer_interrupt(unsigned long now);
> > > > +extern unsigned long get_next_timer_interrupt(unsigned long now, bool *raise_softirq);
> > > >  
> > > >  /*
> > > >   * Timer-statistics info:
> > > > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > > > index a4c4eda..615e276 100644
> > > > --- a/kernel/time/tick-sched.c
> > > > +++ b/kernel/time/tick-sched.c
> > > > @@ -568,6 +568,7 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> > > >  	unsigned long rcu_delta_jiffies;
> > > >  	struct clock_event_device *dev = __this_cpu_read(tick_cpu_device.evtdev);
> > > >  	u64 time_delta;
> > > > +	bool raise_softirq;
> > > >  
> > > >  	time_delta = timekeeping_max_deferment();
> > > >  
> > > > @@ -582,9 +583,11 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> > > >  	    arch_needs_cpu() || irq_work_needs_cpu()) {
> > > >  		next_jiffies = last_jiffies + 1;
> > > >  		delta_jiffies = 1;
> > > > +		raise_softirq = true;
> > > 
> > > I believe that irq_work doesn't need the softirq. 
> > 
> > Can drop that, right.
> > 
> > > It needs a tick only in order to call
> > > irq_work_tick(). And I believe this is the same for RCU which needs a call to
> > > rcu_check_callbacks(), but it might need something else that the softirq does
> > > (but this is the timer softirq, not the rcu one). 
> > > 
> > > >  	} else {
> > > >  		/* Get the next timer wheel timer */
> > > > -		next_jiffies = get_next_timer_interrupt(last_jiffies);
> > > > +		next_jiffies = get_next_timer_interrupt(last_jiffies,
> > > > +							&raise_softirq);
> > > >  		delta_jiffies = next_jiffies - last_jiffies;
> > > >  		if (rcu_delta_jiffies < delta_jiffies) {
> > > >  			next_jiffies = last_jiffies + rcu_delta_jiffies;
> > > > @@ -703,7 +706,8 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
> > > >  		 */
> > > >  		tick_do_update_jiffies64(ktime_get());
> > > >  	}
> > > > -	raise_softirq_irqoff(TIMER_SOFTIRQ);
> > > > +	if (raise_softirq)
> > > > +		raise_softirq_irqoff(TIMER_SOFTIRQ);
> > > >  out:
> > > >  	ts->next_jiffies = next_jiffies;
> > > >  	ts->last_jiffies = last_jiffies;
> > > 
> > > Lets look at the things outside the pending timer list that can end up failing
> > > to program the timer because it is in the past already:
> > 
> > Is this an attempt to find possible regressions introduced 
> > by this change ?
> 
> Yeah, it would be nice to make sure that the cause of these softirqs isn't
> mistakenly ignored. 
> And also I want to be sure we really understand what we
> are doing, which is not the case right now as we don't know what is causing
> this expired timer.

What is the interrupt that is the cause for tick_nohz_stop_sched_tick,
you mean? 

       <...>-45815 [015] d...2.. 25722056692012 (+961446): kvm_exit: reason EXTERNAL_INTERRUPT rip 0x7f5e448479d0 info 0 800000ef
       <...>-45815 [015] d..h1.. 25722056692844 (+832): apic_timer_fn<-__run_hrtimer
       <...>-45815 [015] d...1.. 25722056695442 (+2598): raise_softirq_irqoff <-tick_nohz_stop_sched_tick

Emulation of guest APIC timer by hrtimer (apic_timer_fn).

> > > _ timekeeping_max_deferment(): I doubt, the value is pretty high
> > > _ scheduler_tick_max_deferment(); it's one second long, way enough to never be in
> > >   the past by the time we program the clock
> > > _ RCU, irq_work, arch: may be, if the last jiffies update is far enough. But apparently
> > >   the problem is elsewhere since you keep the softirq for these and your patch solves your
> > >   problem.
> > > _ In case hrtimer runs in low-res mode and the next hrtimer is very close, or even in the past
> > >   already, you may run into such issue. And hrtimer doesn't need the timer softirq, at least not
> > >   to run the callbacks. It needs it only if hrtimer is switching to high-res mode, I think it's
> > >   a rare event.
> > > 
> > > Now it would be nice to identify the issue we are facing here. Are you running in hrtimer low-res
> > > mode?
> > 
> > The issue is a latency spike due to ksoftirqd waking up to 
> > process pending timers, processing two deferred timers, 
> > but no non-deferred timers.
> > 
> > hrtimer is not in low-res mode.
> > 
> > The issue is ksoftirqd waking up in the first place.
> 
> Sure, but why is it waking up exactly?

Because there is a bug (the patch is trying to fix the bug by 
raising timer softirq only when timer softirq handler has any 
work to do).

The only timers pending in the timer list are deferred ones
from vmstat_update:

ksoftirqd/15-265   [015] ....111 25722056709372 (+7098): softirq_entry: vec=1 [action=TIMER]
ksoftirqd/15-265   [015] .....11 25722056709964 (+592): run_timer_softirq <-do_current_softirqs
ksoftirqd/15-265   [015] ....111 25722056714034 (+4070): timer_expire_entry: timer=ffff88082f6f14a0 function=delayed_work_timer_fn now=4480299175
ksoftirqd/15-265   [015] ....112 25722056715738 (+1704):
workqueue_queue_work: work struct=ffff88082f6f1480 function=vmstat_update workqueue=ffff88041f408000 req_cpu=5120 cpu=15
ksoftirqd/15-265   [015] ....112 25722056716304 (+566): workqueue_activate_work: work struct ffff88082f6f1480
ksoftirqd/15-265   [015] ....111 25722056719052 (+2748): timer_expire_exit: timer=ffff88082f6f14a0
ksoftirqd/15-265   [015] ....111 25722056719384 (+332): softirq_exit: vec=1 [action=TIMER]

Which should only be processed once there are actual add_timer timers
being fired (there are no such add_timer timers on this CPU).

Does that make sense?


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Powered by blists - more mailing lists