[ClusterLabs] corosync SCHED_RR stuck at 100% cpu usage with kernel 4.19, priority inversion/livelock?
Edwin Török
edvin.torok at citrix.com
Thu Feb 14 12:33:26 EST 2019
Hello,
We were testing corosync 2.4.3/libqb 1.0.1-6/sbd 1.3.1/gfs2 on 4.19 and
noticed a fundamental problem with realtime priorities:
- corosync runs on CPU3, and interrupts for the NIC used by corosync are
also routed to CPU3
- corosync runs with SCHED_RR, ksoftirqd does not (should it?), but
without it packets sent/received from that interface would not get processed
- corosync is in a busy loop using 100% CPU, never giving a chance for
softirqs to be processed (including TIMER and SCHED)
This appears to be a priority inversion problem, if corosync runs as
realtime then everything it needs (timers...) should be realtime as
well, otherwise running as realtime guarantees we'll miss the watchdog
deadline, instead of guaranteeing that we process the data before the
deadline.
Do you have some advice on what the expected realtime priorities would
be for:
- corosync
- sbd
- hard irqs
- soft irqs
Also would it be possible for corosync to avoid hogging the CPU in libqb?
(Our hypothesis is that if softirqs are not processed then timers
wouldn't work for processes on that CPU either)
Some more background and analysis:
We noticed that cluster membership changes were very unstable
(especially as you approach 16 physical host clusters) causing the whole
cluster to fence when adding a single node. This was previously working
fairly reliably with a 4.4 based kernel.
I've increased SBD timeout to 3600 to be able to investigate the problem
and noticed that corosync was using 100% of CPU3 [1] and I immediately
lost SSH access on eth0 (corosync was using eth1), where eth0's
interrupts were also processed on CPU3 (and irqbalance didn't move it).
IIUC SCHED_RR tasks should not be able to take up 100% of CPU, according
to [3] it shouldn't be allowed to use more than 95% of CPU.
Softirqs were not processed at all on CPU3 (see [2], the numbers in the
CPU3 column did not change, the numbers in the other columns did).
Tried decreasing priority of corosync using chrt to 1, which didn't
help. I then increased the priority of ksoftirqd to 50 using chrt, which
immediately solved the CPU usage problem on corosync.
I tried a simple infinite loop program with realtime priority, but it
didn't reproduce the problems with interrupts getting stuck.
Three problems here:
* all softirqs were stuck (not being processed) on CPU3, which included
TIMER and SCHED. corosync relies quite heavily on timers, would lack of
processing them cause the 100% CPU usage?
* is there a kernel bug introduced between 4.4 - 4.19 that causes
realtime tasks to not respect the 95% limit anymore? This would leave 5%
time for IRQs, including NIC IRQs
* if corosync runs at higher priority than the kernel softirq thread
processing NIC IRQ how is corosync expecting incoming packets to be
processed, if it is hogging the CPU by receiving, polling and sending
packets?
On another host which exhibited the same problem I've run strace (which
also had the side-effect of getting corosync unstuck from 100% CPU use
after strace finished):
1 bind
5 close
688 epoll_wait
8 futex
1 getsockname
3 ioctl
1 open
3 recvfrom
190 recvmsg
87 sendmsg
9 sendto
4 socket
6 write
On yet another host I've run gdb while corosync was stuck:
Thread 2 (Thread 0x7f6fd0c9b700 (LWP 16245)):
#0 0x00007f6fd34a0afb in do_futex_wait.constprop.1 ()
from /lib64/libpthread.so.0
#1 0x00007f6fd34a0b8f in __new_sem_wait_slow.constprop.0 ()
from /lib64/libpthread.so.0
#2 0x00007f6fd34a0c2b in sem_wait@@GLIBC_2.2.5 () from
/lib64/libpthread.so.0
#3 0x00007f6fd3b38991 in qb_logt_worker_thread () from /lib64/libqb.so.0
#4 0x00007f6fd349ae25 in start_thread () from /lib64/libpthread.so.0
#5 0x00007f6fd31c4bad in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x7f6fd43c7b80 (LWP 16242)):
#0 0x00007f6fd31c5183 in epoll_wait () from /lib64/libc.so.6
#1 0x00007f6fd3b3dea8 in poll_and_add_to_jobs () from /lib64/libqb.so.0
#2 0x00007f6fd3b2ed93 in qb_loop_run () from /lib64/libqb.so.0
#3 0x000055592d62ff78 in main ()
[1]
top - 15:51:38 up 47 min, 2 users, load average: 3.81, 1.70, 0.70
Tasks: 208 total, 4 running, 130 sleeping, 0 stopped, 0 zombie
%Cpu0 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
%Cpu1 : 53.8 us, 46.2 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
%Cpu2 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
%Cpu3 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
%Cpu4 : 3.8 us, 0.0 sy, 0.0 ni, 96.2 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
%Cpu5 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
%Cpu6 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
%Cpu7 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
KiB Mem : 4210184 total, 3374752 free, 387380 used, 448052 buff/cache
KiB Swap: 1048572 total, 1048572 free, 0 used. 3660276 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
16217 root rt 0 194832 92532 66128 R 104.0 2.2 2:54.00 corosync
24004 root 20 0 161984 4432 3696 R 4.0 0.1 0:00.02 top
cat /proc/interrupts |grep eth
88: 2 0 0 0 0 0
0 0 xen-pirq -msi-x eth0
89: 2805 0 0 419621 0 0
0 0 xen-pirq -msi-x eth0-TxRx-0
90: 2 0 0 0 0 0
1 0 xen-pirq -msi-x eth1
91: 435 171086 0 0 0 0
0 0 xen-pirq -msi-x eth1-TxRx-0
[2]
watch cat /proc/softirqs
CPU0 CPU1 CPU2 CPU3 CPU4
CPU5 CPU6 CPU7
HI: 1 0 0 0 0
0 0 0
TIMER: 355339 786951 367148 266583 389591
357184 369577 374880
NET_TX: 8 1081 1 743 1
1 223 5
NET_RX: 5807 230818 2709 529755 3323
2598 2550 1878
BLOCK: 8166 53 42 13 10
6563 21 6894
IRQ_POLL: 0 0 0 0 0
0 0 0
TASKLET: 103 6 9 85 0
0 0 0
SCHED: 240428 100842 83166 51213 77824
77270 72074 72261
HRTIMER: 0 0 0 0 0
0 0 0
RCU: 135491 245345 139513 130591 140280
135094 141007 136063
[3]
/proc/sys/kernel/sched_rt_runtime_us
950000
/proc/sys/kernel/sched_rt_period_us
1000000
Best regards,
--Edwin
More information about the Users
mailing list