Re: Unexpected switches to in-band

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

Hi Philippe, Jan,

> Jan Kiszka <jan.kiszka@siemens.com> writes:
> 
> > On 31.10.25 17:30, Philippe Gerum wrote:  
> >> Łukasz Majewski <lukma@nabladev.com> writes:
> >>   
> >>> 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
> >>>  
> >> 
> >> Thanks. I need to analyze the fault flags next week to see if I
> >> can make something of these, but I just stumbled on an obviously
> >> significant fact when looking at the multi-CPU view: the memory
> >> compaction daemon is running asynchronously on other cores while
> >> the responder is taking the fault. Compaction is all about moving
> >> memory around to free larger physical regions, so updating PTEs
> >> will happen as a result.
> >> 
> >> Moreover, I could not reproduce the issue at hand, but I did not
> >> have CONFIG_COMPACTION enabled. In the meantime, could you try
> >> disabling this on your end, to see if the fault still appears?  
> >
> > CONFIG_COMPACTION selects CONFIG_MIGRATION, and that is well-known
> > to be incompatible with RT. Xenomai 3 is warning about that that,
> > EVL does not? 
> 
> Dovetail should do that when CONFIG_DOVETAIL is set, this is by
> definition common to any rt core.
> 

bash-5.2# evl check
CONFIG_ACPI_PROCESSOR_IDLE=y
CONFIG_EVL_DEBUG_CORE=y
CONFIG_EVL_DEBUG_MEMORY=y
CONFIG_FTRACE=y

And of course three last entries were enabled when I've been "hunting"
the ISW in latmus cause.

-- 
Best regards,

Lukasz Majewski

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