2.6.14-rt22 (and mainline) excessive latency

2.6.14-rt22 (and mainline) excessive latency

[Lee Revell]

I captured this 3+ ms latency trace when killing a process with a few
thousand threads.  Can a cond_resched be added to this code path?

preemption latency trace v1.1.5 on 2.6.14-rt22
--------------------------------------------------------------------
 latency: 3321 us, #2830/2830, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
    -----------------
    | task: softirq-timer/0-3 (uid:0 nice:0 policy:1 rt_prio:1)
    -----------------

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> need-resched
               || / _---=> hardirq/softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
    bash-17992 0D.h2    1us : __trace_start_sched_wakeup (try_to_wake_up)
    bash-17992 0D.h2    1us : __trace_start_sched_wakeup <<...>-3> (62 0)
    bash-17992 0D.h.    2us : wake_up_process (wakeup_softirqd)
    bash-17992 0D.h.    3us : rcu_check_callbacks (update_process_times)
    bash-17992 0D.h.    3us : idle_cpu (rcu_check_callbacks)
    bash-17992 0D.h.    4us : __tasklet_schedule (rcu_check_callbacks)
    bash-17992 0D.h.    5us : wakeup_softirqd (__tasklet_schedule)
    bash-17992 0D.h.    6us : wake_up_process (wakeup_softirqd)
    bash-17992 0D.h.    6us : try_to_wake_up (wake_up_process)
    bash-17992 0D.h1    7us : activate_task (try_to_wake_up)
    bash-17992 0D.h1    8us : sched_clock (activate_task)
    bash-17992 0D.h1    9us : recalc_task_prio (activate_task)
    bash-17992 0D.h1   10us : __recalc_task_prio (recalc_task_prio)
    bash-17992 0D.h1   10us : __recalc_task_prio <<...>-7> (62 62)
    bash-17992 0D.h1   11us : activate_task <<...>-7> (62 d)
    bash-17992 0D.h1   12us : enqueue_task (activate_task)
    bash-17992 0D.h1   12us : __trace_start_sched_wakeup (try_to_wake_up)
    bash-17992 0D.h.   14us : wake_up_process (wakeup_softirqd)
    bash-17992 0D.h.   14us : scheduler_tick (update_process_times)
    bash-17992 0D.h.   15us : sched_clock (scheduler_tick)
    bash-17992 0D.h1   16us : task_timeslice (scheduler_tick)
    bash-17992 0D.h.   17us : run_posix_cpu_timers (update_process_times)
    bash-17992 0D.h1   19us : note_interrupt (__do_IRQ)
    bash-17992 0D.h1   19us : end_8259A_irq (__do_IRQ)
    bash-17992 0D.h1   20us+: enable_8259A_irq (end_8259A_irq)
    bash-17992 0Dnh1   22us : irq_exit (do_IRQ)
    bash-17992 0Dn.1   23us < (608)
    bash-17992 0.n.1   24us : eligible_child (do_wait)
    bash-17992 0.n.1   25us : eligible_child (do_wait)
    bash-17992 0.n.1   26us : eligible_child (do_wait)
    bash-17992 0.n.1   28us : eligible_child (do_wait)
    bash-17992 0.n.1   29us : eligible_child (do_wait)

    [ 3000+ of these deleted ]

    bash-17992 0.n.1 3296us : eligible_child (do_wait)
    bash-17992 0.n.1 3297us : eligible_child (do_wait)
    bash-17992 0.n.1 3298us : eligible_child (do_wait)
    bash-17992 0.n.1 3299us : eligible_child (do_wait)
    bash-17992 0.n.1 3300us : eligible_child (do_wait)
    bash-17992 0.n.1 3301us : eligible_child (do_wait)
    bash-17992 0.n.1 3303us : eligible_child (do_wait)
    bash-17992 0.n.1 3304us : next_thread (do_wait)
    bash-17992 0.n.. 3305us : preempt_schedule (do_wait)
    bash-17992 0Dn.. 3306us : __schedule (preempt_schedule)
    bash-17992 0Dn.. 3307us : profile_hit (__schedule)
    bash-17992 0Dn.1 3308us+: sched_clock (__schedule)
   <...>-3     0D..2 3314us+: __switch_to (__schedule)
   <...>-3     0D..2 3316us : __schedule <bash-17992> (73 62)
   <...>-3     0...1 3317us : trace_stop_sched_switched (__schedule)
   <...>-3     0D..2 3318us : trace_stop_sched_switched <<...>-3> (62 0)
   <...>-3     0D..2 3320us : trace_stop_sched_switched (__schedule)

