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

[Luotao Fu <l.fu@pengutronix.de>]

[-- Attachment #1.1: Type: text/plain, Size: 2587 bytes --]

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


[-- Attachment #1.2: trace_600_1.log --]
[-- Type: text/plain, Size: 4621 bytes --]

cyclicte-16669 0D..2 2203085us+: __schedule+0x1f4/0x40c <IRQ-131-151> (150 180)
cyclicte-16669 0D..1 2203115us+: enqueue_hrtimer+0x48/0x194 (  394 1ca956ec c3a11e98)
cyclicte-16669 0D..2 2203129us+: deactivate_task+0x58/0x9c <cyclicte-16669> (180 5)
 IRQ-131-151   0D..2 2203135us+: __schedule+0x1f4/0x40c <cyclicte-16669> (180 150)
 IRQ-131-151   0D..3 2203160us+: task_setprio+0xc0/0x258 <cyclicte-16668> (0 150)
 IRQ-131-151   0D..3 2203164us+: task_setprio+0x13c/0x258 (    0     0     0)
 IRQ-131-151   0D.h1 2203173us+: hrtimer_interrupt+0xa8/0x2d0 (  394 1c9cb6c7     0)
 IRQ-131-151   0D.h2 2203176us+: hrtimer_interrupt+0x128/0x2d0 (  394 1c9c3800 c02d6788)
 IRQ-131-151   0D.h2 2203199us+: activate_task+0x58/0x9c <softirq--5> (150 4)
 IRQ-131-151   0D.h2 2203217us+: activate_task+0x58/0x9c <softirq--12> (150 5)
 IRQ-131-151   0D.h2 2203224us+: enqueue_hrtimer+0x48/0x194 (  394 1d34ce80 c02d6788)
 IRQ-131-151   0D.h1 2203231us+: clockevents_program_event+0x7c/0x1d0 (  394 1ca956ec bc1d7)
 IRQ-131-151   0D..2 2203250us+: deactivate_task+0x58/0x9c <IRQ-131-151> (150 6)
cyclicte-16668 0D..2 2203259us+: __schedule+0x1f4/0x40c <IRQ-131-151> (150 150)
cyclicte-16668 0D..2 2203272us+: activate_task+0x58/0x9c <IRQ-131-151> (150 5)
cyclicte-16668 0D..2 2203282us+: task_setprio+0x184/0x258 <cyclicte-16668> (150 0)
cyclicte-16668 0DN.2 2203291us+: task_setprio+0x13c/0x258 (    0     1     0)
softirq--5     0D..2 2203306us+: __schedule+0x1f4/0x40c <cyclicte-16668> (0 150)
softirq--5     0D..2 2203340us+: deactivate_task+0x58/0x9c <softirq--5> (150 6)
softirq--12    0D..2 2203346us+: __schedule+0x1f4/0x40c <softirq--5> (150 150)
softirq--12    0D..2 2203361us+: deactivate_task+0x58/0x9c <softirq--12> (150 5)
 IRQ-131-151   0D..2 2203367us+: __schedule+0x1f4/0x40c <softirq--12> (150 150)
 IRQ-131-151   0D..1 2203401us+: activate_task+0x58/0x9c <softirq--9> (150 4)
 IRQ-131-151   0D..2 2203428us+: deactivate_task+0x58/0x9c <IRQ-131-151> (150 5)
softirq--9     0D..2 2203435us+: __schedule+0x1f4/0x40c <IRQ-131-151> (150 150)
softirq--9     0D..2 2203454us+: deactivate_task+0x58/0x9c <softirq--9> (150 4)
cyclicte-16668 0D..2 2203465us+: __schedule+0x1f4/0x40c <softirq--9> (150 0)
cyclicte-16668 0D.h2 2203491us+: activate_task+0x58/0x9c <IRQ-131-151> (150 3)
cyclicte-16668 0D.h2 2203494us+: __trace_start_sched_wakeup+0x14c/0x184 <IRQ-131-151> (49 -1)
cyclicte-16668 0DNh2 2203500us+: __trace_start_sched_wakeup+0x14c/0x184 <IRQ-131-151> (49 -1)
cyclicte-16668 0DNh2 2203501us+: try_to_wake_up+0x184/0x1a4 <IRQ-131-151> (150 0)
 IRQ-131-151   0D..2 2203519us+: __schedule+0x1f4/0x40c <cyclicte-16668> (0 150)
 IRQ-131-151   0D..3 2203539us+: task_setprio+0xc0/0x258 <cyclicte-16668> (0 150)
 IRQ-131-151   0D..3 2203544us+: task_setprio+0x13c/0x258 (    0     0     0)
 IRQ-131-151   0D..2 2203554us+: deactivate_task+0x58/0x9c <IRQ-131-151> (150 4)
cyclicte-16668 0D..2 2203559us+: __schedule+0x1f4/0x40c <IRQ-131-151> (150 150)
cyclicte-16668 0D..2 2203570us+: activate_task+0x58/0x9c <IRQ-131-151> (150 3)
cyclicte-16668 0D..2 2203577us+: task_setprio+0x184/0x258 <cyclicte-16668> (150 0)
cyclicte-16668 0DN.2 2203583us+: task_setprio+0x13c/0x258 (    0     1     0)
 IRQ-131-151   0D..2 2203594us+: __schedule+0x1f4/0x40c <cyclicte-16668> (0 150)
 IRQ-131-151   0D..1 2203605us+: activate_task+0x58/0x9c <softirq--9> (150 4)
 IRQ-131-151   0D..2 2203631us+: deactivate_task+0x58/0x9c <IRQ-131-151> (150 5)
softirq--9     0D..2 2203636us+: __schedule+0x1f4/0x40c <IRQ-131-151> (150 150)
softirq--9     0D..2 2203654us+: deactivate_task+0x58/0x9c <softirq--9> (150 4)
cyclicte-16668 0D..2 2203663us+: __schedule+0x1f4/0x40c <softirq--9> (150 0)
cyclicte-16668 0D..1 2203711us+: enqueue_hrtimer+0x48/0x194 (  394 1d3d76bb c3a15ea8)
cyclicte-16668 0D..2 2203726us+: deactivate_task+0x58/0x9c <cyclicte-16668> (0 3)
      sh-19600 0D..2 2203742us!: __schedule+0x1f4/0x40c <cyclicte-16668> (0 0)
      sh-19600 0D.h1 2204020us+: hrtimer_interrupt+0xa8/0x2d0 (  394 1ca99383     0)
      sh-19600 0D.h2 2204025us+: hrtimer_interrupt+0x128/0x2d0 (  394 1ca956ec c3a11e98)
      sh-19600 0D.h3 2204039us+: activate_task+0x58/0x9c <cyclicte-16669> (180 2)
      sh-19600 0D.h3 2204044us+: __trace_start_sched_wakeup+0x14c/0x184 <cyclicte-16669> (19 -1)
      sh-19600 0DNh3 2204050us+: __trace_start_sched_wakeup+0x14c/0x184 <cyclicte-16669> (19 -1)
      sh-19600 0DNh3 2204051us+: try_to_wake_up+0x184/0x1a4 <cyclicte-16669> (180 0)
      sh-19600 0DNh1 2204058us!: clockevents_program_event+0x7c/0x1d0 (  394 1d34ce80 8a9639)
cyclicte-16669 0D..2 2204680us : __schedule+0x1f4/0x40c <sh-19600> (0 180)


[-- Attachment #1.3: trace_600_2.log --]
[-- Type: text/plain, Size: 2789 bytes --]

cyclicte-1193  0D..2 2211546us+: __schedule+0x1f4/0x40c <softirq--6> (150 180)
cyclicte-1193  0D..1 2211575us+: enqueue_hrtimer+0x48/0x194 ( 1846 4569198 c3a33e98)
cyclicte-1193  0D..1 2211583us+: clockevents_program_event+0x7c/0x1d0 ( 1846 4569198 dbc5e)
cyclicte-1193  0D..2 2211597us+: deactivate_task+0x58/0x9c <cyclicte-1193> (180 4)
softirq--6     0D..2 2211603us+: __schedule+0x1f4/0x40c <cyclicte-1193> (180 150)
softirq--6     0D..2 2211625us+: deactivate_task+0x58/0x9c <softirq--6> (150 3)
      sh-1902  0D..2 2211637us+: __schedule+0x1f4/0x40c <softirq--6> (150 0)
      sh-1902  0D..2 2211689us+: deactivate_task+0x58/0x9c <sh-1902> (0 2)
      sh-449   0D..2 2211704us+: __schedule+0x1f4/0x40c <sh-1902> (0 0)
      sh-449   0D.h2 2211762us+: activate_task+0x58/0x9c <IRQ-192-149> (150 1)
      sh-449   0D.h2 2211767us+: __trace_start_sched_wakeup+0x14c/0x184 <IRQ-192-149> (49 -1)
      sh-449   0DNh2 2211772us+: __trace_start_sched_wakeup+0x14c/0x184 <IRQ-192-149> (49 -1)
      sh-449   0DNh2 2211773us+: try_to_wake_up+0x184/0x1a4 <IRQ-192-149> (150 0)
 IRQ-192-149   0D..2 2211792us+: __schedule+0x1f4/0x40c <sh-449> (0 150)
 IRQ-192-149   0D..1 2211821us+: activate_task+0x58/0x9c <softirq--7> (150 2)
 IRQ-192-149   0D..2 2211839us+: deactivate_task+0x58/0x9c <IRQ-192-149> (150 3)
softirq--7     0D..2 2211846us!: __schedule+0x1f4/0x40c <IRQ-192-149> (150 150)
softirq--7     0D..1 2211957us+: activate_task+0x58/0x9c <sh-1902> (0 2)
softirq--7     0D.h2 2212039us+: activate_task+0x58/0x9c <IRQ-193-150> (150 3)
softirq--7     0D..2 2212072us+: deactivate_task+0x58/0x9c <softirq--7> (150 4)
 IRQ-193-150   0D..2 2212083us+: __schedule+0x1f4/0x40c <softirq--7> (150 150)
 IRQ-193-150   0D..1 2212098us+: activate_task+0x58/0x9c <softirq--6> (150 3)
 IRQ-193-150   0D..2 2212111us+: deactivate_task+0x58/0x9c <IRQ-193-150> (150 4)
softirq--6     0D..2 2212118us+: __schedule+0x1f4/0x40c <IRQ-193-150> (150 150)
softirq--6     0D..2 2212139us+: deactivate_task+0x58/0x9c <softirq--6> (150 3)
      sh-1902  0D..2 2212152us!: __schedule+0x1f4/0x40c <softirq--6> (150 0)
      sh-1902  0D.h1 2212501us+: hrtimer_interrupt+0xa8/0x2d0 ( 1846 456cfc8     0)
      sh-1902  0D.h2 2212507us+: hrtimer_interrupt+0x128/0x2d0 ( 1846 4569198 c3a33e98)
      sh-1902  0D.h3 2212521us+: activate_task+0x58/0x9c <cyclicte-1193> (180 2)
      sh-1902  0D.h3 2212526us+: __trace_start_sched_wakeup+0x14c/0x184 <cyclicte-1193> (19 -1)
      sh-1902  0DNh3 2212533us+: __trace_start_sched_wakeup+0x14c/0x184 <cyclicte-1193> (19 -1)
      sh-1902  0DNh3 2212534us+: try_to_wake_up+0x184/0x1a4 <cyclicte-1193> (180 0)
      sh-1902  0DNh1 2212541us!: clockevents_program_event+0x7c/0x1d0 ( 1846 4820f3a 2a9658)
cyclicte-1193  0D..2 2213164us : __schedule+0x1f4/0x40c <sh-1902> (0 180)

[-- Attachment #1.4: trace_150.log --]
[-- Type: text/plain, Size: 2708 bytes --]

cyclicte-12651 0D..2 2241836us+: __schedule+0x1f4/0x40c <sh-12822> (0 180)
cyclicte-12651 0D..1 2241863us+: enqueue_hrtimer+0x48/0x194 ( 2038 2ae2bf80 c3b57e98)
cyclicte-12651 0D..1 2241871us+: clockevents_program_event+0x7c/0x1d0 ( 2038 2ae2bf80 d8949)
cyclicte-12651 0D..2 2241886us+: deactivate_task+0x58/0x9c <cyclicte-12651> (180 2)
      sh-12822 0D..2 2241898us!: __schedule+0x1f4/0x40c <cyclicte-12651> (180 0)
      sh-12822 0D..1 2242158us+: activate_task+0x58/0x9c <telnetd-423> (0 1)
      sh-12822 0DN.1 2242172us+: try_to_wake_up+0x184/0x1a4 <telnetd-423> (0 0)
 telnetd-423   0D..2 2242198us+: __schedule+0x1f4/0x40c <sh-12822> (0 0)
 telnetd-423   0D..2 2242253us+: deactivate_task+0x58/0x9c <telnetd-423> (0 2)
      sh-12822 0D..2 2242264us+: __schedule+0x1f4/0x40c <telnetd-423> (0 0)
      sh-12822 0D..2 2242274us+: activate_task+0x58/0x9c <telnetd-423> (0 1)
      sh-12822 0DN.2 2242281us+: try_to_wake_up+0x184/0x1a4 <telnetd-423> (0 0)
 telnetd-423   0D..2 2242293us+: __schedule+0x1f4/0x40c <sh-12822> (0 0)
 telnetd-423   0D..2 2242339us+: deactivate_task+0x58/0x9c <telnetd-423> (0 2)
      sh-12822 0D..2 2242351us!: __schedule+0x1f4/0x40c <telnetd-423> (0 0)
      sh-12822 0D..3 2242490us+: activate_task+0x58/0x9c <telnetd-423> (0 1)
      sh-12822 0DN.3 2242499us+: try_to_wake_up+0x184/0x1a4 <telnetd-423> (0 0)
 telnetd-423   0D..2 2242516us!: __schedule+0x1f4/0x40c <sh-12822> (0 0)
 telnetd-423   0D..2 2242774us+: deactivate_task+0x58/0x9c <telnetd-423> (0 2)
      sh-12822 0D..2 2242796us+: __schedule+0x1f4/0x40c <telnetd-423> (0 0)
      sh-12822 0D.h2 2242819us+: activate_task+0x58/0x9c <IRQ-193-150> (150 1)
      sh-12822 0D.h2 2242824us+: __trace_start_sched_wakeup+0x14c/0x184 <IRQ-193-150> (49 -1)
      sh-12822 0DNh2 2242828us+: __trace_start_sched_wakeup+0x14c/0x184 <IRQ-193-150> (49 -1)
      sh-12822 0DNh2 2242830us+: try_to_wake_up+0x184/0x1a4 <IRQ-193-150> (150 0)
 IRQ-193-150   0D..2 2242846us+: __schedule+0x1f4/0x40c <sh-12822> (0 150)
 IRQ-193-150   0D.h. 2242860us+: hrtimer_interrupt+0xa8/0x2d0 ( 2038 2ae44ab9     0)
 IRQ-193-150   0D.h1 2242863us+: hrtimer_interrupt+0x128/0x2d0 ( 2038 2ae2bf80 c3b57e98)
 IRQ-193-150   0D.h2 2242871us+: activate_task+0x58/0x9c <cyclicte-12651> (180 2)
 IRQ-193-150   0D.h2 2242875us+: __trace_start_sched_wakeup+0x14c/0x184 <cyclicte-12651> (19 -1)
 IRQ-193-150   0DNh2 2242877us : __trace_start_sched_wakeup+0x14c/0x184 <cyclicte-12651> (19 -1)
 IRQ-193-150   0DNh2 2242878us+: try_to_wake_up+0x184/0x1a4 <cyclicte-12651> (180 150)
 IRQ-193-150   0DNh. 2242885us+: clockevents_program_event+0x7c/0x1d0 ( 2038 2aea5400 5a227)
cyclicte-12651 0D..2 2242900us : __schedule+0x1f4/0x40c <IRQ-193-150> (150 180)

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 189 bytes --]