Merge pull request #9286 from ZappoMan/improveScriptRPC

Improve performance of Entities.callEntityMethod()

libraries/script-engine/src/ScriptEngine.cpp

@@ -908,19 +908,11 @@ void ScriptEngine::run() {
                 break;
             }
 
-            // determine how long before the next timer should fire, we'd ideally like to sleep just
-            // that long, so the next processEvents() will allow the timers to fire on time.
-            const std::chrono::microseconds minTimerTimeRemaining(USECS_PER_MSEC * getTimersRemainingTime());
-
-            // However, if we haven't yet slept at least as long as our average timer per frame, then we will 
-            // punish the timers to at least wait as long as the average run time of the timers.
-            auto untilTimer = std::max(minTimerTimeRemaining, averageTimerPerFrame);
-
-            // choose the closest time point, our 
-            auto remainingSleepUntil = std::chrono::duration_cast<std::chrono::microseconds>(sleepUntil - clock::now());
-            auto closestUntil = std::min(remainingSleepUntil, untilTimer);
-            auto thisSleepUntil = std::min(sleepUntil, clock::now() + closestUntil);
-            std::this_thread::sleep_until(thisSleepUntil);
+            // We only want to sleep a small amount so that any pending events (like timers or invokeMethod events)
+            // will be able to process quickly.
+            static const int SMALL_SLEEP_AMOUNT = 100;
+            auto smallSleepUntil = clock::now() + static_cast<std::chrono::microseconds>(SMALL_SLEEP_AMOUNT);
+            std::this_thread::sleep_until(smallSleepUntil);
         }
 
 #ifdef SCRIPT_DELAY_DEBUG
@@ -1010,21 +1002,6 @@ void ScriptEngine::run() {
     emit doneRunning();
 }
 
-quint64 ScriptEngine::getTimersRemainingTime() {
-    quint64 minimumTime = USECS_PER_SECOND; // anything larger than this can be ignored
-    QMutableHashIterator<QTimer*, CallbackData> i(_timerFunctionMap);
-    while (i.hasNext()) {
-        i.next();
-        QTimer* timer = i.key();
-        int remainingTime = timer->remainingTime();
-        if (remainingTime >= 0) {
-            minimumTime = std::min((quint64)remainingTime, minimumTime);
-        }
-    }
-    return minimumTime;
-}
-
-
 // NOTE: This is private because it must be called on the same thread that created the timers, which is why
 // we want to only call it in our own run "shutdown" processing.
 void ScriptEngine::stopAllTimers() {
@@ -1035,6 +1012,7 @@ void ScriptEngine::stopAllTimers() {
         stopTimer(timer);
     }
 }
