Re: After upgrading from Debian 11 to Debian 12, the latency became worse

On 29.06.26 14:13, mars_liu wrote:
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> At 2026-06-24 21:40:58, "mars_liu" <[email protected]> wrote:
>>
>>
>>
>>
>> At 2026-06-22 22:17:28, "Jan Kiszka" <[email protected]> wrote:
>>> Can you try to systematically eliminate variables that may contribute to
>>> the increase? E.g., use the old kernel with its original configuration
>>> on the new installation or go back to the original Xenomai version.
>>>
>>> If the kernel is the cause, checking once more if the effective config
>>> of 6.1 is not missing or adding suspicious things compared to the
>>> effective 5.10 kernel config.
>>>
>>> An alternative is obviously turning on tracing and record one of those
>>> events that are longer than expected. At least basic event traces
>>> (cobalt events) should not increase latencies on their own a lot while
>>> giving a general overview what happens.
>>>
>>> Jan
>>>
>>> -- 
>>> Siemens AG, Foundational Technologies
>>> Linux Expert Center
>>
>>
>> I was running latency test with event trace on. Initially I enabled cobalt event and irq_pipeline – got result 1. Then I enabled local_timer_entry as well to see what's going on, got result 2. Both times the test cut off when max latency exceeded 70us.
>>
>>
>> result 1:============================================================================================
>> 	      ...
>>              ......
>>              dd-1728    [000] *.~..  7426.819882: cobalt_tick_shot: next tick at 7426.819975 (delay: 93 us)
>>              dd-1728    [000] *.~..  7426.819883: irq_pipeline_exit: irq=524547
>>              dd-1728    [000] #.~..  7426.819883: cobalt_schedule: status=0x10000000
>>              dd-1728    [000] #.~..  7426.819883: cobalt_trace_pid: pid=1728, prio=-1
>>              dd-1728    [000] #.~..  7426.819883: cobalt_switch_context: prev_name=ROOT/0 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=sampling-1732 next_pid=1736 next_prio=1
>>              dd-1728    [000] #.~..  7426.819883: cobalt_timer_start: timer=00000000885e65cf([watchdog]) value=1000000000 interval=0 mode=rel
>>   sampling-1732-1736    [000] *.~2.  7426.819884: cobalt_trace_pid: pid=1736, prio=1
>>   sampling-1732-1736    [000] d.~2.  7426.819885: cobalt_head_sysexit: result=8
>>   sampling-1732-1736    [000] d.~2.  7426.819885: cobalt_head_sysentry: syscall=read
>>   sampling-1732-1736    [000] d.~2.  7426.819885: cobalt_fd_read: device=00000000705fa65c fd=3 arg=0x8 pid=1736 comm=sampling-1732
>>   sampling-1732-1736    [000] *.~2.  7426.819886: cobalt_synch_sleepon: synch=00000000a14e53ef
>>   sampling-1732-1736    [000] *.~2.  7426.819886: cobalt_thread_suspend: pid=1736 mask=0x2 timeout=0 timeout_mode=0 wchan=00000000a14e53ef
>>   sampling-1732-1736    [000] *.~2.  7426.819886: cobalt_schedule: status=0x10000000
>>   sampling-1732-1736    [000] *.~2.  7426.819886: cobalt_trace_pid: pid=1736, prio=1
>>   sampling-1732-1736    [000] *.~2.  7426.819886: cobalt_switch_context: prev_name=sampling-1732 prev_pid=1736 prev_prio=1 prev_state=0x4c042 ==> next_name=ROOT/0 next_pid=0 next_prio=-1
>>   sampling-1732-1736    [000] *.~2.  7426.819886: cobalt_timer_stop: timer=00000000885e65cf
>>              dd-1728    [000] #.~..  7426.819887: cobalt_trace_pid: pid=1728, prio=-1
>>              dd-1728    [000] *.~..  7426.820043: irq_pipeline_entry: irq=524547
>>              dd-1728    [000] *.~..  7426.820044: cobalt_timer_expire: timer=00000000a7d2b833
>>              dd-1728    [000] *.~..  7426.820044: cobalt_synch_wakeup: synch=00000000a14e53ef
>>              dd-1728    [000] *.~..  7426.820044: cobalt_thread_resume: name=sampling-1732 pid=1736 mask=0x2
>>              dd-1728    [000] *.~..  7426.820044: cobalt_trace_pid: pid=1736, prio=1
>>              dd-1728    [000] *.~..  7426.820045: cobalt_tick_shot: next tick at 7426.820075 (delay: 30 us)
>>              dd-1728    [000] *.~..  7426.820045: irq_pipeline_exit: irq=524547
>>               ...
>>               ......
>>
>> result 2:============================================================================================
>>            ...
>>            ......
>>              dd-1510    [001] *.~..  1689.009700: cobalt_tick_shot: next tick at 1689.009796 (delay: 95 us)
>>              dd-1510    [001] *.~..  1689.009701: local_timer_exit: vector=236
>>              dd-1510    [001] *.~..  1689.009701: irq_pipeline_exit: irq=524547
>>              dd-1510    [001] #.~..  1689.009702: cobalt_schedule: status=0x10000000
>>              dd-1510    [001] #.~..  1689.009702: cobalt_trace_pid: pid=1510, prio=-1
>>              dd-1510    [001] #.~..  1689.009702: cobalt_switch_context: prev_name=ROOT/1 prev_pid=0 prev_prio=-1 prev_state=0x18008 ==> next_name=sampling-1512 next_pid=1516 next_prio=1
>>              dd-1510    [001] #.~..  1689.009702: cobalt_timer_start: timer=0000000086a46b6d([watchdog]) value=1000000000 interval=0 mode=rel
>>   sampling-1512-1516    [001] *.~2.  1689.009702: cobalt_trace_pid: pid=1516, prio=1
>>   sampling-1512-1516    [001] d.~2.  1689.009703: cobalt_head_sysexit: result=8
>>   sampling-1512-1516    [001] d.~2.  1689.009703: cobalt_head_sysentry: syscall=read
>>   sampling-1512-1516    [001] d.~2.  1689.009703: cobalt_fd_read: device=00000000693aa32d fd=3 arg=0x8 pid=1516 comm=sampling-1512
>>   sampling-1512-1516    [001] *.~2.  1689.009703: cobalt_synch_sleepon: synch=00000000978f36ce
>>   sampling-1512-1516    [001] *.~2.  1689.009703: cobalt_thread_suspend: pid=1516 mask=0x2 timeout=0 timeout_mode=0 wchan=00000000978f36ce
>>   sampling-1512-1516    [001] *.~2.  1689.009704: cobalt_schedule: status=0x10000000
>>   sampling-1512-1516    [001] *.~2.  1689.009704: cobalt_trace_pid: pid=1516, prio=1
>>   sampling-1512-1516    [001] *.~2.  1689.009704: cobalt_switch_context: prev_name=sampling-1512 prev_pid=1516 prev_prio=1 prev_state=0x4c042 ==> next_name=ROOT/1 next_pid=0 next_prio=-1
>>   sampling-1512-1516    [001] *.~2.  1689.009704: cobalt_timer_stop: timer=0000000086a46b6d
>>              dd-1510    [001] #.~..  1689.009705: cobalt_trace_pid: pid=1510, prio=-1
>>              dd-1510    [001] *.~..  1689.009800: irq_pipeline_entry: irq=524547
>>              dd-1510    [001] *.~..  1689.009861: local_timer_entry: vector=236
>>              dd-1510    [001] *.~..  1689.009862: cobalt_timer_expire: timer=00000000ac269294
>>              dd-1510    [001] *.~..  1689.009862: cobalt_synch_wakeup: synch=00000000978f36ce
>>              dd-1510    [001] *.~..  1689.009862: cobalt_thread_resume: name=sampling-1512 pid=1516 mask=0x2
>>              dd-1510    [001] *.~..  1689.009862: cobalt_trace_pid: pid=1516, prio=1
>>              dd-1510    [001] *.~..  1689.009862: cobalt_tick_shot: next tick at 1689.009896 (delay: 34 us)
>>              dd-1510    [001] *.~..  1689.009862: local_timer_exit: vector=236
>>              dd-1510    [001] *.~..  1689.009863: irq_pipeline_exit: irq=524547
>>           ============================================================================================
>>
>> In result 1, the max latency interval was between the expected next tick and irq_pipeline_entry:
>> 7426820043 – 7426.819975 = 68 µs.
>>
>> In result 2, the max latency interval was between irq_pipeline_entry and local_timer_entry:
>> 1689.009861 – 1689.009800 = 61 µs.
>>
>> What caused these two scenarios? Please give me some hints. 
>>
> 
> Hi Jan,
> 
> Regarding the first result, when the issue occurred again, I didn't see any SMI. Usually, the interrupt delay is within 10 µs. What else could cause the delay to be more than 60 µs? Or do you have any suggestions for further debugging? Thanks a lot for your help.
> 

Power tuning is one of the usual suspects. Or hyper-threading (if not
disabled at firmware level).

You could try running with the function tracer enabled. That will
massively increase latencies, but if you do that both in old and new
kernel setup, you may see qualitative differences.

Jan

-- 
Siemens AG, Foundational Technologies
Linux Expert Center