Long max latencies on Wandbaord / Freescale i.MX6

Long max latencies on Wandbaord / Freescale i.MX6

[Matthias Meier]

Hi,

using cyclictest I measure long max latencies of >10ms on a Wandboard 
dual (Freescale i.MX6 dual Cortex-A9 SoC).

The latency problem happens with diffent scenarios:
- without or with rt-patch  (4.1.7-rt8 w. CONFIG_PREEMPT_RT_FULL)
- different Kernels (3.17, 4.1, 4.2 w. CONFIG_PREEMPT__LL)
- different CPU governors including 'performance'
- independant of CPU load
- even with no other userspace processes but init, the login sh and 
cyclictest (I use a minimal builroot rfs).
- independant of cyclictest prio

Using the same buildroot rfs on a A20 SoC (bananapro) with 4.1.7-rt8 
shows acceptable rt-latencies of ~ 200us.

Ftracing 'irqsoff' on the rt-patched 4.1 kernel shows always long 
latency after 'raw_spin_lock_irq' (see log below).

Do you think it is a driver which stalls or hrtimer not working 
correctly on this SoC or someting else?
If it is a driver, how could I find out which it is?

Thanks
Matthias

------------------------------------------

Test log with 4.1.7-rt8 kernel and no additional load:

# cyclictest --smp -p98 -m
# /dev/cpu_dma_latency sepolicy: fifo: loadavg: 3.66 3.87 3.61 4/87 580
WARN: Running on unknown kernel version...YMMV
T: 0 (  572) P:98 I:1000 C:1225776 Min:     52 Act:  317 Avg:  393 
Max:    6161
T: 1 (  573) P:98 I:1500 C: 816449 Min:     64 Act:  143 Avg:  381 
Max:    4567


# cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 4.1.7-rt8-wb+
# --------------------------------------------------------------------
# latency: 4062 us, #7/7, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
#    -----------------
#    | task: cyclictest-338 (uid:0 nice:0 policy:1 rt_prio:95)
#    -----------------
#  => started at: _raw_spin_lock_irq
#  => ended at:   _raw_spin_unlock_irq
#
#
#                   _--------=> CPU#
#                  / _-------=> irqs-off
#                 | / _------=> need-resched
#                 || / _-----=> need-resched_lazy
#                 ||| / _----=> hardirq/softirq
#                 |||| / _---=> preempt-depth
#                 ||||| / _--=> preempt-lazy-depth
#                 |||||| / _-=> migrate-disable
#                 ||||||| /     delay
#  cmd     pid    |||||||| time  |   caller
#     \   /      ||||||||  \   |   /
       sh-156     0dn..111    1us#: trace_hardirqs_off <-_raw_spin_lock_irq
cyclicte-338     0d...3.. 4052us : finish_task_switch <-__schedule
cyclicte-338     0d...3.. 4057us : _raw_spin_unlock_irq <-finish_task_switch
cyclicte-338     0d...3.. 4059us : do_raw_spin_unlock <-_raw_spin_unlock_irq
cyclicte-338     0d...2.. 4061us : trace_hardirqs_on <-_raw_spin_unlock_irq
cyclicte-338     0d...2.. 4066us+: time_hardirqs_on <-_raw_spin_unlock_irq
cyclicte-338     0d...2.. 4080us : <stack trace>
  => trace_hardirqs_on
  => _raw_spin_unlock_irq
  => finish_task_switch
  => __schedule
  => schedule
  => do_nanosleep
  => __hrtimer_nanosleep
  => hrtimer_nanosleep
  => common_nsleep
  => SyS_clock_nanosleep
  => ret_fast_syscall
#

Re: Long max latencies on Wandbaord / Freescale i.MX6

[Joe Korty]

Usually delays this long, and independent of OS, indicate that an SMI
interrupt is happening on this hardware.  You can test this with the
the hardware latency detector (CONFIG_HWLAT_DETECTOR).

Regards,
Joe

