make sure RPC is timely

libraries/entities/src/EntityScriptingInterface.cpp

@@ -526,8 +526,6 @@ void EntityScriptingInterface::setEntitiesScriptEngine(EntitiesScriptEngineProvi
 }
 
 void EntityScriptingInterface::callEntityMethod(QUuid id, const QString& method, const QStringList& params) {
-    qDebug() << __FUNCTION__ << "method:" << method << "now:" << usecTimestampNow();
-
     std::lock_guard<std::recursive_mutex> lock(_entitiesScriptEngineLock);
     if (_entitiesScriptEngine) {
         EntityItemID entityID{ id };

libraries/script-engine/src/ScriptEngine.cpp

@@ -573,7 +573,6 @@ void ScriptEngine::registerValue(const QString& valueName, QScriptValue value) {
         QMetaObject::invokeMethod(this, "registerValue",
                                   Q_ARG(const QString&, valueName),
                                   Q_ARG(QScriptValue, value));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 
@@ -604,7 +603,6 @@ void ScriptEngine::registerGlobalObject(const QString& name, QObject* object) {
         QMetaObject::invokeMethod(this, "registerGlobalObject",
                                   Q_ARG(const QString&, name),
                                   Q_ARG(QObject*, object));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -630,7 +628,6 @@ void ScriptEngine::registerFunction(const QString& name, QScriptEngine::Function
                                   Q_ARG(const QString&, name),
                                   Q_ARG(QScriptEngine::FunctionSignature, functionSignature),
                                   Q_ARG(int, numArguments));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -650,7 +647,6 @@ void ScriptEngine::registerFunction(const QString& parent, const QString& name,
                                   Q_ARG(const QString&, name),
                                   Q_ARG(QScriptEngine::FunctionSignature, functionSignature),
                                   Q_ARG(int, numArguments));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -676,7 +672,6 @@ void ScriptEngine::registerGetterSetter(const QString& name, QScriptEngine::Func
                                   Q_ARG(QScriptEngine::FunctionSignature, getter),
                                   Q_ARG(QScriptEngine::FunctionSignature, setter),
                                   Q_ARG(const QString&, parent));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -709,7 +704,6 @@ void ScriptEngine::removeEventHandler(const EntityItemID& entityID, const QStrin
                                   Q_ARG(const EntityItemID&, entityID),
                                   Q_ARG(const QString&, eventName),
                                   Q_ARG(QScriptValue, handler));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -741,7 +735,6 @@ void ScriptEngine::addEventHandler(const EntityItemID& entityID, const QString&
                                   Q_ARG(const EntityItemID&, entityID),
                                   Q_ARG(const QString&, eventName),
                                   Q_ARG(QScriptValue, handler));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -828,7 +821,6 @@ QScriptValue ScriptEngine::evaluate(const QString& sourceCode, const QString& fi
                                   Q_ARG(const QString&, sourceCode),
                                   Q_ARG(const QString&, fileName),
                                   Q_ARG(int, lineNumber));
-        _hasInvokeMethod.wakeAll();
         return result;
     }
 
@@ -916,38 +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);
-            auto untilThisSleepUntil = std::chrono::duration_cast<std::chrono::microseconds>(thisSleepUntil - clock::now());
-
-            // if the sleep until is more than 1 ms away, then don't sleep, and instead use a wait condition 
-            // for any possible invoke methods that might also be pending.
-            const std::chrono::microseconds MAX_USECS_TO_SLEEP(USECS_PER_MSEC);
-            if (untilThisSleepUntil < MAX_USECS_TO_SLEEP) {
-                qDebug() << "[" << getFilename() << "]" << "about to sleep untilThisSleepUntil:" << untilThisSleepUntil.count() << "usec -- averageTimerPerFrame:" << averageTimerPerFrame.count();
-                std::this_thread::sleep_until(thisSleepUntil);
-            } else {
-                // FIXME - we might want to make this 1 less ms to wait
-                unsigned long maxWait = untilThisSleepUntil.count() / USECS_PER_MSEC;
-                qDebug() << "[" << getFilename() << "]" << "about to wait:" << maxWait << "ms --- untilThisSleepUntil:" << untilThisSleepUntil.count() << "usec -- averageTimerPerFrame:" << averageTimerPerFrame.count();
-                _waitingOnInvokeMethod.lock();
-                bool signalled = _hasInvokeMethod.wait(&_waitingOnInvokeMethod, maxWait);
-                _waitingOnInvokeMethod.unlock();
-                if (signalled) {
-                    qDebug() << "[" << getFilename() << "]" << "SIGNALLED!! done waiting... now:" << usecTimestampNow();
-                }
-
-            }
+            // 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
@@ -1037,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() {
@@ -1062,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;
@@ -1085,7 +1036,6 @@ void ScriptEngine::stop(bool marshal) {
 
     if (marshal) {
         QMetaObject::invokeMethod(this, "stop");
-        _hasInvokeMethod.wakeAll();
         return;
     }
     if (!_isFinished) {
@@ -1106,7 +1056,6 @@ void ScriptEngine::callAnimationStateHandler(QScriptValue callback, AnimVariantM
                                   Q_ARG(QStringList, names),
                                   Q_ARG(bool, useNames),
                                   Q_ARG(AnimVariantResultHandler, resultHandler));
-        _hasInvokeMethod.wakeAll();
         return;
     }
     QScriptValue javascriptParameters = parameters.animVariantMapToScriptValue(this, names, useNames);
@@ -1457,7 +1406,6 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co
                                   Q_ARG(const QString&, contents),
                                   Q_ARG(bool, isURL),
                                   Q_ARG(bool, success));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 
@@ -1556,7 +1504,6 @@ void ScriptEngine::unloadEntityScript(const EntityItemID& entityID) {
 
         QMetaObject::invokeMethod(this, "unloadEntityScript",
                                   Q_ARG(const EntityItemID&, entityID));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -1578,7 +1525,6 @@ void ScriptEngine::unloadAllEntityScripts() {
 #endif
 
         QMetaObject::invokeMethod(this, "unloadAllEntityScripts");
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -1665,21 +1611,16 @@ void ScriptEngine::callWithEnvironment(const EntityItemID& entityID, const QUrl&
 }
 
 void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QString& methodName, const QStringList& params) {
-    qDebug() << "[" << getFilename() << "]" << __FUNCTION__ << "method:" << methodName << "now:" << usecTimestampNow();
-
     if (QThread::currentThread() != thread()) {
 #ifdef THREAD_DEBUGGING
         qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::callEntityScriptMethod() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "]  "
             "entityID:" << entityID << "methodName:" << methodName;
 #endif
 
-        qDebug() << "[" << getFilename() << "]" << "about to invokeMethod callEntityScriptMethod() now:" << usecTimestampNow();
-
         QMetaObject::invokeMethod(this, "callEntityScriptMethod",
                                   Q_ARG(const EntityItemID&, entityID),
                                   Q_ARG(const QString&, methodName),
                                   Q_ARG(const QStringList&, params));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -1695,8 +1636,6 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS
             QScriptValueList args;
             args << entityID.toScriptValue(this);
             args << qScriptValueFromSequence(this, params);
-
-            qDebug() << "[" << getFilename() << "]" << __FUNCTION__ << "about to callWithEnvironment()... method:" << methodName << "now:" << usecTimestampNow();
             callWithEnvironment(entityID, details.definingSandboxURL, entityScript.property(methodName), entityScript, args);
         }
 
@@ -1714,7 +1653,6 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS
                                   Q_ARG(const EntityItemID&, entityID),
                                   Q_ARG(const QString&, methodName),
                                   Q_ARG(const PointerEvent&, event));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING
@@ -1748,7 +1686,6 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS
                                   Q_ARG(const QString&, methodName),
                                   Q_ARG(const EntityItemID&, otherID),
                                   Q_ARG(const Collision&, collision));
-        _hasInvokeMethod.wakeAll();
         return;
     }
 #ifdef THREAD_DEBUGGING

libraries/script-engine/src/ScriptEngine.h

@@ -217,9 +217,6 @@ protected:
 
     void init();
 
-    QWaitCondition _hasInvokeMethod;
-    QMutex _waitingOnInvokeMethod;
-
     bool evaluatePending() const { return _evaluatesPending > 0; }
     quint64 getTimersRemainingTime();
     void timerFired();

scripts/developer/tests/testInterval.js

@@ -0,0 +1,253 @@
+
+// Tester, try testing these different settings.
+//
+//  +-----------------+---------------------+----------------------+------------------------------------------------------------------------------------------------------------------
+//  | TIMER_INTERVAL  |  TIMER_WORK_EFFORT  |  UPDATE_WORK_EFFORT  |  Expected result                                   
+//  +-----------------+---------------------+----------------------+------------------------------------------------------------------------------------------------------------------
+//  | 20              |  < 1000             |  < 1000              |  timer 20ms/work 0ms, update 16.6ms/work 0ms       
+//  | 5               |  < 1000             |  < 1000              |  timer 5ms/work 0ms, update 16.6ms/work 0ms        
+//  | 11              |  < 1000             |  < 1000              |  timer 11ms/work 0ms, update 16.6ms/work 0ms       
+//  | 11              |  ~100000            |  < 1000              |  timer 11ms/work 3ms, update 16.6ms/work 0ms       
+//  | 11              |  ~500000            |  < 1000              |  timer 17.3ms/work 16.4ms, update 17.4ms/work 0ms, punishing the script, timer & update delayed 
+//  | 40              |  ~1000000           |  < 1000              |  timer 40ms/work 32ms, update 31ms/work 0ms, punishing the script, update delayed, timer on time
+//  | 10              |  ~1000              |  ~1000000            |  timer 16ms/work 0ms, update 63ms/work 33ms, punishing the script, update delayed, timer slightly delayed
+//  | 10              |  ~1000000           |  ~1000000            |  timer 90ms/work 33ms, update ~100-120ms/work 33ms, punishing the script, timer & update delayed 
+//  +-----------------+---------------------+----------------------+------------------------------------------------------------------------------------------------------------------
+
+var TIMER_HZ = 50;
+var TIMER_INTERVAL = 1000 / TIMER_HZ;
+var TIMER_WORK_EFFORT = 0; // 1000 is light work, 1000000 ~= 30ms
+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 UPDATE_HZ = 60; // standard script update interval
+var UPDATE_INTERVAL = 1000/UPDATE_HZ; // standard script update interval
+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,8 +816,6 @@ function MyController(hand) {
     };
 
     this.update = function(deltaTime, timestamp) {
-        print("this.update() deltaTime:" + deltaTime + " timestamp:" + timestamp + " now:" + Date.now());
-
         this.updateSmoothedTrigger();
 
         //  If both trigger and grip buttons squeezed and nothing is held, rescale my avatar!
@@ -845,7 +843,6 @@ function MyController(hand) {
 
     this.callEntityMethodOnGrabbed = function(entityMethodName) {
         var args = [this.hand === RIGHT_HAND ? "right" : "left", MyAvatar.sessionUUID];
-        print("this.callEntityMethodOnGrabbed() entityMethodName:" + entityMethodName + " now:" + Date.now());
         Entities.callEntityMethod(this.grabbedEntity, entityMethodName, args);
     };
 
@@ -2143,8 +2140,6 @@ function MyController(hand) {
     };
 
     this.nearGrabbing = function(deltaTime, timestamp) {
-        print("nearGrabbing() deltaTime:" + deltaTime + " now:" + Date.now());
-
         this.grabPointSphereOff();
 
         if (this.state == STATE_NEAR_GRABBING && (!this.triggerClicked && this.secondaryReleased())) {
@@ -3069,16 +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(){
+
+    intervalCount++;
     var thisInterval = Date.now();
     var deltaTimeMsec = thisInterval - lastInterval;
     var deltaTime = deltaTimeMsec / 1000;
     lastInterval = thisInterval;
 
-    print("setInterval function() deltaTimeMsec:" + deltaTimeMsec + " deltaTime:" + deltaTime + "(sec) now:" + Date.now());
+    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() {