History

Merge branch 'master' into tablet-ui

Anthony J. Thibault committed 9 years ago

Commit 00980362 parents 6729421 45c71fd173 files · +5924 −1762Browse files

Showing the changes to libraries/script-engine/src/ScriptEngine.cpp (1 of 173 files). Show all

Unified · Split

libraries/script-engine/src/ScriptEngine.cpp+160−86
@@ -71,6 +71,8 @@ static const QString SCRIPT_EXCEPTION_FORMAT = "[UncaughtException] %1 in %2:%3" · 70 unmodified lines
7171 Q_DECLARE_METATYPE(QScriptEngine::FunctionSignature)
7272 int functionSignatureMetaID = qRegisterMetaType<QScriptEngine::FunctionSignature>();
7373
74+Q_LOGGING_CATEGORY(scriptengineScript, "hifi.scriptengine.script")
75+
7476 static QScriptValue debugPrint(QScriptContext* context, QScriptEngine* engine){
7577 QString message = "";
7678 for (int i = 0; i < context->argumentCount(); i++) {
@@ -79,12 +81,14 @@ static QScriptValue debugPrint(QScriptContext* context, QScriptEngine* engine){ · 2 unmodified lines
7981 }
8082 message += context->argument(i).toString();
8183 }
82− qCDebug(scriptengine).noquote() << "script:print()<<" << message; // noquote() so that \n is treated as newline
84+ qCDebug(scriptengineScript).noquote() << "script:print()<<" << message; // noquote() so that \n is treated as newline
8385
8486 message = message.replace("\\", "\\\\")
8587 .replace("\n", "\\n")
8688 .replace("\r", "\\r")
8789 .replace("'", "\\'");
90+
91+ // FIXME - this approach neeeds revisiting. print() comes here, which ends up doing an evaluate?
8892 engine->evaluate("Script.print('" + message + "')");
8993
9094 return QScriptValue();
@@ -129,20 +133,20 @@ QString encodeEntityIdIntoEntityUrl(const QString& url, const QString& entityID) · 38 unmodified lines
129133 return url + " [EntityID:" + entityID + "]";
130134 }
131135
132−static bool hasCorrectSyntax(const QScriptProgram& program) {
136+static bool hasCorrectSyntax(const QScriptProgram& program, ScriptEngine* reportingEngine) {
133137 const auto syntaxCheck = QScriptEngine::checkSyntax(program.sourceCode());
134138 if (syntaxCheck.state() != QScriptSyntaxCheckResult::Valid) {
135139 const auto error = syntaxCheck.errorMessage();
136140 const auto line = QString::number(syntaxCheck.errorLineNumber());
137141 const auto column = QString::number(syntaxCheck.errorColumnNumber());
138142 const auto message = QString("[SyntaxError] %1 in %2:%3(%4)").arg(error, program.fileName(), line, column);
139− qCWarning(scriptengine) << qPrintable(message);
143+ reportingEngine->scriptErrorMessage(qPrintable(message));
140144 return false;
141145 }
142146 return true;
143147 }
144148
145−static bool hadUncaughtExceptions(QScriptEngine& engine, const QString& fileName) {
149+static bool hadUncaughtExceptions(QScriptEngine& engine, const QString& fileName, ScriptEngine* reportingEngine) {
146150 if (engine.hasUncaughtException()) {
147151 const auto backtrace = engine.uncaughtExceptionBacktrace();
148152 const auto exception = engine.uncaughtException().toString();
@@ -154,7 +158,7 @@ static bool hadUncaughtExceptions(QScriptEngine& engine, const QString& fileName · 5 unmodified lines
154158 static const auto lineSeparator = "\n ";
155159 message += QString("\n[Backtrace]%1%2").arg(lineSeparator, backtrace.join(lineSeparator));
156160 }
157− qCWarning(scriptengine) << qPrintable(message);
161+ reportingEngine->scriptErrorMessage(qPrintable(message));
158162 return true;
159163 }
160164 return false;
@@ -169,20 +173,20 @@ ScriptEngine::ScriptEngine(const QString& scriptContents, const QString& fileNam · 8 unmodified lines
169173 DependencyManager::get<ScriptEngines>()->addScriptEngine(this);
170174
171175 connect(this, &QScriptEngine::signalHandlerException, this, [this](const QScriptValue& exception) {
172− hadUncaughtExceptions(*this, _fileNameString);
176+ hadUncaughtExceptions(*this, _fileNameString, this);
173177 });
174178
175179 setProcessEventsInterval(MSECS_PER_SECOND);
176180 }
177181
178182 ScriptEngine::~ScriptEngine() {
179− qCDebug(scriptengine) << "Script Engine shutting down:" << getFilename();
183+ scriptInfoMessage("Script Engine shutting down:" + getFilename());
180184
181185 auto scriptEngines = DependencyManager::get<ScriptEngines>();
182186 if (scriptEngines) {
183187 scriptEngines->removeScriptEngine(this);
184188 } else {
185− qCWarning(scriptengine) << "Script destroyed after ScriptEngines!";
189+ scriptWarningMessage("Script destroyed after ScriptEngines!");
186190 }
187191 }
188192
@@ -273,7 +277,7 @@ void ScriptEngine::runDebuggable() { · 84 unmodified lines
273277 }
274278 _lastUpdate = now;
275279 // Debug and clear exceptions
276− hadUncaughtExceptions(*this, _fileNameString);
280+ hadUncaughtExceptions(*this, _fileNameString, this);
277281 });
278282
279283 timer->start(10);
@@ -358,7 +362,7 @@ void ScriptEngine::waitTillDoneRunning() { · 78 unmodified lines
358362 QThread::yieldCurrentThread();
359363 }
360364
361− qCDebug(scriptengine) << "Script Engine has stopped:" << getFilename();
365+ scriptInfoMessage("Script Engine has stopped:" + getFilename());
362366 }
363367 }
364368
@@ -397,10 +401,25 @@ void ScriptEngine::scriptContentsAvailable(const QUrl& url, const QString& scrip · 32 unmodified lines
397401 emit scriptLoaded(url.toString());
398402 }
399403
404+void ScriptEngine::scriptErrorMessage(const QString& message) {
405+ qCCritical(scriptengine) << message;
406+ emit errorMessage(message);
407+}
408+
409+void ScriptEngine::scriptWarningMessage(const QString& message) {
410+ qCWarning(scriptengine) << message;
411+ emit warningMessage(message);
412+}
413+
414+void ScriptEngine::scriptInfoMessage(const QString& message) {
415+ qCInfo(scriptengine) << message;
416+ emit infoMessage(message);
417+}
418+
400419 // FIXME - switch this to the new model of ScriptCache callbacks
401420 void ScriptEngine::errorInLoadingScript(const QUrl& url) {
402− qCDebug(scriptengine) << "ERROR Loading file:" << url.toString() << "line:" << __LINE__;
403− emit errorLoadingScript(_fileNameString); // ??
421+ scriptErrorMessage("ERROR Loading file:" + url.toString());
422+ emit errorLoadingScript(_fileNameString);
404423 }
405424
406425 // Even though we never pass AnimVariantMap directly to and from javascript, the queued invokeMethod of
@@ -552,7 +571,7 @@ void ScriptEngine::init() { · 145 unmodified lines
552571 void ScriptEngine::registerValue(const QString& valueName, QScriptValue value) {
553572 if (QThread::currentThread() != thread()) {
554573 #ifdef THREAD_DEBUGGING
555− qDebug() << "*** WARNING *** ScriptEngine::registerValue() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "]";
574+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::registerValue() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "]";
556575 #endif
557576 QMetaObject::invokeMethod(this, "registerValue",
558577 Q_ARG(const QString&, valueName),
@@ -582,7 +601,7 @@ void ScriptEngine::registerValue(const QString& valueName, QScriptValue value) { · 23 unmodified lines
582601 void ScriptEngine::registerGlobalObject(const QString& name, QObject* object) {
583602 if (QThread::currentThread() != thread()) {
584603 #ifdef THREAD_DEBUGGING
585− qDebug() << "*** WARNING *** ScriptEngine::registerGlobalObject() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] name:" << name;
604+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::registerGlobalObject() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] name:" << name;
586605 #endif
587606 QMetaObject::invokeMethod(this, "registerGlobalObject",
588607 Q_ARG(const QString&, name),
@@ -590,7 +609,7 @@ void ScriptEngine::registerGlobalObject(const QString& name, QObject* object) { · 1 unmodified line
590609 return;
591610 }
592611 #ifdef THREAD_DEBUGGING
593− qDebug() << "ScriptEngine::registerGlobalObject() called on thread [" << QThread::currentThread() << "] name:" << name;
612+ qCDebug(scriptengine) << "ScriptEngine::registerGlobalObject() called on thread [" << QThread::currentThread() << "] name:" << name;
594613 #endif
595614
596615 if (!globalObject().property(name).isValid()) {
@@ -606,7 +625,7 @@ void ScriptEngine::registerGlobalObject(const QString& name, QObject* object) { · 9 unmodified lines
606625 void ScriptEngine::registerFunction(const QString& name, QScriptEngine::FunctionSignature functionSignature, int numArguments) {
607626 if (QThread::currentThread() != thread()) {
608627 #ifdef THREAD_DEBUGGING
609− qDebug() << "*** WARNING *** ScriptEngine::registerFunction() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] name:" << name;
628+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::registerFunction() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] name:" << name;
610629 #endif
611630 QMetaObject::invokeMethod(this, "registerFunction",
612631 Q_ARG(const QString&, name),
@@ -615,7 +634,7 @@ void ScriptEngine::registerFunction(const QString& name, QScriptEngine::Function · 2 unmodified lines
615634 return;
616635 }
617636 #ifdef THREAD_DEBUGGING
618− qDebug() << "ScriptEngine::registerFunction() called on thread [" << QThread::currentThread() << "] name:" << name;
637+ qCDebug(scriptengine) << "ScriptEngine::registerFunction() called on thread [" << QThread::currentThread() << "] name:" << name;
619638 #endif
620639
621640 QScriptValue scriptFun = newFunction(functionSignature, numArguments);
@@ -625,7 +644,7 @@ void ScriptEngine::registerFunction(const QString& name, QScriptEngine::Function · 3 unmodified lines
625644 void ScriptEngine::registerFunction(const QString& parent, const QString& name, QScriptEngine::FunctionSignature functionSignature, int numArguments) {
626645 if (QThread::currentThread() != thread()) {
627646 #ifdef THREAD_DEBUGGING
628− qDebug() << "*** WARNING *** ScriptEngine::registerFunction() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] parent:" << parent << "name:" << name;
647+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::registerFunction() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] parent:" << parent << "name:" << name;
629648 #endif
630649 QMetaObject::invokeMethod(this, "registerFunction",
631650 Q_ARG(const QString&, name),
@@ -634,7 +653,7 @@ void ScriptEngine::registerFunction(const QString& parent, const QString& name, · 2 unmodified lines
634653 return;
635654 }
636655 #ifdef THREAD_DEBUGGING
637− qDebug() << "ScriptEngine::registerFunction() called on thread [" << QThread::currentThread() << "] parent:" << parent << "name:" << name;
656+ qCDebug(scriptengine) << "ScriptEngine::registerFunction() called on thread [" << QThread::currentThread() << "] parent:" << parent << "name:" << name;
638657 #endif
639658
640659 QScriptValue object = globalObject().property(parent);
@@ -648,7 +667,7 @@ void ScriptEngine::registerGetterSetter(const QString& name, QScriptEngine::Func · 7 unmodified lines
648667 QScriptEngine::FunctionSignature setter, const QString& parent) {
649668 if (QThread::currentThread() != thread()) {
650669 #ifdef THREAD_DEBUGGING
651− qDebug() << "*** WARNING *** ScriptEngine::registerGetterSetter() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
670+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::registerGetterSetter() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
652671 " name:" << name << "parent:" << parent;
653672 #endif
654673 QMetaObject::invokeMethod(this, "registerGetterSetter",
@@ -659,7 +678,7 @@ void ScriptEngine::registerGetterSetter(const QString& name, QScriptEngine::Func · 4 unmodified lines
659678 return;
660679 }
661680 #ifdef THREAD_DEBUGGING
662− qDebug() << "ScriptEngine::registerGetterSetter() called on thread [" << QThread::currentThread() << "] name:" << name << "parent:" << parent;
681+ qCDebug(scriptengine) << "ScriptEngine::registerGetterSetter() called on thread [" << QThread::currentThread() << "] name:" << name << "parent:" << parent;
663682 #endif
664683
665684 QScriptValue setterFunction = newFunction(setter, 1);
@@ -681,7 +700,7 @@ void ScriptEngine::registerGetterSetter(const QString& name, QScriptEngine::Func · 15 unmodified lines
681700 void ScriptEngine::removeEventHandler(const EntityItemID& entityID, const QString& eventName, QScriptValue handler) {
682701 if (QThread::currentThread() != thread()) {
683702 #ifdef THREAD_DEBUGGING
684− qDebug() << "*** WARNING *** ScriptEngine::removeEventHandler() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
703+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::removeEventHandler() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
685704 "entityID:" << entityID << " eventName:" << eventName;
686705 #endif
687706 QMetaObject::invokeMethod(this, "removeEventHandler",
@@ -691,7 +710,7 @@ void ScriptEngine::removeEventHandler(const EntityItemID& entityID, const QStrin · 3 unmodified lines
691710 return;
692711 }
693712 #ifdef THREAD_DEBUGGING
694− qDebug() << "ScriptEngine::removeEventHandler() called on thread [" << QThread::currentThread() << "] entityID:" << entityID << " eventName : " << eventName;
713+ qCDebug(scriptengine) << "ScriptEngine::removeEventHandler() called on thread [" << QThread::currentThread() << "] entityID:" << entityID << " eventName : " << eventName;
695714 #endif
696715
697716 if (!_registeredHandlers.contains(entityID)) {
@@ -711,7 +730,7 @@ void ScriptEngine::removeEventHandler(const EntityItemID& entityID, const QStrin · 13 unmodified lines
711730 void ScriptEngine::addEventHandler(const EntityItemID& entityID, const QString& eventName, QScriptValue handler) {
712731 if (QThread::currentThread() != thread()) {
713732 #ifdef THREAD_DEBUGGING
714− qDebug() << "*** WARNING *** ScriptEngine::addEventHandler() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
733+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::addEventHandler() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
715734 "entityID:" << entityID << " eventName:" << eventName;
716735 #endif
717736
@@ -722,7 +741,7 @@ void ScriptEngine::addEventHandler(const EntityItemID& entityID, const QString& · 4 unmodified lines
722741 return;
723742 }
724743 #ifdef THREAD_DEBUGGING
725− qDebug() << "ScriptEngine::addEventHandler() called on thread [" << QThread::currentThread() << "] entityID:" << entityID << " eventName : " << eventName;
744+ qCDebug(scriptengine) << "ScriptEngine::addEventHandler() called on thread [" << QThread::currentThread() << "] entityID:" << entityID << " eventName : " << eventName;
726745 #endif
727746
728747 if (_registeredHandlers.count() == 0) { // First time any per-entity handler has been added in this script...
@@ -784,7 +803,7 @@ void ScriptEngine::addEventHandler(const EntityItemID& entityID, const QString& · 55 unmodified lines
784803 _registeredHandlers[entityID] = RegisteredEventHandlers();
785804 }
786805 CallbackList& handlersForEvent = _registeredHandlers[entityID][eventName];
787− CallbackData handlerData = {handler, currentEntityIdentifier, currentSandboxURL};
806+ CallbackData handlerData = { handler, currentEntityIdentifier, currentSandboxURL };
788807 handlersForEvent << handlerData; // Note that the same handler can be added many times. See removeEntityEventHandler().
789808 }
790809
@@ -797,7 +816,7 @@ QScriptValue ScriptEngine::evaluate(const QString& sourceCode, const QString& fi · 6 unmodified lines
797816 if (QThread::currentThread() != thread()) {
798817 QScriptValue result;
799818 #ifdef THREAD_DEBUGGING
800− qDebug() << "*** WARNING *** ScriptEngine::evaluate() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
819+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::evaluate() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
801820 "sourceCode:" << sourceCode << " fileName:" << fileName << "lineNumber:" << lineNumber;
802821 #endif
803822 QMetaObject::invokeMethod(this, "evaluate", Qt::BlockingQueuedConnection,
@@ -810,7 +829,7 @@ QScriptValue ScriptEngine::evaluate(const QString& sourceCode, const QString& fi · 6 unmodified lines
810829
811830 // Check syntax
812831 const QScriptProgram program(sourceCode, fileName, lineNumber);
813− if (!hasCorrectSyntax(program)) {
832+ if (!hasCorrectSyntax(program, this)) {
814833 return QScriptValue();
815834 }
816835
@@ -818,7 +837,7 @@ QScriptValue ScriptEngine::evaluate(const QString& sourceCode, const QString& fi · 1 unmodified line
818837 const auto result = QScriptEngine::evaluate(program);
819838 --_evaluatesPending;
820839
821− const auto hadUncaughtException = hadUncaughtExceptions(*this, program.fileName());
840+ const auto hadUncaughtException = hadUncaughtExceptions(*this, program.fileName(), this);
822841 emit evaluationFinished(result, hadUncaughtException);
823842 return result;
824843 }
@@ -862,23 +881,48 @@ void ScriptEngine::run() { · 37 unmodified lines
862881 // Throttle to SCRIPT_FPS
863882 // We'd like to try to keep the script at a solid SCRIPT_FPS update rate. And so we will
864883 // calculate a sleepUntil to be the time from our start time until the original target
865− // sleepUntil for this frame.
866− const std::chrono::microseconds FRAME_DURATION(USECS_PER_SECOND / SCRIPT_FPS + 1);
867− clock::time_point targetSleepUntil(startTime + thisFrame++ * FRAME_DURATION);
868−
869− // However, if our sleepUntil is not at least our average update time into the future
870− // it means our script is taking too long in it's updates, and we want to punish the
871− // script a little bit. So we will force the sleepUntil to be at least our averageUpdate
872− // time into the future.
884+ // sleepUntil for this frame. This approach will allow us to "catch up" in the event
885+ // that some of our script udpates/frames take a little bit longer than the target average
886+ // to execute.
887+ // NOTE: if we go to variable SCRIPT_FPS, then we will need to reconsider this approach
888+ const std::chrono::microseconds TARGET_SCRIPT_FRAME_DURATION(USECS_PER_SECOND / SCRIPT_FPS + 1);
889+ clock::time_point targetSleepUntil(startTime + (thisFrame++ * TARGET_SCRIPT_FRAME_DURATION));
890+
891+ // However, if our sleepUntil is not at least our average update and timer execution time
892+ // into the future it means our script is taking too long in its updates, and we want to
893+ // punish the script a little bit. So we will force the sleepUntil to be at least our
894+ // averageUpdate + averageTimerPerFrame time into the future.
873895 auto averageUpdate = totalUpdates / thisFrame;
874− auto sleepUntil = std::max(targetSleepUntil, beforeSleep + averageUpdate);
896+ auto averageTimerPerFrame = _totalTimerExecution / thisFrame;
897+ auto averageTimerAndUpdate = averageUpdate + averageTimerPerFrame;
898+ auto sleepUntil = std::max(targetSleepUntil, beforeSleep + averageTimerAndUpdate);
875899
876900 // We don't want to actually sleep for too long, because it causes our scripts to hang
877901 // on shutdown and stop... so we want to loop and sleep until we've spent our time in
878902 // purgatory, constantly checking to see if our script was asked to end
903+ bool processedEvents = false;
879904 while (!_isFinished && clock::now() < sleepUntil) {
905+
880906 QCoreApplication::processEvents(); // before we sleep again, give events a chance to process
881− auto thisSleepUntil = std::min(sleepUntil, clock::now() + FRAME_DURATION);
907+ processedEvents = true;
908+
909+ // If after processing events, we're past due, exit asap
910+ if (clock::now() >= sleepUntil) {
911+ break;
912+ }
913+
914+ // determine how long before the next timer should fire, we'd ideally like to sleep just
915+ // that long, so the next processEvents() will allow the timers to fire on time.
916+ const std::chrono::microseconds minTimerTimeRemaining(USECS_PER_MSEC * getTimersRemainingTime());
917+
918+ // However, if we haven't yet slept at least as long as our average timer per frame, then we will
919+ // punish the timers to at least wait as long as the average run time of the timers.
920+ auto untilTimer = std::max(minTimerTimeRemaining, averageTimerPerFrame);
921+
922+ // choose the closest time point, our
923+ auto remainingSleepUntil = std::chrono::duration_cast<std::chrono::microseconds>(sleepUntil - clock::now());
924+ auto closestUntil = std::min(remainingSleepUntil, untilTimer);
925+ auto thisSleepUntil = std::min(sleepUntil, clock::now() + closestUntil);
882926 std::this_thread::sleep_until(thisSleepUntil);
883927 }
884928
@@ -903,7 +947,10 @@ void ScriptEngine::run() { · 18 unmodified lines
903947 break;
904948 }
905949
906− QCoreApplication::processEvents();
950+ // Only call this if we didn't processEvents as part of waiting for next frame
951+ if (!processedEvents) {
952+ QCoreApplication::processEvents();
953+ }
907954
908955 if (_isFinished) {
909956 break;
@@ -935,10 +982,10 @@ void ScriptEngine::run() { · 25 unmodified lines
935982 _lastUpdate = now;
936983
937984 // Debug and clear exceptions
938− hadUncaughtExceptions(*this, _fileNameString);
985+ hadUncaughtExceptions(*this, _fileNameString, this);
939986 }
940987
941− qCDebug(scriptengine) << "Script Engine stopping:" << getFilename();
988+ scriptInfoMessage("Script Engine stopping:" + getFilename());
942989
943990 stopAllTimers(); // make sure all our timers are stopped if the script is ending
944991 emit scriptEnding();
@@ -966,6 +1013,21 @@ void ScriptEngine::run() { · 21 unmodified lines
9661013 emit doneRunning();
9671014 }
9681015
1016+quint64 ScriptEngine::getTimersRemainingTime() {
1017+ quint64 minimumTime = USECS_PER_SECOND; // anything larger than this can be ignored
1018+ QMutableHashIterator<QTimer*, CallbackData> i(_timerFunctionMap);
1019+ while (i.hasNext()) {
1020+ i.next();
1021+ QTimer* timer = i.key();
1022+ int remainingTime = timer->remainingTime();
1023+ if (remainingTime >= 0) {
1024+ minimumTime = std::min((quint64)remainingTime, minimumTime);
1025+ }
1026+ }
1027+ return minimumTime;
1028+}
1029+
1030+
9691031 // NOTE: This is private because it must be called on the same thread that created the timers, which is why
9701032 // we want to only call it in our own run "shutdown" processing.
9711033 void ScriptEngine::stopAllTimers() {
@@ -1011,7 +1073,7 @@ void ScriptEngine::stop(bool marshal) { · 39 unmodified lines
10111073 void ScriptEngine::callAnimationStateHandler(QScriptValue callback, AnimVariantMap parameters, QStringList names, bool useNames, AnimVariantResultHandler resultHandler) {
10121074 if (QThread::currentThread() != thread()) {
10131075 #ifdef THREAD_DEBUGGING
1014− qDebug() << "*** WARNING *** ScriptEngine::callAnimationStateHandler() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] name:" << name;
1076+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::callAnimationStateHandler() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] name:" << name;
10151077 #endif
10161078 QMetaObject::invokeMethod(this, "callAnimationStateHandler",
10171079 Q_ARG(QScriptValue, callback),
@@ -1045,7 +1107,7 @@ void ScriptEngine::timerFired() { · 27 unmodified lines
10451107 {
10461108 auto engine = DependencyManager::get<ScriptEngines>();
10471109 if (!engine || engine->isStopped()) {
1048− qCDebug(scriptengine) << "Script.timerFired() while shutting down is ignored... parent script:" << getFilename();
1110+ scriptWarningMessage("Script.timerFired() while shutting down is ignored... parent script:" + getFilename());
10491111 return; // bail early
10501112 }
10511113 }
@@ -1061,7 +1123,12 @@ void ScriptEngine::timerFired() { · 9 unmodified lines
10611123
10621124 // call the associated JS function, if it exists
10631125 if (timerData.function.isValid()) {
1126+ auto preTimer = p_high_resolution_clock::now();
10641127 callWithEnvironment(timerData.definingEntityIdentifier, timerData.definingSandboxURL, timerData.function, timerData.function, QScriptValueList());
1128+ auto postTimer = p_high_resolution_clock::now();
1129+ auto elapsed = (postTimer - preTimer);
1130+ _totalTimerExecution += std::chrono::duration_cast<std::chrono::microseconds>(elapsed);
1131+
10651132 }
10661133 }
10671134
@@ -1071,12 +1138,18 @@ QObject* ScriptEngine::setupTimerWithInterval(const QScriptValue& function, int · 3 unmodified lines
10711138 QTimer* newTimer = new QTimer(this);
10721139 newTimer->setSingleShot(isSingleShot);
10731140
1141+ // The default timer type is not very accurate below about 200ms http://doc.qt.io/qt-5/qt.html#TimerType-enum
1142+ static const int MIN_TIMEOUT_FOR_COARSE_TIMER = 200;
1143+ if (intervalMS < MIN_TIMEOUT_FOR_COARSE_TIMER) {
1144+ newTimer->setTimerType(Qt::PreciseTimer);
1145+ }
1146+
10741147 connect(newTimer, &QTimer::timeout, this, &ScriptEngine::timerFired);
10751148
10761149 // make sure the timer stops when the script does
10771150 connect(this, &ScriptEngine::scriptEnding, newTimer, &QTimer::stop);
10781151
1079− CallbackData timerData = {function, currentEntityIdentifier, currentSandboxURL};
1152+ CallbackData timerData = {function, currentEntityIdentifier, currentSandboxURL };
10801153 _timerFunctionMap.insert(newTimer, timerData);
10811154
10821155 newTimer->start(intervalMS);
@@ -1085,7 +1158,7 @@ QObject* ScriptEngine::setupTimerWithInterval(const QScriptValue& function, int · 2 unmodified lines
10851158
10861159 QObject* ScriptEngine::setInterval(const QScriptValue& function, int intervalMS) {
10871160 if (DependencyManager::get<ScriptEngines>()->isStopped()) {
1088− qCDebug(scriptengine) << "Script.setInterval() while shutting down is ignored... parent script:" << getFilename();
1161+ scriptWarningMessage("Script.setInterval() while shutting down is ignored... parent script:" + getFilename());
10891162 return NULL; // bail early
10901163 }
10911164
@@ -1094,7 +1167,7 @@ QObject* ScriptEngine::setInterval(const QScriptValue& function, int intervalMS) · 2 unmodified lines
10941167
10951168 QObject* ScriptEngine::setTimeout(const QScriptValue& function, int timeoutMS) {
10961169 if (DependencyManager::get<ScriptEngines>()->isStopped()) {
1097− qCDebug(scriptengine) << "Script.setTimeout() while shutting down is ignored... parent script:" << getFilename();
1170+ scriptWarningMessage("Script.setTimeout() while shutting down is ignored... parent script:" + getFilename());
10981171 return NULL; // bail early
10991172 }
11001173
@@ -1154,8 +1227,8 @@ void ScriptEngine::print(const QString& message) { · 53 unmodified lines
11541227 // all of the files have finished loading.
11551228 void ScriptEngine::include(const QStringList& includeFiles, QScriptValue callback) {
11561229 if (DependencyManager::get<ScriptEngines>()->isStopped()) {
1157− qCDebug(scriptengine) << "Script.include() while shutting down is ignored..."
1158− << "includeFiles:" << includeFiles << "parent script:" << getFilename();
1230+ scriptWarningMessage("Script.include() while shutting down is ignored... includeFiles:"
1231+ + includeFiles.join(",") + "parent script:" + getFilename());
11591232 return; // bail early
11601233 }
11611234 QList<QUrl> urls;
@@ -1183,7 +1256,7 @@ void ScriptEngine::include(const QStringList& includeFiles, QScriptValue callbac · 21 unmodified lines
11831256 thisURL = expandScriptUrl(QUrl::fromLocalFile(expandScriptPath(file)));
11841257 QUrl defaultScriptsLoc = defaultScriptsLocation();
11851258 if (!defaultScriptsLoc.isParentOf(thisURL)) {
1186− qDebug() << "ScriptEngine::include -- skipping" << file << "-- outside of standard libraries";
1259+ scriptWarningMessage("Script.include() -- skipping" + file + "-- outside of standard libraries");
11871260 continue;
11881261 }
11891262 isStandardLibrary = true;
@@ -1194,8 +1267,9 @@ void ScriptEngine::include(const QStringList& includeFiles, QScriptValue callbac · 4 unmodified lines
11941267 if (!isStandardLibrary && !currentSandboxURL.isEmpty() && (thisURL.scheme() == "file") &&
11951268 (currentSandboxURL.scheme() != "file" ||
11961269 !thisURL.toString(strippingFlags).startsWith(currentSandboxURL.toString(strippingFlags), getSensitivity()))) {
1197− qCWarning(scriptengine) << "Script.include() ignoring file path"
1198− << thisURL << "outside of original entity script" << currentSandboxURL;
1270+
1271+ scriptWarningMessage("Script.include() ignoring file path" + thisURL.toString()
1272+ + "outside of original entity script" + currentSandboxURL.toString());
11991273 } else {
12001274 // We could also check here for CORS, but we don't yet.
12011275 // It turns out that QUrl.resolve will not change hosts and copy authority, so we don't need to check that here.
@@ -1217,7 +1291,7 @@ void ScriptEngine::include(const QStringList& includeFiles, QScriptValue callbac · 15 unmodified lines
12171291 for (QUrl url : urls) {
12181292 QString contents = data[url];
12191293 if (contents.isNull()) {
1220− qCDebug(scriptengine) << "Error loading file: " << url << "line:" << __LINE__;
1294+ scriptErrorMessage("Error loading file: " + url.toString());
12211295 } else {
12221296 std::lock_guard<std::recursive_mutex> lock(_lock);
12231297 if (!_includedURLs.contains(url)) {
@@ -1231,7 +1305,7 @@ void ScriptEngine::include(const QStringList& includeFiles, QScriptValue callbac · 7 unmodified lines
12311305
12321306 doWithEnvironment(capturedEntityIdentifier, capturedSandboxURL, operation);
12331307 } else {
1234− qCDebug(scriptengine) << "Script.include() skipping evaluation of previously included url:" << url;
1308+ scriptWarningMessage("Script.include() skipping evaluation of previously included url:" + url.toString());
12351309 }
12361310 }
12371311 }
@@ -1260,8 +1334,8 @@ void ScriptEngine::include(const QStringList& includeFiles, QScriptValue callbac · 22 unmodified lines
12601334
12611335 void ScriptEngine::include(const QString& includeFile, QScriptValue callback) {
12621336 if (DependencyManager::get<ScriptEngines>()->isStopped()) {
1263− qCDebug(scriptengine) << "Script.include() while shutting down is ignored... "
1264− << "includeFile:" << includeFile << "parent script:" << getFilename();
1337+ scriptWarningMessage("Script.include() while shutting down is ignored... includeFile:"
1338+ + includeFile + "parent script:" + getFilename());
12651339 return; // bail early
12661340 }
12671341
@@ -1275,13 +1349,13 @@ void ScriptEngine::include(const QString& includeFile, QScriptValue callback) { · 7 unmodified lines
12751349 // the Application or other context will connect to in order to know to actually load the script
12761350 void ScriptEngine::load(const QString& loadFile) {
12771351 if (DependencyManager::get<ScriptEngines>()->isStopped()) {
1278− qCDebug(scriptengine) << "Script.load() while shutting down is ignored... "
1279− << "loadFile:" << loadFile << "parent script:" << getFilename();
1352+ scriptWarningMessage("Script.load() while shutting down is ignored... loadFile:"
1353+ + loadFile + "parent script:" + getFilename());
12801354 return; // bail early
12811355 }
12821356 if (!currentEntityIdentifier.isInvalidID()) {
1283− qCWarning(scriptengine) << "Script.load() from entity script is ignored... "
1284− << "loadFile:" << loadFile << "parent script:" << getFilename();
1357+ scriptWarningMessage("Script.load() from entity script is ignored... loadFile:"
1358+ + loadFile + "parent script:" + getFilename());
12851359 return; // bail early
12861360 }
12871361
@@ -1298,7 +1372,7 @@ void ScriptEngine::load(const QString& loadFile) { · 10 unmodified lines
12981372 // Look up the handler associated with eventName and entityID. If found, evalute the argGenerator thunk and call the handler with those args
12991373 void ScriptEngine::forwardHandlerCall(const EntityItemID& entityID, const QString& eventName, QScriptValueList eventHandlerArgs) {
13001374 if (QThread::currentThread() != thread()) {
1301− qDebug() << "*** ERROR *** ScriptEngine::forwardHandlerCall() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "]";
1375+ qCDebug(scriptengine) << "*** ERROR *** ScriptEngine::forwardHandlerCall() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "]";
13021376 assert(false);
13031377 return ;
13041378 }
@@ -1332,7 +1406,7 @@ void ScriptEngine::loadEntityScript(QWeakPointer<ScriptEngine> theEngine, const · 27 unmodified lines
13321406 QSharedPointer<ScriptEngine> strongEngine = theEngine.toStrongRef();
13331407 if (strongEngine) {
13341408 #ifdef THREAD_DEBUGGING
1335− qDebug() << "ScriptEngine::entityScriptContentAvailable() IN LAMBDA contentAvailable on thread ["
1409+ qCDebug(scriptengine) << "ScriptEngine::entityScriptContentAvailable() IN LAMBDA contentAvailable on thread ["
13361410 << QThread::currentThread() << "] expected thread [" << strongEngine->thread() << "]";
13371411 #endif
13381412 strongEngine->entityScriptContentAvailable(entityID, scriptOrURL, contents, isURL, success);
@@ -1345,7 +1419,7 @@ void ScriptEngine::loadEntityScript(QWeakPointer<ScriptEngine> theEngine, const · 6 unmodified lines
13451419 void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, const QString& scriptOrURL, const QString& contents, bool isURL, bool success) {
13461420 if (QThread::currentThread() != thread()) {
13471421 #ifdef THREAD_DEBUGGING
1348− qDebug() << "*** WARNING *** ScriptEngine::entityScriptContentAvailable() called on wrong thread ["
1422+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::entityScriptContentAvailable() called on wrong thread ["
13491423 << QThread::currentThread() << "], invoking on correct thread [" << thread()
13501424 << "] " "entityID:" << entityID << "scriptOrURL:" << scriptOrURL << "contents:"
13511425 << contents << "isURL:" << isURL << "success:" << success;
@@ -1361,7 +1435,7 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 9 unmodified lines
13611435 }
13621436
13631437 #ifdef THREAD_DEBUGGING
1364− qDebug() << "ScriptEngine::entityScriptContentAvailable() thread [" << QThread::currentThread() << "] expected thread [" << thread() << "]";
1438+ qCDebug(scriptengine) << "ScriptEngine::entityScriptContentAvailable() thread [" << QThread::currentThread() << "] expected thread [" << thread() << "]";
13651439 #endif
13661440
13671441 auto scriptCache = DependencyManager::get<ScriptCache>();
@@ -1369,7 +1443,7 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 1 unmodified line
13691443 auto fileName = isURL ? scriptOrURL : "EmbeddedEntityScript";
13701444
13711445 QScriptProgram program(contents, fileName);
1372− if (!hasCorrectSyntax(program)) {
1446+ if (!hasCorrectSyntax(program, this)) {
13731447 if (!isFileUrl) {
13741448 scriptCache->addScriptToBadScriptList(scriptOrURL);
13751449 }
@@ -1397,7 +1471,7 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 21 unmodified lines
13971471 });
13981472 testConstructor = sandbox.evaluate(program);
13991473 }
1400− if (hadUncaughtExceptions(sandbox, program.fileName())) {
1474+ if (hadUncaughtExceptions(sandbox, program.fileName(), this)) {
14011475 return;
14021476 }
14031477
@@ -1411,10 +1485,10 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 7 unmodified lines
14111485 if (testConstructorValue.size() > maxTestConstructorValueSize) {
14121486 testConstructorValue = testConstructorValue.mid(0, maxTestConstructorValueSize) + "...";
14131487 }
1414− qCDebug(scriptengine) << "Error -- ScriptEngine::loadEntityScript() entity:" << entityID
1415− << "failed to load entity script -- expected a function, got " + testConstructorType
1416− << "," << testConstructorValue
1417− << "," << scriptOrURL;
1488+ scriptErrorMessage("Error -- ScriptEngine::loadEntityScript() entity:" + entityID.toString()
1489+ + "failed to load entity script -- expected a function, got " + testConstructorType
1490+ + "," + testConstructorValue
1491+ + "," + scriptOrURL);
14181492
14191493 if (!isFileUrl) {
14201494 scriptCache->addScriptToBadScriptList(scriptOrURL);
@@ -1449,7 +1523,7 @@ void ScriptEngine::entityScriptContentAvailable(const EntityItemID& entityID, co · 28 unmodified lines
14491523 void ScriptEngine::unloadEntityScript(const EntityItemID& entityID) {
14501524 if (QThread::currentThread() != thread()) {
14511525 #ifdef THREAD_DEBUGGING
1452− qDebug() << "*** WARNING *** ScriptEngine::unloadEntityScript() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
1526+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::unloadEntityScript() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
14531527 "entityID:" << entityID;
14541528 #endif
14551529
@@ -1458,7 +1532,7 @@ void ScriptEngine::unloadEntityScript(const EntityItemID& entityID) { · 2 unmodified lines
14581532 return;
14591533 }
14601534 #ifdef THREAD_DEBUGGING
1461− qDebug() << "ScriptEngine::unloadEntityScript() called on correct thread [" << thread() << "] "
1535+ qCDebug(scriptengine) << "ScriptEngine::unloadEntityScript() called on correct thread [" << thread() << "] "
14621536 "entityID:" << entityID;
14631537 #endif
14641538
@@ -1472,14 +1546,14 @@ void ScriptEngine::unloadEntityScript(const EntityItemID& entityID) { · 7 unmodified lines
14721546 void ScriptEngine::unloadAllEntityScripts() {
14731547 if (QThread::currentThread() != thread()) {
14741548 #ifdef THREAD_DEBUGGING
1475− qDebug() << "*** WARNING *** ScriptEngine::unloadAllEntityScripts() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "]";
1549+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::unloadAllEntityScripts() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "]";
14761550 #endif
14771551
14781552 QMetaObject::invokeMethod(this, "unloadAllEntityScripts");
14791553 return;
14801554 }
14811555 #ifdef THREAD_DEBUGGING
1482− qDebug() << "ScriptEngine::unloadAllEntityScripts() called on correct thread [" << thread() << "]";
1556+ qCDebug(scriptengine) << "ScriptEngine::unloadAllEntityScripts() called on correct thread [" << thread() << "]";
14831557 #endif
14841558 foreach(const EntityItemID& entityID, _entityScripts.keys()) {
14851559 callEntityScriptMethod(entityID, "unload");
@@ -1487,13 +1561,13 @@ void ScriptEngine::unloadAllEntityScripts() { · 1 unmodified line
14871561 _entityScripts.clear();
14881562
14891563 #ifdef DEBUG_ENGINE_STATE
1490− qDebug() << "---- CURRENT STATE OF ENGINE: --------------------------";
1564+ qCDebug(scriptengine) << "---- CURRENT STATE OF ENGINE: --------------------------";
14911565 QScriptValueIterator it(globalObject());
14921566 while (it.hasNext()) {
14931567 it.next();
1494− qDebug() << it.name() << ":" << it.value().toString();
1568+ qCDebug(scriptengine) << it.name() << ":" << it.value().toString();
14951569 }
1496− qDebug() << "--------------------------------------------------------";
1570+ qCDebug(scriptengine) << "--------------------------------------------------------";
14971571 #endif // DEBUG_ENGINE_STATE
14981572 }
14991573
@@ -1514,7 +1588,7 @@ void ScriptEngine::refreshFileScript(const EntityItemID& entityID) { · 14 unmodified lines
15141588 QString filePath = QUrl(details.scriptText).toLocalFile();
15151589 auto lastModified = QFileInfo(filePath).lastModified().toMSecsSinceEpoch();
15161590 if (lastModified > details.lastModified) {
1517− qCDebug(scriptengine) << "Reloading modified script " << details.scriptText;
1591+ scriptInfoMessage("Reloading modified script " + details.scriptText);
15181592
15191593 QFile file(filePath);
15201594 file.open(QIODevice::ReadOnly);
@@ -1522,7 +1596,7 @@ void ScriptEngine::refreshFileScript(const EntityItemID& entityID) { · 1 unmodified line
15221596 this->unloadEntityScript(entityID);
15231597 this->entityScriptContentAvailable(entityID, details.scriptText, scriptContents, true, true);
15241598 if (!_entityScripts.contains(entityID)) {
1525− qWarning() << "Reload script " << details.scriptText << " failed";
1599+ scriptWarningMessage("Reload script " + details.scriptText + " failed");
15261600 } else {
15271601 details = _entityScripts[entityID];
15281602 }
@@ -1549,7 +1623,7 @@ void ScriptEngine::doWithEnvironment(const EntityItemID& entityID, const QUrl& s · 20 unmodified lines
15491623 #else
15501624 operation();
15511625 #endif
1552− hadUncaughtExceptions(*this, _fileNameString);
1626+ hadUncaughtExceptions(*this, _fileNameString, this);
15531627
15541628 currentEntityIdentifier = oldIdentifier;
15551629 currentSandboxURL = oldSandboxURL;
@@ -1564,7 +1638,7 @@ void ScriptEngine::callWithEnvironment(const EntityItemID& entityID, const QUrl& · 8 unmodified lines
15641638 void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QString& methodName, const QStringList& params) {
15651639 if (QThread::currentThread() != thread()) {
15661640 #ifdef THREAD_DEBUGGING
1567− qDebug() << "*** WARNING *** ScriptEngine::callEntityScriptMethod() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
1641+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::callEntityScriptMethod() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
15681642 "entityID:" << entityID << "methodName:" << methodName;
15691643 #endif
15701644
@@ -1575,7 +1649,7 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS · 4 unmodified lines
15751649 return;
15761650 }
15771651 #ifdef THREAD_DEBUGGING
1578− qDebug() << "ScriptEngine::callEntityScriptMethod() called on correct thread [" << thread() << "] "
1652+ qCDebug(scriptengine) << "ScriptEngine::callEntityScriptMethod() called on correct thread [" << thread() << "] "
15791653 "entityID:" << entityID << "methodName:" << methodName;
15801654 #endif
15811655
@@ -1596,7 +1670,7 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS · 14 unmodified lines
15961670 void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QString& methodName, const PointerEvent& event) {
15971671 if (QThread::currentThread() != thread()) {
15981672 #ifdef THREAD_DEBUGGING
1599− qDebug() << "*** WARNING *** ScriptEngine::callEntityScriptMethod() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
1673+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::callEntityScriptMethod() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
16001674 "entityID:" << entityID << "methodName:" << methodName << "event: mouseEvent";
16011675 #endif
16021676
@@ -1607,7 +1681,7 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS · 4 unmodified lines
16071681 return;
16081682 }
16091683 #ifdef THREAD_DEBUGGING
1610− qDebug() << "ScriptEngine::callEntityScriptMethod() called on correct thread [" << thread() << "] "
1684+ qCDebug(scriptengine) << "ScriptEngine::callEntityScriptMethod() called on correct thread [" << thread() << "] "
16111685 "entityID:" << entityID << "methodName:" << methodName << "event: pointerEvent";
16121686 #endif
16131687
@@ -1628,7 +1702,7 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS · 14 unmodified lines
16281702 void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QString& methodName, const EntityItemID& otherID, const Collision& collision) {
16291703 if (QThread::currentThread() != thread()) {
16301704 #ifdef THREAD_DEBUGGING
1631− qDebug() << "*** WARNING *** ScriptEngine::callEntityScriptMethod() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
1705+ qCDebug(scriptengine) << "*** WARNING *** ScriptEngine::callEntityScriptMethod() called on wrong thread [" << QThread::currentThread() << "], invoking on correct thread [" << thread() << "] "
16321706 "entityID:" << entityID << "methodName:" << methodName << "otherID:" << otherID << "collision: collision";
16331707 #endif
16341708
@@ -1640,7 +1714,7 @@ void ScriptEngine::callEntityScriptMethod(const EntityItemID& entityID, const QS · 5 unmodified lines
16401714 return;
16411715 }
16421716 #ifdef THREAD_DEBUGGING
1643− qDebug() << "ScriptEngine::callEntityScriptMethod() called on correct thread [" << thread() << "] "
1717+ qCDebug(scriptengine) << "ScriptEngine::callEntityScriptMethod() called on correct thread [" << thread() << "] "
16441718 "entityID:" << entityID << "methodName:" << methodName << "otherID:" << otherID << "collision: collision";
16451719 #endif
16461720