RT patch + LTTng

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

Hi,

	I have added the LTTng patch to the 2.6.16-rt23.
In the LTT trace, I see some odd time stamps :

First case :

...
process.schedchange: 12.800681016 (/cpu_1), 7667, lttctl, 0, 0x0, MODE_UNKNOWN { 17, 7667, 2 }
socket.call: 12.800685053 (/cpu_1), 7667, lttctl, 0, 0x0, MODE_UNKNOWN { 11, 3 }
socket.sendmsg: 12.800687153 (/cpu_1), 7667, lttctl, 0, 0x0, MODE_UNKNOWN { 0xf3b78b80, 16, 3, 31, 288 }
>The pb is effectively on the next line : we skip from 12.800687153 to 13.397691687
>0,597 seconde ??? 
core.time_heartbeat: 13.397691687 (/control/facilities_1), 7667, lttctl, 0, 0x0, MODE_UNKNOWN
core.time_heartbeat: 13.397691979 (/control/facilities_0), 7662, lttd, 7660, 0x0, USER_MODE
core.time_heartbeat: 13.397694936 (/control/interrupts_0), 7662, lttd, 7660, 0x0, USER_MODE
...

Second case :

...
process.schedchange: 4.062674969 (/cpu_1), 0, UNNAMED, 0, 0x0, SYSCALL { 17, 0, 2 }
process.wakeup: 4.062733369 (/cpu_0), 7538, lttd, 1, 0x0, USER_MODE { 5, 2 }
process.wakeup: 4.062738209 (/cpu_0), 7538, lttd, 1, 0x0, USER_MODE { 3, 2 }
process.schedchange: 4.062746308 (/cpu_0), 3, posix_cpu_timer, 1, 0x0, SYSCALL { 7538, 3, 0 }
process.schedchange: 4.062751787 (/cpu_0), 5, softirq-timer/0, 1, 0x0, SYSCALL { 3, 5, 2 }
timer.softirq: 4.062753184 (/cpu_0), 5, softirq-timer/0, 1, 0x0, SYSCALL
process.schedchange: 4.062759716 (/cpu_0), 7538, lttd, 1, 0x0, USER_MODE { 5, 7538, 2 }
>====================== Problem On the following lines
>573us between 4.062759716 and 4.063493275
kernel.trap_entry: 4.063493275 (/cpu_1), 0, UNNAMED, 0, 0x0, TRAP { 2, 0xc0101329 }
kernel.trap_exit: 4.063494252 (/cpu_1), 0, UNNAMED, 0, 0x0, SYSCALL
kernel.trap_entry: 4.063494624 (/cpu_0), 7538, lttd, 1, 0x0, TRAP { 2, 0xc032e8b9 }
kernel.trap_exit: 4.063495799 (/cpu_0), 7538, lttd, 1, 0x0, USER_MODE
kernel.irq_entry: 4.063497194 (/cpu_0), 7538, lttd, 1, 0x0, IRQ { 0, kernel }
kernel.irq_exit: 4.063500254 (/cpu_0), 7538, lttd, 1, 0x0, USER_MODE
process.wakeup: 4.063644762 (/cpu_1), 0, UNNAMED, 0, 0x0, SYSCALL { 17, 2 }
...

My questions are :
What could explains these gaps :
NMI ?
ACPI ?
clock synchronization between CPU ?
other cause ?

There is no big latencies :
-sh-2.05b# cat /proc/latency_trace
preemption latency trace v1.1.5 on 2.6.16-DAV07_ltt
--------------------------------------------------------------------
 latency: 93 us, #240/240, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
    -----------------
    | task: posix_cpu_timer-3 (uid:0 nice:0 policy:1 rt_prio:99)
    -----------------

                 _------=> CPU#            
                / _-----=> irqs-off        
               | / _----=> need-resched    
               || / _---=> hardirq/softirq 
               ||| / _--=> preempt-depth   
               |||| /                      
               |||||     delay             
   cmd     pid ||||| time  |   caller      
      \   /    |||||   \   |   /           
