Re:Re: After upgrading from Debian 11 to Debian 12, the latency became worse
mars_liu <[email protected]> Wed, 24 Jun 2026 21:40:58 +0800 (CST)
| Newsgroups | dev.linux.lists.xenomai |
|---|---|
| Message-ID | <[email protected]> |
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.