On Mon, 18 May 2015, Sebastian Andrzej Siewior wrote:

* Gary Robertson | 2015-05-18 08:23:16 [-0500]:

quoted

I have been following this thread and was able to obtain a copy of the full
log from Anders.
My initial impression based upon the log entries is that the excessive
latencies did not occur during the fpsimd calls -
but the actual progress of an individual task is a bit difficult to follow
through the logs, so in my spare time
I started writing a parser to sort it into a format easier to follow.  I
hope to have it completed shortly.
This parser will sort the log first by CPU and then by thread so the cause
of the delay will be easier to see.

There is a smaller version of it at 
    https://breakpoint.cc/arm64_simd_trace_cpu.txt

which contains only CPU0 around that "event. Here are a few pieces:
|cyclicte-964     0....1.. 511965877us : __schedule <-schedule
cyclictest goes away

|kworker/-353     0....111 511965906us : rt_spin_unlock <-process_one_work
kworker is now active

|kworker/-353     0....112 511965954us : kernel_neon_begin_partial <-virt_efi_set_time
|kworker/-353     0....112 511965955us : preempt_count_add <-kernel_neon_begin_partial
and kworker invokes virt_efi_set_time which does the neon save thingy.

|kworker/-353     0d...212 511966764us : __handle_domain_irq <-gic_handle_irq
now we have an interrupt comming.

|kworker/-353     0dn.h412 511966793us : task_woken_rt <-ttwu_do_wakeup
it might be the timer for cyclictest wakeup it might not, however we
have the N flag set and kworker has to go.

|kworker/-353     0dn..212 511966806us : rcu_sysidle_enter <-rcu_irq_exit
|kworker/-353     0dn..212 511967108us : __handle_domain_irq <-gic_handle_irq
|kworker/-353     0dn..212 511967109us : irq_enter <-__handle_domain_irq
so we finished handling one irq and we contiunue with the next one? This
goes on and on and on until finally after a while we have this:

|kworker/-353     0dn..212 512064373us : rcu_irq_exit <-irq_exit
|kworker/-353     0dn..212 512064374us : rcu_sysidle_enter <-rcu_irq_exit
|kworker/-353     0.n..212 512065116us : kernel_neon_end <-virt_efi_set_time
|kworker/-353     0.n..212 512065116us : preempt_count_sub <-kernel_neon_end
|kworker/-353     0.n..112 512065117us : __schedule <-preempt_schedule

and this time we were able to return from rcu_irq_exit and continue with
virt_efi_set_time and finally switch the task. So yes, preemption was
disabled during kernel_neon_{being|end} but we also received 81
interrupt ("gic_handle_irq invocation") during that time. Why is that?

|kworker/-353     0dn..212 512064373us : rcu_irq_exit <-irq_exit
|kworker/-353     0dn..212 512064374us : rcu_sysidle_enter <-rcu_irq_exit

That's called from RCU_NONIDLE(). Go figure ...

Thanks,

	tglx