Re: Unexpected switches to in-band

["Łukasz Majewski" <lukma@nabladev.com>]

Hi Philippe,

> Hi Łukasz,
> 
> Łukasz Majewski <lukma@nabladev.com> writes:
> 
> >> > Could you get me a trace which goes back up to two secs before
> >> > the time reported by evl about the inband switch of the timer
> >> > responder? e.g.  
> >
> > Why is it 2 seconds? Is it related to latmus "refresh time"? (which
> > is 1s)
> >  
> 
> Picking this delay is purely heuristical. Such a long backlog is
> likely going to include the smoking gun, if any.
> 
> >> > 
> >> > [   75.214527] EVL: timer-responder:743 switching in-band
> >> > [pid=745, excpt=14, user_pc=0x77d08492a5fe]
> >> > 
> >> > In the above case, I would need a trace going back to 73.214527
> >> > or so.   
> >> 
> >> Apparently the ftrace buffer was too small. I will adjust it to
> >> store more data and share results.  
> >
> > It is also interesting, that:
> >
> > bash-5.2# echo 16384 > /sys/kernel/debug/tracing/buffer_size_kb
> > bash-5.2# cat /sys/kernel/debug/tracing/buffer_size_kb
> > 16387
> > bash-5.2# evl trace -eirq -f
> > tracing enabled
> > bash-5.2# cat /sys/kernel/debug/tracing/buffer_size_kb
> > 131
> >
> > Reduces the buffer size...
> >  
> 
> Yeah, the evl-trace script is not that smart. I can see the issue
> causing this, will fix.
> 
> > Hence, I've used the "normal" ftrace with enabled evl functions -
> > the  
> 
> FWIW, EVL relies on the normal ftrace. However, evl-trace fiddles with
> the sysfs entries manually, and may be a bit naive at times. As Jan
> pointed out long ago, relying on the trace-cmd front-end would be a
> better approach than tweaking ftrace's sysfs-based controls manually
> at the very least. evl-trace adds EVL semantics to the tracing
> configuration which is handy, but the way it is done today may
> deserve a revamping, or maybe drop it entirely in favor of trace-cmd
> if we have enough flexibility there in order to introduce some EVL
> specifics.
> 
> > detailed information about the ftrace config is with log files:
> > https://nextcloud.swupdate.org/index.php/s/czBd3Ydq9B9noZ7
> >
> >
> > To extract the cpu2 specific data:
> > bash-5.2# grep -rnE '\[002\]' Xenomai4-ISW-trace-6.6-logs.txt >
> > cpu2.txt
> >
> > Here again the ISW happens in the cpu2 execution "hole":
> > [  128.466459] EVL: timer-responder:736 switching in-band [pid=738,
> > excpt=14, user_pc=0x7588e71985fe]
> >
> > Happens for cpu2 between:
> >
> > 11832546:          <idle>-0     [002] *..2.   128.466438:
> > 	sched_idle_set_state <-cpuidle_enter_state
> > 11832547:          <idle>-0     [002] *..2.   128.466468:
> > 	handle_irq_pipelined_prepare <-arch_pipeline_entry
> >
> > However, now the log is large enough to inspect what has happened in
> > the system for ~4s before.
> >
> >
> > With the logs:
> > timer-responder-738     [002] *.~2.   128.466214: evl_timer_shot:
> > [proxy-timer/2] at 128.466467 (delay: 253 us, 66918 cycles)
> >
> > and after ISW:
> >
> > <idle>-0       [002] *.~1.   128.466469: evl_timer_shot:
> > latmus_pulse_handler at 128.467208 (delay: 739 us, 195206 cycles)
> >
> > Why there is such increase in "delay" (253 vs 739 us) ? 
> >
> > It looks like we have only 2us delay as the timer has fired on
> > 128.466469 vs. expected 128.466467.
> >  
> 
> Ok, so the issue is still the same: for some reason, the
> timer-responder thread is taking a (minor) fault when accessing some
> memory, on its way back from the ioctl(EVL_LATIOC_PULSE) syscall, or
> right after. This seems to be valid memory though, just not
> immediately accessible, otherwise we'd have received SEGV, which we
> did not.

