From mboxrd@z Thu Jan 1 00:00:00 1970 From: Sebastian Andrzej Siewior Subject: Re: [PATCH] arch/arm64 :Cyclic Test fix in ARM64 fpsimd Date: Mon, 18 May 2015 23:38:35 +0200 Message-ID: <20150518213835.GD4275@linutronix.de> References: <20150506193803.GC32577@8074w.roxell.se> <20150508000929.GE31914@8074w.roxell.se> <20150514160733.GE13442@linutronix.de> Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8 Cc: Ayyappa Ch , Anders Roxell , linux-arm-kernel@lists.infradead.org, RT , Kevin Hilman To: Gary Robertson Return-path: Received: from www.linutronix.de ([62.245.132.108]:51330 "EHLO Galois.linutronix.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752398AbbERVii (ORCPT ); Mon, 18 May 2015 17:38:38 -0400 Content-Disposition: inline In-Reply-To: Sender: linux-rt-users-owner@vger.kernel.org List-ID: * 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