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

[Sebastian Andrzej Siewior <bigeasy@linutronix.de>]

On 2025-06-14 10:52:36 [+0200], Marc Strämke wrote:
> Sebastian,
Hi,

> i tried that in the past (rtla top auto analysis). But i do not really
> understand the result:
> 
> rtla timerlat hit stop tracing
> ## CPU 1 hit stop tracing, analyzing it ##
>   IRQ handler delay:                                         0.00 us (0.00
> %)
>   IRQ latency:                                             709.25 us
>   Blocking thread:
>                               ip:3567
>     Blocking thread stack trace
>                 -> timerlat_irq
>                 -> __hrtimer_run_queues
>                 -> hrtimer_interrupt
>                 -> __sysvec_apic_timer_interrupt
>                 -> sysvec_apic_timer_interrupt
>                 -> asm_sysvec_apic_timer_interrupt
>                 -> igb_update_mc_addr_list
>                 -> igb_set_rx_mode
>                 -> __dev_change_flags
>                 -> netif_change_flags
>                 -> do_setlink.constprop.0
>                 -> rtnl_newlink
>                 -> rtnetlink_rcv_msg
>                 -> netlink_rcv_skb
>                 -> netlink_unicast
>                 -> netlink_sendmsg
>                 -> ____sys_sendmsg
>                 -> ___sys_sendmsg
>                 -> __sys_sendmsg
>                 -> do_syscall_64
>                 -> entry_SYSCALL_64_after_hwframe
> ------------------------------------------------------------------------
>      IRQ latency:                                          709.25 us (100%)
> 
> 
> I do not really understand where the IRQ/Preemption disabling is happening.
> What would the next thing be to do? Function (graph?) tracing on all the
> functions visible in the backtrace?

So somewhere between entry_SYSCALL_64_after_hwframe() and timerlat_irq()
something happened that led to the spike. Up to __dev_change_flags() it
is mostly regular and asm_sysvec_apic_timer_interrupt() is already the
interrupt. 
There is only one calling site for igb_update_mc_addr_list() and
everything before that looks harmless.
igb_update_mc_addr_list() has these loops where it writes to FIFO
register. This is followed by wrfl() which reads the status register.
This read forces the writes to go through the bus. What might happen is
that all the writes are "cached" and scheduled for a better time. That
read will force the writes to actually happen and the CPU will stall
until this done.
My guess would be one the writes cause the stall here.

> I tried to look at the event race output starting with the call to
> igb_set_rx_mode. I have attached the trace with all events and a function
> filter on igb on only the cpu executing ip.  I cannot understand what is
> happening between timestasmp 700.149995 and the IRQ disable event on
> 700.150795....
> 
>               ip-4931    [001] b...3   700.149994: igb_set_rx_mode <-__dev_change_flags
>               ip-4931    [001] b...3   700.149995: kmalloc: call_site=igb_set_rx_mode+0x4f8/0x5a0 ptr=00000000b0b4e5c8 bytes_req=12 bytes_alloc=16 gfp_flags=GFP_ATOMIC|__GFP_ZERO node=-1 accounted=false
>               ip-4931    [001] b...3   700.149995: igb_update_mc_addr_list <-igb_set_rx_mode
>               ip-4931    [001] Dn..3   700.150795: irq_disable: caller=irqentry_enter+0x2a/0x60 parent=0x0

The CPU is somewhere in igb_update_mc_addr_list(). Based on the
timestamps it was there for 800us before the irq_disable() occurred.
This did not happen within igb_update_mc_addr_list() but due to an
interrupt.

> Thanks for your help,
> 
> Marc

Sebastian