Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.5.2

[Ingo Molnar <mingo@elte.hu>]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> It did not take long to collect this information. These may be false
> positives, here is the start of one example (note 00000000 for preempt
> count in some of the lines).
> 
> preemption latency trace v1.0.7 on 2.6.9-mm1-RT-V0.5.1
> -------------------------------------------------------
>  latency: 1976 us, entries: 2148 (2148)   |   [VP:0 KP:1 SP:1 HP:1 #CPUS:2]
>     -----------------
>     | task: get_ltrace.sh/3673, uid:0 nice:0 policy:1 rt_prio:50
>     -----------------
>  => started at: try_to_wake_up+0x1cc/0x330 <c011c1cc>
>  => ended at:   finish_task_switch+0x41/0xc0 <c011c7e1>
> =======>
> 80000000 0.000ms (+0.000ms): _spin_unlock (try_to_wake_up)
> 80000000 0.000ms (+0.000ms): (105) ((140))
> 80000000 0.000ms (+0.000ms): (6) ((0))

here pid 6 got woken up and it's about to preempt pid 0 [the idle task].

> 80000000 0.000ms (+0.000ms): resched_task (try_to_wake_up)
> 80000000 0.001ms (+0.000ms): _spin_unlock_irqrestore (try_to_wake_up)
> 80000000 0.001ms (+0.000ms): preempt_schedule (try_to_wake_up)
> 00000000 0.001ms (+0.000ms): preempt_schedule (cpu_idle)
> 80000000 0.002ms (+0.000ms): __sched_text_start (preempt_schedule)
> 80000000 0.002ms (+0.000ms): sched_clock (__sched_text_start)
> 80000000 0.002ms (+0.000ms): _spin_lock_irq (__sched_text_start)
> 80000000 0.003ms (+0.000ms): _spin_lock_irqsave (__sched_text_start)
> 80000000 0.003ms (+0.000ms): dequeue_task (__sched_text_start)
> 80000000 0.004ms (+0.000ms): recalc_task_prio (__sched_text_start)
> 80000000 0.004ms (+0.000ms): effective_prio (recalc_task_prio)
> 80000000 0.004ms (+0.000ms): enqueue_task (__sched_text_start)
> 80000000 0.005ms (+0.000ms): __switch_to (__sched_text_start)
> 80000000 0.005ms (+0.000ms): (0) ((6))
> 80000000 0.005ms (+0.000ms): (140) ((105))
> 80000000 0.006ms (+0.000ms): finish_task_switch (__sched_text_start)
> 80000000 0.006ms (+0.000ms): trace_stop_sched_switched (finish_task_switch)
> 80000000 0.006ms (+0.000ms): (6) ((105))
> 80000000 0.006ms (+0.000ms): _spin_lock (trace_stop_sched_switched)

the trace should have stopped here! We just successfully switched from
pid 0 to pid 6 and called trace_stop_sched_switched() - the tracer
should really have noticed it. But the trace goes on for eternity:

> 00000000 1.862ms (+0.001ms): follow_mount (link_path_walk)
> 00000000 1.863ms (+33179.004ms): dput (link_path_walk)

which is just wrong.

i think the tracer is more broken on SMP systems than i thought. If we
start tracing on one CPU and it goes over to another CPU [which might
have happened in the above case - another task on another CPU took
precedence over pid 6 on this CPU] ... but the tracing timestamp is
per-CPU.

what needs to happen is some sort of 'handover' whenever the
highest-prio task is migrated from one CPU to another. Until this is
fixed i'd not suggest to use the wakeup latency tracer on SMP :-|

	Ingo