Merge pull request #564 from overte-org/feature/js_profiling

Add JS profiling API

libraries/script-engine/src/ScriptEngine.h

@@ -413,6 +413,16 @@ public:
      */
     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);

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<std::chrono::microseconds>(actuallySleptUntil - beforeSleep).count() <<
                         "Avg Updates (us):" << averageUpdate.count() <<
+                        "averageTimerPerFrame (us):" << averageTimerPerFrame.count() <<
                         "FPS:" << fps;
                 }
             }

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();
+}

libraries/script-engine/src/ScriptManagerScriptingInterface.h

@@ -529,6 +529,34 @@ public:
      */
      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 <caption>Collect profiling data from a script.</caption>
+     * 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 @@ signals:
      */
     void unhandledException(const ScriptValue& exception);
 
-
 protected:
     /*@jsdoc
      * @function Script.executeOnScriptThread

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,87 @@ 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.csv";
+    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() {
+    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);

libraries/script-engine/src/v8/ScriptEngineV8.h

@@ -30,6 +30,7 @@
 #include <QtCore/QSharedPointer>
 #include <QtCore/QString>
 #include <QQueue>
+#include <v8-profiler.h>
 
 #include "libplatform/libplatform.h"
 #include "v8.h"
@@ -138,6 +139,8 @@ public:  // ScriptEngine implementation
     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 @@ private:
     std::atomic<size_t> scriptValueCount{0};
     std::atomic<size_t> 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;
 };