Re: 2.6.14-rt22 (and mainline) excessive latency

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> I captured this 3+ ms latency trace when killing a process with a few 
> thousand threads.  Can a cond_resched be added to this code path?

>     bash-17992 0.n.1   29us : eligible_child (do_wait)
> 
>     [ 3000+ of these deleted ]
> 
>     bash-17992 0.n.1 3296us : eligible_child (do_wait)

Atomicity of signal delivery is pretty much a must, so i'm not sure this 
particular latency can be fixed, short of running PREEMPT_RT. Paul E.  
McKenney is doing some excellent stuff by RCU-ifying the task lookup and 
signal code, but i'm not sure whether it could cover do_wait().

	Ingo

Re: 2.6.14-rt22 (and mainline) excessive latency

[Paul E. McKenney]

On Tue, Dec 20, 2005 at 05:24:42AM +0100, Ingo Molnar wrote:
> 
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > I captured this 3+ ms latency trace when killing a process with a few 
> > thousand threads.  Can a cond_resched be added to this code path?
> 
> >     bash-17992 0.n.1   29us : eligible_child (do_wait)
> > 
> >     [ 3000+ of these deleted ]
> > 
> >     bash-17992 0.n.1 3296us : eligible_child (do_wait)
> 
> Atomicity of signal delivery is pretty much a must, so i'm not sure this 
> particular latency can be fixed, short of running PREEMPT_RT. Paul E.  
> McKenney is doing some excellent stuff by RCU-ifying the task lookup and 
> signal code, but i'm not sure whether it could cover do_wait().

Took a quick break from repeatedly shooting myself in the foot with
RCU read-side priority boosting (still have a few toes left) to take
a quick look at this.  The TASK_TRACED and TASK_STOPPED cases seem
non-trivial, and I am concerned about races with exit.

Any thoughts on whether the latency is due to contention on the
tasklist lock vs. the "goto repeat" in do_wait()?

						Thanx, Paul

Re: 2.6.14-rt22 (and mainline) excessive latency

[Lee Revell]

On Tue, 2005-12-20 at 17:47 -0800, Paul E. McKenney wrote:
> On Tue, Dec 20, 2005 at 05:24:42AM +0100, Ingo Molnar wrote:
> > 
> > * Lee Revell <rlrevell@joe-job.com> wrote:
> > 
> > > I captured this 3+ ms latency trace when killing a process with a few 
> > > thousand threads.  Can a cond_resched be added to this code path?
> > 
> > >     bash-17992 0.n.1   29us : eligible_child (do_wait)
> > > 
> > >     [ 3000+ of these deleted ]
> > > 
> > >     bash-17992 0.n.1 3296us : eligible_child (do_wait)
> > 
> > Atomicity of signal delivery is pretty much a must, so i'm not sure this 
> > particular latency can be fixed, short of running PREEMPT_RT. Paul E.  
> > McKenney is doing some excellent stuff by RCU-ifying the task lookup and 
> > signal code, but i'm not sure whether it could cover do_wait().
> 
> Took a quick break from repeatedly shooting myself in the foot with
> RCU read-side priority boosting (still have a few toes left) to take
> a quick look at this.  The TASK_TRACED and TASK_STOPPED cases seem
> non-trivial, and I am concerned about races with exit.
> 
> Any thoughts on whether the latency is due to contention on the
> tasklist lock vs. the "goto repeat" in do_wait()?

It's a UP system so I'd be surprised if there were any contention.

Lee

Re: 2.6.14-rt22 (and mainline) excessive latency

[Paul E. McKenney]