On Sat, Sep 26, 2015 at 05:38:02AM -0400, Matthias Meier wrote:
> Hi,
> 
> using cyclictest I measure long max latencies of >10ms on a Wandboard 
> dual (Freescale i.MX6 dual Cortex-A9 SoC).
> 
> The latency problem happens with diffent scenarios:
> - without or with rt-patch  (4.1.7-rt8 w. CONFIG_PREEMPT_RT_FULL)
> - different Kernels (3.17, 4.1, 4.2 w. CONFIG_PREEMPT__LL)
> - different CPU governors including 'performance'
> - independant of CPU load
> - even with no other userspace processes but init, the login sh and 
> cyclictest (I use a minimal builroot rfs).
> - independant of cyclictest prio
> 
> Using the same buildroot rfs on a A20 SoC (bananapro) with 4.1.7-rt8 
> shows acceptable rt-latencies of ~ 200us.
> 
> Ftracing 'irqsoff' on the rt-patched 4.1 kernel shows always long 
> latency after 'raw_spin_lock_irq' (see log below).
> 
> Do you think it is a driver which stalls or hrtimer not working 
> correctly on this SoC or someting else?
> If it is a driver, how could I find out which it is?
> 
> Thanks
> Matthias
> 
> ------------------------------------------
> 
> Test log with 4.1.7-rt8 kernel and no additional load:
> 
> # cyclictest --smp -p98 -m
> # /dev/cpu_dma_latency sepolicy: fifo: loadavg: 3.66 3.87 3.61 4/87 580
> WARN: Running on unknown kernel version...YMMV
> T: 0 (  572) P:98 I:1000 C:1225776 Min:     52 Act:  317 Avg:  393 
> Max:    6161
> T: 1 (  573) P:98 I:1500 C: 816449 Min:     64 Act:  143 Avg:  381 
> Max:    4567
> 
> 
> # cat trace
> # tracer: irqsoff
> #
> # irqsoff latency trace v1.1.5 on 4.1.7-rt8-wb+
> # --------------------------------------------------------------------
> # latency: 4062 us, #7/7, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
> #    -----------------
> #    | task: cyclictest-338 (uid:0 nice:0 policy:1 rt_prio:95)
> #    -----------------
> #  => started at: _raw_spin_lock_irq
> #  => ended at:   _raw_spin_unlock_irq
> #
> #
> #                   _--------=> CPU#
> #                  / _-------=> irqs-off
> #                 | / _------=> need-resched
> #                 || / _-----=> need-resched_lazy
> #                 ||| / _----=> hardirq/softirq
> #                 |||| / _---=> preempt-depth
> #                 ||||| / _--=> preempt-lazy-depth
> #                 |||||| / _-=> migrate-disable
> #                 ||||||| /     delay
> #  cmd     pid    |||||||| time  |   caller
> #     \   /      ||||||||  \   |   /
>        sh-156     0dn..111    1us#: trace_hardirqs_off <-_raw_spin_lock_irq
> cyclicte-338     0d...3.. 4052us : finish_task_switch <-__schedule
> cyclicte-338     0d...3.. 4057us : _raw_spin_unlock_irq <-finish_task_switch
> cyclicte-338     0d...3.. 4059us : do_raw_spin_unlock <-_raw_spin_unlock_irq
> cyclicte-338     0d...2.. 4061us : trace_hardirqs_on <-_raw_spin_unlock_irq
> cyclicte-338     0d...2.. 4066us+: time_hardirqs_on <-_raw_spin_unlock_irq
> cyclicte-338     0d...2.. 4080us : <stack trace>
>   => trace_hardirqs_on
>   => _raw_spin_unlock_irq
>   => finish_task_switch
>   => __schedule
>   => schedule
>   => do_nanosleep
>   => __hrtimer_nanosleep
>   => hrtimer_nanosleep
>   => common_nsleep
>   => SyS_clock_nanosleep
>   => ret_fast_syscall
> #
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

-- 

Regards,
Joe

_________________________________________________
Joe Korty
Concurrent Computer Corporation
2881 Gateway Drive
Pompano Beach, Florida USA 33069
Phone: +1 954.973.5262
Email: joe.korty@ccur.com
_________________________________________________

Re: Long max latencies on Wandbaord / Freescale i.MX6

[Matthias Meier]

there is no BIOS or (U)EFI on this platform - just a (u-boot) loader so 
there is no SMI