ltt_stat-7809  0Dnh3    0us : __trace_start_sched_wakeup (try_to_wake_up)
ltt_stat-7809  0Dnh3    0us : __trace_start_sched_wakeup <<...>-3> (0 0)
ltt_stat-7809  0Dnh3    0us : _raw_spin_unlock (__trace_start_sched_wakeup)
ltt_stat-7809  0Dnh2    1us : preempt_schedule (_raw_spin_unlock)
ltt_stat-7809  0Dnh2    1us : resched_task (try_to_wake_up)
ltt_stat-7809  0Dnh2    1us : try_to_wake_up <<...>-3> (199 -8)
ltt_stat-7809  0Dnh2    1us : _raw_spin_unlock_irqrestore (try_to_wake_up)
ltt_stat-7809  0Dnh1    1us : preempt_schedule (_raw_spin_unlock_irqrestore)
ltt_stat-7809  0Dnh1    1us : wake_up_process (run_posix_cpu_timers)
ltt_stat-7809  0Dnh1    2us : irq_exit (smp_apic_timer_interrupt)
ltt_stat-7809  0.n.1    2us : ltt_heartbeat_read_synthetic_tsc (ltt_statedump_thread)
...
ltt_stat-7809  0.n.1   81us : ltt_heartbeat_read_synthetic_tsc (ltt_statedump_thread)
ltt_stat-7809  0.n.1   81us : preempt_schedule (ltt_heartbeat_read_synthetic_tsc)
ltt_stat-7809  0.n.1   82us : ltt_heartbeat_read_synthetic_tsc (ltt_statedump_thread)
ltt_stat-7809  0.n.1   82us : preempt_schedule (ltt_heartbeat_read_synthetic_tsc)
ltt_stat-7809  0.n.1   82us : ltt_heartbeat_read_synthetic_tsc (ltt_statedump_thread)
ltt_stat-7809  0.n.1   83us : preempt_schedule (ltt_heartbeat_read_synthetic_tsc)
ltt_stat-7809  0.n.1   83us : ltt_heartbeat_read_synthetic_tsc (ltt_statedump_thread)
ltt_stat-7809  0.n.1   83us : preempt_schedule (ltt_heartbeat_read_synthetic_tsc)
ltt_stat-7809  0.n..   84us : rt_up_read (ltt_statedump_thread)
ltt_stat-7809  0.n..   84us : _raw_spin_lock_irqsave (rt_up_read)
ltt_stat-7809  0Dn.1   84us : _raw_spin_unlock_irqrestore (rt_up_read)
ltt_stat-7809  0.n..   85us : preempt_schedule (_raw_spin_unlock_irqrestore)
ltt_stat-7809  0Dn..   85us : __schedule (preempt_schedule)
ltt_stat-7809  0Dn..   85us : profile_hit (__schedule)
ltt_stat-7809  0Dn.1   85us : sched_clock (__schedule)
ltt_stat-7809  0Dn.1   86us : _raw_spin_lock_irq (__schedule)
ltt_stat-7809  0Dn.2   86us : balance_rt_tasks (__schedule)
ltt_stat-7809  0Dn.2   86us : find_next_bit (balance_rt_tasks)
ltt_stat-7809  0Dn.2   86us : find_next_bit (balance_rt_tasks)
ltt_stat-7809  0D..2   87us : trace_array (__schedule)
ltt_stat-7809  0D..2   87us : trace_array <<...>-3> (0 199)
ltt_stat-7809  0D..2   88us : trace_array <<...>-5> (98 101)
ltt_stat-7809  0D..2   89us : trace_array <ltt_stat-7809> (112 -8)
ltt_stat-7809  0D..2   89us : trace_array <<...>-7806> (118 -2)
ltt_stat-7809  0D..2   89us : trace_array (__schedule)
ltt_stat-7809  0D..2   90us : sched_info_arrive (__schedule)
ltt_stat-7809  0D..3   91us : ltt_heartbeat_read_synthetic_tsc (__schedule)
   <...>-3     0D..2   91us : __switch_to (__schedule)
   <...>-3     0D..2   92us : __schedule <ltt_stat-7809> (-8 199)
   <...>-3     0D..2   92us : _raw_spin_unlock_irq (__schedule)
   <...>-3     0...1   92us : trace_stop_sched_switched (__schedule)
   <...>-3     0D..1   93us : _raw_spin_lock (trace_stop_sched_switched)
   <...>-3     0D..2   93us : trace_stop_sched_switched <<...>-3> (0 0)
   <...>-3     0D..2   93us : trace_stop_sched_switched (__schedule)


I don't use CPU FREQ :
-sh-2.05b# zgrep   CPU_FREQ    /proc/config.gz 
# CONFIG_CPU_FREQ is not set
-sh-2.05b#


-- 
Serge Noiraud
-
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/