LinuxLists.cc - 2.6.24-rc8-rt1

2008-01-17 04:27:55

Subject: 2.6.24-rc8-rt1

We are pleased to announce the 2.6.24-rc8-rt1 tree, which can be
downloaded from the location:

http://rt.et.redhat.com/download/

Information on the RT patch can be found at:

http://rt.wiki.kernel.org/index.php/Main_Page

Changes since 2.6.24-rc7-rt3

- ported to 2.6.24-rc8

- PPC bootup notrace added for function trace (Luotao Fu)

- MIPS remove duplicate Kconfig (Frank Rowand)

to build a 2.6.24-rc8-rt1 tree, the following patches should be applied:

http://www.kernel.org/pub/linux/kernel/v2.6/linux-2.6.23.tar.bz2
http://www.kernel.org/pub/linux/kernel/v2.6/testing/patch-2.6.24-rc8.bz2
http://rt.et.redhat.com/download/patch-2.6.24-rc8-rt1.bz2

And like always, my RT version of Matt Mackall's ketchup will get this
for you nicely:

http://people.redhat.com/srostedt/rt/tools/ketchup-0.9.8-rt3

The broken out patches are also available.

-- Steve

2008-01-17 05:26:51

by Mark Knecht

[permalink] [raw]

On Jan 16, 2008 8:27 PM, Steven Rostedt <[email protected]> wrote:
> We are pleased to announce the 2.6.24-rc8-rt1 tree, which can be
> downloaded from the location:
>
> http://rt.et.redhat.com/download/
>

Up and running fine here:

mark@lightning ~ $ uname -a
Linux lightning 2.6.24-rc8-rt1 #1 PREEMPT RT Wed Jan 16 21:11:05 PST
2008 x86_64 AMD Athlon(tm) 64 Processor 3000+ AuthenticAMD GNU/Linux
mark@lightning ~ $

Cheers,
Mark

2008-01-17 10:13:45

by Wolfgang Grandegger

[permalink] [raw]

Subject: Re: 2.6.24-rc8-rt1

Steven Rostedt wrote:
> We are pleased to announce the 2.6.24-rc8-rt1 tree, which can be
> downloaded from the location:
>
> http://rt.et.redhat.com/download/

It builds and runs fine on my Icecube-MPC5200 board, now also with the
latency tracer enabled. That's great. Still, "cyclictest -n -p80 -i1000"
reports latencies up to 400 us and therefore I tried to trigger and save
a high latency trace using:

# ./cyclictest -n -p80 -i1000 -b400
1.21 0.33 0.11 4/42 1048

