ip-4931 [001] ...1. 700.149994: preempt_disable: caller=__local_bh_disable_ip+0x76/0xe0 parent=__local_bh_disable_ip+0x76/0xe0 ip-4931 [001] ...11 700.149994: preempt_enable: caller=__local_bh_disable_ip+0x76/0xe0 parent=__local_bh_disable_ip+0x76/0xe0 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 ip-4931 [001] Dnh.3 700.150795: preempt_disable: caller=sysvec_reschedule_ipi+0x24/0x130 parent=sysvec_reschedule_ipi+0x24/0x130 ip-4931 [001] Dnh.3 700.150795: reschedule_entry: vector=253 ip-4931 [001] DNh.3 700.150795: reschedule_exit: vector=253 ip-4931 [001] DNh.3 700.150796: preempt_enable: caller=sysvec_reschedule_ipi+0x8d/0x130 parent=sysvec_reschedule_ipi+0x8d/0x130 ip-4931 [001] DN.13 700.150796: preempt_disable: caller=irqentry_exit+0x64/0x70 parent=irqentry_exit+0x64/0x70 ip-4931 [001] DN.13 700.150796: irq_enable: caller=preempt_schedule_irq+0x3b/0xe0 parent=0x0 ip-4931 [001] DN.13 700.150796: irq_disable: caller=irqentry_enter+0x2a/0x60 parent=0x0 ip-4931 [001] DNh13 700.150797: call_function_single_entry: vector=251 ip-4931 [001] DNh23 700.150798: ipi_send_cpu: cpu=1 callsite=irq_work_queue_on+0x109/0x120 callback=rto_push_irq_work_func+0x0/0xa0 ip-4931 [001] DNh13 700.150798: call_function_single_exit: vector=251 ip-4931 [001] DN.13 700.150798: irq_enable: caller=asm_sysvec_call_function_single+0x1a/0x20 parent=0x0 ip-4931 [001] DN.13 700.150799: irq_disable: caller=irqentry_enter+0x2a/0x60 parent=0x0 ip-4931 [001] DNh13 700.150799: irq_work_entry: vector=246 ip-4931 [001] DNh13 700.150799: irq_work_exit: vector=246 ip-4931 [001] DN.13 700.150800: irq_enable: caller=asm_sysvec_irq_work+0x1a/0x20 parent=0x0 ip-4931 [001] DN.13 700.150800: irq_disable: caller=irqentry_enter+0x2a/0x60 parent=0x0 ip-4931 [001] DNh13 700.150800: local_timer_entry: vector=236 ip-4931 [001] DNh23 700.150801: hrtimer_cancel: hrtimer=000000003093a798 ip-4931 [001] DNh13 700.150801: hrtimer_expire_entry: hrtimer=000000003093a798 function=hrtimer_wakeup now=700145368977 ip-4931 [001] DNh33 700.150802: sched_waking: comm=cyclictest pid=4893 prio=9 target_cpu=001 ip-4931 [001] DNh43 700.150802: sched_stat_sleep: comm=cyclictest pid=4893 delay=1223239 [ns] ip-4931 [001] DNh43 700.150803: sched_wakeup: comm=cyclictest pid=4893 prio=9 target_cpu=001 ip-4931 [001] DNh13 700.150803: hrtimer_expire_exit: hrtimer=000000003093a798 ip-4931 [001] DNh23 700.150803: hrtimer_cancel: hrtimer=000000001da73767 ip-4931 [001] DNh13 700.150803: hrtimer_expire_entry: hrtimer=000000001da73767 function=tick_nohz_handler now=700145368977 ip-4931 [001] DNh13 700.150804: softirq_raise: vec=1 [action=TIMER] ip-4931 [001] DNh13 700.150804: rcu_utilization: Start scheduler-tick ip-4931 [001] DNh13 700.150805: rcu_utilization: End scheduler-tick ip-4931 [001] DNh13 700.150805: read_msr: e8, value 1787ff7229c ip-4931 [001] DNh13 700.150805: read_msr: e7, value 177daa8fd55 ip-4931 [001] DNh23 700.150805: sched_stat_runtime: comm=ip pid=4931 runtime=1226636 [ns] ip-4931 [001] DNh13 700.150808: hrtimer_expire_exit: hrtimer=000000001da73767 ip-4931 [001] DNh23 700.150808: hrtimer_start: hrtimer=000000001da73767 function=tick_nohz_handler expires=700146000000 softexpires=700146000000 mode=ABS ip-4931 [001] DNh13 700.150809: local_timer_exit: vector=236 ip-4931 [001] DN.33 700.150809: sched_waking: comm=ktimers/1 pid=31 prio=98 target_cpu=001 ip-4931 [001] DN.43 700.150809: sched_stat_sleep: comm=ktimers/1 pid=31 delay=3349898 [ns] ip-4931 [001] DN.43 700.150810: sched_wakeup: comm=ktimers/1 pid=31 prio=98 target_cpu=001 ip-4931 [001] DN.13 700.150810: irq_enable: caller=asm_sysvec_apic_timer_interrupt+0x1a/0x20 parent=0x0 ip-4931 [001] DN.13 700.150810: irq_disable: caller=__schedule+0x67f/0x1080 parent=0x0 ip-4931 [001] DN.13 700.150810: rcu_utilization: Start context switch ip-4931 [001] DN.23 700.150810: rcu_preempt_task: rcu_preempt 93628 4931 ip-4931 [001] DN.13 700.150811: rcu_utilization: End context switch ip-4931 [001] DN.23 700.150811: sched_stat_runtime: comm=ip pid=4931 runtime=4037 [ns] ip-4931 [001] DN.23 700.150812: sched_stat_wait: comm=cyclictest pid=4893 delay=7434 [ns] ip-4931 [001] D..23 700.150813: sched_stat_wait: comm=ip pid=4931 delay=0 [ns] ip-4931 [001] D..33 700.150814: hrtimer_start: hrtimer=0000000087697d14 function=inactive_task_timer expires=700464978086 softexpires=700464978086 mode=REL|HARD ip-4931 [001] D..33 700.150814: hrtimer_cancel: hrtimer=0000000096921230 ip-4931 [001] D..33 700.150815: hrtimer_cancel: hrtimer=0000000087697d14 ip-4931 [001] D..33 700.150816: hrtimer_start: hrtimer=0000000096921230 function=dl_task_timer expires=701094857133 softexpires=701094857133 mode=ABS|HARD ip-4931 [001] Dp.23 700.150816: sched_switch: prev_comm=ip prev_pid=4931 prev_prio=120 prev_state=R+ ==> next_comm=cyclictest next_pid=4893 next_prio=9 ip-4931 [001] Dp.23 700.150817: tlb_flush: pages:-1 reason:flush on task switch (0) ip-4931 [001] Dp.23 700.150817: x86_fpu_regs_deactivated: x86/fpu: 00000000dd84b5fb load: 0 xfeatures: 2 xcomp_bv: 8000000000000007 cyclictest-4893 [001] dN.3. 700.150818: sched_stat_runtime: comm=cyclictest pid=4893 runtime=8747 [ns] cyclictest-4893 [001] dN.3. 700.150819: sched_migrate_task: comm=rcu_preempt pid=17 prio=98 orig_cpu=1 dest_cpu=0 cyclictest-4893 [001] dN.3. 700.150819: sched_wake_idle_without_ipi: cpu=0 cyclictest-4893 [001] dN.1. 700.150820: irq_enable: caller=finish_task_switch.isra.0+0xb1/0x300 parent=0x0 cyclictest-4893 [001] dN.1. 700.150820: irq_disable: caller=irqentry_enter+0x2a/0x60 parent=0x0 cyclictest-4893 [001] dNh1. 700.150820: call_function_single_entry: vector=251 cyclictest-4893 [001] dNh2. 700.150821: csd_queue_cpu: cpu=0 callsite=irq_work_queue_on+0xc6/0x120 func=rto_push_irq_work_func csd=00000000e2a8d506 cyclictest-4893 [001] dNh2. 700.150821: ipi_send_cpu: cpu=0 callsite=irq_work_queue_on+0xc6/0x120 callback=generic_smp_call_function_single_interrupt+0x0/0x20 cyclictest-4893 [001] dNh1. 700.150821: call_function_single_exit: vector=251 cyclictest-4893 [001] dN.1. 700.150822: irq_enable: caller=asm_sysvec_call_function_single+0x1a/0x20 parent=0x0 cyclictest-4893 [001] .N.1. 700.150822: preempt_enable: caller=do_nanosleep+0x72/0x190 parent=do_nanosleep+0x72/0x190 cyclictest-4893 [001] .N.1. 700.150822: preempt_disable: caller=do_nanosleep+0x72/0x190 parent=do_nanosleep+0x72/0x190 cyclictest-4893 [001] dN.1. 700.150822: irq_disable: caller=__schedule+0x67f/0x1080 parent=0x0 cyclictest-4893 [001] dN.1. 700.150822: rcu_utilization: Start context switch cyclictest-4893 [001] dN.1. 700.150822: rcu_utilization: End context switch cyclictest-4893 [001] d..1. 700.150823: irq_enable: caller=__schedule+0xb5e/0x1080 parent=0x0 cyclictest-4893 [001] ...1. 700.150823: preempt_enable: caller=do_nanosleep+0x72/0x190 parent=do_nanosleep+0x72/0x190 cyclictest-4893 [001] ..... 700.150823: sys_exit: NR 230 = 0 cyclictest-4893 [001] d.... 700.150823: irq_disable: caller=syscall_exit_to_user_mode+0x1c4/0x240 parent=0x0 cyclictest-4893 [001] d.... 700.150824: irq_enable: caller=syscall_exit_to_user_mode+0xe4/0x240 parent=0x0 cyclictest-4893 [001] ..... 700.150824: rseq_update: cpu_id=1 node_id=0 mm_cid=0 cyclictest-4893 [001] d.... 700.150824: irq_disable: caller=syscall_exit_to_user_mode+0x203/0x240 parent=0x0 cyclictest-4893 [001] d.... 700.150825: x86_fpu_regs_activated: x86/fpu: 00000000ff492f85 load: 1 xfeatures: 2 xcomp_bv: 8000000000000007 cyclictest-4893 [001] d.... 700.150825: irq_enable: caller=syscall_exit_to_user_mode+0x7c/0x240 parent=0x0 cyclictest-4893 [001] d.... 700.150830: irq_disable: caller=do_syscall_64+0x45/0x1a0 parent=0x0 cyclictest-4893 [001] d.... 700.150830: irq_enable: caller=do_syscall_64+0x4a/0x1a0 parent=0x0 cyclictest-4893 [001] ..... 700.150831: sys_enter: NR 1 (4, 7f640320e2c0, 21, 7f640320d5b5, 0, 64) cyclictest-4893 [001] ...1. 700.150832: preempt_disable: caller=vfs_write+0x306/0x430 parent=vfs_write+0x306/0x430 cyclictest-4893 [001] ...1. 700.150832: preempt_enable: caller=vfs_write+0x328/0x430 parent=vfs_write+0x328/0x430 cyclictest-4893 [001] ..... 700.150832: tracing_mark_write: hit latency threshold (759 > 700) cyclictest-4893 [001] ...1. 700.150833: preempt_disable: caller=vfs_write+0x12f/0x430 parent=vfs_write+0x12f/0x430 cyclictest-4893 [001] ...1. 700.150833: preempt_enable: caller=vfs_write+0x151/0x430 parent=vfs_write+0x151/0x430 cyclictest-4893 [001] ...1. 700.150833: preempt_disable: caller=fput+0x1f/0x90 parent=fput+0x1f/0x90 cyclictest-4893 [001] ...1. 700.150833: preempt_enable: caller=fput+0x3f/0x90 parent=fput+0x3f/0x90 cyclictest-4893 [001] ..... 700.150833: sys_exit: NR 1 = 33 cyclictest-4893 [001] d.... 700.150834: irq_disable: caller=syscall_exit_to_user_mode+0x1c4/0x240 parent=0x0 cyclictest-4893 [001] d.... 700.150834: irq_enable: caller=syscall_exit_to_user_mode+0x7c/0x240 parent=0x0 cyclictest-4893 [001] d.... 700.150834: irq_disable: caller=do_syscall_64+0x45/0x1a0 parent=0x0 cyclictest-4893 [001] d.... 700.150834: irq_enable: caller=do_syscall_64+0x4a/0x1a0 parent=0x0 cyclictest-4893 [001] ..... 700.150834: sys_enter: NR 1 (5, 5556d858a461, 2, 7f640320d5b5, 0, 64) cyclictest-4893 [001] ...1. 700.150835: preempt_disable: caller=vfs_write+0x306/0x430 parent=vfs_write+0x306/0x430 cyclictest-4893 [001] ...1. 700.150835: preempt_enable: caller=vfs_write+0x328/0x430 parent=vfs_write+0x328/0x430