Long max latencies on Wandbaord / Freescale i.MX6

[Matthias Meier <matthias.j.meier@gmx.net>]

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
#