Hello Everyone,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 sufficient for my application, but I saw some spikes of many hundred us in testing.
I can provoke latencys of more then 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 intrepret the function tracers and function_graph tracers output in a Meaningful way.
I have attached my config for reference. Kind Regars 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
