* 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
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
