linux-kernel - Re: 2.6.24-rc8-rt1: Strange latencies on mpc5200 powerpc

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20080123145340.GE6200@pengutronix.de>
Date:	Wed, 23 Jan 2008 15:53:40 +0100
From:	Luotao Fu <l.fu@...gutronix.de>
To:	Steven Rostedt <rostedt@...dmis.org>,
	Wolfgang Grandegger <wg@...ndegger.com>
Cc:	LKML <linux-kernel@...r.kernel.org>,
	RT <linux-rt-users@...r.kernel.org>, Ingo Molnar <mingo@...e.hu>,
	Thomas Gleixner <tglx@...utronix.de>
Subject: Re: 2.6.24-rc8-rt1: Strange latencies on mpc5200 powerpc

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

View attachment "trace_600_1.log" of type "text/plain" (4621 bytes)

View attachment "trace_600_2.log" of type "text/plain" (2789 bytes)

View attachment "trace_150.log" of type "text/plain" (2709 bytes)

Download attachment "signature.asc" of type "application/pgp-signature" (190 bytes)