Yes, I also think so - like some "deferred allocation" despite of
mlockall.

Please find the logs with the below patch applied:
https://nextcloud.swupdate.org/index.php/s/JXNW5bJrB3fQo5E

> 
> --
>           <idle>-0       [002] #.~2.   129.084225:
> fpu__suspend_inband <-dovetail_context_switch <idle>-0       [002]
> #.~2.   129.084225: switch_mm_irqs_off <-dovetail_context_switch
> timer-responder-738     [002] *.~3.   129.084225: switch_fpu_return
> <-dovetail_context_switch timer-responder-738     [002] *.~2.
> 129.084225: evl_switch_tail: { current=timer-responder:736[738] }
> timer-responder-738     [002] d.~2.   129.084225: evl_finish_wait:
> wchan=&wf->wait timer-responder-738     [002] d.~2.   129.084225:
> evl_oob_sysexit: result=0 --
> 
> The responder is resuming from a wait on the EVL_LATIOC_PULSE flag,
> leaving the kernel, all seems fine so far.. I'm trying to find some
> rationale for taking a fault in the syscall return path from the
> assembly section which would explain a lack of trace _and_ the
> faulting instruction living in a user-space mapping (this is no vDSO
> call anyway), but cannot find any so far. A corruption of the
> register frame used in restoring the calling user context would most
> likely have triggered a major fault, not a minor one. Hopefully.
> 
> --
>  timer-responder-738     [002] *.~3.   129.084226:
> handle_oob_trap_entry <-__oob_trap_notify timer-responder-738
> [002] *.~2.   129.084227: evl_thread_fault: ip=0x7588e71985fe
> trapnr=0xe timer-responder-738     [002] *.~3.   129.084227: _printk
> <-handle_oob_trap_entry --
> 
> We need more information from the register file passed to us upon
> trap. Could you apply the following quick patch to the test kernel?
> (not to be upstreamed as-is, this is x86-specific unlike the file it
> applies to). TIA,
> 
> diff --git a/include/trace/events/evl.h b/include/trace/events/evl.h
> index 7136437d00227..3deeafb17e0fc 100644
> --- a/include/trace/events/evl.h
> +++ b/include/trace/events/evl.h
> @@ -443,17 +443,26 @@ TRACE_EVENT(evl_thread_fault,
>  	TP_ARGS(trapnr, regs),
>  
>  	TP_STRUCT__entry(
> +		__field(long,	sp)
> +		__field(long,	flags)
>  		__field(long,	ip)
> +		__field(long,	orig_ax)
> +		__field(u16,	cs)
>  		__field(unsigned int, trapnr)
>  	),
>  
>  	TP_fast_assign(
> +		__entry->sp = regs->sp;
> +		__entry->flags = regs->flags;
>  		__entry->ip = instruction_pointer(regs);
> +		__entry->orig_ax = regs->orig_ax;
> +		__entry->cs = regs->cs;
>  		__entry->trapnr = trapnr;
>  	),
>  
> -	TP_printk("ip=%#lx trapnr=%#x",
> -		  __entry->ip, __entry->trapnr)
> +	TP_printk("ip=%#lx trapnr=%#x, sp=%#lx, flags=%#lx,
> orig_ax=%#lx, cs=%#hx",
> +		__entry->ip, __entry->trapnr,
> +		__entry->sp, __entry->flags, __entry->orig_ax,
> __entry->cs) );
>  
>  TRACE_EVENT(evl_thread_set_current_prio,
> 



-- 
Best regards,

Lukasz Majewski

--
Nabla Software Engineering GmbH
HRB 40522 Augsburg
Phone: +49 821 45592596
E-Mail: office@nabladev.com
Geschftsfhrer : Stefano Babic