Long max latencies on Wandbaord / Freescale i.MX6

DISCUSSION Matthias Meier 5 participants 10 messages Sep 26, 2015 – Oct 2, 2015

lore

Share & tools

lore

Matthias Meier

author

2015-09-26 09:38 UTC #0 lore raw

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
#

Joe Korty

2015-09-26 14:21 UTC #1 lore raw

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

Quoted 88 lines · 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
#
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Signature · 11 lines

Regards,
Joe

_________________________________________________
Joe Korty
Concurrent Computer Corporation
2881 Gateway Drive
Pompano Beach, Florida USA 33069
Phone: +1 954.973.5262
Email: [email protected]
_________________________________________________

Matthias Meier

author

2015-09-26 14:52 UTC #2 lore raw

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:

Quoted 97 lines

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
Quoted 88 lines · 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
#
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Thomas Gleixner

2015-09-27 11:49 UTC #3 lore raw

In reply to Matthias Meier

Quoted 17 lines · 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.

Quoted 6 lines

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

Matthias Meier

author

2015-09-29 06:30 UTC #4 lore raw

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:

Quoted 39 lines · Matthias Meier

Quoted 18 lines
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.
Quoted 6 lines
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

Matthias Klein

2015-09-29 07:13 UTC #5 lore raw

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" <[email protected]>
An: [email protected]
Gesendet: 29.09.2015 08:30:56
Betreff: Re: Long max latencies on Wandbaord / Freescale i.MX6

Quoted 62 lines

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:
Quoted 31 lines · Matthias Meier
Quoted 19 lines
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.
Quoted 6 lines
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
Quoted 9 lines
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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Thomas Gleixner

2015-09-30 07:12 UTC #6 lore raw

In reply to Matthias Meier

Quoted 5 lines · 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).

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

Matthias Meier

author

2015-10-01 08:08 UTC #7 lore raw

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

Matthias Meier

author

2015-10-02 06:48 UTC #8 lore raw

In reply to Thomas Gleixner

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

Mats Karrman

2015-10-02 07:40 UTC #9 lore raw

Quoted 4 lines · Matthias Meier

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