[EnMasse] AddressController performance / ConfigMap lookups

Mon Mar 5 13:17:48 UTC 2018

Hi,

We have noticed some performance issues when using the AddressController REST API.

Here is a log excerpt with added debug output concerning the addition of 2 addresses:

---------------------
2018-03-02 16:31:43.281 [vert.x-worker-thread-15] DEBUG HttpAddressService:94 - appendAddresses: [telemetry/tst_8432b9a6d2194c3f8c6328706eb455a0, event/tst_8432b9a6d2194c3f8c6328706eb455a0]
2018-03-02 16:31:43.290 [vert.x-worker-thread-15] DEBUG ConfigMapAddressSpaceApi:38 - getAddressSpaceWithName: get() took 8ms
2018-03-02 16:31:43.291 [vert.x-worker-thread-15] DEBUG AddressApiHelper:47 - verifyAuthorized took 0ms
2018-03-02 16:31:43.305 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=address-space-plan, resultList.size=1 took 14ms
2018-03-02 16:31:43.321 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=address-plan, resultList.size=6 took 15ms
2018-03-02 16:31:43.336 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 14ms
2018-03-02 16:31:43.351 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=address-plan, resultList.size=6 took 14ms
2018-03-02 16:31:43.365 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 14ms
2018-03-02 16:31:43.380 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 14ms
2018-03-02 16:31:43.397 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 16ms
2018-03-02 16:31:43.412 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 15ms
2018-03-02 16:31:43.427 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 14ms
2018-03-02 16:31:43.442 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 14ms
2018-03-02 16:31:43.456 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 14ms
2018-03-02 16:31:43.456 [vert.x-worker-thread-15] DEBUG ConfigMapSchemaApi:166 - getSchema took 165ms
2018-03-02 16:31:43.473 [vert.x-worker-thread-15] DEBUG ConfigMapAddressApi:89 - listAddresses: list() took 16ms
2018-03-02 16:31:43.494 [vert.x-worker-thread-15] DEBUG ConfigMapAddressApi:103 - createAddress: create() took 20ms
2018-03-02 16:31:43.506 [vert.x-worker-thread-15] DEBUG ConfigMapAddressApi:103 - createAddress: create() took 12ms
2018-03-02 16:31:43.524 [vert.x-worker-thread-15] DEBUG ConfigMapAddressApi:89 - listAddresses: list() took 17ms
2018-03-02 16:31:43.524 [vert.x-worker-thread-15] DEBUG HttpAddressService:48 - appendAddresses [telemetry/tst_8432b9a6d2194c3f8c6328706eb455a0, event/tst_8432b9a6d2194c3f8c6328706eb455a0] end (result: 56 items) - requestProcessing took 242ms
--------------------

What becomes obvious here is that the " ConfigMapSchemaApi.getSchema" invocation is quite expensive with its "listConfigMaps" calls.
The duration of 160ms is quite typical in our environment.

We even had times where the API server took longer for the requests and where the output looked like this:
--------------------
2018-03-02 17:20:07.197 [vert.x-worker-thread-13] DEBUG HttpAddressService:94 - appendAddresses: [telemetry/tst_a77831ab936849c4b8a1ba8d15d2e018, event/tst_a77831ab936849c4b8a1ba8d15d2e018]
2018-03-02 17:20:07.345 [vert.x-worker-thread-13] DEBUG ConfigMapAddressSpaceApi:38 - getAddressSpaceWithName: get() took 147ms
2018-03-02 17:20:07.345 [vert.x-worker-thread-13] DEBUG AddressApiHelper:47 - verifyAuthorized took 0ms
2018-03-02 17:20:07.444 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=address-space-plan, resultList.size=1 took 98ms
2018-03-02 17:20:07.591 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=address-plan, resultList.size=6 took 147ms
2018-03-02 17:20:07.714 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 122ms
2018-03-02 17:20:07.834 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=address-plan, resultList.size=6 took 120ms
2018-03-02 17:20:07.981 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 146ms
2018-03-02 17:20:08.131 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 149ms
2018-03-02 17:20:08.254 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 122ms
2018-03-02 17:20:08.374 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 120ms
2018-03-02 17:20:08.494 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 119ms
2018-03-02 17:20:08.641 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 146ms
2018-03-02 17:20:08.761 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:55 - listConfigMaps type=resource-definition, resultList.size=4 took 120ms
2018-03-02 17:20:08.761 [vert.x-worker-thread-13] DEBUG ConfigMapSchemaApi:166 - getSchema took 1416ms
2018-03-02 17:20:08.913 [vert.x-worker-thread-13] DEBUG ConfigMapAddressApi:89 - listAddresses: list() took 151ms
2018-03-02 17:20:09.145 [vert.x-worker-thread-13] DEBUG ConfigMapAddressApi:103 - createAddress: create() took 231ms
2018-03-02 17:20:09.265 [vert.x-worker-thread-13] DEBUG ConfigMapAddressApi:103 - createAddress: create() took 119ms
2018-03-02 17:20:09.426 [vert.x-worker-thread-13] DEBUG ConfigMapAddressApi:89 - listAddresses: list() took 160ms
2018-03-02 17:20:09.426 [vert.x-worker-thread-13] DEBUG HttpAddressService:48 - appendAddresses [telemetry/tst_a77831ab936849c4b8a1ba8d15d2e018, event/tst_a77831ab936849c4b8a1ba8d15d2e018] end (result: 66 items) - requestProcessing took 2229ms
--------------------

Possible performance improvements concerning the API server aside, there is the question whether there is room to make "getSchema" faster.
To me it looks like the K8s resources requested there (address space plans, address plans, resource definitions) are fairly static and could therefore be cached/kept in memory.
I guess updates on these K8s resources could be handled via ConfigMapAddressAPI.watchResources (?).

WDYT? Would that be feasible?

Best regards

Carsten Lohmann

(INST/ECS4)
Bosch Software Innovations GmbH | Ullsteinstr. 128 | 12109 Berlin | GERMANY | www.bosch-si.com<http://www.bosch-si.com>

Sitz: Berlin, Registergericht: Amtsgericht Charlottenburg; HRB 148411 B
Aufsichtsratsvorsitzender: Dr.-Ing. Thorsten Lücke; Geschäftsführung: Dr. Stefan Ferber, Michael Hahn

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/enmasse/attachments/20180305/938b2f0d/attachment.htm>