From a84c68f4fffc00a862b264fd0c5a36a331547f6a Mon Sep 17 00:00:00 2001 From: Karol Suprynowicz Date: Sat, 12 Aug 2023 16:18:40 +0200 Subject: [PATCH] Add JS profiling API --- libraries/script-engine/src/ScriptEngine.h | 10 +++ libraries/script-engine/src/ScriptManager.cpp | 5 +- .../src/ScriptManagerScriptingInterface.cpp | 8 ++ .../src/ScriptManagerScriptingInterface.h | 29 ++++++- .../script-engine/src/v8/ScriptEngineV8.cpp | 85 +++++++++++++++++++ .../script-engine/src/v8/ScriptEngineV8.h | 9 ++ 6 files changed, 144 insertions(+), 2 deletions(-) diff --git a/libraries/script-engine/src/ScriptEngine.h b/libraries/script-engine/src/ScriptEngine.h index 886e0b66b18..29594a63b89 100644 --- a/libraries/script-engine/src/ScriptEngine.h +++ b/libraries/script-engine/src/ScriptEngine.h @@ -413,6 +413,16 @@ class ScriptEngine : public QObject { */ virtual void dumpHeapObjectStatistics() = 0; + /** + * @brief Starts collecting profiling data. + */ + virtual void startProfiling() = 0; + + /** + * @brief Stops collecting profiling data and saves it to a CSV file in Logs directory. + */ + virtual void stopProfilingAndSave() = 0; + public: // helper to detect and log warnings when other code invokes QScriptEngine/BaseScriptEngine in thread-unsafe ways bool IS_THREADSAFE_INVOCATION(const QString& method); diff --git a/libraries/script-engine/src/ScriptManager.cpp b/libraries/script-engine/src/ScriptManager.cpp index 3ce1877de60..9bde4c1781b 100644 --- a/libraries/script-engine/src/ScriptManager.cpp +++ b/libraries/script-engine/src/ScriptManager.cpp @@ -992,11 +992,14 @@ void ScriptManager::run() { if (seconds > 0) { // avoid division by zero and time travel uint64_t fps = thisFrame / seconds; // Overreporting artificially reduces the reported rate - if (thisFrame % SCRIPT_FPS == 0) { + const int REPORT_BELOW_FPS = 30; + if (thisFrame % SCRIPT_FPS == 0 && fps < REPORT_BELOW_FPS) { qCDebug(scriptengine) << + "Script:" << name << "Frame:" << thisFrame << "Slept (us):" << std::chrono::duration_cast(actuallySleptUntil - beforeSleep).count() << "Avg Updates (us):" << averageUpdate.count() << + "averageTimerPerFrame (us):" << averageTimerPerFrame.count() << "FPS:" << fps; } } diff --git a/libraries/script-engine/src/ScriptManagerScriptingInterface.cpp b/libraries/script-engine/src/ScriptManagerScriptingInterface.cpp index 1c0edc48897..7c9f264327c 100644 --- a/libraries/script-engine/src/ScriptManagerScriptingInterface.cpp +++ b/libraries/script-engine/src/ScriptManagerScriptingInterface.cpp @@ -80,3 +80,11 @@ ScriptValue ScriptManagerScriptingInterface::createGarbageCollectorDebuggingObje return _manager->engine()->newQObject(new TestQObject, ScriptEngine::ScriptOwnership); //return _manager->engine()->newValue(1); } + +void ScriptManagerScriptingInterface::startProfiling() { + _manager->engine()->startProfiling(); +} + +void ScriptManagerScriptingInterface::stopProfilingAndSave() { + _manager->engine()->stopProfilingAndSave(); +} diff --git a/libraries/script-engine/src/ScriptManagerScriptingInterface.h b/libraries/script-engine/src/ScriptManagerScriptingInterface.h index 68d9dba794c..8751f27f72d 100644 --- a/libraries/script-engine/src/ScriptManagerScriptingInterface.h +++ b/libraries/script-engine/src/ScriptManagerScriptingInterface.h @@ -529,6 +529,34 @@ class ScriptManagerScriptingInterface : public QObject { */ Q_INVOKABLE ScriptValue createGarbageCollectorDebuggingObject(); + /*@jsdoc + * Starts collecting profiling data + * @function Script.startProfiling + */ + Q_INVOKABLE void startProfiling(); + + /*@jsdoc + * Stops collecting profiling data and writes them to a timestamped CSV file in Logs directory. + * @function Script.stopProfilingAndSave + * @example Collect profiling data from a script. + * Script.startProfiling(); + * workFunc1(); + * Script.stopProfilingAndSave(); + * + * function workFunc1() { + * for (var i=0; i<100000; i++) { + * var vec1 = {x: i, y: i+1, z: i+2}; + * var vec2 = {x: i+3, y: i+4, z: i+5}; + * workFunc2(vec1, vec2); + * } + * }; + * function workFunc2(vec1, vec2) { + * var cross = Vec3.cross(vec1, vec2); + * var dot = Vec3.dot(vec1, vec2); + * }; + */ + Q_INVOKABLE void stopProfilingAndSave(); + signals: /*@jsdoc @@ -705,7 +733,6 @@ class ScriptManagerScriptingInterface : public QObject { */ void unhandledException(const ScriptValue& exception); - protected: /*@jsdoc * @function Script.executeOnScriptThread diff --git a/libraries/script-engine/src/v8/ScriptEngineV8.cpp b/libraries/script-engine/src/v8/ScriptEngineV8.cpp index a7d0cd8c8df..8c87c47c967 100644 --- a/libraries/script-engine/src/v8/ScriptEngineV8.cpp +++ b/libraries/script-engine/src/v8/ScriptEngineV8.cpp @@ -56,6 +56,7 @@ #include "ScriptValueV8Wrapper.h" #include "ScriptEngineLoggingV8.h" #include "ScriptValueIteratorV8Wrapper.h" +#include "shared/FileUtils.h" static const int MAX_DEBUG_VALUE_LENGTH { 80 }; @@ -1450,6 +1451,90 @@ void ScriptEngineV8::dumpHeapObjectStatistics() { } } +void ScriptEngineV8::startProfiling() { + if (_profiler) { + qWarning(scriptengine_v8) << "ScriptEngineV8::startProfiling: Profiler is already running"; + return; + } + _profiler = v8::CpuProfiler::New(_v8Isolate); + v8::CpuProfilingResult result = _profiler->Start(v8::CpuProfilingOptions()); + if (!result.id) { + qWarning(scriptengine_v8) << "ScriptEngineV8::startProfiling: Profiler failed to start"; + _profiler->Dispose(); + _profiler = nullptr; + return; + } + qDebug(scriptengine_v8) << "Script profiler started"; + _profilerId = result.id; +}; + +// Helper function for ScriptEngineV8::stopProfilingAndSave + +int getTotalNodeHitCount(const v8::CpuProfileNode *node) { + int hitCount = node->GetHitCount(); + for (int i = 0; i < node->GetChildrenCount(); i++) { + hitCount += getTotalNodeHitCount(node->GetChild(i)); + } + return hitCount; +} + +QString getLogFileName() { + static const QString FILENAME_FORMAT = "overte-profile_%1.txt"; + static const QString DATETIME_FORMAT = "yyyy-MM-dd_hh.mm.ss"; + static const QString LOGS_DIRECTORY = "Logs"; + + QString result = FileUtils::standardPath(LOGS_DIRECTORY); + QDateTime now = QDateTime::currentDateTime(); + + result.append(QString(FILENAME_FORMAT).arg(now.toString(DATETIME_FORMAT))); + return result; +} + +void ScriptEngineV8::stopProfilingAndSave() { + // the following will produce 11/18 13:55:36 + const QString DATE_STRING_FORMAT = "MM/dd hh:mm:ss"; + + if (!_profiler || !_profilerId) { + qWarning(scriptengine_v8) << "ScriptEngineV8::stopProfilingAndSave: Profiler is not running"; + return; + } + v8::CpuProfile *profile = _profiler->Stop(_profilerId); + QString filename(getLogFileName()); + QFile file(filename); + if (file.open(QIODevice::WriteOnly)) { + QStringList samples; + for (int i = 0; i < profile->GetSamplesCount(); i++) { + QString line; + QTextStream stream(&line); + const v8::CpuProfileNode *node = profile->GetSample(i); + stream << getTotalNodeHitCount(node) << ";" + << node->GetHitCount() << ";" + << node->GetFunctionNameStr() << ";" + << node->GetScriptResourceNameStr() << ";" + << node->GetLineNumber() << "\n"; + samples.append(line); + } + samples.sort(); + QStringList deduplicated; + deduplicated.append(samples[0]); + for (int i=1; i < samples.size(); i++) { + if (samples[i] != samples[i-1]) { + deduplicated.append(samples[i]); + } + } + QTextStream fileStream(&file); + for (QString line : deduplicated) { + fileStream << line; + } + } else { + qWarning(scriptengine_v8) << "ScriptEngineV8::stopProfilingAndSave: Cannot open output file"; + } + profile->Delete(); + _profiler->Dispose(); + _profiler = nullptr; + qDebug(scriptengine_v8) << "Script profiler stopped, results written to: " << filename; +}; + ContextScopeV8::ContextScopeV8(ScriptEngineV8 *engine) : _engine(engine) { Q_ASSERT(engine); diff --git a/libraries/script-engine/src/v8/ScriptEngineV8.h b/libraries/script-engine/src/v8/ScriptEngineV8.h index 6ffa539a869..9e87edfb624 100644 --- a/libraries/script-engine/src/v8/ScriptEngineV8.h +++ b/libraries/script-engine/src/v8/ScriptEngineV8.h @@ -30,6 +30,7 @@ #include #include #include +#include #include "libplatform/libplatform.h" #include "v8.h" @@ -138,6 +139,8 @@ class ScriptEngineV8 final : public ScriptEngine, virtual ScriptEngineMemoryStatistics getMemoryUsageStatistics() override; virtual void startCollectingObjectStatistics() override; virtual void dumpHeapObjectStatistics() override; + virtual void startProfiling() override; + virtual void stopProfilingAndSave() override; void scheduleValueWrapperForDeletion(ScriptValueV8Wrapper* wrapper) {_scriptValueWrappersToDelete.enqueue(wrapper);} void deleteUnusedValueWrappers(); virtual void perManagerLoopIterationCleanup() override; @@ -272,6 +275,12 @@ class ScriptEngineV8 final : public ScriptEngine, std::atomic scriptValueCount{0}; std::atomic scriptValueProxyCount{0}; #endif + + // Pointers to profiling classes. These are valid only when profiler is running, otherwise null + // Smart pointer cannot be used here since profiler has private destructor + v8::CpuProfiler *_profiler{nullptr}; + v8::ProfilerId _profilerId{0}; + friend ScriptValueV8Wrapper; };