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: 52+ 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
[not found] ` <20080124112847.GE4776@unix.sh>
[not found] ` <47987D73.8090904@grandegger.com>
2008-01-24 13:49 ` Luis Claudio R. Goncalves
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 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-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-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 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.