From bda52c33e615e6be9210d041e4196854d5fef7d0 Mon Sep 17 00:00:00 2001 From: samcake Date: Thu, 22 Jun 2017 15:35:00 -0700 Subject: [PATCH 1/3] Adding the function source when profiling, to explore perf issues --- libraries/script-engine/src/ScriptEngine.cpp | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index 67b16df1ce..d14df662e2 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -1284,7 +1284,8 @@ void ScriptEngine::timerFired() { // call the associated JS function, if it exists if (timerData.function.isValid()) { - PROFILE_RANGE(script, __FUNCTION__); + //PROFILE_RANGE(script, __FUNCTION__); + PROFILE_RANGE(script, timerData.function.toString().toStdString().c_str()); auto preTimer = p_high_resolution_clock::now(); callWithEnvironment(timerData.definingEntityIdentifier, timerData.definingSandboxURL, timerData.function, timerData.function, QScriptValueList()); auto postTimer = p_high_resolution_clock::now(); @@ -1311,6 +1312,7 @@ QObject* ScriptEngine::setupTimerWithInterval(const QScriptValue& function, int // make sure the timer stops when the script does connect(this, &ScriptEngine::scriptEnding, newTimer, &QTimer::stop); + CallbackData timerData = { function, currentEntityIdentifier, currentSandboxURL }; _timerFunctionMap.insert(newTimer, timerData); From c24e254257deee74bb7e0da65c2eeff367b2e1d9 Mon Sep 17 00:00:00 2001 From: samcake Date: Thu, 22 Jun 2017 18:10:20 -0700 Subject: [PATCH 2/3] Add support for profiling from scripts --- libraries/script-engine/src/ScriptEngine.cpp | 17 +++++++++++++++-- libraries/script-engine/src/ScriptEngine.h | 3 +++ .../system/controllers/handControllerGrab.js | 2 ++ 3 files changed, 20 insertions(+), 2 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index d14df662e2..fd61c41583 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -1284,8 +1284,8 @@ void ScriptEngine::timerFired() { // call the associated JS function, if it exists if (timerData.function.isValid()) { - //PROFILE_RANGE(script, __FUNCTION__); - PROFILE_RANGE(script, timerData.function.toString().toStdString().c_str()); + PROFILE_RANGE(script, __FUNCTION__); + // PROFILE_RANGE(script, timerData.function.toString().toStdString().c_str()); auto preTimer = p_high_resolution_clock::now(); callWithEnvironment(timerData.definingEntityIdentifier, timerData.definingSandboxURL, timerData.function, timerData.function, QScriptValueList()); auto postTimer = p_high_resolution_clock::now(); @@ -1396,6 +1396,19 @@ void ScriptEngine::print(const QString& message) { emit printedMessage(message, getFilename()); } + +void ScriptEngine::beginProfileRange(const QString& label) const { + if (trace_script().isDebugEnabled()) { + tracing::traceEvent(trace_script(), label.toStdString().c_str(), tracing::DurationBegin); + } +} + +void ScriptEngine::endProfileRange(const QString& label) const { + if (trace_script().isDebugEnabled()) { + tracing::traceEvent(trace_script(), label.toStdString().c_str(), tracing::DurationEnd); + } +} + // Script.require.resolve -- like resolvePath, but performs more validation and throws exceptions on invalid module identifiers (for consistency with Node.js) QString ScriptEngine::_requireResolve(const QString& moduleId, const QString& relativeTo) { if (!IS_THREADSAFE_INVOCATION(thread(), __FUNCTION__)) { diff --git a/libraries/script-engine/src/ScriptEngine.h b/libraries/script-engine/src/ScriptEngine.h index 9da8603814..7c473a305b 100644 --- a/libraries/script-engine/src/ScriptEngine.h +++ b/libraries/script-engine/src/ScriptEngine.h @@ -43,6 +43,7 @@ #include "Vec3.h" #include "ConsoleScriptingInterface.h" #include "SettingHandle.h" +#include "Profile.h" class QScriptEngineDebugger; @@ -182,6 +183,8 @@ public: Q_INVOKABLE void print(const QString& message); Q_INVOKABLE QUrl resolvePath(const QString& path) const; Q_INVOKABLE QUrl resourcesPath() const; + Q_INVOKABLE void beginProfileRange(const QString& label) const; + Q_INVOKABLE void endProfileRange(const QString& label) const; // Entity Script Related methods Q_INVOKABLE bool isEntityScriptRunning(const EntityItemID& entityID) { diff --git a/scripts/system/controllers/handControllerGrab.js b/scripts/system/controllers/handControllerGrab.js index 04921fe14d..8631a84fcf 100644 --- a/scripts/system/controllers/handControllerGrab.js +++ b/scripts/system/controllers/handControllerGrab.js @@ -1173,6 +1173,7 @@ function MyController(hand) { }; this.update = function(deltaTime, timestamp) { + Script.beginProfileRange("handControllerGrab:MyController:update") this.updateSmoothedTrigger(); this.maybeScaleMyAvatar(); @@ -1209,6 +1210,7 @@ function MyController(hand) { } else { print("WARNING: could not find state " + this.state + " in state machine"); } + Script.endProfileRange("handControllerGrab:MyController:update") }; this.callEntityMethodOnGrabbed = function(entityMethodName) { From c0e8b6c8bcf617b7ef1b64360e6c08085a312811 Mon Sep 17 00:00:00 2001 From: samcake Date: Fri, 23 Jun 2017 14:18:56 -0700 Subject: [PATCH 3/3] clean up --- libraries/script-engine/src/ScriptEngine.cpp | 9 ++------- libraries/shared/src/Profile.h | 16 ++++++++++++++++ scripts/system/controllers/handControllerGrab.js | 2 -- 3 files changed, 18 insertions(+), 9 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngine.cpp b/libraries/script-engine/src/ScriptEngine.cpp index 16927e0d2e..df74c04aaf 100644 --- a/libraries/script-engine/src/ScriptEngine.cpp +++ b/libraries/script-engine/src/ScriptEngine.cpp @@ -1283,7 +1283,6 @@ void ScriptEngine::timerFired() { // call the associated JS function, if it exists if (timerData.function.isValid()) { PROFILE_RANGE(script, __FUNCTION__); - // PROFILE_RANGE(script, timerData.function.toString().toStdString().c_str()); auto preTimer = p_high_resolution_clock::now(); callWithEnvironment(timerData.definingEntityIdentifier, timerData.definingSandboxURL, timerData.function, timerData.function, QScriptValueList()); auto postTimer = p_high_resolution_clock::now(); @@ -1396,15 +1395,11 @@ void ScriptEngine::print(const QString& message) { void ScriptEngine::beginProfileRange(const QString& label) const { - if (trace_script().isDebugEnabled()) { - tracing::traceEvent(trace_script(), label.toStdString().c_str(), tracing::DurationBegin); - } + PROFILE_SYNC_BEGIN(script, label.toStdString().c_str(), label.toStdString().c_str()); } void ScriptEngine::endProfileRange(const QString& label) const { - if (trace_script().isDebugEnabled()) { - tracing::traceEvent(trace_script(), label.toStdString().c_str(), tracing::DurationEnd); - } + PROFILE_SYNC_END(script, label.toStdString().c_str(), label.toStdString().c_str()); } // Script.require.resolve -- like resolvePath, but performs more validation and throws exceptions on invalid module identifiers (for consistency with Node.js) diff --git a/libraries/shared/src/Profile.h b/libraries/shared/src/Profile.h index ee09298deb..5de4e8f41a 100644 --- a/libraries/shared/src/Profile.h +++ b/libraries/shared/src/Profile.h @@ -46,6 +46,20 @@ private: const QLoggingCategory& _category; }; + +inline void syncBegin(const QLoggingCategory& category, const QString& name, const QString& id, const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap()) { + if (category.isDebugEnabled()) { + tracing::traceEvent(category, name, tracing::DurationBegin, id, args, extra); + } +} + + +inline void syncEnd(const QLoggingCategory& category, const QString& name, const QString& id, const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap()) { + if (category.isDebugEnabled()) { + tracing::traceEvent(category, name, tracing::DurationEnd, id, args, extra); + } +} + inline void asyncBegin(const QLoggingCategory& category, const QString& name, const QString& id, const QVariantMap& args = QVariantMap(), const QVariantMap& extra = QVariantMap()) { if (category.isDebugEnabled()) { tracing::traceEvent(category, name, tracing::AsyncNestableStart, id, args, extra); @@ -80,6 +94,8 @@ inline void metadata(const QString& metadataType, const QVariantMap& args) { #define PROFILE_RANGE_EX(category, name, argbColor, payload, ...) Duration profileRangeThis(trace_##category(), name, argbColor, (uint64_t)payload, ##__VA_ARGS__); #define PROFILE_RANGE_BEGIN(category, rangeId, name, argbColor) rangeId = Duration::beginRange(trace_##category(), name, argbColor) #define PROFILE_RANGE_END(category, rangeId) Duration::endRange(trace_##category(), rangeId) +#define PROFILE_SYNC_BEGIN(category, name, id, ...) syncBegin(trace_##category(), name, id, ##__VA_ARGS__); +#define PROFILE_SYNC_END(category, name, id, ...) syncEnd(trace_##category(), name, id, ##__VA_ARGS__); #define PROFILE_ASYNC_BEGIN(category, name, id, ...) asyncBegin(trace_##category(), name, id, ##__VA_ARGS__); #define PROFILE_ASYNC_END(category, name, id, ...) asyncEnd(trace_##category(), name, id, ##__VA_ARGS__); #define PROFILE_COUNTER_IF_CHANGED(category, name, type, value) { static type lastValue = 0; type newValue = value; if (newValue != lastValue) { counter(trace_##category(), name, { { name, newValue }}); lastValue = newValue; } } diff --git a/scripts/system/controllers/handControllerGrab.js b/scripts/system/controllers/handControllerGrab.js index 8631a84fcf..04921fe14d 100644 --- a/scripts/system/controllers/handControllerGrab.js +++ b/scripts/system/controllers/handControllerGrab.js @@ -1173,7 +1173,6 @@ function MyController(hand) { }; this.update = function(deltaTime, timestamp) { - Script.beginProfileRange("handControllerGrab:MyController:update") this.updateSmoothedTrigger(); this.maybeScaleMyAvatar(); @@ -1210,7 +1209,6 @@ function MyController(hand) { } else { print("WARNING: could not find state " + this.state + " in state machine"); } - Script.endProfileRange("handControllerGrab:MyController:update") }; this.callEntityMethodOnGrabbed = function(entityMethodName) {