Pyrakoon calls taking a lot of time

[JeffreyDevloo]

We frequently observe 'Pyrakoon call get took ...` in the webapp-api log.

Further observation lead to:

Mar 12 10:55:45 NY1SRV0016 ovs-webapp-api[31036]: 89efb0ea-578a-427b-a0f3-0dade7baed71 - Lock acquire took 0.515820026398
Mar 12 10:55:45 NY1SRV0016 ovs-webapp-api[31036]: 89efb0ea-578a-427b-a0f3-0dade7baed71 - Connecting and sending message took 8.01086425781e-05
Mar 12 10:55:45 NY1SRV0016 ovs-webapp-api[31036]: 89efb0ea-578a-427b-a0f3-0dade7baed71 - Connecting and reading data took 0.0258631706238
Mar 12 10:55:45 NY1SRV0016 ovs-webapp-api[31036]: Request of type <class 'ovs_extensions.db.arakoon.pyrakoon.pyrakoon.protocol.Get'> with id 89efb0ea-578a-427b-a0f3-0dade7baed71 took 0.541803121567
Mar 12 10:55:45 NY1SRV0016 ovs-webapp-api[31036]: ArakoonClient get took 0.541900873184
Mar 12 10:55:45 NY1SRV0016 ovs-webapp-api[31036]: 2019-03-12 15:55:45 14300 +0100 - NY1SRV0016 - 31043/139943927012720 - extensions/client.py - 41 - WARNING - Pyrakoon call get took 0.54s (arg: ('ovs_data_rolecl
ient_0441145d-6e2b-4b7a-b766-99e6c6ea3059',), kwarg: {}, client: <ovs_extensions.db.arakoon.pyrakoon.pyrakoon.compat.ArakoonClient object at 0x7f477e909f90>)

We can increase the number of api workers to avoid the lock (as it is process bound).
However a more permanent fix is to migrate to a lock-less client

[toolslive]

or pool the clients, or load balance the traffic (you typically have 2 nodes running the API).

The other problem is that gunicorn doesn't balance the work well. the first worker to respond gets the work....
but our work is IO bound and not CPU bound, so having work will not keep 1 worker to enter the race for more work. In practice, there's 1 worker that wins 80% of the race for new work.

[JeffreyDevloo]

Has been fixed by openvstorage/framework-extensions#215. The bulk of the time is spent acquiring a lock because of the single client.