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: <47986E44.3010101@grandegger.com>
Date:	Thu, 24 Jan 2008 11:53:56 +0100
From:	Wolfgang Grandegger <wg@...ndegger.com>
To:	Luotao Fu <l.fu@...gutronix.de>
CC:	Steven Rostedt <rostedt@...dmis.org>,
	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

Wolfgang Grandegger wrote:
> 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:

OK, here is the full report.

I had the occasion to test Linux 2.6.24-rc8-rt1 on a TQM5200 module with
a MPC5200 Rev.B processor and, what surprise, the latencies measured
were much better:

  CPU:   MPC5200B v2.2, Core v1.4 at 396 MHz
         Bus 132 MHz, IPB 132 MHz, PCI 66 MHz
  Board: TQM5200 (TQ-Components GmbH)
         on a STK52xx carrier board

  bash-3.00# ./cyclictest -n -p80 -t1 -i1000
  2.91 4.81 13.72 1/50 23887

  T: 0 (  976) P:80 I:1000 C:1634520 Min: 15 Act:  45 Avg:  68 Max:  138

So far I used my very old Icecube eval board with a MPC5200 *Rev. *A for
testing, This made me curious and I made measurements on a TQM5200
module with a MPC5200 Rev.A processor as well booting the same kernel,
but the results were the same:

  CPU:   MPC5200 v1.2, Core v1.1 at 396 MHz
         Bus 132 MHz, IPB 132 MHz, PCI 66 MHz
  Board: TQM5200 (TQ-Components GmbH)
         on a STK52xx carrier board

  bash-3.00# ./cyclictest -n -p80 -i1000
  52.31 96.08 61.61 2/51 9129

  T: 0 (  976) P:80 I:1000 C: 795180 Min:  14 Act: 75 Avg:  69 Max:  134

Hm, then I used that config for my Icecube and also on that board, the
latency did not yet exceed 150us. With my old config, the latency jumped
up to 500..600us within a minute or so. Therefore I started to study the
impact of the different kernel options on the latency. Let's start from
the *good* settings (see attached .config) giving the following results:

  CPU:   MPC5200 v1.0, Core v1.1 at 198 MHz
         Bus 132 MHz, IPB 66 MHz, PCI 33 MHz
  Board: Motorola MPC5200 (IceCube)

  bash-3.00# ./cyclictest -n -p80 -t1 -i1000
  291.40 143.72 115.43 5/447 28227

  T: 0 (  938) P:80 I:1000 C:3613444 Min: 17 Act: 68 Avg:  65 Max:  143

  Note: this test was running for *1* hour.

Then I repeated the measurements with the following configs:

- .config and "CONFIG_RCU_TRACE=m":

  bash-3.00# ./cyclictest -n -p80 -t1 -i1000
  2.49 1.19 0.45 2/46 2846

  T: 0 ( 1144) P:80 I:1000 C: 130362 Min: 17 Act: 57 Avg:  73 Max:  522

  Note: High latencies show up quickly.

- .config and CONFIG_NO_HZ=y:

  bash-3.00# ./cyclictest -n -p80 -t1 -i1000
  15.83 79.48 83.66 3/47 16861

  T: 0 (  913) P:80 I:1000 C:1924513 Min: 20 Act: 81 Avg:  84 Max:  226

- .config and CONFIG_PPC_BESTCOMM_GEN_BD=y

  bash-3.00# ./cyclictest -n -p80 -t1 -i1000
  87.81 116.12 85.31 3/47 11858

  T: 0 (  914) P:80 I:1000 C:1389487 Min: 17 Act: 80 Avg:  67 Max:  147

- .config and CONFIG_PREEMPT_RCU_BOOST is not set:

  bash-3.00# ./cyclictest -n -p80 -t1 -i10000
  81.36 103.93 67.34 3/46 9593

  T: 0 (  913) P:80 I:10000 C:  91915 Min: 25 Act: 64 Avg:  72 Max:  298

And here is my summary:

- CONFIG_RCU_TRACE=m causes high latencies up to 500..600us.

- CONFIG_NO_HZ=y increases the latency by 90 us, at least.

- CONFIG_PPC_BESTCOMM_GEN_BD=y seems not to harm.

- CONFIG_PREEMPT_RCU_BOOST is not set increases the latency by 150us, at
  least

For the tests I used a root file-system mounted via NFS and "while ls;
do ls/bin; done" in one telnet window and "while ./hackbench 10; do
./calibrator 400 32M cali; sleep 30; done" in another telnet window as
non-rt load.

I don't know if "my" .config is already optimal but a latency below
150us seems more reasonable for that processor.

Please comment.

Wolfgang.




View attachment "uImage-rt-test1.config" of type "text/plain" (21324 bytes)