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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[Index of Archives]
[Kernel Newbies]
[Netfilter]
[Bugtraq]
[Photo]
[Stuff]
[Gimp]
[Yosemite News]
[MIPS Linux]
[ARM Linux]
[Linux Security]
[Linux RAID]
[Video 4 Linux]
[Linux for the blind]
[Linux Resources]
