Re: Unexpected switches to in-band

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

Hi Philippe,

> Ł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=n - it also automatically set CONFIG_MIGRATION=n

From the Kconfig dependencies CONFIG_MIGRATION=n -> !PREEMPT_RT [=n]
(i.e. it can be only enabled when PREEMPT_RT is NOT)

I've just set CONFIG_COMPACTION=n (which also disabled the
CONFIG_MIGRATION) and now I cannot reproduce the issue on my setup (i.e.
v6.6.) anymore.

It looks like those (enabled by default) config options have slipped in
silently and introduced the issue...


-- 
Best regards,

Lukasz Majewski

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