From: Wolfgang Grandegger <wg@grandegger.com>
To: Robert Schwebel <r.schwebel@pengutronix.de>
Cc: Steven Rostedt <rostedt@goodmis.org>,
LKML <linux-kernel@vger.kernel.org>,
RT <linux-rt-users@vger.kernel.org>, Ingo Molnar <mingo@elte.hu>,
Thomas Gleixner <tglx@linutronix.de>
Subject: Re: 2.6.24-rc8-rt1
Date: Thu, 17 Jan 2008 22:36:24 +0100 [thread overview]
Message-ID: <478FCA58.5070101@grandegger.com> (raw)
In-Reply-To: <20080117211149.GQ27137@pengutronix.de>
Robert Schwebel wrote:
> On Thu, Jan 17, 2008 at 11:13:26AM +0100, Wolfgang Grandegger wrote:
>> # ./cyclictest -n -p80 -i1000 -b400
>>
>> [...]
>>
>> Well, I'm not sure if this is the correct way to do it. Is there some
>> doc on how to use the latency tracer and interpret the results?
>
> Could you put in this kind of log information inline next time? It makes
> it easier to review.
OK.
>
> Let's see ...
>
>> preemption latency trace v1.1.5 on 2.6.24-rc8-rt1
>> --------------------------------------------------------------------
>> latency: 39733427 us, #65536/1202801, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1)
>> -----------------
>> | task: cyclictest-914 (uid:0 nice:0 policy:1 rt_prio:80)
>> -----------------
>
> Ok, so cyclictest-914 triggered the tracer. No big surprise at -t 1 :-)
>
>> cyclicte-914 0D..1 40us+: enqueue_hrtimer+0x50/0x1a0 ( 89 5aa9862 c3a6dea8)
>
> cyclictest-914 goes to sleep for next period. We expect it to wake up
> again at 40 us + 1000 us = 1040 us.
>
>> ls-1032 0DNh2 999us+: __trace_start_sched_wakeup+0x154/0x18c <cyclicte-914> (19 -1)
>> ls-1032 0DNh2 1001us+: try_to_wake_up+0x194/0x1b4 <cyclicte-914> (180 0)
>> ls-1032 0DNh. 1008us+: clockevents_program_event+0x84/0x1c0 ( 89 5ad6bbf 18e8e)
>> cyclicte-914 0D..2 1033us+: __schedule+0x21c/0x444 <ls-1032> (0 180)
>> cyclicte-914 0D..1 1071us+: enqueue_hrtimer+0x50/0x1a0 ( 89 5b9daa2 c3a6dea8)
>
> Looks good, it happened. Next wakeup at about 1071 us + 1000 us = 2071
> us.
>
>> cyclicte-914 0D..2 2031us+: __schedule+0x21c/0x444 <IRQ-129-682> (150 180)
>> cyclicte-914 0D..1 2072us+: enqueue_hrtimer+0x50/0x1a0 ( 89 5c91ce2 c3a6dea8)
>
> Bingo. Let's get a cup of coffee in the meantime ...
>
>> cyclicte-914 0D..1 1905066us+: enqueue_hrtimer+0x50/0x1a0 ( 91 66210 c3a6dea8)
>
> Expected arival at 1905066 us + 1000 us = 1906066 us.
>
>> ls-1048 0DNh3 1906017us+: __trace_start_sched_wakeup+0x154/0x18c <cyclicte-914> (19 -1)
>> ls-1048 0DNh3 1906021us : __trace_start_sched_wakeup+0x154/0x18c <cyclicte-914> (19 -1)
>> ls-1048 0DNh3 1906023us+: try_to_wake_up+0x194/0x1b4 <cyclicte-914> (180 0)
>
> It's trying hard to wake up ...
>
>> ls-1048 0DNh1 1906028us!: clockevents_program_event+0x84/0x1c0 ( 91 391676 367eff)
>> ls-1048 0DNh2 1906274us+: activate_task+0x60/0xa4 <IRQ-193-681> (150 6)
>
> Between these it should have happened.
>
>> ls-1048 0DNh2 1906285us+: __trace_start_sched_wakeup+0x154/0x18c <IRQ-193-681> (49 -1)
>> ls-1048 0DNh2 1906293us+: __trace_start_sched_wakeup+0x154/0x18c <IRQ-193-681> (49 -1)
>> ls-1048 0DNh2 1906295us+: try_to_wake_up+0x194/0x1b4 <IRQ-193-681> (150 0)
>> cyclicte-914 0D..2 1906332us : __schedule+0x21c/0x444 <ls-1048> (0 180)
>
> What is this IRQ-193-681? Can you post your /proc/interrupts and the
bash-3.00# cat /proc/interrupts
CPU0
129: 179 MPC52xx Peripherals Edge mpc52xx_psc_uart
133: 0 MPC52xx Peripherals Edge mpc52xx-fec_ctrl
135: 0 MPC52xx Peripherals Edge mpc52xx_ata
192: 14853 MPC52xx SDMA Edge mpc52xx-fec_rx
193: 9488 MPC52xx SDMA Edge mpc52xx-fec_tx
BAD: 0
> output of
>
> ps axHo user,pid,%cpu,%mem,nice,rtprio,policy,tty,stat,start_time,bsdtime,args
time,args# ps axHo
user,pid,%cpu,%mem,nice,rtprio,policy,tty,stat,start_time,bsd
USER PID %CPU %MEM NI RTPRIO POL TT STAT START TIME COMMAND
root 1 1.0 1.0 0 - TS ? Ss 00:00 0:00 init
[3]
root 2 0.0 0.0 -5 - TS ? S< 00:00 0:00
[kthreadd]
root 3 0.0 0.0 - 99 FF ? S< 00:00 0:00
[posix_cpu_t]
root 4 0.0 0.0 - 50 FF ? S< 00:00 0:00
[softirq-hig]
root 5 1.4 0.0 - 50 FF ? S< 00:00 0:01
[softirq-tim]
root 6 0.7 0.0 - 50 FF ? S< 00:00 0:00
[softirq-net]
root 7 2.4 0.0 - 50 FF ? S< 00:00 0:02
[softirq-net]
root 8 0.0 0.0 - 50 FF ? S< 00:00 0:00
[softirq-blo]
root 9 0.0 0.0 - 50 FF ? S< 00:00 0:00
[softirq-tas]
root 10 0.0 0.0 - 50 FF ? S< 00:00 0:00
[softirq-sch]
root 11 0.0 0.0 - 50 FF ? S< 00:00 0:00
[softirq-hrt]
root 12 0.4 0.0 - 50 FF ? S< 00:00 0:00
[softirq-rcu]
root 13 0.0 0.0 - 99 FF ? S< 00:00 0:00
[watchdog/0]
root 14 0.0 0.0 -10 - TS ? S< 00:00 0:00
[desched/0]
root 15 0.0 0.0 - 1 FF ? S< 00:00 0:00
[events/0]
root 16 0.2 0.0 -5 - TS ? S< 00:00 0:00 [khelper]
root 68 0.0 0.0 -5 - TS ? S< 00:00 0:00
[kblockd/0]
root 75 0.0 0.0 -5 - TS ? S< 00:00 0:00 [ata/0]
root 76 0.0 0.0 -5 - TS ? S< 00:00 0:00 [ata_aux]
root 93 0.0 0.0 - 1 FF ? S< 00:00 0:00
[krcupreempt]
root 94 0.0 0.0 0 - TS ? S 00:00 0:00 [pdflush]
root 95 0.0 0.0 0 - TS ? S 00:00 0:00 [pdflush]
root 96 0.0 0.0 -5 - TS ? S< 00:00 0:00 [kswapd0]
root 97 0.0 0.0 -5 - TS ? S< 00:00 0:00 [aio/0]
root 675 0.0 0.0 - 50 FF ? S< 00:00 0:00 [IRQ-135]
root 676 0.0 0.0 -5 - TS ? S< 00:00 0:00
[scsi_eh_0]
root 678 0.1 0.0 -5 - TS ? S< 00:00 0:00
[rpciod/0]
root 679 0.0 0.0 - 50 FF ? S< 00:00 0:00 [IRQ-133]
root 680 1.1 0.0 - 50 FF ? S< 00:00 0:01 [IRQ-192]
root 681 0.9 0.0 - 50 FF ? S< 00:00 0:00 [IRQ-193]
root 682 0.0 0.0 - 50 FF ? S< 00:00 0:00 [IRQ-129]
root 848 0.1 1.3 0 - TS ? Ss 00:00 0:00
syslogd -m 0
root 850 0.0 0.6 0 - TS ? Ss 00:00 0:00 klogd -x
root 884 0.1 1.6 0 - TS ? Ss 00:00 0:00
xinetd -staya
root 890 0.2 2.2 0 - TS ? Ss 00:00 0:00 login
-- root
root 891 0.3 2.8 0 - TS ? Ss 00:00 0:00 -bash
root 913 5.2 1.6 0 - TS ? Ss 00:00 0:03
in.telnetd: 1
root 914 0.1 2.2 0 - TS ? Ss 00:00 0:00 login
-- root
root 915 1.4 2.8 0 - TS ttyp0 Ss 00:00 0:00 -bash
root 938 8.4 1.1 0 - TS ttyp0 Sl+ 00:00 0:03
./cyclictest
root 938 5.5 1.1 - 99 FF ttyp0 Sl+ 00:00 0:02
./cyclictest
root 941 0.0 1.7 0 - TS ? R+ 00:01 0:00 ps
axHo user,
bash-3.00#
Wolfgang.
> Robert
next prev parent reply other threads:[~2008-01-17 21:36 UTC|newest]
Thread overview: 48+ messages / expand[flat|nested] mbox.gz Atom feed top
2008-01-17 4:27 2.6.24-rc8-rt1 Steven Rostedt
2008-01-17 5:26 ` 2.6.24-rc8-rt1 Mark Knecht
2008-01-17 10:13 ` 2.6.24-rc8-rt1 Wolfgang Grandegger
2008-01-17 12:46 ` 2.6.24-rc8-rt1 Luotao Fu
2008-01-17 16:17 ` 2.6.24-rc8-rt1 Daniel Walker
2008-01-17 18:17 ` 2.6.24-rc8-rt1 Wolfgang Grandegger
2008-01-17 18:30 ` 2.6.24-rc8-rt1 Daniel Walker
2008-01-17 18:44 ` 2.6.24-rc8-rt1 Steven Rostedt
2008-01-17 18:45 ` 2.6.24-rc8-rt1 Steven Rostedt
2008-01-17 20:01 ` 2.6.24-rc8-rt1 Wolfgang Grandegger
2008-01-17 18:46 ` 2.6.24-rc8-rt1 Wolfgang Grandegger
2008-01-17 21:11 ` 2.6.24-rc8-rt1 Robert Schwebel
2008-01-17 21:36 ` Wolfgang Grandegger [this message]
2008-01-23 14:53 ` 2.6.24-rc8-rt1: Strange latencies on mpc5200 powerpc Luotao Fu
2008-01-23 15:50 ` Daniel Walker
2008-01-23 16:36 ` Wolfgang Grandegger
2008-01-24 10:53 ` Wolfgang Grandegger
2008-01-28 15:11 ` Luotao Fu
2008-01-28 15:38 ` Wolfgang Grandegger
2008-01-29 12:13 ` 2.6.24-rc8-rt1: Strange latencies on mpc5200 powerpc - RCU issue? Luotao Fu
2008-01-29 13:38 ` Wolfgang Grandegger
2008-01-30 1:07 ` Paul E. McKenney
2008-01-30 8:18 ` Wolfgang Grandegger
2008-01-30 10:22 ` Paul E. McKenney
2008-01-30 10:45 ` Wolfgang Grandegger
2008-01-30 10:57 ` Paul E. McKenney
2008-01-30 11:15 ` Luotao Fu
2008-07-01 14:27 ` Wolfgang Grandegger
2008-07-01 15:11 ` Steven Rostedt
2008-07-01 16:11 ` Wolfgang Grandegger
2008-07-01 21:11 ` Luotao Fu
2008-07-02 11:03 ` Wolfgang Grandegger
2008-07-06 0:42 ` Steven Rostedt
2008-07-06 9:41 ` Wolfgang Grandegger
2008-07-08 15:08 ` Luotao Fu
2008-07-08 19:43 ` Wolfgang Grandegger
2008-07-09 12:53 ` Luotao Fu
2008-07-09 13:15 ` Wolfgang Grandegger
2008-07-09 14:52 ` Luotao Fu
2008-07-10 7:50 ` Wolfgang Grandegger
2008-08-01 21:09 ` Paul E. McKenney
2008-08-01 21:09 ` Paul E. McKenney
2008-08-05 15:40 ` Wolfgang Grandegger
2008-07-02 8:09 ` Wolfgang Grandegger
2008-07-06 0:39 ` Steven Rostedt
2008-07-06 9:34 ` Wolfgang Grandegger
2008-01-30 11:22 ` Wolfgang Grandegger
2008-01-17 19:57 ` 2.6.24-rc8-rt1 Mariusz Kozlowski
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=478FCA58.5070101@grandegger.com \
--to=wg@grandegger.com \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-rt-users@vger.kernel.org \
--cc=mingo@elte.hu \
--cc=r.schwebel@pengutronix.de \
--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
Powered by JetHome