PREEMPT_RT and latency_trace

["Serge Noiraud" <serge.noiraud@bull.net>]

Hi,

I have a big dilemna on one machine :
I run a task with RT priority which make a loop to mesure the system
perturbation.
It works well except on  one machine.
On a multi-cpu, If I run the program on cpu 1, I get 23us. It's OK.
If I run the same program on cpu 0, I get 17373us !
If I do :
# echo 0 >/proc/sys/kernel/preempt_max_latency
# ./tsc 0
 temps deb 60229d5e6ee 
cptr mlockall 0
 temps fin 6c386df6612 
 temps max 1  6472c52d682 
 temps max 2  6472fa35c26 
duree du test 259.450819 s max detecte 17373 µs
#cat /proc/latency_trace 
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.51-13-DAV06
--------------------------------------------------------------------
 latency: 33 us, #48/48, CPU#1 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
   -----------------
   | task: softirq-timer/1-12 (uid:0 nice:-10 policy:0 rt_prio:0)
   -----------------

                _------=> CPU#            
               / _-----=> irqs-off        
              | / _----=> need-resched    
              || / _---=> hardirq/softirq 
              ||| / _--=> preempt-depth
              |||| /                      
              |||||     delay             
  cmd     pid ||||| time  |   caller      
     \   /    |||||   \   |   /           
 <idle>-0     1Dnh3    0us!: <70617773> (<00726570>)
 <idle>-0     1Dnh3    0us : __trace_start_sched_wakeup (try_to_wake_up)
 <idle>-0     1Dnh3    0us : __trace_start_sched_wakeup <<...>-12>(69 1)
 <idle>-0     1Dnh3    0us : _raw_spin_unlock (try_to_wake_up)
 <idle>-0     1Dnh2    0us : resched_task (try_to_wake_up)
 <idle>-0     1Dnh2    0us+: try_to_wake_up <<...>-12> (69 8c)
 <idle>-0     1Dnh2   22us : _raw_spin_unlock_irqrestore
(try_to_wake_up)
 <idle>-0     1Dnh1   22us : preempt_schedule (try_to_wake_up)
 <idle>-0     1Dnh1   22us : wake_up_process (trigger_softirqs)
 <idle>-0     1Dnh.   23us : preempt_schedule_irq (need_resched)
 <idle>-0     1Dnh.   23us : __schedule (preempt_schedule_irq)
 <idle>-0     1Dnh.   23us : profile_hit (__schedule)
 <idle>-0     1Dnh1   23us : sched_clock (__schedule)
 <idle>-0     1Dnh1   23us : _raw_spin_lock_irq (__schedule)
 <idle>-0     1Dnh1   24us : _raw_spin_lock_irqsave (__schedule)
 <idle>-0     1Dnh2   24us : pull_rt_tasks (__schedule)
 <idle>-0     1Dnh2   24us : double_lock_balance (pull_rt_tasks)
 <idle>-0     1Dnh2   24us : _raw_spin_trylock (double_lock_balance)
 <idle>-0     1Dnh3   25us : pick_rt_task (pull_rt_tasks)
 <idle>-0     1Dnh3   25us : find_next_bit (pick_rt_task)
 <idle>-0     1Dnh3   25us : find_next_bit (pick_rt_task)
 <idle>-0     1Dnh3   25us : find_next_bit (pick_rt_task)
 <idle>-0     1Dnh3   25us : _raw_spin_unlock (pull_rt_tasks)
 <idle>-0     1Dnh2   26us : preempt_schedule (pull_rt_tasks)
 <idle>-0     1Dnh2   26us : find_next_bit (pull_rt_tasks)
 <idle>-0     1Dnh2   26us : find_next_bit (pull_rt_tasks)
 <idle>-0     1Dnh2   26us : dependent_sleeper (__schedule)
 <idle>-0     1Dnh2   26us : _raw_spin_unlock (dependent_sleeper)
 <idle>-0     1Dnh1   27us : preempt_schedule (dependent_sleeper)
 <idle>-0     1Dnh1   27us : _raw_spin_lock (dependent_sleeper)
 <idle>-0     1Dnh2   27us : find_next_bit (dependent_sleeper)
 <idle>-0     1Dnh2   27us : dequeue_task (__schedule)
 <idle>-0     1Dnh2   27us : recalc_task_prio (__schedule)
 <idle>-0     1Dnh2   28us : effective_prio (recalc_task_prio)
 <idle>-0     1Dnh2   28us : enqueue_task (__schedule)
 <idle>-0     1Dnh2   28us : trace_array (__schedule)
 <idle>-0     1Dnh2   29us : trace_array <<...>-12> (69 6e)
 <idle>-0     1Dnh2   29us : trace_array (__schedule)
  <...>-12    1Dnh2   31us : __switch_to (__schedule)
  <...>-12    1Dnh2   31us : __schedule <<idle>-0> (8c 69)
  <...>-12    1Dnh2   31us : finish_task_switch (__schedule)
  <...>-12    1Dnh2   31us : _raw_spin_unlock (finish_task_switch)
  <...>-12    1Dnh1   32us : trace_stop_sched_switched
(finish_task_switch)
  <...>-12    1Dnh1   32us : _raw_spin_lock (trace_stop_sched_switched)
  <...>-12    1Dnh2   32us : trace_stop_sched_switched <<...>-12>(69 1)
  <...>-12    1Dnh2   32us : trace_stop_sched_switched
(finish_task_switch)


vim:ft=help


My Question is : where is the time missing ?

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