Am 26.09.2015 um 16:16 schrieb Joe Korty:
> Usually delays this long, and independent of OS, indicate that an SMI
> interrupt is happening on this hardware.  You can test this with the
> the hardware latency detector (CONFIG_HWLAT_DETECTOR).
>
> Regards,
> Joe
>
> On Sat, Sep 26, 2015 at 05:38:02AM -0400, Matthias Meier wrote:
>> Hi,
>>
>> using cyclictest I measure long max latencies of >10ms on a Wandboard
>> dual (Freescale i.MX6 dual Cortex-A9 SoC).
>>
>> The latency problem happens with diffent scenarios:
>> - without or with rt-patch  (4.1.7-rt8 w. CONFIG_PREEMPT_RT_FULL)
>> - different Kernels (3.17, 4.1, 4.2 w. CONFIG_PREEMPT__LL)
>> - different CPU governors including 'performance'
>> - independant of CPU load
>> - even with no other userspace processes but init, the login sh and
>> cyclictest (I use a minimal builroot rfs).
>> - independant of cyclictest prio
>>
>> Using the same buildroot rfs on a A20 SoC (bananapro) with 4.1.7-rt8
>> shows acceptable rt-latencies of ~ 200us.
>>
>> Ftracing 'irqsoff' on the rt-patched 4.1 kernel shows always long
>> latency after 'raw_spin_lock_irq' (see log below).
>>
>> Do you think it is a driver which stalls or hrtimer not working
>> correctly on this SoC or someting else?
>> If it is a driver, how could I find out which it is?
>>
>> Thanks
>> Matthias
>>
>> ------------------------------------------
>>
>> Test log with 4.1.7-rt8 kernel and no additional load:
>>
>> # cyclictest --smp -p98 -m
>> # /dev/cpu_dma_latency sepolicy: fifo: loadavg: 3.66 3.87 3.61 4/87 580
>> WARN: Running on unknown kernel version...YMMV
>> T: 0 (  572) P:98 I:1000 C:1225776 Min:     52 Act:  317 Avg:  393
>> Max:    6161
>> T: 1 (  573) P:98 I:1500 C: 816449 Min:     64 Act:  143 Avg:  381
>> Max:    4567
>>
>>
>> # cat trace
>> # tracer: irqsoff
>> #
>> # irqsoff latency trace v1.1.5 on 4.1.7-rt8-wb+
>> # --------------------------------------------------------------------
>> # latency: 4062 us, #7/7, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
>> #    -----------------
>> #    | task: cyclictest-338 (uid:0 nice:0 policy:1 rt_prio:95)
>> #    -----------------
>> #  => started at: _raw_spin_lock_irq
>> #  => ended at:   _raw_spin_unlock_irq
>> #
>> #
>> #                   _--------=> CPU#
>> #                  / _-------=> irqs-off
>> #                 | / _------=> need-resched
>> #                 || / _-----=> need-resched_lazy
>> #                 ||| / _----=> hardirq/softirq
>> #                 |||| / _---=> preempt-depth
>> #                 ||||| / _--=> preempt-lazy-depth
>> #                 |||||| / _-=> migrate-disable
>> #                 ||||||| /     delay
>> #  cmd     pid    |||||||| time  |   caller
>> #     \   /      ||||||||  \   |   /
>>         sh-156     0dn..111    1us#: trace_hardirqs_off <-_raw_spin_lock_irq
>> cyclicte-338     0d...3.. 4052us : finish_task_switch <-__schedule
>> cyclicte-338     0d...3.. 4057us : _raw_spin_unlock_irq <-finish_task_switch
>> cyclicte-338     0d...3.. 4059us : do_raw_spin_unlock <-_raw_spin_unlock_irq
>> cyclicte-338     0d...2.. 4061us : trace_hardirqs_on <-_raw_spin_unlock_irq
>> cyclicte-338     0d...2.. 4066us+: time_hardirqs_on <-_raw_spin_unlock_irq
>> cyclicte-338     0d...2.. 4080us : <stack trace>
>>    => trace_hardirqs_on
>>    => _raw_spin_unlock_irq
>>    => finish_task_switch
>>    => __schedule
>>    => schedule
>>    => do_nanosleep
>>    => __hrtimer_nanosleep
>>    => hrtimer_nanosleep
>>    => common_nsleep
>>    => SyS_clock_nanosleep
>>    => ret_fast_syscall
>> #
>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

Re: Long max latencies on Wandbaord / Freescale i.MX6

[Thomas Gleixner]

On Sat, 26 Sep 2015, Matthias Meier wrote:

> Hi,
> 
> using cyclictest I measure long max latencies of >10ms on a Wandboard dual
> (Freescale i.MX6 dual Cortex-A9 SoC).
> 
> The latency problem happens with diffent scenarios:
> - without or with rt-patch  (4.1.7-rt8 w. CONFIG_PREEMPT_RT_FULL)
> - different Kernels (3.17, 4.1, 4.2 w. CONFIG_PREEMPT__LL)
> - different CPU governors including 'performance'
> - independant of CPU load
> - even with no other userspace processes but init, the login sh and cyclictest
> (I use a minimal builroot rfs).
> - independant of cyclictest prio
> 
> Using the same buildroot rfs on a A20 SoC (bananapro) with 4.1.7-rt8 shows
> acceptable rt-latencies of ~ 200us.
> 
> Ftracing 'irqsoff' on the rt-patched 4.1 kernel shows always long latency
> after 'raw_spin_lock_irq' (see log below).
> 
> Do you think it is a driver which stalls or hrtimer not working correctly on
> this SoC or someting else?
> If it is a driver, how could I find out which it is?

