Re: Unexpected switches to in-band

[Philippe Gerum <rpm@xenomai.org>]

Philippe Gerum <rpm@xenomai.org> writes:

> 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.

Also, it would be much better to find a way to exclude any mm bearing
the MMF_DOVETAIL flag from the movable set, instead of excluding
everything that sets CONFIG_COMPACTION.

-- 
Philippe.