From d440532cff46d4f5d2ffda360b90ca375adf223a Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Tue, 3 Jan 2017 11:10:07 -0800 Subject: [PATCH] make sure RPC is timely --- .../entities/src/EntityScriptingInterface.cpp | 2 - libraries/script-engine/src/ScriptEngine.cpp | 75 +----- libraries/script-engine/src/ScriptEngine.h | 3 - scripts/developer/tests/testInterval.js | 253 ++++++++++++++++++ .../tests/testIntervalRpcFunction.js | 77 ++++++ .../system/controllers/handControllerGrab.js | 58 +++- 6 files changed, 387 insertions(+), 81 deletions(-) create mode 100644 scripts/developer/tests/testInterval.js create mode 100644 scripts/developer/tests/testIntervalRpcFunction.js diff --git a/libraries/entities/src/EntityScriptingInterface.cpp b/libraries/entities/src/EntityScriptingInterface.cpp index 55f640022a..498e0959c6 100644 --- a/libraries/entities/src/EntityScriptingInterface.cpp +++ b/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 lock(_entitiesScriptEngineLock); if (_entitiesScriptEngine) { EntityItemID entityID{ id }; diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index 61b6b3c13b..6bcf1b1c01 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/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(sleepUntil - clock::now()); - auto closestUntil = std::min(remainingSleepUntil, untilTimer); - auto thisSleepUntil = std::min(sleepUntil, clock::now() + closestUntil); - auto untilThisSleepUntil = std::chrono::duration_cast(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(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 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 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 diff --git a/libraries/script-engine/src/ScriptEngine.h b/libraries/script-engine/src/ScriptEngine.h index 8e6184f62f..803aa7fa22 100644 --- a/libraries/script-engine/src/ScriptEngine.h +++ b/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(); diff --git a/scripts/developer/tests/testInterval.js b/scripts/developer/tests/testInterval.js new file mode 100644 index 0000000000..0b6b70686b --- /dev/null +++ b/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); +}); diff --git a/scripts/developer/tests/testIntervalRpcFunction.js b/scripts/developer/tests/testIntervalRpcFunction.js new file mode 100644 index 0000000000..86caef3f61 --- /dev/null +++ b/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(); +}); diff --git a/scripts/system/controllers/handControllerGrab.js b/scripts/system/controllers/handControllerGrab.js index 84e3acf430..513e70d18c 100644 --- a/scripts/system/controllers/handControllerGrab.js +++ b/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() {