Latency spikes on V6.15.1 Preempt RT and maybe related to intel IGB

From: Marc Strämke
Date: Tue Jun 10 2025 - 09:59:24 EST

Next message: Parvathi Pudi: "[PATCH net-next v8 08/11] net: ti: prueth: Adds support for RX interrupt coalescing/pacing"
Previous message: Jarkko Sakkinen: "Re: [PATCH v2 0/2] fix failure of integration IMA with tpm_crb_ffa"
Next in thread: Sebastian Andrzej Siewior: "Re: Latency spikes on V6.15.1 Preempt RT and maybe related to intel IGB"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hello Everyone, I am reposting to LKML as I am not sure the rt-users mailinglist is read by many people, (I hope that is okay)

On an AMD Ryzen Embedded machine I am experiencing strange Latency spikes in cyclictest and need some hints how to debug that further.

The system typically has max latencys of 88 us and averages of 4-8 which is more then sufficient for my application, but I saw some spikes of many hundred us in testing.

I can provoke latenciess of more then 500-1000 us by invoking "ip l set enp1s0 promisc off" on the first network interfaces. The network interface is an "Intel Corporation I210 Gigabit Network Connection" using the IGB driver.

I tried more or less all tracers but am not knowledgeable enough to make sense of the output. IRQSoff and wakeup_rt trace output attached.

Can anyone point me in the right direction? I am not sure how to interpret the function tracers and function_graph tracers output in a meaningful way. As mainly a user of of the kernel I am a bit overwhelmed by the interaction of the scheduler, RCU and so on..

I have attached my config for reference.

Kind Regards

Marc

# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 6.15.1-dirty
# --------------------------------------------------------------------
# latency: 208 us, #15/15, CPU#1 | (M:PREEMPT_RT VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: ktimers/1-31 (uid:0 nice:0 policy:1 rt_prio:1)
# -----------------
# => started at: handle_softirqs.constprop.0
# => ended at: run_ktimerd
#
#
# _------=> CPU#
# / _-----=> irqs-off/BH-disabled
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / _-=> migrate-disable
# ||||| / delay
# cmd pid |||||| time | caller
# \ / |||||| \ | /
ktimers/-31 1d.s.2 0us : handle_softirqs.constprop.0
ktimers/-31 1d.s.2 0us : irq_disable: caller=handle_softirqs.constprop.0+0x2d8/0x300 parent=0x0
ktimers/-31 1d.s.2 0us : __local_bh_enable(cnt=256, unlock=1) <-run_ktimerd
ktimers/-31 1d...2 0us : __rcu_read_unlock() <-__local_bh_enable
ktimers/-31 1d...2 1us+: rt_spin_unlock(lock=0xffff983497d17660) <-__local_bh_enable
ktimers/-31 1d...2 99us : migrate_enable() <-rt_spin_unlock
ktimers/-31 1d...1 99us : __rcu_read_unlock() <-rt_spin_unlock
ktimers/-31 1d...1 99us : migrate_enable() <-run_ktimerd
ktimers/-31 1d..11 100us!: preempt_disable: caller=run_ktimerd+0x4f/0x90 parent=run_ktimerd+0x4f/0x90
ktimers/-31 1d..1. 208us : preempt_enable: caller=run_ktimerd+0x4f/0x90 parent=run_ktimerd+0x4f/0x90
ktimers/-31 1d.... 209us : irq_enable: caller=run_ktimerd+0x78/0x90 parent=0x0
ktimers/-31 1d.... 209us : run_ktimerd
ktimers/-31 1d..1. 209us : preempt_disable: caller=_raw_spin_lock_irqsave+0x23/0x60 parent=0x0
ktimers/-31 1d.... 209us!: tracer_hardirqs_on <-run_ktimerd
ktimers/-31 1d.... 581us : <stack trace>
=> smpboot_thread_fn
=> kthread
=> ret_from_fork
=> ret_from_fork_asm
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 6.15.1-dirty
# --------------------------------------------------------------------
# latency: 411 us, #89/89, CPU#1 | (M:PREEMPT_RT VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: cyclictest-218784 (uid:0 nice:0 policy:1 rt_prio:95)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off/BH-disabled
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / _-=> migrate-disable
# ||||| / delay
# cmd pid |||||| time | caller
# \ / |||||| \ | /
<idle>-0 1dNh5. 0us : 0:120:R + [001] 218784: 4:R cyclictest
<idle>-0 1dNh5. 8us : <stack trace>
=> __ftrace_trace_stack
=> probe_wakeup
=> __traceiter_sched_wakeup
=> ttwu_do_activate
=> try_to_wake_up
=> hrtimer_wakeup
=> __hrtimer_run_queues
=> hrtimer_interrupt
=> __sysvec_apic_timer_interrupt
=> sysvec_apic_timer_interrupt
=> asm_sysvec_apic_timer_interrupt
=> cpu_idle_poll.isra.0
=> do_idle
=> cpu_startup_entry
=> start_secondary
=> common_startup_64
<idle>-0 1dNh5. 8us : 0
<idle>-0 1dNh4. 8us : task_woken_rt(rq=0xffff983497d2b400, p=0xffff9833c394a000) <-ttwu_do_activate
<idle>-0 1dNh4. 8us : _raw_spin_unlock(lock=0xffff983497d2b400) <-try_to_wake_up
<idle>-0 1dNh4. 8us+: preempt_count_sub(val=1) <-_raw_spin_unlock
<idle>-0 1dNh3. 74us : _raw_spin_unlock_irqrestore(lock=0xffff9833c394a8d8, flags=134) <-try_to_wake_up
<idle>-0 1dNh3. 74us : preempt_count_sub(val=1) <-_raw_spin_unlock_irqrestore
<idle>-0 1dNh1. 75us : hrtimer_expire_exit: hrtimer=00000000129a7594
<idle>-0 1dNh1. 75us+: _raw_spin_lock_irq(lock=0xffff983497d1b700) <-__hrtimer_run_queues
<idle>-0 1dNh1. 112us : preempt_count_add(val=1) <-_raw_spin_lock_irq
<idle>-0 1dNh2. 112us : hrtimer_update_next_event(cpu_base=0xffff983497d1b700) <-hrtimer_interrupt
<idle>-0 1dNh2. 112us : __hrtimer_next_event_base(cpu_base=0xffff983497d1b700, exclude=0x0, active=1, expires_next=9223372036854775807) <-hrtimer_interrupt
<idle>-0 1dNh2. 112us : _raw_spin_unlock_irqrestore(lock=0xffff983497d1b700, flags=134) <-hrtimer_interrupt
<idle>-0 1dNh2. 112us : preempt_count_sub(val=1) <-_raw_spin_unlock_irqrestore
<idle>-0 1dNh1. 113us : tick_program_event(expires=57049782000000, force=0) <-hrtimer_interrupt
<idle>-0 1dNh1. 113us : clockevents_program_event(dev=0xffff983497d17380, expires=57049782000000, force=0) <-hrtimer_interrupt
<idle>-0 1dNh1. 113us : ktime_get() <-clockevents_program_event
<idle>-0 1dNh1. 113us : lapic_next_event(delta=838, evt=0xffff983497d17380) <-clockevents_program_event
<idle>-0 1dNh1. 113us : local_timer_exit: vector=236
<idle>-0 1dNh1. 113us : irq_exit_rcu() <-sysvec_apic_timer_interrupt
<idle>-0 1dNh1. 113us : preempt_count_sub(val=65536) <-__irq_exit_rcu
<idle>-0 1dN.1. 113us : wake_up_process(p=0xffff9833c0366000) <-__irq_exit_rcu
<idle>-0 1dN.1. 113us : try_to_wake_up(p=0xffff9833c0366000, state=3, wake_flags=0) <-__irq_exit_rcu
<idle>-0 1dN.2. 114us : _raw_spin_lock_irqsave(lock=0xffff9833c03668d8) <-try_to_wake_up
<idle>-0 1dN.2. 114us : preempt_count_add(val=1) <-_raw_spin_lock_irqsave
<idle>-0 1dN.3. 114us : sched_waking: comm=ktimers/1 pid=31 prio=98 target_cpu=001
<idle>-0 1dN.3. 114us : kthread_is_per_cpu(p=0xffff9833c0366000) <-try_to_wake_up
<idle>-0 1dN.3. 114us : ttwu_queue_wakelist(p=0xffff9833c0366000, cpu=1, wake_flags=8) <-try_to_wake_up
<idle>-0 1dN.4. 114us : _raw_spin_lock(lock=0xffff983497d2b400) <-try_to_wake_up
<idle>-0 1dN.4. 114us : preempt_count_add(val=1) <-_raw_spin_lock
<idle>-0 1dN.4. 114us+: update_rq_clock(rq=0xffff983497d2b400) <-try_to_wake_up
<idle>-0 1dN.4. 149us : ttwu_do_activate(rq=0xffff983497d2b400, p=0xffff9833c0366000, wake_flags=8, rf=0xffffb7c340160f88) <-try_to_wake_up
<idle>-0 1dN.4. 149us : enqueue_task(rq=0xffff983497d2b400, p=0xffff9833c0366000, flags=9) <-ttwu_do_activate
<idle>-0 1dN.4. 149us+: enqueue_task_rt(rq=0xffff983497d2b400, p=0xffff9833c0366000, flags=9) <-enqueue_task
<idle>-0 1dN.4. 185us : dequeue_rt_stack(rt_se=0xffff9833c0366180, flags=9) <-enqueue_task_rt
<idle>-0 1dN.4. 186us : wakeup_preempt(rq=0xffff983497d2b400, p=0xffff9833c0366000, flags=8) <-ttwu_do_activate
<idle>-0 1dN.4. 186us : __resched_curr.constprop.0() <-wakeup_preempt
<idle>-0 1dN.5. 186us : __traceiter_sched_wakeup(__data=0x0, p=0xffff9833c0366000) <-ttwu_do_activate
<idle>-0 1dN.4. 186us : sched_wakeup: comm=ktimers/1 pid=31 prio=98 target_cpu=001
<idle>-0 1dN.4. 186us : task_woken_rt(rq=0xffff983497d2b400, p=0xffff9833c0366000) <-ttwu_do_activate
<idle>-0 1dN.4. 186us : _raw_spin_unlock(lock=0xffff983497d2b400) <-try_to_wake_up
<idle>-0 1dN.4. 186us : preempt_count_sub(val=1) <-_raw_spin_unlock
<idle>-0 1dN.3. 187us : _raw_spin_unlock_irqrestore(lock=0xffff9833c03668d8, flags=146) <-try_to_wake_up
<idle>-0 1dN.3. 187us : preempt_count_sub(val=1) <-_raw_spin_unlock_irqrestore
<idle>-0 1dN.1. 187us : idle_cpu(cpu=1) <-__irq_exit_rcu
<idle>-0 1dN.1. 187us : irq_enable: caller=irqentry_exit+0x50/0x70 parent=0x0
<idle>-0 1dN.1. 187us!: rcu_watching: Endirq 1 0 0x5cc
<idle>-0 1dN.1. 295us : rcu_watching: Start 0 1 0x5d4
<idle>-0 1dN.1. 295us : cpu_idle: state=4294967295 cpu_id=1
<idle>-0 1dN.2. 295us : irq_disable: caller=wakeup_tracer_call+0xbb/0xe0 parent=0x0
<idle>-0 1.N.1. 295us : arch_cpu_idle_exit() <-do_idle
<idle>-0 1dN.2. 296us : irq_enable: caller=wakeup_tracer_call+0xd4/0xe0 parent=0x0
<idle>-0 1dN.2. 296us : irq_disable: caller=wakeup_tracer_call+0xbb/0xe0 parent=0x0
<idle>-0 1.N.1. 296us : tick_nohz_idle_exit() <-do_idle
<idle>-0 1dN.2. 296us : irq_enable: caller=wakeup_tracer_call+0xd4/0xe0 parent=0x0
<idle>-0 1dN.1. 296us : irq_disable: caller=tick_nohz_idle_exit+0x75/0x140 parent=0x0
<idle>-0 1dN.1. 296us : irq_enable: caller=tick_nohz_idle_exit+0x64/0x140 parent=0x0
<idle>-0 1dN.2. 296us : irq_disable: caller=wakeup_tracer_call+0xbb/0xe0 parent=0x0
<idle>-0 1.N.1. 296us!: flush_smp_call_function_queue() <-do_idle
<idle>-0 1dN.2. 404us : irq_enable: caller=wakeup_tracer_call+0xd4/0xe0 parent=0x0
<idle>-0 1dN.2. 405us : irq_disable: caller=wakeup_tracer_call+0xbb/0xe0 parent=0x0
<idle>-0 1.N.1. 405us : schedule_idle() <-cpu_startup_entry
<idle>-0 1dN.2. 405us : irq_enable: caller=wakeup_tracer_call+0xd4/0xe0 parent=0x0
<idle>-0 1dN.2. 405us : irq_disable: caller=wakeup_tracer_call+0xbb/0xe0 parent=0x0
<idle>-0 1.N.1. 405us : hrtimer_active(timer=0xffff983497d2bfe0) <-__schedule
<idle>-0 1dN.2. 405us : irq_enable: caller=wakeup_tracer_call+0xd4/0xe0 parent=0x0
<idle>-0 1dN.1. 405us : irq_disable: caller=__schedule+0x67f/0x1080 parent=0x0
<idle>-0 1dN.1. 405us : rcu_note_context_switch(preempt=0) <-__schedule
<idle>-0 1dN.1. 405us : rcu_utilization: Start context switch
<idle>-0 1dN.1. 405us : rcu_qs() <-rcu_note_context_switch
<idle>-0 1dN.1. 406us : rcu_utilization: End context switch
<idle>-0 1dN.1. 406us : raw_spin_rq_lock_nested.constprop.0() <-__schedule
<idle>-0 1dN.2. 406us : _raw_spin_lock(lock=0xffff983497d2b400) <-raw_spin_rq_lock_nested.constprop.0
<idle>-0 1dN.2. 406us : preempt_count_add(val=1) <-_raw_spin_lock
<idle>-0 1dN.2. 406us : update_rq_clock(rq=0xffff983497d2b400) <-__schedule
<idle>-0 1dN.2. 406us : pick_task_stop(rq=0xffff983497d2b400) <-__schedule
<idle>-0 1dN.2. 406us : pick_task_dl(rq=0xffff983497d2b400) <-__schedule
<idle>-0 1dN.2. 406us : pick_task_rt(rq=0xffff983497d2b400) <-__schedule
<idle>-0 1dN.2. 407us : put_prev_task_idle(rq=0xffff983497d2b400, prev=0xffff9833c035a000, next=0xffff9833c394a000) <-__schedule
<idle>-0 1dN.2. 407us : dl_scaled_delta_exec(rq=0xffff983497d2b400, dl_se=0xffff983497d2bce8, delta_exec=332332) <-put_prev_task_idle
<idle>-0 1dN.2. 407us : arch_scale_cpu_capacity(cpu=1) <-dl_scaled_delta_exec
<idle>-0 1dN.2. 407us : dequeue_pushable_task(rq=0xffff983497d2b400, p=0xffff9833c394a000) <-set_next_task_rt
<idle>-0 1dN.2. 407us : update_rt_rq_load_avg(now=57049782342572, rq=0xffff983497d2b400, running=0) <-set_next_task_rt
<idle>-0 1d..3. 407us : __traceiter_sched_switch(__data=0x0, preempt=0, prev=0xffff9833c035a000, next=0xffff9833c394a000, prev_state=0) <-__schedule
<idle>-0 1d..2. 407us : sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=218784 next_prio=4
<idle>-0 1d..3. 407us : __traceiter_sched_switch
<idle>-0 1d..3. 408us : 0:120:R ==> [001] 218784: 4:R cyclictest
<idle>-0 1d..3. 412us : <stack trace>
=> __ftrace_trace_stack
=> probe_wakeup_sched_switch
=> __traceiter_sched_switch
=> __schedule
=> schedule_idle
=> cpu_startup_entry
=> start_secondary
=> common_startup_64

Attachment: config.gz
Description: GNU Zip compressed data

Next message: Parvathi Pudi: "[PATCH net-next v8 08/11] net: ti: prueth: Adds support for RX interrupt coalescing/pacing"
Previous message: Jarkko Sakkinen: "Re: [PATCH v2 0/2] fix failure of integration IMA with tpm_crb_ffa"
Next in thread: Sebastian Andrzej Siewior: "Re: Latency spikes on V6.15.1 Preempt RT and maybe related to intel IGB"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]