I did some more testing on 5.10 and it seems my
network irq thread runs into some kind of PI with
the RCU thread and thus cannot run for ~200us.
Some questions:
- Why does this PI happen?
- Can I avoid it? How?
- Can I avoid that the RCU runs for such a long
time at once?
I'm playing around with NOHZ_FULL and RCU callback
offloading at the moment to see if this helps somehow.
But with only two cores my options on juggling
threads onto CPUs are somewhat limited.
rcuc/1-20 [001] .....12 16017.277265: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=000000000c04e43c
rcuc/1-20 [001] .....12 16017.277265: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=00000000c6b95ab2
rcuc/1-20 [001] .....12 16017.277266: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=00000000f9863725
rcuc/1-20 [001] d..h212 16017.277266: irq_handler_entry: irq=130 name=ecat0-rx-0
rcuc/1-20 [001] d..h212 16017.277266: irq_handler_exit: irq=130 ret=handled
rcuc/1-20 [001] d..h412 16017.277266: sched_waking: comm=irq/130-ecat0-r pid=25665 prio=19 target_cpu=001
rcuc/1-20 [001] dN.h512 16017.277267: sched_wakeup: comm=irq/130-ecat0-r pid=25665 prio=19 target_cpu=001
rcuc/1-20 [001] dN..112 16017.277267: rcu_utilization: Start context switch
rcuc/1-20 [001] dN..112 16017.277267: rcu_utilization: End context switch
rcuc/1-20 [001] d...212 16017.277268: sched_switch: prev_comm=rcuc/1 prev_pid=20 prev_prio=98 prev_state=R+ ==> next_comm=irq/130-ecat0-r next_pid=25665 next_prio=19
irq/130-ecat0-r-25665 [001] d...311 16017.277269: sched_pi_setprio: comm=rcuc/1 pid=20 oldprio=98 newprio=19
irq/130-ecat0-r-25665 [001] d...111 16017.277270: rcu_utilization: Start context switch
irq/130-ecat0-r-25665 [001] d...111 16017.277270: rcu_utilization: End context switch
irq/130-ecat0-r-25665 [001] d...211 16017.277270: sched_switch: prev_comm=irq/130-ecat0-r prev_pid=25665 prev_prio=19 prev_state=R+ ==> next_comm=rcuc/1 next_pid=20 next_prio=19
rcuc/1-20 [001] .....12 16017.277271: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=000000008900a49c
<lots of similar lines>
rcuc/1-20 [001] d...112 16017.277288: workqueue_queue_work: work struct=0000000093763c71 function=css_killed_work_fn workqueue=0000000040d70e90 req_cpu=16 cpu=1
rcuc/1-20 [001] d...112 16017.277289: workqueue_activate_work: work struct 0000000093763c71
rcuc/1-20 [001] d...312 16017.277289: sched_waking: comm=kworker/1:2 pid=13240 prio=120 target_cpu=001
rcuc/1-20 [001] d...412 16017.277290: sched_wakeup: comm=kworker/1:2 pid=13240 prio=120 target_cpu=001
rcuc/1-20 [001] .....13 16017.277290: percpu_free_percpu: base_addr=0000000026e5557e off=111288 ptr=00000000cb224c7a
rcuc/1-20 [001] .....13 16017.277290: percpu_free_percpu: base_addr=0000000026e5557e off=111280 ptr=000000001ea01103
rcuc/1-20 [001] .....12 16017.277290: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=00000000f7fe2da7
<lots of similar lines>
rcuc/1-20 [001] .....12 16017.277299: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=000000004363b5fd
rcuc/1-20 [001] d..h212 16017.277300: local_timer_entry: vector=236
rcuc/1-20 [001] d..h312 16017.277300: softirq_raise: vec=8 [action=HRTIMER]
rcuc/1-20 [001] d..h212 16017.277300: write_msr: 6e0, value 304f993b507a
rcuc/1-20 [001] d..h212 16017.277300: local_timer_exit: vector=236
rcuc/1-20 [001] .....12 16017.277301: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=00000000407b3531
<lots of similar lines>
rcuc/1-20 [001] .....12 16017.277305: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=00000000af2cd46f
rcuc/1-20 [001] d..h.12 16017.277305: local_timer_entry: vector=236
rcuc/1-20 [001] d..h112 16017.277306: hrtimer_cancel: hrtimer=0000000082cde4bc
rcuc/1-20 [001] d..h.12 16017.277306: hrtimer_expire_entry: hrtimer=0000000082cde4bc function=hrtimer_wakeup now=16017273215561
rcuc/1-20 [001] d..h212 16017.277306: sched_waking: comm=cyclictest pid=20680 prio=19 target_cpu=001
rcuc/1-20 [001] d..h312 16017.277306: sched_wakeup: comm=cyclictest pid=20680 prio=19 target_cpu=001
rcuc/1-20 [001] d..h.12 16017.277307: hrtimer_expire_exit: hrtimer=0000000082cde4bc
rcuc/1-20 [001] d..h.12 16017.277307: write_msr: 6e0, value 304f996a73c6
rcuc/1-20 [001] d..h.12 16017.277307: local_timer_exit: vector=236
rcuc/1-20 [001] .....12 16017.277307: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=000000008da0302a
<lots of similar lines>
rcuc/1-20 [001] .....12 16017.277418: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=00000000994b1e7d
rcuc/1-20 [001] .....12 16017.277418: mm_page_free: page=00000000a7e4a633 pfn=104560 order=2
rcuc/1-20 [001] .....12 16017.277418: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=0000000054b769bf
rcuc/1-20 [001] .....12 16017.277419: sched_process_free: comm=kill pid=14926 prio=120
rcuc/1-20 [001] d...113 16017.277421: workqueue_queue_work: work struct=00000000d2b86e8a function=css_release_work_fn workqueue=0000000040d70e90 req_cpu=16 cpu=1
rcuc/1-20 [001] .....13 16017.277421: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=000000000b628ae9
rcuc/1-20 [001] d...113 16017.277422: workqueue_queue_work: work struct=00000000d6255bb4 function=css_release_work_fn workqueue=0000000040d70e90 req_cpu=16 cpu=1
rcuc/1-20 [001] .....13 16017.277422: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=00000000d844ad24
rcuc/1-20 [001] .....13 16017.277422: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=00000000a49f8139
rcuc/1-20 [001] .....13 16017.277422: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=00000000f2b3224d
rcuc/1-20 [001] .....13 16017.277422: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=00000000d2397b3c
rcuc/1-20 [001] .....13 16017.277423: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=00000000a367555e
rcuc/1-20 [001] .....13 16017.277423: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=000000002aaa5cac
rcuc/1-20 [001] .....13 16017.277423: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=00000000430e91ae
rcuc/1-20 [001] .....13 16017.277423: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=00000000f8512c96
rcuc/1-20 [001] .....13 16017.277423: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=000000005e5ac681
rcuc/1-20 [001] d...213 16017.277424: timer_start: timer=0000000098e46346 function=delayed_work_timer_fn expires=4310684537 [timeout=20] cpu=1 idx=58 flags=I
rcuc/1-20 [001] .....12 16017.277425: kfree: call_site=security_task_free+0x36/0x50 ptr=00000000e928d73e
rcuc/1-20 [001] .....12 16017.277425: kmem_cache_free: call_site=__put_task_struct+0x88/0x190 ptr=00000000d32d025d
<lots of similar lines>
rcuc/1-20 [001] .....12 16017.277452: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=00000000097691fb
rcuc/1-20 [001] .....12 16017.277453: sched_process_free: comm=(sd-pam) pid=14847 prio=120
rcuc/1-20 [001] d...112 16017.277454: workqueue_queue_work: work struct=0000000077c15f97 function=free_work workqueue=00000000f605602a req_cpu=16 cpu=1
rcuc/1-20 [001] d...112 16017.277454: workqueue_activate_work: work struct 0000000077c15f97
rcuc/1-20 [001] .....12 16017.277454: kfree: call_site=security_task_free+0x36/0x50 ptr=000000003016d2cc
rcuc/1-20 [001] .....12 16017.277454: kmem_cache_free: call_site=__put_task_struct+0x88/0x190 ptr=000000008d44c92c
rcuc/1-20 [001] .....12 16017.277455: kmem_cache_free: call_site=__put_task_struct+0x101/0x190 ptr=00000000bf1f1ae9
rcuc/1-20 [001] .....12 16017.277455: kfree: call_site=free_task+0x1b/0x60 ptr=0000000000000000
rcuc/1-20 [001] .....12 16017.277455: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=00000000eb792cfc
rcuc/1-20 [001] .....12 16017.277456: sched_process_free: comm=systemd pid=14846 prio=120
rcuc/1-20 [001] d...113 16017.277457: workqueue_queue_work: work struct=00000000a65dcda5 function=css_release_work_fn workqueue=0000000040d70e90 req_cpu=16 cpu=1
rcuc/1-20 [001] .....13 16017.277457: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=00000000a29d18ed
rcuc/1-20 [001] d...113 16017.277457: workqueue_queue_work: work struct=0000000000e1ccca function=css_release_work_fn workqueue=0000000040d70e90 req_cpu=16 cpu=1
rcuc/1-20 [001] .....13 16017.277457: kfree: call_site=put_css_set_locked+0x155/0x2b0 ptr=00000000cfeca6c9
<lots of similar lines>
rcuc/1-20 [001] .....12 16017.277461: kmem_cache_free: call_site=rcu_do_batch+0x194/0x480 ptr=000000009e31b81e
rcuc/1-20 [001] .....12 16017.277461: rcu_utilization: End RCU core
rcuc/1-20 [001] ...s.12 16017.277462: softirq_entry: vec=8 [action=HRTIMER]
rcuc/1-20 [001] d..s113 16017.277462: hrtimer_cancel: hrtimer=000000009862add4
rcuc/1-20 [001] ...s.13 16017.277462: hrtimer_expire_entry: hrtimer=000000009862add4 function=hrtimer_wakeup now=16017273371650
rcuc/1-20 [001] d..s213 16017.277462: sched_waking: comm=EtherlabDaemon pid=25770 prio=120 target_cpu=001
rcuc/1-20 [001] d..s313 16017.277464: sched_wakeup: comm=EtherlabDaemon pid=25770 prio=120 target_cpu=001
rcuc/1-20 [001] ...s.13 16017.277464: hrtimer_expire_exit: hrtimer=000000009862add4
rcuc/1-20 [001] d..s113 16017.277464: write_msr: 6e0, value 304f994bc448
rcuc/1-20 [001] ...s.12 16017.277464: softirq_exit: vec=8 [action=HRTIMER]
rcuc/1-20 [001] dN..311 16017.277465: sched_pi_setprio: comm=rcuc/1 pid=20 oldprio=19 newprio=98
rcuc/1-20 [001] dN..311 16017.277466: sched_waking: comm=irq/130-ecat0-r pid=25665 prio=19 target_cpu=001
rcuc/1-20 [001] dN..411 16017.277466: sched_wakeup: comm=irq/130-ecat0-r pid=25665 prio=19 target_cpu=001
rcuc/1-20 [001] .N..... 16017.277467: rcu_utilization: End CPU kthread@rcu_wait
rcuc/1-20 [001] dN..1.. 16017.277467: rcu_utilization: Start context switch
rcuc/1-20 [001] dN..1.. 16017.277467: rcu_utilization: End context switch
rcuc/1-20 [001] d...2.. 16017.277468: sched_switch: prev_comm=rcuc/1 prev_pid=20 prev_prio=98 prev_state=R+ ==> next_comm=cyclictest next_pid=20680 next_prio=19
rcuc/1-20 [001] d...2.. 16017.277468: tlb_flush: pages:0 reason:flush on task switch (0)
cyclictest-20680 [001] ....1.. 16017.277469: sys_clock_nanosleep -> 0x0
cyclictest-20680 [001] ....... 16017.277470: sys_exit: NR 230 = 0
cyclictest-20680 [001] d...... 16017.277470: x86_fpu_regs_activated: x86/fpu: 000000001e825867 load: 1 xfeatures: 2 xcomp_bv: 8000000000000003
cyclictest-20680 [001] d..h... 16017.277474: call_function_single_entry: vector=251
cyclictest-20680 [001] d..h... 16017.277475: call_function_single_exit: vector=251
cyclictest-20680 [001] d..h... 16017.277476: irq_work_entry: vector=246
cyclictest-20680 [001] d..h2.. 16017.277479: sched_migrate_task: comm=EtherCATControl pid=25916 prio=20 orig_cpu=1 dest_cpu=0
cyclictest-20680 [001] d..h... 16017.277480: irq_work_exit: vector=246
cyclictest-20680 [001] ....1.. 16017.277485: sys_write(fd: 4, buf: 7f98e50e0300, count: 21)
cyclictest-20680 [001] ....... 16017.277485: sys_enter: NR 1 (4, 7f98e50e0300, 21, 0, 0, 0)
cyclictest-20680 [001] ....... 16017.277486: tracing_mark_write: hit latency threshold (165 > 150)
cyclictest-20680 [001] ....1.. 16017.277487: sys_write -> 0x21
cyclictest-20680 [001] ....... 16017.277487: sys_exit: NR 1 = 33
cyclictest-20680 [001] ....1.. 16017.277487: sys_write(fd: 5, buf: 409a8a, count: 2)
cyclictest-20680 [001] ....... 16017.277487: sys_enter: NR 1 (5, 409a8a, 2, 0, 0, 0)