On Tue, Dec 20, 2005 at 10:32:48PM -0500, Lee Revell wrote:
> On Tue, 2005-12-20 at 17:47 -0800, Paul E. McKenney wrote:
> > On Tue, Dec 20, 2005 at 05:24:42AM +0100, Ingo Molnar wrote:
> > > 
> > > * Lee Revell <rlrevell@joe-job.com> wrote:
> > > 
> > > > I captured this 3+ ms latency trace when killing a process with a few 
> > > > thousand threads.  Can a cond_resched be added to this code path?
> > > 
> > > >     bash-17992 0.n.1   29us : eligible_child (do_wait)
> > > > 
> > > >     [ 3000+ of these deleted ]
> > > > 
> > > >     bash-17992 0.n.1 3296us : eligible_child (do_wait)
> > > 
> > > Atomicity of signal delivery is pretty much a must, so i'm not sure this 
> > > particular latency can be fixed, short of running PREEMPT_RT. Paul E.  
> > > McKenney is doing some excellent stuff by RCU-ifying the task lookup and 
> > > signal code, but i'm not sure whether it could cover do_wait().
> > 
> > Took a quick break from repeatedly shooting myself in the foot with
> > RCU read-side priority boosting (still have a few toes left) to take
> > a quick look at this.  The TASK_TRACED and TASK_STOPPED cases seem
> > non-trivial, and I am concerned about races with exit.
> > 
> > Any thoughts on whether the latency is due to contention on the
> > tasklist lock vs. the "goto repeat" in do_wait()?
> 
> It's a UP system so I'd be surprised if there were any contention.

Couldn't there be contention due to preemption of someone holding
the tasklist lock?

						Thanx, Paul

Re: 2.6.14-rt22 (and mainline) excessive latency

[Lee Revell]

On Wed, 2005-12-21 at 05:36 -0800, Paul E. McKenney wrote:
> On Tue, Dec 20, 2005 at 10:32:48PM -0500, Lee Revell wrote:
> > On Tue, 2005-12-20 at 17:47 -0800, Paul E. McKenney wrote:
> > > On Tue, Dec 20, 2005 at 05:24:42AM +0100, Ingo Molnar wrote:
> > > > 
> > > > * Lee Revell <rlrevell@joe-job.com> wrote:
> > > > 
> > > > > I captured this 3+ ms latency trace when killing a process with a few 
> > > > > thousand threads.  Can a cond_resched be added to this code path?
> > > > 
> > > > >     bash-17992 0.n.1   29us : eligible_child (do_wait)
> > > > > 
> > > > >     [ 3000+ of these deleted ]
> > > > > 
> > > > >     bash-17992 0.n.1 3296us : eligible_child (do_wait)
> > > > 
> > > > Atomicity of signal delivery is pretty much a must, so i'm not sure this 
> > > > particular latency can be fixed, short of running PREEMPT_RT. Paul E.  
> > > > McKenney is doing some excellent stuff by RCU-ifying the task lookup and 
> > > > signal code, but i'm not sure whether it could cover do_wait().
> > > 
> > > Took a quick break from repeatedly shooting myself in the foot with
> > > RCU read-side priority boosting (still have a few toes left) to take
> > > a quick look at this.  The TASK_TRACED and TASK_STOPPED cases seem
> > > non-trivial, and I am concerned about races with exit.
> > > 
> > > Any thoughts on whether the latency is due to contention on the
> > > tasklist lock vs. the "goto repeat" in do_wait()?
> > 
> > It's a UP system so I'd be surprised if there were any contention.
> 
> Couldn't there be contention due to preemption of someone holding
> the tasklist lock?

But I'm running with PREEMPT_DESKTOP (specifically I configured a system
to have the exact same preemption model as mainline - PREEMPT_DESKTOP
with no soft/hardirq preemption) so holding a spinlock will disable
preemption.

Lee

Re: 2.6.14-rt22 (and mainline) excessive latency

[Paul E. McKenney]

