Controller scripts are very slow

[ksuprynowicz]

This is probably related to https://github.com/overte-org/overte/issues/707

Controller scripts are currently extremely slow:

[11/20 19:44:3[11/20 19:44:31] [DEBUG] [overte.scriptengine] Script: "controllerScripts.js" Frame: 4200 Slept (us): 127317 Avg Updates (us): 6694 averageTimerPerFrame (us): 97327 FPS: 61] [DEBUG] [overte.scriptengine] Script: "controllerScripts.js" Frame: 4200 Slept (us): 127317 Avg Updates (us): 6694 averageTimerPerFrame (us): 97327 FPS: 6

According to V8 profiling data it looks like parts thet aren't even currently used take a significant part of the processing time:

7105    6448    ControllerDispatcher.checkForHandTrackingClick  file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerDispatcher.js   176
6830    10  FarTriggerEntity.isReady    file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerModules/farTrigger.js   64
6817    6271    handsAreTracked file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/libraries/controllerDispatcherUtils.js    612
5721    5721    (program)       0
5433    12  EquipEntity.isReady file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerModules/equipEntity.js  643
5410    33  EquipEntity.checkNearbyHotspots file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerModules/equipEntity.js  589
3421    8   TrackedHandWalk.isReady file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerModules/trackedHandWalk.js  107
3413    3134    handsAreTracked file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/libraries/controllerDispatcherUtils.js    612
3413    4   TrackedHandTablet.isReady   file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerModules/trackedHandTablet.js    96
3409    3151    handsAreTracked file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/libraries/controllerDispatcherUtils.js    612
2998    2998    EquipEntity.handToController    file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerModules/equipEntity.js  353
2682    1664    ControllerDispatcher.dataGatherers.rightControllerLocation  file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerDispatcher.js   141
2494    977 ControllerDispatcher.dataGatherers.leftControllerLocation   file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerDispatcher.js   138
2285    2136    update  file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/squeezeHands.js   88
1745    904 getControllerWorldLocation  file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/libraries/controllers.js  47
1517    910 getControllerWorldLocation  file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/libraries/controllers.js  47
1288    31  WebSurfaceLaserInput.isReady    file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerModules/webSurfaceLaserInput.js 188
1187    7   WebSurfaceLaserInput.farGrabActive  file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerModules/webSurfaceLaserInput.js 44
1175    273 FarGrabEntity.targetIsNull  file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/controllers/controllerModules/farGrabEntity.js    370
1111    456 findHandChildEntities   file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/libraries/controllerDispatcherUtils.js    500
1018    504 getControllerWorldLocation  file:///home/ksuprynowicz/overte/overte_v8/overte/cmake-build-relwithdebinfo/interface/scripts/system/libraries/controllers.js  47

It looks like mostly converting entity properties to script values takes a lot of time:

[ksuprynowicz]

In unoptimized version it runs at 1 frame per 3 second: [11/21 00:04:21] [DEBUG] [overte.scriptengine] Script: "controllerScripts.js" Frame: 360 Slept (us): 1501464 Avg Updates (us): 14697 averageTimerPerFrame (us): 1412341 FPS: 0 After disabling hand gesture related parts it's better, but still incredibly slow: [11/21 00:15:23] [DEBUG] [overte.scriptengine] Script: "controllerScripts.js" Frame: 60 Slept (us): 1222020 Avg Updates (us): 15447 averageTimerPerFrame (us): 1168147 FPS: 0

[ksuprynowicz]

If equipEntity is also disabled then perfomance improves twice: [11/21 00:33:54] [DEBUG] [overte.scriptengine] Script: "controllerScripts.js" Frame: 60 Slept (us): 962033 Avg Updates (us): 15718 averageTimerPerFrame (us): 897876 FPS: 0

[ksuprynowicz]

On unoptimized build controller scripts get just 10 FPS with only squeezeHands.js: [11/21 00:44:52] [DEBUG] [overte.scriptengine] Script: "controllerScripts.js" Frame: 840 Slept (us): 75825 Avg Updates (us): 16361 averageTimerPerFrame (us): 59576 FPS: 10 And 25 FPS with only grab.js: [11/21 00:57:46] [DEBUG] [overte.scriptengine] Script: "controllerScripts.js" Frame: 3660 Slept (us): 40170 Avg Updates (us): 3 averageTimerPerFrame (us): 27129 FPS: 25

[ksuprynowicz]

The controller scripts seem to be way faster in smaller worlds, like for example tutorial world, and extremely slow in large worlds like Overte Hub. This probably means that some part is getting too many entities.

[ksuprynowicz]

It looks like Controller.Standard.RightHand is very slow for some reason, about 1.5 ms per call.

[ksuprynowicz]

It looks like most of the time is consumed getting Controller.Standard. If it's cached as a variable then the call is almost for free. Here are profiling results for Controller.Standard.RightHand without caching: