All functions became slooow (corosync problem?)

[grin]

On some clusters (4.2 and 4.3) every management function started to get slow; GUI refresh calls take 4+ seconds (literally anything, from options to summary), 'pct' on console (w/o params, too) take 4-8 sec to finish. pvecm took 48 sec just now for a 4 node testcluster with full quorum.

I have tried to trace the wait and reached RPCEnvironment->init_request--> PVE::Cluster::cfs_update();, or possibly anything calling ipcc_send_receive_* Every call takes 2-4 sec.

I am lost here, there's no obvious documentation who handles these requests, visibly not pvestatd or pveproxy. Someone's timing out on something I suspect but I just don't see who and where and why. Any idea what do check?

 

[grin]

corosync-quorumtool -l takes like forever, 150 sec. There's plenty of traffic on 5404 and 5405.

[update] Somehow it seems to be related to corosync: on clusters with fast response quorumtool resonds immediately. I do not see anything in logs, however:

Nov 15 16:36:08 node01 corosync[2941]: [QB ] IPC credentials authenticated (2941-19005-3)
Nov 15 16:36:08 node01 corosync[2941]: [QB ] connecting to client [19005]
Nov 15 16:36:08 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:08 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:08 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:08 node01 corosync[2941]: [MAIN ] connection created
Nov 15 16:36:08 node01 corosync[2941]: [CMAP ] lib_init_fn: conn=0x55fd73ae9fa0
Nov 15 16:36:08 node01 corosync[2941]: [QB ] IPC credentials authenticated (2941-19005-23)
Nov 15 16:36:08 node01 corosync[2941]: [QB ] connecting to client [19005]
Nov 15 16:36:08 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:08 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:08 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:08 node01 corosync[2941]: [MAIN ] connection created
Nov 15 16:36:08 node01 corosync[2941]: [QUORUM] lib_init_fn: conn=0x55fd739e4e40
Nov 15 16:36:08 node01 corosync[2941]: [QUORUM] got quorum_type request on 0x55fd739e4e40
Nov 15 16:36:10 node01 corosync[2941]: [QB ] IPC credentials authenticated (2941-19005-24)
Nov 15 16:36:10 node01 corosync[2941]: [QB ] connecting to client [19005]
Nov 15 16:36:10 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:10 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:10 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:10 node01 corosync[2941]: [MAIN ] connection created
Nov 15 16:36:14 node01 corosync[2941]: [QB ] IPC credentials authenticated (2941-19005-25)
Nov 15 16:36:14 node01 corosync[2941]: [QB ] connecting to client [19005]
Nov 15 16:36:14 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:14 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:14 node01 corosync[2941]: [QB ] shm size:1048589; real_size:1052672; rb->word_size:263168
Nov 15 16:36:14 node01 corosync[2941]: [MAIN ] connection created
Nov 15 16:36:14 node01 pvestatd[41380]: status update time (16.174 seconds)
Nov 15 16:36:16 node01 corosync[2941]: [QUORUM] got trackstart request on 0x55fd739e4e40
Nov 15 16:36:16 node01 corosync[2941]: [QUORUM] sending initial status to 0x55fd739e4e40
Nov 15 16:36:16 node01 corosync[2941]: [QUORUM] sending quorum notification to 0x55fd739e4e40, length = 64
Nov 15 16:36:18 node01 corosync[2941]: [VOTEQ ] got getinfo request on 0x55fd73af0580 for node 1
Nov 15 16:36:18 node01 corosync[2941]: [VOTEQ ] getinfo response error: 1
Nov 15 16:36:20 node01 corosync[2941]: [VOTEQ ] got getinfo request on 0x55fd73af0580 for node 2
Nov 15 16:36:20 node01 corosync[2941]: [VOTEQ ] getinfo response error: 1
Nov 15 16:36:22 node01 corosync[2941]: [VOTEQ ] got getinfo request on 0x55fd73af0580 for node 3
Nov 15 16:36:22 node01 corosync[2941]: [VOTEQ ] getinfo response error: 1
Nov 15 16:36:24 node01 corosync[2941]: [VOTEQ ] got getinfo request on 0x55fd73af0580 for node 4
Nov 15 16:36:24 node01 corosync[2941]: [VOTEQ ] getinfo response error: 1

Nov 15 16:36:30 node01 pvestatd[41380]: status update time (16.181 seconds)

Nov 15 16:36:47 node01 pvestatd[41380]: status update time (16.192 seconds)

Nov 15 16:37:03 node01 pvestatd[41380]: status update time (16.188 seconds)

Nov 15 16:37:14 node01 corosync[2941]: [QB ] HUP conn (2941-19005-25)
Nov 15 16:37:14 node01 corosync[2941]: [QB ] qb_ipcs_disconnect(2941-19005-25) state:2
Nov 15 16:37:14 node01 corosync[2941]: [MAIN ] cs_ipcs_connection_closed()
Nov 15 16:37:14 node01 corosync[2941]: [MAIN ] cs_ipcs_connection_destroyed()
Nov 15 16:37:14 node01 corosync[2941]: [QB ] Free'ing ringbuffer: /dev/shm/qb-votequorum-response-2941-19005-25-header
Nov 15 16:37:14 node01 corosync[2941]: [QB ] Free'ing ringbuffer: /dev/shm/qb-votequorum-event-2941-19005-25-header
Nov 15 16:37:14 node01 corosync[2941]: [QB ] Free'ing ringbuffer: /dev/shm/qb-votequorum-request-2941-19005-25-header
Nov 15 16:37:14 node01 corosync[2941]: [QB ] HUP conn (2941-19005-24)
Nov 15 16:37:14 node01 corosync[2941]: [QB ] qb_ipcs_disconnect(2941-19005-24) state:2
Nov 15 16:37:14 node01 corosync[2941]: [MAIN ] cs_ipcs_connection_closed()
Nov 15 16:37:14 node01 corosync[2941]: [MAIN ] cs_ipcs_connection_destroyed()


​

 

[grin]

More info (you won't be happy I guess): due to that *&^%$#@!ing 60 sec fencing (I will murder it someday while praying for a real fencing) one cluster in question have rebooted. The result: it's fast again. corosync-quorumtool returns in 13 ms.

Where to see what (on the still slow clusters)?

 

[grin]

This keeps happening on various clusters, and only on some member nodes. Right now I have a 3 node cluster (a different one from the above) where node1 and node2 observes this extreme slowdown behaviour (CT/VM are okay but anything related to cluster management, from corosync-* command line tools through pvecm /pvect / qm to the GUI in general are mindboggingly slow; corosync-quorum returns in 65581 ms, which, incidentally, but possibly with no real meaning, quite close to 65536 ms), while node3 is okay (c-q returns in 24ms).

Interesting: corosync-cpgtool [on slow nodes] seem to be running forever (30 minutes now).

corosync-cfgtool -R won't fix it.
Restarting corosync fixes it (but due to a proxmox bug it reboots the node in 1 minute).

 

[dietmar]

strange, but I never observer such problems here. I have no real idea what is wrong ...

 

[spirit]

If you have same behaviour on differents cluster, I think it's a network problem or config somewhere.

Do you use bonding ? if yes, which mode ?

 

[grin]

bond mode 802.3ad
is there any known problem related to multicast and bonding?