Re: [PATCH] arch/arm64 :Cyclic Test fix in ARM64 fpsimd

[Sebastian Andrzej Siewior <bigeasy@linutronix.de>]

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

>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?

>Regards,
>
>Gary Robertson

Sebastian