Uploaded image for project: 'VOLTHA'
  1. VOLTHA
  2. VOL-1894

Long Device data retrieval and update durations

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved (View Workflow)
    • Priority: Medium
    • Resolution: Won't Do
    • Affects Version/s: None
    • Fix Version/s: VOLTHA v2.3
    • Component/s: etcd, rw-core
    • Labels:
      None
    • Environment:

      Description

      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.

       

        Attachments

          Issue Links

          No reviews matched the request. Check your Options in the drop-down menu of this sections header.

            Activity

              People

              Assignee:
              sbarbari Stephane Barbarie
              Reporter:
              mahirgu Mahir Gunyel
              Watchers:
              11 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  Gerrit Reviews

                  There are no open Gerrit changes