From: Lee Revell <rlrevell@joe-job.com>
To: Ingo Molnar <mingo@elte.hu>
Cc: linux-kernel@vger.kernel.org,
Thomas Gleixner <tglx@linutronix.de>,
Steven Rostedt <rostedt@goodmis.org>
Subject: More weird latency trace output (was Re: 2.6.17-rt1)
Date: Wed, 21 Jun 2006 22:51:03 -0400 [thread overview]
Message-ID: <1150944663.2754.416.camel@mindpipe> (raw)
In-Reply-To: <1150937848.2754.379.camel@mindpipe>
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
next prev parent reply other threads:[~2006-06-22 2:51 UTC|newest]
Thread overview: 51+ messages / expand[flat|nested] mbox.gz Atom feed top
2006-06-18 7:06 2.6.17-rt1 Ingo Molnar
2006-06-18 16:13 ` 2.6.17-rt1 Michal Piotrowski
[not found] ` <Pine.LNX.4.64.0606201656230.11643@localhost.localdomain>
2006-06-20 15:13 ` Why can't I set the priority of softirq-hrt? (Re: 2.6.17-rt1) Thomas Gleixner
2006-06-20 17:09 ` Esben Nielsen
2006-06-20 16:35 ` Thomas Gleixner
2006-06-20 21:16 ` Esben Nielsen
2006-06-20 20:35 ` Thomas Gleixner
2006-06-20 23:19 ` Esben Nielsen
2006-06-20 16:39 ` Steven Rostedt
2006-06-20 18:12 ` Esben Nielsen
2006-06-20 17:21 ` Thomas Gleixner
2006-06-20 21:26 ` Esben Nielsen
2006-06-20 20:51 ` Thomas Gleixner
2006-06-21 8:20 ` Steven Rostedt
2006-06-21 11:05 ` Esben Nielsen
2006-06-21 15:43 ` Esben Nielsen
2006-06-21 15:21 ` Steven Rostedt
2006-06-21 16:37 ` Esben Nielsen
2006-06-21 15:51 ` Steven Rostedt
2006-06-21 17:14 ` Esben Nielsen
2006-06-21 16:26 ` Thomas Gleixner
2006-06-21 18:30 ` Ingo Molnar
2006-06-22 10:28 ` Esben Nielsen
2006-06-21 21:29 ` Esben Nielsen
2006-06-21 20:33 ` Thomas Gleixner
2006-06-21 23:35 ` Esben Nielsen
2006-06-22 7:06 ` Thomas Gleixner
2006-06-22 10:32 ` Esben Nielsen
2006-06-22 13:33 ` Steven Rostedt
2006-06-22 13:45 ` Steven Rostedt
2006-06-22 14:20 ` Thomas Gleixner
2006-06-22 14:23 ` Steven Rostedt
2006-06-22 14:26 ` Thomas Gleixner
2006-06-22 18:06 ` Esben Nielsen
2006-06-22 18:05 ` Thomas Gleixner
2006-06-23 11:23 ` Esben Nielsen
2006-06-23 11:06 ` Steven Rostedt
2006-07-03 11:48 ` Esben Nielsen
2006-06-21 8:13 ` Steven Rostedt
2006-06-21 11:03 ` Esben Nielsen
2006-06-22 0:57 ` 2.6.17-rt1 Lee Revell
2006-06-22 2:51 ` Lee Revell [this message]
2006-06-23 1:24 ` More weird latency trace output (was Re: 2.6.17-rt1) Lee Revell
2006-06-24 22:15 ` Lee Revell
2006-06-24 22:12 ` Ingo Molnar
2006-06-24 22:31 ` Lee Revell
2006-06-24 23:49 ` Lee Revell
2006-06-23 20:56 ` 2.6.17-rt1 - mm_struct leak Vernon Mauery
2006-06-24 9:24 ` Mark Hounschell
2006-06-24 9:32 ` Mark Hounschell
2006-06-30 16:02 ` [PATCH -RT]Re: " Vernon Mauery
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=1150944663.2754.416.camel@mindpipe \
--to=rlrevell@joe-job.com \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@elte.hu \
--cc=rostedt@goodmis.org \
--cc=tglx@linutronix.de \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.