On Mon, 18 May 2015, Sebastian Andrzej Siewior wrote: > * 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? > |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 -- 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
