Long Device data retrieval and update durations

During the scale test(with BBSIM), when bringing up more than 100 ONUs, Update and Get queries for device data started to take too much time. I put the code below to identify the time to acquire a Lock in DeviceAgent.updateDeviceUsingAdapterData function

log.Debugw("DeviceAgent.updateDeviceUsingAdapterData before Lock", log.Fields{"deviceId": device.Id, "uuid":uuid})
agent.lockDevice.Lock()
defer agent.lockDevice.Unlock()
log.Debugw("DeviceAgent.updateDeviceUsingAdapterData after Lock", log.Fields{"deviceId": device.Id, "uuid":uuid})

Some results I got for 120 ONUs case:

{"level":"debug","ts":"2019-08-30T22:36:36.885Z","msg":"DeviceAgent.updateDeviceUsingAdapterData before Lock","instanceId":"23097dade1cc","caller":"device_agent.updateDeviceUsingAdapterData:1051","deviceId":"a09f6ee177d3fcaf4bb01410","uuid":"e3ab55af-fb9f-3e77-fef7-2fef77cf36e9"}{"level":"debug","ts":"2019-08-30T22:36:46.782Z","msg":"DeviceAgent.updateDeviceUsingAdapterData after Lock","instanceId":"23097dade1cc","caller":"device_agent.updateDeviceUsingAdapterData:1054","uuid":"e3ab55af-fb9f-3e77-fef7-2fef77cf36e9","deviceId":"a09f6ee177d3fcaf4bb01410"}

For 240 ONUs case:

{"level":"debug","ts":"2019-08-30T22:48:01.780Z","msg":"DeviceAgent.updateDeviceUsingAdapterData before Lock","instanceId":"953fca23fa77","caller":"device_agent.updateDeviceUsingAdapterData:1051","deviceId":"b088cbfae6a7661c4dba8a4b","uuid":"1cd58291-fd56-a87c-a734-71c28a7ab339"}
{"level":"debug","ts":"2019-08-30T22:48:55.257Z","msg":"DeviceAgent.updateDeviceUsingAdapterData after Lock","instanceId":"953fca23fa77","caller":"device_agent.updateDeviceUsingAdapterData:1054","deviceId":"b088cbfae6a7661c4dba8a4b","uuid":"1cd58291-fd56-a87c-a734-71c28a7ab339"}

I attached rw_core log which is filtered for an onu device id(9e81dd59db06930e6c572474). I put the string "=====" to some points of the log(during reading) for an updateDevice call. If you search the "=====" string then you will see the logs below:

{"level":"debug","ts":"2019-08-30T18:34:30.645Z","msg":"updateDeviceUsingAdapterData","instanceId":"3d5c8383b960","caller":"device_manager.updateDeviceUsingAdapterData:629","deviceid":"9e81dd59db06930e6c572474","device":"id:\"9e81dd59db06930e6c572474\" type:\"brcm_openomci_onu\" parent_id:\"ded60badd0ca50e1364f10af\" parent_port_no:536870913 vendor:\"OpenONU\" serial_number:\"BBSM00030120\" vendor_id:\"BBSM\" adapter:\"brcm_openomci_onu\" vlan:1 proxy_address:<device_id:\"ded60badd0ca50e1364f10af\" device_type:\"openolt\" channel_id:1 onu_id:33 > admin_state:ENABLED oper_status:ACTIVATING reason:\"starting-openomci\" flows:<> flow_groups:<> "}

{"level":"debug","ts":"2019-08-30T18:34:55.574Z","msg":"updateDeviceUsingAdapterData","instanceId":"3d5c8383b960","caller":"device_agent.updateDeviceUsingAdapterData:1046","deviceId":"9e81dd59db06930e6c572474"}

{"level":"debug","ts":"2019-08-30T18:34:59.584Z","msg":"proxy-update","instanceId":"3d5c8383b960","caller":"proxy.Update:291","path":"/devices/9e81dd59db06930e6c572474","effective":"/devices/9e81dd59db06930e6c572474","full":"/devices/9e81dd59db06930e6c572474","pathLock":"devices/9e81dd59db06930e6c572474","controlled":true,"operation":"PROXY_UPDATE"}

{"level":"debug","ts":"2019-08-30T18:34:59.759Z","msg":"updated-device-in-store","instanceId":"3d5c8383b960","caller":"device_agent.updateDeviceInStoreWithoutLock:1326","deviceId: ":"9e81dd59db06930e6c572474"}

Between first two lines, the thread waits 25 second to acquire the Lock. Then between second and third lines it spends 4 sec, which should be identified also. Details can be read at the log file.

The test is done in a single machine which is deployed with docker-compose with compose/system-test-openolt-go.yml. BBSIM is executed in a separate machine.