How to prevent nonvoluntary_ctxt_switches on SQPOLL thread? IORING_REGISTER_IOWQ_AFF not working on Linux 6.3.2

[sharpobject]

Hello,

Although I don't know whether this is possible, I would like ideally like the kernel-side busy polling thread to always be busy polling. I am using cpuset to assign threads to cores other than the SQPOLL thread. I am assigning the SQPOLL thread to a core when setting up my io_uring instance. I am assigning the iou-wrk threads to a core by calling io_uring_register with IORING_REGISTER_IOWQ_AFF. My application enters steady state soon after startup with the main thread having performed (in this example) 580 context switches, but the SQPOLL thread continues to perform ~500 context switches per second indefinitely because the iou-wrk thread is scheduled to the same core (disregarding the prior io_uring_register!) and apparently cannot ever be moved to another core.

I'm running this on Linux 6.3.2 on AWS with whatever virtualization AWS normally uses. I'm not sure which details matter here so I'm trying to be thorough.

I previously observed the same behavior on Linux 5.17.0.

Here's my version of linux

user@host:~/repos/zigbot$ uname -a
Linux ip-my-ipv4-address 6.3.2-060302-generic #202305111150 SMP PREEMPT_DYNAMIC Thu May 11 22:22:15 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Here's a lightly redacted strace output of my application

