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 a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox