[EnMasse] AddressController performance / ConfigMap lookups

Mon Mar 5 13:59:44 UTC 2018

Hi Carsten,

Yes, the getSchema() will lookup the configmaps every time. I suspected
that we might need to cache it, but decided to see how often this would
actually be used before optimizing it. Sounds like it should be optimized
:). I'm a bit surprised that it takes this long to get this information
from the kubernetes master though.

Using watchResources instead to cache it sounds like a sensible thing to do
to me.

Best regards,

Ulf

On Mon, Mar 5, 2018 at 2:17 PM, Lohmann Carsten (INST/ECS4) <
Carsten.Lohmann at bosch-si.com> wrote:

> 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_8432b9a6d2194c3f8c6328706eb455
> a0]
>
> 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_a77831ab936849c4b8a1ba8d15d2e0
> 18]
>
> 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
>
> Sitz: Berlin, Registergericht: Amtsgericht Charlottenburg; HRB 148411 B
> Aufsichtsratsvorsitzender: Dr.-Ing. Thorsten Lücke; Geschäftsführung: Dr.
> Stefan Ferber, Michael Hahn
>
>
>
>
> _______________________________________________
> enmasse mailing list
> enmasse at redhat.com
> https://www.redhat.com/mailman/listinfo/enmasse
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/enmasse/attachments/20180305/5ce0a0a6/attachment.htm>