On Wed, Dec 21, 2005 at 02:54:18PM -0500, Lee Revell wrote:
> On Wed, 2005-12-21 at 05:36 -0800, Paul E. McKenney wrote:
> > On Tue, Dec 20, 2005 at 10:32:48PM -0500, Lee Revell wrote:
> > > On Tue, 2005-12-20 at 17:47 -0800, Paul E. McKenney wrote:
> > > > On Tue, Dec 20, 2005 at 05:24:42AM +0100, Ingo Molnar wrote:
> > > > > 
> > > > > * Lee Revell <rlrevell@joe-job.com> wrote:
> > > > > 
> > > > > > I captured this 3+ ms latency trace when killing a process with a few 
> > > > > > thousand threads.  Can a cond_resched be added to this code path?
> > > > > 
> > > > > >     bash-17992 0.n.1   29us : eligible_child (do_wait)
> > > > > > 
> > > > > >     [ 3000+ of these deleted ]
> > > > > > 
> > > > > >     bash-17992 0.n.1 3296us : eligible_child (do_wait)
> > > > > 
> > > > > Atomicity of signal delivery is pretty much a must, so i'm not sure this 
> > > > > particular latency can be fixed, short of running PREEMPT_RT. Paul E.  
> > > > > McKenney is doing some excellent stuff by RCU-ifying the task lookup and 
> > > > > signal code, but i'm not sure whether it could cover do_wait().
> > > > 
> > > > Took a quick break from repeatedly shooting myself in the foot with
> > > > RCU read-side priority boosting (still have a few toes left) to take
> > > > a quick look at this.  The TASK_TRACED and TASK_STOPPED cases seem
> > > > non-trivial, and I am concerned about races with exit.
> > > > 
> > > > Any thoughts on whether the latency is due to contention on the
> > > > tasklist lock vs. the "goto repeat" in do_wait()?
> > > 
> > > It's a UP system so I'd be surprised if there were any contention.
> > 
> > Couldn't there be contention due to preemption of someone holding
> > the tasklist lock?
> 
> But I'm running with PREEMPT_DESKTOP (specifically I configured a system
> to have the exact same preemption model as mainline - PREEMPT_DESKTOP
> with no soft/hardirq preemption) so holding a spinlock will disable
> preemption.

My head just exploded.  I will see about getting you a
CONFIG_FREAKING_INSANE patch, if you are willing to test it.

						Thanx, Paul

Re: 2.6.14-rt22 (and mainline) excessive latency

[Lee Revell]

On Thu, 2005-12-22 at 20:07 -0800, Paul E. McKenney wrote:
> On Wed, Dec 21, 2005 at 02:54:18PM -0500, Lee Revell wrote:
> > On Wed, 2005-12-21 at 05:36 -0800, Paul E. McKenney wrote:
> > > On Tue, Dec 20, 2005 at 10:32:48PM -0500, Lee Revell wrote:
> > > > On Tue, 2005-12-20 at 17:47 -0800, Paul E. McKenney wrote:
> > > > > On Tue, Dec 20, 2005 at 05:24:42AM +0100, Ingo Molnar wrote:
> > > > > > 
> > > > > > * Lee Revell <rlrevell@joe-job.com> wrote:
> > > > > > 
> > > > > > > I captured this 3+ ms latency trace when killing a process with a few 
> > > > > > > thousand threads.  Can a cond_resched be added to this code path?
> > > > > > 
> > > > > > >     bash-17992 0.n.1   29us : eligible_child (do_wait)
> > > > > > > 
> > > > > > >     [ 3000+ of these deleted ]
> > > > > > > 
> > > > > > >     bash-17992 0.n.1 3296us : eligible_child (do_wait)
> > > > > > 
> > > > > > Atomicity of signal delivery is pretty much a must, so i'm not sure this 
> > > > > > particular latency can be fixed, short of running PREEMPT_RT. Paul E.  
> > > > > > McKenney is doing some excellent stuff by RCU-ifying the task lookup and 
> > > > > > signal code, but i'm not sure whether it could cover do_wait().
> > > > > 
> > > > > Took a quick break from repeatedly shooting myself in the foot with
> > > > > RCU read-side priority boosting (still have a few toes left) to take
> > > > > a quick look at this.  The TASK_TRACED and TASK_STOPPED cases seem
> > > > > non-trivial, and I am concerned about races with exit.
> > > > > 
> > > > > Any thoughts on whether the latency is due to contention on the
> > > > > tasklist lock vs. the "goto repeat" in do_wait()?
> > > > 
> > > > It's a UP system so I'd be surprised if there were any contention.
> > > 
> > > Couldn't there be contention due to preemption of someone holding
> > > the tasklist lock?
> > 
> > But I'm running with PREEMPT_DESKTOP (specifically I configured a system
> > to have the exact same preemption model as mainline - PREEMPT_DESKTOP
> > with no soft/hardirq preemption) so holding a spinlock will disable
> > preemption.
> 
> My head just exploded.  I will see about getting you a
> CONFIG_FREAKING_INSANE patch, if you are willing to test it.

I'm not sure I know what you mean but sure, I'll try whatever you come
up with.

Lee