execve("my_app", ["my_app", "arg"], 0x7ffd6cd3b3c0 /* 30 vars */) = 0
arch_prctl(ARCH_SET_FS, 0x4a2028)       = 0
prlimit64(0, RLIMIT_STACK, {rlim_cur=16384*1024, rlim_max=16384*1024}, NULL) = 0
io_uring_setup(512, {flags=IORING_SETUP_SQPOLL|IORING_SETUP_SQ_AFF, sq_thread_cpu=0x2, sq_thread_idle=60000, sq_entries=512, cq_entries=1024, features=IORING_FEAT_SINGLE_MMAP|IORING_FEAT_NODROP|IORING_FEAT_SUBMIT_STABLE|IORING_FEAT_RW_CUR_POS|IORING_FEAT_CUR_PERSONALITY|IORING_FEAT_FAST_POLL|IORING_FEAT_POLL_32BITS|IORING_FEAT_SQPOLL_NONFIXED|IORING_FEAT_EXT_ARG|IORING_FEAT_NATIVE_WORKERS|IORING_FEAT_RSRC_TAGS|0x3800, sq_off={head=0, tail=64, ring_mask=256, ring_entries=264, flags=276, dropped=272, array=16704}, cq_off={head=128, tail=192, ring_mask=260, ring_entries=268, overflow=284, cqes=320, flags=280}}) = 3
mmap(NULL, 18752, PROT_READ|PROT_WRITE, MAP_SHARED|MAP_POPULATE, 3, 0) = 0x7fd2c04ab000
mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_SHARED|MAP_POPULATE, 3, 0x10000000) = 0x7fd2c04a3000
io_uring_register(3, IORING_REGISTER_IOWQ_AFF, [1], 128) = 0
mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE|MAP_HUGETLB|21<<MAP_HUGE_SHIFT, -1, 0) = 0x7fd2c0200000
mmap(0x7fd2c0400000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE|MAP_HUGETLB|21<<MAP_HUGE_SHIFT, -1, 0) = 0x7fd2c0000000
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
mmap(0x7fd2c0200000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE|MAP_HUGETLB|21<<MAP_HUGE_SHIFT, -1, 0) = 0x7fd2bfe00000
mmap(0x7fd2c0000000, 136314880, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE|MAP_HUGETLB|21<<MAP_HUGE_SHIFT, -1, 0) = 0x7fd2b7c00000
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
openat(AT_FDCWD, "stderr.txt", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 4
mmap(0x7fd2bfe00000, 214748364800, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE|MAP_HUGETLB|21<<MAP_HUGE_SHIFT, -1, 0) = 0x7fa0b7c00000
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
openat(AT_FDCWD, "config.json", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 5
read(5, "this is a config file"..., 1048576) = 136874
read(5, "", 911702)                     = 0
close(5)                                = 0
open("another_config.json", O_RDWR)      = 5
write(2, "logging"..., 35) = 35
mmap(0x7fd2b7c00000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE|MAP_HUGETLB|21<<MAP_HUGE_SHIFT, -1, 0) = 0x7fa0b7a00000
mmap(0x7fa0b7c00000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE|MAP_HUGETLB|21<<MAP_HUGE_SHIFT, -1, 0) = 0x7fa0b7800000
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
mmap(0x7fa0b7a00000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE|MAP_HUGETLB|21<<MAP_HUGE_SHIFT, -1, 0) = 0x7fa0b7600000
mmap(0x7fa0b7800000, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE|MAP_HUGETLB|21<<MAP_HUGE_SHIFT, -1, 0) = 0x7fa0b7400000
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
msync(0x7fff9092d000, 4096, MS_ASYNC)   = 0
io_uring_enter(3, 1, 0, IORING_ENTER_SQ_WAKEUP, NULL, 8) = 1
write(2, "logging"..., 35) = 35
close(5)                                = 0
open("yet_another_config.json", O_RDONLY) = 5
// I know this seems weird, but we are actually reading this one via io_uring, so it won't show up here...
write(2, "logging"..., 35) = 35
close(5)                                = 0
write(2, "logging"..., 35) = 35
mmap(NULL, 16785408, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa0b63fe000
mprotect(0x7fa0b63ff000, 16781312, PROT_READ|PROT_WRITE) = 0
clone(child_stack=0x7fa0b73feff8, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[5822], tls=0x7fa0b73ff028, child_tidptr=0x7fa0b73ff054) = 5822
write(2, "logging"..., 35) = 35
rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
signalfd4(-1, [INT], 8, SFD_CLOEXEC)    = 5
mmap(NULL, 64, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd2c04a2000
madvise(0x7fd2c04a2000, 0, 0xffffffff /* MADV_??? */) = -1 EINVAL (Invalid argument)
madvise(0x7fd2c04a2000, 64, MADV_WIPEONFORK) = 0
getrandom("\x33\x38\x37\xf9\xcd\x11\x8d\x1d\x3e\xd8\x44\xfa\xa3\xe7\x0d\x61\x5f\x8b\x45\x07\x8c\x8b\x47\xe1\xce\x8f\x70\xce\xa1\x9f\xd4\xa6"..., 48, 0) = 48
// no further syscalls ever

Here's some information about the threads in my application in one run. Thread 5116 is my userspace busy-polling thread. Thread 5117 is my kernel busy polling thread. Thread 5118 is an offload thread for doing DNS because async DNS is hard. Threads 5119 and 5463 are iou-wrk threads whose CPU affinity is all CPUs even though I specifically asked for it to be only one CPU and which always get scheduled to the CPU that I am trying to reserve for thread 5117 even though their affinity says they could go anywhere and 2 other CPUs are idle.

user@host:~/repos/zigbot$ ps -eL | grep 511
   5116    5116 pts/3    00:08:22 my_app
   5116    5117 pts/3    00:08:20 iou-sqp-5116
   5116    5118 pts/3    00:00:00 my_app
   5116    5119 pts/3    00:00:01 iou-wrk-5117
   5116    5463 pts/3    00:00:00 iou-wrk-5117
user@host:~/repos/zigbot$ cat /proc/5117/status | grep Cpus_allowed_list
Cpus_allowed_list:	2
user@host:~/repos/zigbot$ cat /proc/5116/status | grep Cpus_allowed_list
Cpus_allowed_list:	3
user@host:~/repos/zigbot$ cat /proc/5119/status | grep Cpus_allowed_list
Cpus_allowed_list:	0-3
user@host:~/repos/zigbot$ cat /proc/5116/status | grep ctxt
voluntary_ctxt_switches:	0
nonvoluntary_ctxt_switches:	580
user@host:~/repos/zigbot$ cat /proc/5117/status | grep ctxt
voluntary_ctxt_switches:	1
nonvoluntary_ctxt_switches:	285864
user@host:~/repos/zigbot$ cat /proc/5116/status | grep ctxt
voluntary_ctxt_switches:	0
nonvoluntary_ctxt_switches:	580
user@host:~/repos/zigbot$ cat /proc/5117/status | grep ctxt
voluntary_ctxt_switches:	1
nonvoluntary_ctxt_switches:	326164
user@host:~/repos/zigbot$ cat /proc/5119/status | grep ctxt
voluntary_ctxt_switches:	326516
nonvoluntary_ctxt_switches:	16494

As you can see my kernel busy polling thread 5117 is being nonvoluntary_ctxt_switched quite often, apparently by thread 5119.

[sharpobject]

After trying random things in desperation, I've discovered that the noisier iou-wrk thread is associated with disk i/o, so I can avoid spawning it by doing no disk i/o from this ring. (For now that means I have no logs, but later today I can send logs over a userspace spsc queue to another thread and output them with write(2) or whatever). The less noisy iou-wrk thread still causes about 20 context switches per second to the precious iou-sqp thread though, and it would still be swell to reduce that to 0.