From 82ab8635d715165fef53342834b1a77b44ab541c Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Fri, 30 Dec 2016 12:02:48 -0800 Subject: [PATCH] debugging --- .../entities/src/EntityScriptingInterface.cpp | 2 ++ libraries/script-engine/src/ScriptEngine.cpp | 17 +++++++++++------ .../system/controllers/handControllerGrab.js | 13 +++++++++++-- 3 files changed, 24 insertions(+), 8 deletions(-) diff --git a/libraries/entities/src/EntityScriptingInterface.cpp b/libraries/entities/src/EntityScriptingInterface.cpp index 498e0959c6..55f640022a 100644 --- a/libraries/entities/src/EntityScriptingInterface.cpp +++ b/libraries/entities/src/EntityScriptingInterface.cpp @@ -526,6 +526,8 @@ 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 02f2efd063..61b6b3c13b 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -928,22 +928,23 @@ void ScriptEngine::run() { 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 (closestUntil < MAX_USECS_TO_SLEEP) { - qDebug() << "about to sleep:" << closestUntil.count() << "usec"; + 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 = closestUntil.count() / USECS_PER_MSEC; - qDebug() << "about to wait:" << maxWait << "ms --- closestUntil:" << closestUntil.count() << "usec"; + 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() << "SIGNALLED!! done waiting... now:" << usecTimestampNow(); + qDebug() << "[" << getFilename() << "]" << "SIGNALLED!! done waiting... now:" << usecTimestampNow(); } } @@ -1664,13 +1665,15 @@ 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() << "about to invokeMethod callEntityScriptMethod() now:" << usecTimestampNow(); + qDebug() << "[" << getFilename() << "]" << "about to invokeMethod callEntityScriptMethod() now:" << usecTimestampNow(); QMetaObject::invokeMethod(this, "callEntityScriptMethod", Q_ARG(const EntityItemID&, entityID), @@ -1692,6 +1695,8 @@ 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); } diff --git a/scripts/system/controllers/handControllerGrab.js b/scripts/system/controllers/handControllerGrab.js index 23a98ccc1a..84e3acf430 100644 --- a/scripts/system/controllers/handControllerGrab.js +++ b/scripts/system/controllers/handControllerGrab.js @@ -816,6 +816,7 @@ function MyController(hand) { }; this.update = function(deltaTime, timestamp) { + print("this.update() deltaTime:" + deltaTime + " timestamp:" + timestamp + " now:" + Date.now()); this.updateSmoothedTrigger(); @@ -844,6 +845,7 @@ 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); }; @@ -2141,7 +2143,7 @@ function MyController(hand) { }; this.nearGrabbing = function(deltaTime, timestamp) { - print("nearGrabbing() deltaTime:" + deltaTime); + print("nearGrabbing() deltaTime:" + deltaTime + " now:" + Date.now()); this.grabPointSphereOff(); @@ -3068,8 +3070,15 @@ var handleHandMessages = function(channel, message, sender) { Messages.messageReceived.connect(handleHandMessages); var BASIC_TIMER_INTERVAL_MS = 20; // 20ms = 50hz good enough +var lastInterval = Date.now(); var updateIntervalTimer = Script.setInterval(function(){ - update(BASIC_TIMER_INTERVAL_MS / 1000); + 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()); + update(deltaTime); }, BASIC_TIMER_INTERVAL_MS); function cleanup() {