+
 void ScriptEngine::stopAllTimersForEntityScript(const EntityItemID& entityID) {
      // We could maintain a separate map of entityID => QTimer, but someone will have to prove to me that it's worth the complexity. -HRS
     QVector<QTimer*> toDelete;

libraries/script-engine/src/ScriptEngine.h

@@ -218,7 +218,6 @@ protected:
     void init();
 
     bool evaluatePending() const { return _evaluatesPending > 0; }
-    quint64 getTimersRemainingTime();
     void timerFired();
     void stopAllTimers();
     void stopAllTimersForEntityScript(const EntityItemID& entityID);

scripts/developer/tests/testInterval.js

@@ -0,0 +1,244 @@
+// Tester, try testing these different settings.
+//
+// Changing the TIMER_HZ will show different performance results. It's expected that at 90hz you'll see a fair
+// amount of variance, as Qt Timers simply aren't accurate enough. In general RPC peformance should match the timer
+// without significant difference in variance.
+
+var TIMER_HZ = 50; // Change this for different values
+var TIMER_INTERVAL = 1000 / TIMER_HZ;
+var TIMER_WORK_EFFORT = 0; // 1000 is light work, 1000000 ~= 30ms
+
+var UPDATE_HZ = 60; // standard script update rate
+var UPDATE_INTERVAL = 1000/UPDATE_HZ; // standard script update interval
+var UPDATE_WORK_EFFORT = 0; // 1000 is light work, 1000000 ~= 30ms
+
+var basePosition = Vec3.sum(Camera.getPosition(), Quat.getFront(Camera.getOrientation()));
+
+var timerBox = Entities.addEntity(
+  { type: "Box",
+    position: basePosition,
+    dimensions: { x: 0.1, y: 0.1, z: 0.1 },  
+    color: { red: 255, green: 0, blue: 255 },
+    dynamic: false,
+    collisionless: true
+  });
+
+var lastTick = Date.now();
+var deltaTick = 0;
+var tickSamples = 0;
+var totalVariance = 0;
+var tickCount = 0;
+var totalWork = 0;
+var highVarianceCount = 0;
+var varianceCount = 0;
+
+print("Set interval = " + TIMER_INTERVAL);
+
+var timerTime = 0.0; 
+var range = 0.5;
+var rotationFactor = 0.5; // smaller == faster
+var omega = 2.0 * Math.PI / rotationFactor;
+
+var ticker = Script.setInterval(function() {
+
+	tickCount++;
+	var tickNow = Date.now();
+	deltaTick = tickNow - lastTick;
+
+    var variance = Math.abs(deltaTick - TIMER_INTERVAL);
+    totalVariance += variance;
+
+    if (variance > 1) {
+        varianceCount++;
+    }
+    if (variance > 5) {
+        highVarianceCount++;
+    }
+
+	var preWork = Date.now();
+    var y = 2;
+    for (var x = 0; x < TIMER_WORK_EFFORT; x++) {
+        y = y * y;
+    }
+	var postWork = Date.now();
+    deltaWork = postWork - preWork;
+    totalWork += deltaWork;
+
+    // move a box
+    var deltaTime = deltaTick / 1000;
+    timerTime += deltaTime;
+    rotation = Quat.angleAxis(timerTime * omega  / Math.PI * 180.0, { x: 0, y: 1, z: 0 });
+    Entities.editEntity(timerBox, 
+                {
+                    position: { x: basePosition.x + Math.sin(timerTime * omega) / 2.0 * range, 
+                                y: basePosition.y, 
+                                z: basePosition.z  },  
+                    //rotation: rotation 
+                }); 
+
+	tickSamples = tickSamples + deltaTick;
+    lastTick = tickNow;
+
+    // report about every 5 seconds
+	if(tickCount == (TIMER_HZ * 5)) {
+		print("TIMER  -- For " + tickCount + " samples average interval = " + tickSamples/tickCount + " ms" 
+                     + " average variance:" + totalVariance/tickCount + " ms"
+                     + " min variance:" + varianceCount + " [" + (varianceCount/tickCount) * 100 + " %] "
+                     + " high variance:" + highVarianceCount + " [" + (highVarianceCount/tickCount) * 100 + " %] "
+                     + " average work:" + totalWork/tickCount + " ms");
+        tickCount = 0;
+        tickSamples = 0;
+        totalWork = 0;
+        totalVariance = 0;
+        varianceCount = 0;
+        highVarianceCount = 0;
+	}
+}, TIMER_INTERVAL);
+
+/////////////////////////////////////////////////////////////////////////
+
+var rpcPosition = Vec3.sum(basePosition, { x:0, y: 0.2, z: 0});
+
+var theRpcFunctionInclude = Script.resolvePath("testIntervalRpcFunction.js");
+
+print("theRpcFunctionInclude:" + theRpcFunctionInclude);
+
+var rpcBox = Entities.addEntity(
+  { type: "Box",
+    position: rpcPosition,
+    dimensions: { x: 0.1, y: 0.1, z: 0.1 },  
+    color: { red: 255, green: 255, blue: 0 },
+    dynamic: false,
+    collisionless: true,
+    script: theRpcFunctionInclude
+  });
+
+var rpcLastTick = Date.now();
+var rpcTotalTicks = 0;
+var rpcCount = 0;
+var rpcTotalVariance = 0;
+var rpcTickCount = 0;
+var rpcVarianceCount = 0;
+var rpcHighVarianceCount = 0;
+
+var rpcTicker = Script.setInterval(function() {
+
+	rpcTickCount++;
+	var tickNow = Date.now();
+	var deltaTick = tickNow - rpcLastTick;
+    var variance = Math.abs(deltaTick - TIMER_INTERVAL);
+    rpcTotalVariance += variance;
+
+    if (variance > 1) {
+        rpcVarianceCount++;
+    }
+    if (variance > 5) {
+        rpcHighVarianceCount++;
+    }
+
+	rpcTotalTicks += deltaTick;
+    rpcLastTick = tickNow;
+
+    var args = [range, rotationFactor, omega, TIMER_INTERVAL, TIMER_HZ];
+
+    Entities.callEntityMethod(rpcBox, "doRPC", args);
+
+    // report about every 5 seconds
+	if(rpcTickCount == (TIMER_HZ * 5)) {
+		print("RPCTIMER- For " + rpcTickCount + " samples average interval = " + rpcTotalTicks/rpcTickCount + " ms" 
+                     + " average variance:" + rpcTotalVariance/rpcTickCount + " ms"
+                     + " min variance:" + rpcVarianceCount + " [" + (rpcVarianceCount/rpcTickCount) * 100 + " %] "
+                     + " high variance:" + rpcHighVarianceCount + " [" + (rpcHighVarianceCount/rpcTickCount) * 100 + " %] "
+              );
+        rpcTickCount = 0;
+        rpcTotalTicks = 0;
+        rpcTotalVariance = 0;
+        rpcVarianceCount = 0;
+        rpcHighVarianceCount = 0;
+	}
+}, TIMER_INTERVAL);
+
+
+var updateCount = 0;
+var updateTotalElapsed = 0;
+var lastUpdate = Date.now();
+var updateTotalWork = 0;
+var updateTotalVariance = 0;
+var updateVarianceCount = 0;
+var updateHighVarianceCount = 0;
+
+var updatePosition = Vec3.sum(basePosition, { x:0, y: -0.2, z: 0});
+
+var updateBox = Entities.addEntity(
+  { type: "Box",
+    position: updatePosition,
+    dimensions: { x: 0.1, y: 0.1, z: 0.1 },  
+    color: { red: 0, green: 255, blue: 255 },
+    dynamic: false,
+    collisionless: true
+  });
+
+
+var updateTime = 0;
+var updateFunction = function(deltaTime){
+	updateCount++;
+    var updateAt = Date.now();
+	deltaUpdate = updateAt - lastUpdate;
+	updateTotalElapsed += deltaUpdate;
+	lastUpdate = updateAt;
+
+    var variance = Math.abs(deltaUpdate - UPDATE_INTERVAL);
+    updateTotalVariance += variance;
+
+    if (variance > 1) {
+        updateVarianceCount++;
+    }
+
+    if (variance > 5) {
+        updateHighVarianceCount++;
+    }
+
+	var preWork = Date.now();
+    var y = 2;
+    for (var x = 0; x < UPDATE_WORK_EFFORT; x++) {
+        y = y * y;
+    }
+	var postWork = Date.now();
+    deltaWork = postWork - preWork;
+    updateTotalWork += deltaWork;
+
+    // move a box
+
+    updateTime += deltaTime;
+    rotation = Quat.angleAxis(updateTime * omega  / Math.PI * 180.0, { x: 0, y: 1, z: 0 });
+    Entities.editEntity(updateBox, 
+                {
+                    position: { x: updatePosition.x + Math.sin(updateTime * omega) / 2.0 * range, 
+                                y: updatePosition.y, 
+                                z: updatePosition.z  },  
+                }); 
+
+
+	if(updateCount == (UPDATE_HZ * 5)) {
+		print("UPDATE -- For " + updateCount + " samples average update = " + updateTotalElapsed/updateCount + " ms" 
+                     + " average variance:" + updateTotalVariance/updateCount + " ms"
+                     + " min variance:" + updateVarianceCount + " [" + (updateVarianceCount/updateCount) * 100 + " %] "
+                     + " high variance:" + updateHighVarianceCount + " [" + (updateHighVarianceCount/updateCount) * 100 + " %] "
+                     + " average work:" + updateTotalWork/updateCount + " ms");
+
+        updateCount = 0;
+        updateTotalElapsed = 0;
+        updateTotalWork = 0;
+        updateTotalVariance = 0;
+        updateVarianceCount = 0;
+        updateHighVarianceCount = 0;
+	}
+};
+
+Script.update.connect(updateFunction);
+
+Script.scriptEnding.connect(function(){
+    Entities.deleteEntity(timerBox);
+    Entities.deleteEntity(rpcBox);
+    Entities.deleteEntity(updateBox);
+});

scripts/developer/tests/testIntervalRpcFunction.js

@@ -0,0 +1,77 @@
+(function() { 
+    var x = false;
+    var y = false;
+    var z = false;
+
+    var entityLastTick = Date.now();
+    var entityTotalTicks = 0;
+    var entityCount = 0;
+    var entityTotalVariance = 0;
+    var entityTickCount = 0;
+    var entityVarianceCount = 0;
+    var entityHighVarianceCount = 0;
+    var _entityID;
+    var time = 0;
+
+    function Foo() { return; };
+    Foo.prototype = {
+        preload: function(entityID) { print('Foo preload'); _entityID = entityID; },
+        doRPC: function(entityID, args) { 
+            var range = args[0];
+            var rotationFactor = args[1];
+            var omega = args[2];
+            var TIMER_INTERVAL = args[3];
+            var TIMER_HZ = args[4];
+
+            // first time, set our x,y,z
+            if (x === false) {
+                var position = Entities.getEntityProperties(_entityID, "position").position;
+                x = position.x;
+                y = position.y;
+                z = position.z;
+            }
+	        entityTickCount++;
+	        var tickNow = Date.now();
+	        var deltaTick = tickNow - entityLastTick;
+            var variance = Math.abs(deltaTick - TIMER_INTERVAL);
+            entityTotalVariance += variance;
+
+            if (variance > 1) {
+                entityVarianceCount++;
+            }
+            if (variance > 5) {
+                entityHighVarianceCount++;
+            }
+
+	        entityTotalTicks += deltaTick;
+            entityLastTick = tickNow;
+
+            // move self!!
+            var deltaTime = deltaTick / 1000;
+            time += deltaTime;
+            rotation = Quat.angleAxis(time * omega  / Math.PI * 180.0, { x: 0, y: 1, z: 0 });
+            Entities.editEntity(_entityID, 
+                        {
+                            position: { x: x + Math.sin(time * omega) / 2.0 * range, 
+                                        y: y, 
+                                        z: z  },  
+                        }); 
+
+
+	        if(entityTickCount == (TIMER_HZ * 5)) {
+		        print("ENTITY -- For " + entityTickCount + " samples average interval = " + entityTotalTicks/entityTickCount + " ms" 
+                             + " average variance:" + entityTotalVariance/entityTickCount + " ms"
+                             + " min variance:" + entityVarianceCount + " [" + (entityVarianceCount/entityTickCount) * 100 + " %] "
+                             + " high variance:" + entityHighVarianceCount + " [" + (entityHighVarianceCount/entityTickCount) * 100 + " %] "
+                      );
+                entityTickCount = 0;
+                entityTotalTicks = 0;
+                entityTotalVariance = 0;
+                entityVarianceCount = 0;
+                entityHighVarianceCount = 0;
+	        }
+        }
+    }; 
+
+    return new Foo(); 
+});

scripts/system/controllers/handControllerGrab.js

@@ -816,7 +816,6 @@ function MyController(hand) {
     };
 
     this.update = function(deltaTime, timestamp) {
-
         this.updateSmoothedTrigger();
 
         //  If both trigger and grip buttons squeezed and nothing is held, rescale my avatar!
@@ -2141,7 +2140,6 @@ function MyController(hand) {
     };
 
     this.nearGrabbing = function(deltaTime, timestamp) {
-
         this.grabPointSphereOff();
 
         if (this.state == STATE_NEAR_GRABBING && (!this.triggerClicked && this.secondaryReleased())) {
@@ -3066,9 +3064,65 @@ var handleHandMessages = function(channel, message, sender) {
 
 Messages.messageReceived.connect(handleHandMessages);
 
-var BASIC_TIMER_INTERVAL_MS = 20; // 20ms = 50hz good enough
+var TARGET_UPDATE_HZ = 50; // 50hz good enough (no change in logic)
+var BASIC_TIMER_INTERVAL_MS = 1000 / TARGET_UPDATE_HZ; 
+var lastInterval = Date.now();
+
+var intervalCount = 0;
+var totalDelta = 0;
+var totalVariance = 0;
+var highVarianceCount = 0;
+var veryhighVarianceCount = 0;
+var updateTotalWork = 0;
+
+var UPDATE_PERFORMANCE_DEBUGGING = false;
+    
 var updateIntervalTimer = Script.setInterval(function(){
-    update(BASIC_TIMER_INTERVAL_MS / 1000);
+
+    intervalCount++;
+    var thisInterval = Date.now();
+    var deltaTimeMsec = thisInterval - lastInterval;
+    var deltaTime = deltaTimeMsec / 1000;
+    lastInterval = thisInterval;
+
+    totalDelta += deltaTimeMsec;
+
+    var variance = Math.abs(deltaTimeMsec - BASIC_TIMER_INTERVAL_MS);
+    totalVariance += variance;
+
+    if (variance > 1) {
+        highVarianceCount++;
+    }
+
+    if (variance > 5) {
+        veryhighVarianceCount++;
+    }
+
+    // will call update for both hands
+    var preWork = Date.now();
+    update(deltaTime);
+    var postWork = Date.now();
+    var workDelta = postWork - preWork;
+    updateTotalWork += workDelta;
+
+    if (intervalCount == 100) {
+
+        if (UPDATE_PERFORMANCE_DEBUGGING) {
+    		print("handControllerGrab.js -- For " + intervalCount + " samples average= " + totalDelta/intervalCount + " ms" 
+                     + " average variance:" + totalVariance/intervalCount + " ms"
+                     + " high variance count:" + highVarianceCount + " [ " + (highVarianceCount/intervalCount) * 100 + "% ] "
+                     + " VERY high variance count:" + veryhighVarianceCount + " [ " + (veryhighVarianceCount/intervalCount) * 100 + "% ] "
+                     + " average work:" + updateTotalWork/intervalCount + " ms");
+        }
+
+        intervalCount = 0;
+        totalDelta = 0;
+        totalVariance = 0;
+        highVarianceCount = 0;
+        veryhighVarianceCount = 0;
+        updateTotalWork = 0;
+    }
+
 }, BASIC_TIMER_INTERVAL_MS);
 
 function cleanup() {