More weird latency trace output (was Re: 2.6.17-rt1)

[Lee Revell]

On Wed, 2006-06-21 at 20:57 -0400, Lee Revell wrote:
> I'm getting some strange latency tracer output on a dual core AMD box.
> Why does it start at 404us?
> 

After setting trace_all_cpus to 1, I get the following:

( posix_cpu_timer-15   |#1): new 8 us maximum-latency wakeup.
(         IRQ 233-2446 |#1): new 14 us maximum-latency wakeup.
( posix_cpu_timer-15   |#1): new 19 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 861 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 862 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 862 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 868 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 876 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 879 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 880 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 882 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 884 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 884 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 885 us maximum-latency wakeup.

[ max latencies continue to creep up by 1-2 us at a time ]

(          IRQ 14-1783 |#0): new 1826 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 1827 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 1828 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 1831 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 1832 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 1834 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 1836 us maximum-latency wakeup.
(         IRQ 233-2446 |#0): new 1838 us maximum-latency wakeup.

Here is a typical trace:

preemption latency trace v1.1.5 on 2.6.17-rt1-smp-latency-trace
--------------------------------------------------------------------
 latency: 1898 us, #78/78, CPU#1 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
    -----------------
    | task: IRQ 233-2446 (uid:0 nice:-5 policy:1 rt_prio:40)
    -----------------

                 _------=> CPU#            
                / _-----=> irqs-off        
               | / _----=> need-resched    
               || / _---=> hardirq/softirq 
               ||| / _--=> preempt-depth   
               |||| /                      
               |||||     delay             
   cmd     pid ||||| time  |   caller      
      \   /    |||||   \   |   /           
softirq--5     0....    0us : __wake_up (ksoftirqd)
softirq--5     0....    0us : __lock_text_start (__wake_up)
softirq--5     0....    0us : __wake_up_common (__wake_up)
softirq--5     0....    0us : rt_unlock (__wake_up)
softirq--5     0....    0us : kthread_should_stop (ksoftirqd)
softirq--5     0....    0us : schedule (ksoftirqd)
softirq--5     0....    1us : __schedule (schedule)
softirq--5     0....    1us : profile_hit (__schedule)
softirq--5     0...1    1us : sched_clock (__schedule)
softirq--5     0...1    1us : _raw_spin_lock_irq (__schedule)
softirq--5     0D..2    2us : touch_softlockup_watchdog (__schedule)
softirq--5     0D..2    2us : deactivate_task (__schedule)
softirq--5     0D..2    2us : deactivate_task <softirq--5> (101 1)
softirq--5     0D..2    2us : dequeue_task (deactivate_task)
softirq--5     0D..2    3us : __first_cpu (__schedule)
softirq--5     0D..2    3us : __next_cpu (__schedule)
softirq--5     0D..2    3us : double_lock_balance (__schedule)
softirq--5     0D..2    3us : _raw_spin_trylock (double_lock_balance)
softirq--5     0D..3    4us : trace_change_sched_cpu (__schedule)
softirq--5     0D..3    5us : trace_change_sched_cpu (1 1 0)
softirq--5     0D..3    5us : _raw_spin_lock (trace_change_sched_cpu)
softirq--5     0D..4    5us : trace_change_sched_cpu (1 0 0)
softirq--5     0D..4    6us : _raw_spin_unlock (trace_change_sched_cpu)
softirq--5     0D..3    6us : constant_test_bit (_raw_spin_unlock)
softirq--5     0D..3    6us : deactivate_task (__schedule)
softirq--5     0D..3    6us : deactivate_task <<...>-2446> (140 3)
softirq--5     0D..3    7us : dequeue_task (deactivate_task)
softirq--5     0D..3    7us : activate_task (__schedule)
softirq--5     0D..3    7us : sched_clock (activate_task)
softirq--5     0D..3    7us : __activate_task (activate_task)
softirq--5     0D..3    8us : __activate_task <<...>-2446> (59 0)
softirq--5     0D..3    8us : enqueue_task (__activate_task)
softirq--5     0D..3    8us : _raw_spin_unlock (__schedule)
softirq--5     0D..2    8us : constant_test_bit (_raw_spin_unlock)
softirq--5     0D..2    8us : __next_cpu (__schedule)
softirq--5     0D..2    9us : __switch_to (thread_return)
   <...>-2446  0D..2   10us : thread_return <softirq--5> (101 140)
   <...>-2446  0D..2   10us : _raw_spin_unlock_irq (thread_return)
   <...>-2446  0...1   10us : constant_test_bit (_raw_spin_unlock_irq)
   <...>-2446  0...1   11us : trace_stop_sched_switched (thread_return)
   <...>-2446  0D..1   11us : _raw_spin_lock (trace_stop_sched_switched)
   <...>-2446  0D..2   11us : trace_stop_sched_switched <<...>-2446> (59 0)
   <...>-2446  0D..3   11us : _raw_spin_unlock (trace_stop_sched_switched)
   <...>-2446  0D..2   12us : constant_test_bit (_raw_spin_unlock)
   <...>-2446  0D..2   12us : report_latency (trace_stop_sched_switched)
   <...>-2446  0D..2   12us!: thread_return (thread_return)

How can the latency tracer be reporting 1898us max latency while the
trace is of a 12us latency?  This must be a bug, correct?

Lee


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