[ClusterLabs] corosync SCHED_RR stuck at 100% cpu usage with kernel 4.19, priority inversion/livelock?

Wed Feb 20 20:25:09 UTC 2019

On 02/20/2019 06:37 PM, Edwin Török wrote:
> On 20/02/2019 13:08, Jan Friesse wrote:
>> Edwin Török napsal(a):
>>> On 20/02/2019 07:57, Jan Friesse wrote:
>>>> Edwin,
>>>>>
>>>>> On 19/02/2019 17:02, Klaus Wenninger wrote:
>>>>>> On 02/19/2019 05:41 PM, Edwin Török wrote:
>>>>>>> On 19/02/2019 16:26, Edwin Török wrote:
>>>>>>>> On 18/02/2019 18:27, Edwin Török wrote:
>>>>>>>>> Did a test today with CentOS 7.6 with upstream kernel and with
>>>>>>>>> 4.20.10-1.el7.elrepo.x86_64 (tested both with upstream SBD, and our
>>>>>>>>> patched [1] SBD) and was not able to reproduce the issue yet.
>>>>>>>> I was able to finally reproduce this using only upstream components
>>>>>>>> (although it seems to be easier to reproduce if we use our patched
>>>>>>>> SBD,
>>>>>>>> I was able to reproduce this by using only upstream packages
>>>>>>>> unpatched
>>>>>>>> by us):
>>>>>> Just out of curiosity: What did you patch in SBD?
>>>>>> Sorry if I missed the answer in the previous communication.
>>>>> It is mostly this PR, which calls getquorate quite often (a more
>>>>> efficient impl. would be to use the quorum notification API like
>>>>> dlm/pacemaker do, although see concerns in
>>>>> https://lists.clusterlabs.org/pipermail/users/2019-February/016249.html):
>>>>>
>>>>> https://github.com/ClusterLabs/sbd/pull/27
>>>>>
>>>>> We have also added our own servant for watching the health of our
>>>>> control plane, but that is not relevant to this bug (it reproduces with
>>>>> that watcher turned off too).
>>>>>
>>>>>>> I was also able to get a corosync blackbox from one of the stuck VMs
>>>>>>> that showed something interesting:
>>>>>>> https://clbin.com/d76Ha
>>>>>>>
>>>>>>> It is looping on:
>>>>>>> debug   Feb 19 16:37:24 mcast_sendmsg(408):12: sendmsg(mcast) failed
>>>>>>> (non-critical): Resource temporarily unavailable (11)
>>>>>> Hmm ... something like tx-queue of the device full, or no buffers
>>>>>> available anymore and kernel-thread doing the cleanup isn't
>>>>>> scheduled ...
>>>>> Yes that is very plausible. Perhaps it'd be nicer if corosync went back
>>>>> to the epoll_wait loop when it gets too many EAGAINs from sendmsg.
>>>> But this is exactly what happens. Corosync will call sendmsg to all
>>>> active udpu members and returns back to main loop -> epoll_wait.
>>>>
>>>>> (although this seems different from the original bug where it got stuck
>>>>> in epoll_wait)
>>>> I'm pretty sure it is.
>>>>
>>>> Anyway, let's try "sched_yield" idea. Could you please try included
>>>> patch and see if it makes any difference (only for udpu)?
>>> Thanks for the patch, unfortunately corosync still spins 106% even with
>>> yield:
>>> https://clbin.com/CF64x
>> Yep, it was kind of expected, but at lost worth a try. How does strace
>> look when this happens?
>>
> strace for the situation described below (corosync 95%, 1 vCPU):
> https://clbin.com/hZL5z
>
>> Also Klaus had an idea to try remove sbd from the picture and try
>> different RR process to find out what happens. And I think it's again
>> worth try.
>>
>> Could you please try install/enable/start
>> https://github.com/jfriesse/spausedd (packages built by copr are
>> https://copr.fedorainfracloud.org/coprs/honzaf/spausedd/),
>> disable/remove sbd and run your test?
>>
> Tried this with 4 vCPUs but it didn't detect any pauses (kind of
> expected, plenty of other CPUs to have spausedd scheduled on even if
> corosync hogs one).
> Then tried with 1 vCPU and it didn't detect any pauses here either. The
> 95% max realtime runtime protection kicks in and limits corosync to 95%
> CPU since now global 95% = this CPU's 95% since there is only one.
> Interestingly corosync stays running at 95% CPU usage now, unlike in SMP
> scenarios where the 95% limit was enough to avoid the situation.

Hmm maybe the thing that should be scheduled is running at
SCHED_RR as well but with just a lower prio. So it wouldn't
profit from the sched_yield and it wouldn't get anything of
the 5% either.

> There is a visible keyboard lag over SSH, but spausedd does get scheduled:

But it shows at least that the sched_yield is doing something ...
although the RR might be triggered even without the explicit
sched_yield in cases like this.

>
> 4923 root      rt   0  213344 111036  84732 R 93.3  2.8  19:07.50
> corosync
>
>      9 root      20   0       0      0      0 S  0.3  0.0   0:02.02
> ksoftirqd/0
>
>   4256 root      rt   0   88804  35612  34368 R  0.3  0.9   0:04.36
> spausedd
>
> No SBD running, and corosync-blackbox does not work at all now.
>
> ifconfig eth0; sleep 1; ifconfig eth0
> eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
>         inet 10.62.98.26  netmask 255.255.240.0  broadcast 10.62.111.255
>         inet6 fd06:7768:b9e5:8c50:4c0e:daff:fe14:55f0  prefixlen 64
> scopeid 0x0<global>
>         inet6 fe80::4c0e:daff:fe14:55f0  prefixlen 64  scopeid 0x20<link>
>         ether 4e:0e:da:14:55:f0  txqueuelen 1000  (Ethernet)
>         RX packets 4929031  bytes 4644924223 (4.3 GiB)
>         RX errors 0  dropped 0  overruns 0  frame 0
>         TX packets 15445220  bytes 22485760076 (20.9 GiB)
>         TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
>
> eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
>         inet 10.62.98.26  netmask 255.255.240.0  broadcast 10.62.111.255
>         inet6 fd06:7768:b9e5:8c50:4c0e:daff:fe14:55f0  prefixlen 64
> scopeid 0x0<global>
>         inet6 fe80::4c0e:daff:fe14:55f0  prefixlen 64  scopeid 0x20<link>
>         ether 4e:0e:da:14:55:f0  txqueuelen 1000  (Ethernet)
>         RX packets 4934042  bytes 4649642415 (4.3 GiB)
>         RX errors 0  dropped 0  overruns 0  frame 0
>         TX packets 15464987  bytes 22514562910 (20.9 GiB)
>         TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
>
> Looking at this from the hypervisor side the VM is not sending many
> packets once CPU usage goes up:
> https://pasteboard.co/I246a1W.png
>
>>> On another host corosync failed to start up completely (Denied
>>> connection not ready), and:
>>> https://clbin.com/Z35Gl
>>> (I don't think this is related to the patch, it was doing that before
>>> when I looked at it this morning, kernel 4.20.0 this time)
>> This one looks kind of normal and I'm pretty sure it's unrelated (I've
>> seen it already sadly never was able to find a "reliable" reproducer)
> Got a fairly reliable one now, only 3/16 VMs were able to start
> corosync, one got stuck with CPU usage as shown above, the others failed
> to start with 'Denied connection'.
>
> In the past we've seen this kind of problem when dhclient happened to
> take up and listen on corosync's port, but thats been fixed in recent
> CentOS 7.x releases, and is not the case now.
>
> Anything you'd like me to try help debug this?
>
> Thanks,
> --Edwin