From a21bc66fa3c6901304164d0b7a05e1eecc77a34a Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Tue, 26 Apr 2016 16:21:11 -0700 Subject: [PATCH 1/8] add support to abort evaluation of long running scripts on shutdown --- libraries/script-engine/src/ScriptEngine.cpp | 19 ++++++++++++++++++- libraries/script-engine/src/ScriptEngines.cpp | 16 ++++++++++++++-- 2 files changed, 32 insertions(+), 3 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index 15f3ebb985..c4ceba4365 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -199,11 +199,28 @@ void ScriptEngine::waitTillDoneRunning() { // NOTE: waitTillDoneRunning() will be called on the main Application thread, inside of stopAllScripts() // we want the application thread to continue to process events, because the scripts will likely need to - // marshall messages across to the main thread. For example if they access Settings or Meny in any of their + // marshall messages across to the main thread. For example if they access Settings or Menu in any of their // shutdown code. + auto startedWaiting = usecTimestampNow(); while (thread()->isRunning()) { // process events for the main application thread, allowing invokeMethod calls to pass between threads QCoreApplication::processEvents(); + auto stillWaiting = usecTimestampNow(); + auto elapsed = stillWaiting - startedWaiting; + + // if we've been waiting a second or more, then tell the script engine to stop evaluating + if (elapsed > USECS_PER_SECOND) { + qDebug() << __FUNCTION__ << "...giving up on evaluation elapsed:" << elapsed << "calling abortEvaluation()"; + abortEvaluation(); + } + + // if we've been waiting for more than 5 seconds then we should be more aggessive about stopping + static const auto WAITING_TOO_LONG = USECS_PER_SECOND * 5; + if (elapsed > WAITING_TOO_LONG) { + qDebug() << __FUNCTION__ << "...giving up on thread elapsed:" << elapsed << "calling thread->quit()"; + thread()->quit(); + break; + } } } } diff --git a/libraries/script-engine/src/ScriptEngines.cpp b/libraries/script-engine/src/ScriptEngines.cpp index eeca49ff84..624498c2b3 100644 --- a/libraries/script-engine/src/ScriptEngines.cpp +++ b/libraries/script-engine/src/ScriptEngines.cpp @@ -129,19 +129,31 @@ void ScriptEngines::shutdownScripting() { // "entities sandbox" which is only used to evaluate entities scripts to test their validity before using // them. We don't need to stop scripts that aren't running. if (scriptEngine->isRunning()) { + qCDebug(scriptengine) << "about to shutdown script:" << scriptName; // If the script is running, but still evaluating then we need to wait for its evaluation step to // complete. After that we can handle the stop process appropriately if (scriptEngine->evaluatePending()) { + qCDebug(scriptengine) << "script still evaluating:" << scriptName; + auto startedWaiting = usecTimestampNow(); while (scriptEngine->evaluatePending()) { // This event loop allows any started, but not yet finished evaluate() calls to complete // we need to let these complete so that we can be guaranteed that the script engine isn't // in a partially setup state, which can confuse our shutdown unwinding. QEventLoop loop; - QObject::connect(scriptEngine, &ScriptEngine::evaluationFinished, &loop, &QEventLoop::quit); - loop.exec(); + static const int MAX_PROCESSING_TIME = 500; // in MS + loop.processEvents(QEventLoop::AllEvents, MAX_PROCESSING_TIME); + auto stillWaiting = usecTimestampNow(); + auto elapsed = stillWaiting - startedWaiting; + // if we've been waiting for more than 5 seconds, then tell the script engine to stop evaluating + static const auto WAITING_TOO_LONG = USECS_PER_SECOND * 5; + if (elapsed > WAITING_TOO_LONG) { + qCDebug(scriptengine) << "giving up on script evaluation elapsed:" << elapsed << "calling abortEvaluation() script:" << scriptName; + scriptEngine->abortEvaluation(); + } } + qCDebug(scriptengine) << "script DONE evaluating:" << scriptName; } // We disconnect any script engine signals from the application because we don't want to do any From 48e63ea8280003f1315a1c35421e6c4bb5cecd15 Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Tue, 26 Apr 2016 16:24:53 -0700 Subject: [PATCH 2/8] add support to abort evaluation of long running scripts on shutdown --- libraries/script-engine/src/ScriptEngine.cpp | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index c4ceba4365..a30a786b32 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -201,6 +201,8 @@ void ScriptEngine::waitTillDoneRunning() { // we want the application thread to continue to process events, because the scripts will likely need to // marshall messages across to the main thread. For example if they access Settings or Menu in any of their // shutdown code. + QString scriptName = getFilename(); + auto startedWaiting = usecTimestampNow(); while (thread()->isRunning()) { // process events for the main application thread, allowing invokeMethod calls to pass between threads @@ -210,14 +212,14 @@ void ScriptEngine::waitTillDoneRunning() { // if we've been waiting a second or more, then tell the script engine to stop evaluating if (elapsed > USECS_PER_SECOND) { - qDebug() << __FUNCTION__ << "...giving up on evaluation elapsed:" << elapsed << "calling abortEvaluation()"; + qDebug() << "giving up on evaluation elapsed:" << elapsed << "calling abortEvaluation() script:" << scriptName; abortEvaluation(); } // if we've been waiting for more than 5 seconds then we should be more aggessive about stopping static const auto WAITING_TOO_LONG = USECS_PER_SECOND * 5; if (elapsed > WAITING_TOO_LONG) { - qDebug() << __FUNCTION__ << "...giving up on thread elapsed:" << elapsed << "calling thread->quit()"; + qDebug() << "giving up on thread elapsed:" << elapsed << "calling thread->quit() script:" << scriptName; thread()->quit(); break; } From 73ff0308a9cdcf4a2f0b72c0d2c41e98b10dabb9 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Sat, 30 Apr 2016 15:23:50 -0700 Subject: [PATCH 3/8] some CR feedback --- libraries/script-engine/src/ScriptEngine.cpp | 12 +++++++++++- libraries/script-engine/src/ScriptEngine.h | 1 + 2 files changed, 12 insertions(+), 1 deletion(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index a30a786b32..fd5df60415 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -140,6 +140,8 @@ ScriptEngine::ScriptEngine(const QString& scriptContents, const QString& fileNam connect(this, &QScriptEngine::signalHandlerException, this, [this](const QScriptValue& exception) { hadUncaughtExceptions(*this, _fileNameString); }); + + setProcessEventsInterval(MSECS_PER_SECOND); } ScriptEngine::~ScriptEngine() { @@ -193,6 +195,14 @@ void ScriptEngine::runInThread() { workerThread->start(); } +void ScriptEngine::threadSafeAbortEvaluation() { + if (QThread::currentThread() != thread()) { + QMetaObject::invokeMethod(this, "threadSafeAbortEvaluation"); + return; + } + abortEvaluation(); +} + void ScriptEngine::waitTillDoneRunning() { // If the script never started running or finished running before we got here, we don't need to wait for it if (_isRunning && _isThreaded) { @@ -213,7 +223,7 @@ void ScriptEngine::waitTillDoneRunning() { // if we've been waiting a second or more, then tell the script engine to stop evaluating if (elapsed > USECS_PER_SECOND) { qDebug() << "giving up on evaluation elapsed:" << elapsed << "calling abortEvaluation() script:" << scriptName; - abortEvaluation(); + threadSafeAbortEvaluation(); } // if we've been waiting for more than 5 seconds then we should be more aggessive about stopping diff --git a/libraries/script-engine/src/ScriptEngine.h b/libraries/script-engine/src/ScriptEngine.h index e8ce00c66c..f1bd7463d2 100644 --- a/libraries/script-engine/src/ScriptEngine.h +++ b/libraries/script-engine/src/ScriptEngine.h @@ -134,6 +134,7 @@ public: //////////////////////////////////////////////////////////////////////////////////////////////////////////////////// // NOTE - this is intended to be a public interface for Agent scripts, and local scripts, but not for EntityScripts Q_INVOKABLE void stop(); + Q_INVOKABLE void threadSafeAbortEvaluation(); bool isFinished() const { return _isFinished; } // used by Application and ScriptWidget bool isRunning() const { return _isRunning; } // used by ScriptWidget From ee4748fee965c649a6d7a48183abb7c001da73be Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Sat, 30 Apr 2016 15:31:09 -0700 Subject: [PATCH 4/8] CR Feedback --- libraries/script-engine/src/ScriptEngine.cpp | 10 ++-------- 1 file changed, 2 insertions(+), 8 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index fd5df60415..fc09c21929 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -222,14 +222,14 @@ void ScriptEngine::waitTillDoneRunning() { // if we've been waiting a second or more, then tell the script engine to stop evaluating if (elapsed > USECS_PER_SECOND) { - qDebug() << "giving up on evaluation elapsed:" << elapsed << "calling abortEvaluation() script:" << scriptName; + qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsed << "] aborting evaluation."; threadSafeAbortEvaluation(); } // if we've been waiting for more than 5 seconds then we should be more aggessive about stopping static const auto WAITING_TOO_LONG = USECS_PER_SECOND * 5; if (elapsed > WAITING_TOO_LONG) { - qDebug() << "giving up on thread elapsed:" << elapsed << "calling thread->quit() script:" << scriptName; + qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsed << "] quitting."; thread()->quit(); break; } @@ -396,7 +396,6 @@ void ScriptEngine::registerValue(const QString& valueName, QScriptValue value) { if (partsToGo > 0) { //QObject *object = new QObject; QScriptValue partValue = newArray(); //newQObject(object, QScriptEngine::ScriptOwnership); - qDebug() << "partValue[" << pathPart<<"].isArray() :" << partValue.isArray(); partObject.setProperty(pathPart, partValue); } else { partObject.setProperty(pathPart, value); @@ -1089,11 +1088,6 @@ void ScriptEngine::loadEntityScript(QWeakPointer theEngine, const << QThread::currentThread() << "] expected thread [" << strongEngine->thread() << "]"; #endif strongEngine->entityScriptContentAvailable(entityID, scriptOrURL, contents, isURL, success); - } else { - // FIXME - I'm leaving this in for testing, so that QA can confirm that sometimes the script contents - // returns after the ScriptEngine has been deleted, we can remove this after QA verifies the - // repro case. - qDebug() << "ScriptCache::getScriptContents() returned after our ScriptEngine was deleted... script:" << scriptOrURL; } }, forceRedownload); } From 00838d1e1ec4e89b11cac10dd614c15753a8eb1d Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Sat, 30 Apr 2016 15:38:37 -0700 Subject: [PATCH 5/8] more CR feedback removed redundant abort code --- libraries/script-engine/src/ScriptEngines.cpp | 25 ------------------- 1 file changed, 25 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngines.cpp b/libraries/script-engine/src/ScriptEngines.cpp index 624498c2b3..8fea7e4653 100644 --- a/libraries/script-engine/src/ScriptEngines.cpp +++ b/libraries/script-engine/src/ScriptEngines.cpp @@ -131,31 +131,6 @@ void ScriptEngines::shutdownScripting() { if (scriptEngine->isRunning()) { qCDebug(scriptengine) << "about to shutdown script:" << scriptName; - // If the script is running, but still evaluating then we need to wait for its evaluation step to - // complete. After that we can handle the stop process appropriately - if (scriptEngine->evaluatePending()) { - qCDebug(scriptengine) << "script still evaluating:" << scriptName; - auto startedWaiting = usecTimestampNow(); - while (scriptEngine->evaluatePending()) { - - // This event loop allows any started, but not yet finished evaluate() calls to complete - // we need to let these complete so that we can be guaranteed that the script engine isn't - // in a partially setup state, which can confuse our shutdown unwinding. - QEventLoop loop; - static const int MAX_PROCESSING_TIME = 500; // in MS - loop.processEvents(QEventLoop::AllEvents, MAX_PROCESSING_TIME); - auto stillWaiting = usecTimestampNow(); - auto elapsed = stillWaiting - startedWaiting; - // if we've been waiting for more than 5 seconds, then tell the script engine to stop evaluating - static const auto WAITING_TOO_LONG = USECS_PER_SECOND * 5; - if (elapsed > WAITING_TOO_LONG) { - qCDebug(scriptengine) << "giving up on script evaluation elapsed:" << elapsed << "calling abortEvaluation() script:" << scriptName; - scriptEngine->abortEvaluation(); - } - } - qCDebug(scriptengine) << "script DONE evaluating:" << scriptName; - } - // We disconnect any script engine signals from the application because we don't want to do any // extra stopScript/loadScript processing that the Application normally does when scripts start // and stop. We can safely short circuit this because we know we're in the "quitting" process From 6026e055aaa173978e300ffcf7bfc00fe6592ae4 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Sat, 30 Apr 2016 15:45:42 -0700 Subject: [PATCH 6/8] more CR feedback removed redundant abort code --- libraries/script-engine/src/ScriptEngine.cpp | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index fc09c21929..3b8b4925ad 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -221,7 +221,8 @@ void ScriptEngine::waitTillDoneRunning() { auto elapsed = stillWaiting - startedWaiting; // if we've been waiting a second or more, then tell the script engine to stop evaluating - if (elapsed > USECS_PER_SECOND) { + static const auto MAX_SCRIPT_EVALUATION_TIME = USECS_PER_SECOND; + if (elapsed > MAX_SCRIPT_EVALUATION_TIME) { qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsed << "] aborting evaluation."; threadSafeAbortEvaluation(); } From 4569032314fa3a1955c116e0ff9a444cbf1383d1 Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Mon, 2 May 2016 12:44:07 -0700 Subject: [PATCH 7/8] more CR feedback --- libraries/script-engine/src/ScriptEngine.cpp | 23 ++++++-------------- libraries/script-engine/src/ScriptEngine.h | 1 - 2 files changed, 7 insertions(+), 17 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index 3b8b4925ad..d4548aa3df 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -195,14 +195,6 @@ void ScriptEngine::runInThread() { workerThread->start(); } -void ScriptEngine::threadSafeAbortEvaluation() { - if (QThread::currentThread() != thread()) { - QMetaObject::invokeMethod(this, "threadSafeAbortEvaluation"); - return; - } - abortEvaluation(); -} - void ScriptEngine::waitTillDoneRunning() { // If the script never started running or finished running before we got here, we don't need to wait for it if (_isRunning && _isThreaded) { @@ -218,21 +210,20 @@ void ScriptEngine::waitTillDoneRunning() { // process events for the main application thread, allowing invokeMethod calls to pass between threads QCoreApplication::processEvents(); auto stillWaiting = usecTimestampNow(); - auto elapsed = stillWaiting - startedWaiting; + auto elapsedUsecs = stillWaiting - startedWaiting; // if we've been waiting a second or more, then tell the script engine to stop evaluating static const auto MAX_SCRIPT_EVALUATION_TIME = USECS_PER_SECOND; - if (elapsed > MAX_SCRIPT_EVALUATION_TIME) { - qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsed << "] aborting evaluation."; - threadSafeAbortEvaluation(); - } + static const auto WAITING_TOO_LONG = MAX_SCRIPT_EVALUATION_TIME * 5; // if we've been waiting for more than 5 seconds then we should be more aggessive about stopping - static const auto WAITING_TOO_LONG = USECS_PER_SECOND * 5; - if (elapsed > WAITING_TOO_LONG) { - qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsed << "] quitting."; + if (elapsedUsecs > WAITING_TOO_LONG) { + qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsedUsecs << "] quitting."; thread()->quit(); break; + } else if (elapsedUsecs > MAX_SCRIPT_EVALUATION_TIME) { + qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsedUsecs << "] aborting evaluation."; + QMetaObject::invokeMethod(this, "abortEvaluation"); } } } diff --git a/libraries/script-engine/src/ScriptEngine.h b/libraries/script-engine/src/ScriptEngine.h index f1bd7463d2..e8ce00c66c 100644 --- a/libraries/script-engine/src/ScriptEngine.h +++ b/libraries/script-engine/src/ScriptEngine.h @@ -134,7 +134,6 @@ public: //////////////////////////////////////////////////////////////////////////////////////////////////////////////////// // NOTE - this is intended to be a public interface for Agent scripts, and local scripts, but not for EntityScripts Q_INVOKABLE void stop(); - Q_INVOKABLE void threadSafeAbortEvaluation(); bool isFinished() const { return _isFinished; } // used by Application and ScriptWidget bool isRunning() const { return _isRunning; } // used by ScriptWidget From b98419e537e420b8ae415e0f2b2e700278dde9b7 Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Mon, 2 May 2016 14:58:38 -0700 Subject: [PATCH 8/8] add units to debug message --- libraries/script-engine/src/ScriptEngine.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index d4548aa3df..9bced25611 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -218,11 +218,11 @@ void ScriptEngine::waitTillDoneRunning() { // if we've been waiting for more than 5 seconds then we should be more aggessive about stopping if (elapsedUsecs > WAITING_TOO_LONG) { - qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsedUsecs << "] quitting."; + qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsedUsecs << " usecs] quitting."; thread()->quit(); break; } else if (elapsedUsecs > MAX_SCRIPT_EVALUATION_TIME) { - qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsedUsecs << "] aborting evaluation."; + qCDebug(scriptengine) << "Script " << scriptName << " has been running too long [" << elapsedUsecs << " usecs] aborting evaluation."; QMetaObject::invokeMethod(this, "abortEvaluation"); } }