T: 0 ( 914) P:80 I:1000 C: 38726 Min: 61 Act: 107 Avg: 106
Max: 377
[ 91.042169] ( cyclictest-914 |#0): new 39733427 us user-latency.
bash-3.00# cat /proc/latency_trace > trace.log

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?
Nevertheless, I have attached the beginning of trace.log. Maybe it rings
an experts bell.

TIA.

Wolfgang.

Attachments:

trace-partial.log (20.98 kB)

2008-01-17 12:47:12

Hi folks,

On Thu, Jan 17, 2008 at 11:13:26AM +0100, Wolfgang Grandegger wrote:
> It builds and runs fine on my Icecube-MPC5200 board, now also with the
> latency tracer enabled. That's great. Still, "cyclictest -n -p80 -i1000"
> reports latencies up to 400 us and therefore I tried to trigger and save
> a high latency trace using:
>
> # ./cyclictest -n -p80 -i1000 -b400
> 1.21 0.33 0.11 4/42 1048
>
> T: 0 ( 914) P:80 I:1000 C: 38726 Min: 61 Act: 107 Avg: 106
> Max: 377
> [ 91.042169] ( cyclictest-914 |#0): new 39733427 us user-latency.
> bash-3.00# cat /proc/latency_trace > trace.log
>

I was doing some tests on my mpc5200b Board to reproduce the high latency as
measured by wolfgang.

I ran some tests with
while [ 1 ]; do ls /bin;done
as non-rt workload, as in Wolfgangs Scenario.

Now I also got some strange values. My latency lies at round about 100 and the
max. latency keep pending normally at about 150us-200us. However the max. value
will occasionally break out to very high values. I got a max. about 850us after
some rounds of measurement, which is definitively too high for the processor. I
made some traces and attached the last "interesting" path to this mail.
trace_600_1.log and trace_600_2.log are both taken with -b600. For comparation I
also added a "normal" trace taken with -b150. In the traces with abnormal long
latency there're a big "hole" between the last call, which is
clockevents_program_event() in both long traces and the actual schedule()
call. The holes are both about 600 us long, which is the main part of the
latency actually.

Two important things I also noted during my tests:
1. I got the unusual latencies on a system booted with nfsrootfs. I ran the same
test scenario on system booted from flash and got no extraordinory results.
After serveral hours test my max. latency lies at round about 200us.
2. Even on a nfsrootfs system I could not get the high latencies if I run
hackbench as non-rt workload.

Hence I suppose the unusual results are caused by network/Filesystemaccess.
However I have no idea what could be the reason for the "hole"s in the trace.
Looks almost like the cpu is doing nothing. As I don't have a trace on other
architecture at hand at the moment. I can't say for 100 procent if the tracer is
"missing" anything.

Any comments, ideas?

cheers
Luotao Fu
--
Dipl.-Ing. Luotao Fu | Phone: +49-5121-206917-3
Pengutronix - Linux Solutions for Science and Industry
Entwicklungszentrum Nord http://www.pengutronix.de

Attachments:

(No filename) (0.00 B)
signature.asc (189.00 B)
Digital signature Download all attachments

2008-01-23 15:51:16

by Daniel Walker

[permalink] [raw]

Subject: Re: 2.6.24-rc8-rt1: Strange latencies on mpc5200 powerpc

On Wed, 2008-01-23 at 15:53 +0100, Luotao Fu wrote:

> I was doing some tests on my mpc5200b Board to reproduce the high latency as
> measured by wolfgang.
>
> I ran some tests with
> while [ 1 ]; do ls /bin;done
> as non-rt workload, as in Wolfgangs Scenario.
>

Can you try enabling CRITICAL_PREEMPT_TIMING only, and not latency
tracing .. You won't get a trace, but you will get some indication of
the start/stop points of the latency if it's preempt latency, and a
measurement of the longest latency..

Daniel

2008-01-23 16:36:36

by Wolfgang Grandegger

[permalink] [raw]

Subject: Re: 2.6.24-rc8-rt1: Strange latencies on mpc5200 powerpc

Hi Fu,

Luotao Fu wrote:
> Hi folks,
>
> On Thu, Jan 17, 2008 at 11:13:26AM +0100, Wolfgang Grandegger wrote:
>> It builds and runs fine on my Icecube-MPC5200 board, now also with the
>> latency tracer enabled. That's great. Still, "cyclictest -n -p80 -i1000"
>> reports latencies up to 400 us and therefore I tried to trigger and save
>> a high latency trace using:
>>
>> # ./cyclictest -n -p80 -i1000 -b400
>> 1.21 0.33 0.11 4/42 1048
>>
>> T: 0 ( 914) P:80 I:1000 C: 38726 Min: 61 Act: 107 Avg: 106
>> Max: 377
>> [ 91.042169] ( cyclictest-914 |#0): new 39733427 us user-latency.
>> bash-3.00# cat /proc/latency_trace > trace.log
>>
>
> I was doing some tests on my mpc5200b Board to reproduce the high latency as
> measured by wolfgang.
>
> I ran some tests with
> while [ 1 ]; do ls /bin;done
> as non-rt workload, as in Wolfgangs Scenario.

I also did some more measurements and made, by chance, interesting
observations. I will summarize in more detail later on. Here are some
preliminary results. My high latencies of up to 570us (without latency
tracer) seem to be caused mainly by the following setting:

CONFIG_RCU_TRACE=m

which is the default if CONFIG_MODULES=y. With CONFIG_RCU_TRACE=y
latencies go down significantly. I furthermore realized some bad impact
of CONFIG_NO_HZ and CONFIG_PPC_BESTCOMM_GEN_BD. With the following
settings the latencies did not yet exceed 140 us.

CONFIG_PREEMPT_RCU_BOOST=y
CONFIG_RCU_TRACE=y
# CONFIG_PPC_BESTCOMM_GEN_BD is not set
# CONFIG_NO_HZ is not set

With CONFIG_NO_HZ=y or CONFIG_PPC_BESTCOMM_GEN_BD=y the latency
increases by approx. 100..150us, each.

> Now I also got some strange values. My latency lies at round about 100 and the
> max. latency keep pending normally at about 150us-200us. However the max. value
> will occasionally break out to very high values. I got a max. about 850us after
> some rounds of measurement, which is definitively too high for the processor. I
> made some traces and attached the last "interesting" path to this mail.
> trace_600_1.log and trace_600_2.log are both taken with -b600. For comparation I
> also added a "normal" trace taken with -b150. In the traces with abnormal long
> latency there're a big "hole" between the last call, which is
> clockevents_program_event() in both long traces and the actual schedule()
> call. The holes are both about 600 us long, which is the main part of the
> latency actually.
>
> Two important things I also noted during my tests:
> 1. I got the unusual latencies on a system booted with nfsrootfs. I ran the same
> test scenario on system booted from flash and got no extraordinory results.
> After serveral hours test my max. latency lies at round about 200us.
> 2. Even on a nfsrootfs system I could not get the high latencies if I run
> hackbench as non-rt workload.
>
> Hence I suppose the unusual results are caused by network/Filesystemaccess.
> However I have no idea what could be the reason for the "hole"s in the trace.
> Looks almost like the cpu is doing nothing. As I don't have a trace on other
> architecture at hand at the moment. I can't say for 100 procent if the tracer is
> "missing" anything.
>
> Any comments, ideas?

Could you check your .config and try the __good__ settings mentioned
above? Can you back my observations? Don't ask me why. Maybe somebody
else could shed some light on this.

Wolfgang,

2008-01-24 10:54:20

On Wed, Jan 30, 2008 at 11:45:01AM +0100, Wolfgang Grandegger wrote:
> Paul E. McKenney wrote:
> > On Wed, Jan 30, 2008 at 09:18:49AM +0100, Wolfgang Grandegger wrote:
> >> Paul E. McKenney wrote:
> >>> On Tue, Jan 29, 2008 at 02:38:04PM +0100, Wolfgang Grandegger wrote:
> >>>> Luotao Fu wrote:
> >>>>> Hi,
> >>>>>
> >>>>> Wolfgang Grandegger wrote:
> >>>>> ..........
> >>>>>> Do you still get high latencies with:
> >>>>>>
> >>>>>> CONFIG_PREEMPT_RCU_BOOST=y
> >>>>>> CONFIG_RCU_TRACE=y
> >>>>>> CONFIG_NO_HZ is not set
> >>>>>>
> >>>>>> With this setting I have not yet realized latencies > 150us. Could you
> >>>>>> please give it a try? If I change one of the parameters above, latency
> >>>>>> increases in short time.
> >>>>> I played through some combination of the RCU options and can back your
> >>>>> observation this time: With the rcu Tracer or the priority boost turned
> >>>>> off I also could measure reliably extraordinory high latencies. If they
> >>>>> are both turned on, no high latencies could be measured. Turning on the
> >>>>> dynamic ticker however doesn't seem to cause high latencies during my
> >>>>> test runs. Seemed like an rcu issue here.
> >>>> I'm just making a long test run on my TQM5200 module with my good
> >>>> settings. After more than 4.5 hours under load, cyclictest shows a
> >>>> maximum latency of 177 us. I'm going to re-check the effect of CONFIG_NO_HZ.
> >>>>
> >>>>> Further such results only appear if the target board is booted with
> >>>>> nfsrootfs. (As I already have mentioned several times before), which
> >>>>> leads my suspection to rcu usage in nfs implementation. In this case
> >>>>> this problem might even be platformindependent. I'd have to do some
> >>>>> tests on one of our arm boards later to test this. Since there're no
> >>>>> reports like this for other architecture as powerpc till now, I doubt
> >>>>> quite if this is verifiable.
> >>>> It's also my suspicion that the high latencies are related to the RCU
> >>>> usage in the network layer, where it's heavily used. What is really
> >>>> wired is that switching off CONFIG_RCU_TRACE has a negative impact on
> >>>> the latency. As I see it, it just adds some trace points, but I might
> >>>> have missed something.
> >>> I would expect that CONFIG_RCU_TRACE=n (as in "no" rather than "module")
> >>> would have low latencies rather than high latencies. So I am quite
> >>> surprised by your result. I will dig into this more.
> >> Thanks a lot. To be clear. I need "CONFIG_PREEMPT_RCU_BOOST=y" *and*
> >> "CONFIG_RCU_TRACE=y" to achieve reasonable latencies below 180us. With
> >> CONFIG_PREEMPT_RCU_BOOST or CONFIG_RCU_TRACE not set or
> >> CONFIG_RCU_TRACE=m is rmeasure latencies up to 600us within a minute or so.
> >
> > OK, thank you for the confirmation.
> >
> > The large latencies were from cyclictest, correct? Did other tests
> > also show these latencies? In either case, could you please send the
> > exact command line you used to run the test?
>
> Yes, I used "$ cyclictest -n -t1 -p80 -i1000" to measure the latency. So
> far, I have not done other tests. Any recommendation?
> As no-rt load I used "while ls; do ls /bin; done" in one telnet window
> and "while ./hackbench 10; do ./calibrator 400 32M cali; sleep 30; done"
> in another. But already "while ls; do ls /bin; done" is enough to
> trigger the high latencies quickly. Note also, that I work on a root
> files-ystem mounted via NFS resulting in a lot of network traffic and
> utilization.

I have to ask...

Did you see large latencies when -not- running on NFS?

Thanx, Paul

2008-01-30 11:16:20

Hi Wolfgang,

On Tue, Jul 01, 2008 at 06:11:42PM +0200, Wolfgang Grandegger wrote:
[...]

I'm out of office till next week. I will try to narrow down the issue you
reported on my board asap. Unfortunately I was not able to produce such worst
case results in my test runs till now. Anyhow I'll also have a look at the code
segment you found and play a little around there. Hopefully I'll find something
useful. ;-)

Cheers
Luotao Fu
--
Dipl.-Ing. Luotao Fu | Phone: +49-5121-206917-3
Pengutronix - Linux Solutions for Science and Industry
Entwicklungszentrum Nord http://www.pengutronix.de

Attachments:

(No filename) (598.00 B)
signature.asc (189.00 B)
Digital signature Download all attachments

2008-07-02 08:09:18

by Wolfgang Grandegger

[permalink] [raw]

Hi,

I found some time and played with my mpc5200B Board again on this issue
(2.6.25.8-rt7, same test environment)

On Sun, Jul 06, 2008 at 11:41:28AM +0200, Wolfgang Grandegger wrote:
....
> Yep, in 2.6.25.8-rt7 trace_mark() is not used any more, maybe for that
> reason. Nevertheless, this "bug" kept the latency on my MPC5200 box low.
> I will try with the old tracer to understand what the real cause of the
> high latencies is (with CONFIG_RCU_TRACE disabled).
>
As you said, in 2.6.25.8-rt7 there're rcu_trace_boost_unboost_called() and
rcu_trace_boost_unboosted() are used instead of trace_mark. I still haven't had
time to take a closer look waht these routines exactly do. Seemed however to me,
that they possibly do the same thing. I played a little bit around with
the RCU_TRACE and RCU_BOOST Option. Also I tried to comment out the
rcu_trace_boost_unboost_called() and rcu_trace_boost_unboosted() calls. My Tests
last appr. 30 Minutes with non-rt Payload "while [ 1 ]; do ls /;done". None of
my test showed extraordinary results. My worstcase values stay at about 220 us
with all my test combinations. I will attache a config with RCU_BOOST and
RCU_TRACE turned off to this mail, which provide a worst case value at 223 us
after about 40 Minutes test run on my board.

Are you using the FEC all a pci network card?

cheers
Luotao Fu
--
Dipl.-Ing. Luotao Fu | Phone: +49-5121-206917-3
Pengutronix - Linux Solutions for Science and Industry
Entwicklungszentrum Nord http://www.pengutronix.de

Attachments:

(No filename) (0.00 B)
signature.asc (189.00 B)
Digital signature Download all attachments

2008-07-08 19:42:53

by Wolfgang Grandegger

[permalink] [raw]

Subject: Re: 2.6.24-rc8-rt1: Strange latencies on mpc5200 powerpc - RCU issue?

Hi Fun,

Luotao Fu wrote:
> Hi,
>
> I found some time and played with my mpc5200B Board again on this issue
> (2.6.25.8-rt7, same test environment)
>
> On Sun, Jul 06, 2008 at 11:41:28AM +0200, Wolfgang Grandegger wrote:
> ....
>> Yep, in 2.6.25.8-rt7 trace_mark() is not used any more, maybe for that
>> reason. Nevertheless, this "bug" kept the latency on my MPC5200 box low.
>> I will try with the old tracer to understand what the real cause of the
>> high latencies is (with CONFIG_RCU_TRACE disabled).
>>
> As you said, in 2.6.25.8-rt7 there're rcu_trace_boost_unboost_called() and
> rcu_trace_boost_unboosted() are used instead of trace_mark. I still haven't had
> time to take a closer look waht these routines exactly do. Seemed however to me,
> that they possibly do the same thing. I played a little bit around with
> the RCU_TRACE and RCU_BOOST Option. Also I tried to comment out the
> rcu_trace_boost_unboost_called() and rcu_trace_boost_unboosted() calls. My Tests
> last appr. 30 Minutes with non-rt Payload "while [ 1 ]; do ls /;done". None of
> my test showed extraordinary results. My worstcase values stay at about 220 us
> with all my test combinations. I will attache a config with RCU_BOOST and
> RCU_TRACE turned off to this mail, which provide a worst case value at 223 us
> after about 40 Minutes test run on my board.

I think I understood why CONFIG_RCU_TRACEin 2.6.24-rt helped to keep
latencies low. See:

ttp://marc.info/?l=linux-rt-users&m=121499677026236&w=4

But as Steven pointed out, the preempt_enable_noresched at that place
might be illegal, anyway. In 2.6.25-rt, trace_mark() is no longer used
and I do not see an improvement with CONFIG_RCU_TRAC any more. Latencies
go up to 600us. I also tried with CONFIG_RCU_BOOST disabled, but it did
not improve the latencies. Actually, I still measure significantly
different latencies with 2.6.24.4-rt4, 2.6.24.7-rt14 and 2.6.25.8-rt7,
which is quite frustrating. As you seem not be able to reproduce my high
latencies, I wonder if there are some toolchain or glibc related issues.

Using ftrace to localized the latency spot would be the next step. But
it's not yet available for PowerPC. Looking into that now.

> Are you using the FEC all a pci network card?

I use only the FEC. There is no PCI device.

Wolfgang.

2008-07-09 12:54:04

by Luotao Fu

[permalink] [raw]

Subject: Re: 2.6.24-rc8-rt1: Strange latencies on mpc5200 powerpc - RCU issue?

Hi Wolfgang,

Wolfgang Grandegger wrote:
> Hi Fun,

What's so funny? ;-)

[...]

> But as Steven pointed out, the preempt_enable_noresched at that place
> might be illegal, anyway. In 2.6.25-rt, trace_mark() is no longer
> used and I do not see an improvement with CONFIG_RCU_TRAC any more.
> Latencies go up to 600us. I also tried with CONFIG_RCU_BOOST
> disabled, but it did not improve the latencies. Actually, I still
> measure significantly different latencies with 2.6.24.4-rt4,
> 2.6.24.7-rt14 and 2.6.25.8-rt7, which is quite frustrating. As you
> seem not be able to reproduce my high latencies, I wonder if there
> are some toolchain or glibc related issues.

I took a quick look into the rcppreempt boost stuff in 2.6.24-rt and
2.6.25-rt. As you have mentioned, trace_mark is no more used in
2.6.24-rt. Instead of that flags are used to detect if the task is
preempted. It might indeed probably be some toolchain issue.
My powerpc toolchain I'm using here contains gcc 4.1.2 and glibc 2.5

Cheers
Fu (without n)
--
Dipl.-Ing. Luotao Fu | Phone: +49-5121-206917-3
Pengutronix - Linux Solutions for Science and Industry
Entwicklungszentrum Nord http://www.pengutronix.de

2008-07-09 13:14:35

by Wolfgang Grandegger

[permalink] [raw]

Subject: Re: 2.6.24-rc8-rt1: Strange latencies on mpc5200 powerpc - RCU issue?

Hi Fu (without n)

Luotao Fu wrote:
> Hi Wolfgang,
>
> Wolfgang Grandegger wrote:
>> Hi Fun,
>
> What's so funny? ;-)

Ah, oh, just a funny typo ;-).

> [...]
>
>> But as Steven pointed out, the preempt_enable_noresched at that place
>> might be illegal, anyway. In 2.6.25-rt, trace_mark() is no longer
>> used and I do not see an improvement with CONFIG_RCU_TRAC any more.
>> Latencies go up to 600us. I also tried with CONFIG_RCU_BOOST
>> disabled, but it did not improve the latencies. Actually, I still
>> measure significantly different latencies with 2.6.24.4-rt4,
>> 2.6.24.7-rt14 and 2.6.25.8-rt7, which is quite frustrating. As you
>> seem not be able to reproduce my high latencies, I wonder if there
>> are some toolchain or glibc related issues.
>
> I took a quick look into the rcppreempt boost stuff in 2.6.24-rt and
> 2.6.25-rt. As you have mentioned, trace_mark is no more used in
> 2.6.24-rt. Instead of that flags are used to detect if the task is
> preempted. It might indeed probably be some toolchain issue.
> My powerpc toolchain I'm using here contains gcc 4.1.2 and glibc 2.5

OK, in the past you have been able to reproduce the high latencies with
2.6.24-rt1 and CONFIG_RCU_TRACE disabled, IIRC. Did you use a different
toolchain at that time?

Wolfgang.

2008-07-09 14:52:33

Paul E. McKenney wrote:
> On Wed, Jul 02, 2008 at 01:03:27PM +0200, Wolfgang Grandegger wrote:
>> Wolfgang Grandegger wrote:
>>> Steven Rostedt wrote:
>>> There seems to be something in trace_mark() keeping latency low:
>>> http://lxr.linux.no/linux+v2.6.24.4/include/linux/marker.h#L52
>>> I will follow your suggestions.
>> I removed all "likely" and "unlikely" macros, but the latencies did not
>> improve. Then I added
>>
>> preempt_disable();
>> preempt_enable();
>>
>> at the two locations mentioned above, like trace_mark() does, and disabled
>> CONFIG_RCU_TRACE. That helped to keep the latencies low, and it did for
>> 2.6.25.8-rt7 as well. As I see it, adding preemption points seem to prevent
>> high latencies.
>
> Interesting. Perhaps a preempt_enable_no_resched() somewhere that
> should be preempt_enable()?

FYI, Thomas fixed the real problem a week ago and the patch went into
2.6.24.7-rt16. See his mail with the subject "2.6.24.7-rt16".

Wolfgang.