diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index 03b01e1b9c..6bcf1b1c01 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/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(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(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 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 toDelete; diff --git a/libraries/script-engine/src/ScriptEngine.h b/libraries/script-engine/src/ScriptEngine.h index 803aa7fa22..d9a1249b1c 100644 --- a/libraries/script-engine/src/ScriptEngine.h +++ b/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); diff --git a/scripts/developer/tests/testInterval.js b/scripts/developer/tests/testInterval.js new file mode 100644 index 0000000000..94a5fe1fa5 --- /dev/null +++ b/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); +}); 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 1f536b9567..513e70d18c 100644 --- a/scripts/system/controllers/handControllerGrab.js +++ b/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() {