Try to capture the issue with full function tracing.

cyclictest --smp -p80 -m -f -b 5000

That stops the tracer when the latency is > 5ms. You might have to
increase the trace buffer size. Please upload the trace to some place
or send it to me privately (it's over the size limit of the list).

Thanks,

	tglx

Re: Long max latencies on Wandbaord / Freescale i.MX6

[Matthias Meier]

just for imformation what causes the long latencies...

cause of the latency problem of up to 10ms was 'CONFIG_PROVE_LOCKING' 
enabled in the kernel config. After disabling it, the max latency is now 
below 400us. (many thx to tglx who found the problem).

The following arm boards have 'CONFIG_PROVE_LOCKING=y' in the defconfig 
and therefore the same problem:

ezx_defconfig
imote2_defconfig
imx_v6_v7_defconfig
moxart_defconfig
mxs_defconfig
omap2plus_defconfig

Regards
Matthias


Am 27.09.2015 um 13:49 schrieb Thomas Gleixner:
> On Sat, 26 Sep 2015, Matthias Meier wrote:
>
>> Hi,
>>
>> using cyclictest I measure long max latencies of >10ms on a Wandboard dual
>> (Freescale i.MX6 dual Cortex-A9 SoC).
>>
>> The latency problem happens with diffent scenarios:
>> - without or with rt-patch  (4.1.7-rt8 w. CONFIG_PREEMPT_RT_FULL)
>> - different Kernels (3.17, 4.1, 4.2 w. CONFIG_PREEMPT__LL)
>> - different CPU governors including 'performance'
>> - independant of CPU load
>> - even with no other userspace processes but init, the login sh and cyclictest
>> (I use a minimal builroot rfs).
>> - independant of cyclictest prio
>>
>> Using the same buildroot rfs on a A20 SoC (bananapro) with 4.1.7-rt8 shows
>> acceptable rt-latencies of ~ 200us.
>>
>> Ftracing 'irqsoff' on the rt-patched 4.1 kernel shows always long latency
>> after 'raw_spin_lock_irq' (see log below).
>>
>> Do you think it is a driver which stalls or hrtimer not working correctly on
>> this SoC or someting else?
>> If it is a driver, how could I find out which it is?
>
> Try to capture the issue with full function tracing.
>
> cyclictest --smp -p80 -m -f -b 5000
>
> That stops the tracer when the latency is > 5ms. You might have to
> increase the trace buffer size. Please upload the trace to some place
> or send it to me privately (it's over the size limit of the list).
>
> Thanks,
>
> 	tglx
>
>

Re[2]: Long max latencies on Wandbaord / Freescale i.MX6

[Matthias Klein]

Hello Matthias,


thanks a lot for the tip!


I saw something similar on a AM335x board, but investigated in not 
further until now.
But CONFIG_PROVE_LOCKING is enabled from the defconfig ...

Best regards,
Matthias


------ Originalnachricht ------
Von: "Matthias Meier" <matthias.j.meier@gmx.net>
An: linux-rt-users@vger.kernel.org
Gesendet: 29.09.2015 08:30:56
Betreff: Re: Long max latencies on Wandbaord / Freescale i.MX6

>just for imformation what causes the long latencies...
>
>cause of the latency problem of up to 10ms was 'CONFIG_PROVE_LOCKING' 
>enabled in the kernel config. After disabling it, the max latency is 
>now below 400us. (many thx to tglx who found the problem).
>
>The following arm boards have 'CONFIG_PROVE_LOCKING=y' in the defconfig 
>and therefore the same problem:
>
>ezx_defconfig
>imote2_defconfig
>imx_v6_v7_defconfig
>moxart_defconfig
>mxs_defconfig
>omap2plus_defconfig
>
>Regards
>Matthias
>
>
>Am 27.09.2015 um 13:49 schrieb Thomas Gleixner:
>>On Sat, 26 Sep 2015, Matthias Meier wrote:
>>
>>>Hi,
>>>
>>>using cyclictest I measure long max latencies of >10ms on a Wandboard 
>>>dual
>>>(Freescale i.MX6 dual Cortex-A9 SoC).
>>>
>>>The latency problem happens with diffent scenarios:
>>>- without or with rt-patch  (4.1.7-rt8 w. CONFIG_PREEMPT_RT_FULL)
>>>- different Kernels (3.17, 4.1, 4.2 w. CONFIG_PREEMPT__LL)
>>>- different CPU governors including 'performance'
>>>- independant of CPU load
>>>- even with no other userspace processes but init, the login sh and 
>>>cyclictest
>>>(I use a minimal builroot rfs).
>>>- independant of cyclictest prio
>>>
>>>Using the same buildroot rfs on a A20 SoC (bananapro) with 4.1.7-rt8 
>>>shows
>>>acceptable rt-latencies of ~ 200us.
>>>
>>>Ftracing 'irqsoff' on the rt-patched 4.1 kernel shows always long 
>>>latency
>>>after 'raw_spin_lock_irq' (see log below).
>>>
>>>Do you think it is a driver which stalls or hrtimer not working 
>>>correctly on
>>>this SoC or someting else?
>>>If it is a driver, how could I find out which it is?
>>
>>Try to capture the issue with full function tracing.
>>
>>cyclictest --smp -p80 -m -f -b 5000
>>
>>That stops the tracer when the latency is > 5ms. You might have to
>>increase the trace buffer size. Please upload the trace to some place
>>or send it to me privately (it's over the size limit of the list).
>>
>>Thanks,
>>
>>  tglx
>>
>>
>--
>To unsubscribe from this list: send the line "unsubscribe 
>linux-rt-users" in
>the body of a message to majordomo@vger.kernel.org
>More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Long max latencies on Wandbaord / Freescale i.MX6

[Thomas Gleixner]

On Tue, 29 Sep 2015, Matthias Meier wrote:

> just for imformation what causes the long latencies...
> 
> cause of the latency problem of up to 10ms was 'CONFIG_PROVE_LOCKING' enabled
> in the kernel config. After disabling it, the max latency is now below 400us.
> (many thx to tglx who found the problem).

There are plenty of other debug options enabled in that config file,
which introduce latencies. If you switch them off you should get
results which are below 100us.

Thanks,

	tglx

Re: Long max latencies on Wandbaord / Freescale i.MX6

[Matthias Meier]

PROVE_LOCKING is not so bad I thought

finally I guess my latency problem is caused by a spurious interrupt on 
a unused mmc slot causing heavy load when using PROVE_LOCKING ...


Here a little more in detail what I did:

Disabling CONFIG_PROVE_LOCKING together with a lot other debug options 
as Thomas proposed indeed gave max latencies in the range of 100us - at 
least most of the time...

After adding besides 'hackbench' additional heavy network load via the 
on-board WiFi interface, the max latency raised further and finally I 
the kernel fired a backtrace which ended in a "Disabling IRQ #284"

/proc/interrupts indeed shows a hugh amout of interrupts on mmc1 
although I don't use mmc1 at all (the Wandboard boots via mmc0)

(possible a pullup config is missing at the mmc interfaces?)

After reboot I tried to stop the spurious interrupts by inserting a 
sd-card on mmc1 but this does not work - still high interrupts.

Now I'm trying to disable mmc1 and mmc2 completely which is not as easy 
as I thought: via sysfs it seems not to be possible and via DT I think I 
would have to modify all imx6* DTS files of all imx6 boards - otherwise 
the dtbs does not compile...


Is there a simple solution to disable either a single interrupt or a 
individual mmc interface from userspace?

Thanks,
	Matthias

Long max latencies on Wandbaord / Freescale i.MX6

[Matthias Meier]

Comming to the end of my CONFIG_PROVE_LOCKING / "max latency" story:

It is not a spurious interrupt...

The source of problem is the WiFi driver (brcmfmac via SDIO) which 
produces up to 6k interrupts per second, which when 
CONFIG_PROOVE_LOCKING is enabled, results sporadically in very long 
latencies (up to 10ms). (Possible because pending interrupts were queued).

Further after exactly 1600001 interrupts, the kernel disables this mmc 
interrupt with "__report_bad_irq"
(The mmc driver is not only used for SD-cards but also for the SDIO 
attached devices.)

Or with other words: never use (this) WiFi on a realtime system...

Regards and sorry for the noise I produced on this list
	Matthias

Re: Long max latencies on Wandbaord / Freescale i.MX6

[Mats Karrman]

On 2015-10-02 08:48, Matthias Meier wrote:
>
> Regards and sorry for the noise I produced on this list
>     Matthias
>
Don't be, it's cheaper to learn from other peoples mistakes!
Thanks,
Mats