diff --git a/libraries/script-engine/src/ScriptEngine.h b/libraries/script-engine/src/ScriptEngine.h
index 886e0b66b1..29594a63b8 100644
--- a/libraries/script-engine/src/ScriptEngine.h
+++ b/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);
diff --git a/libraries/script-engine/src/ScriptManager.cpp b/libraries/script-engine/src/ScriptManager.cpp
index 3ce1877de6..9bde4c1781 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<std::chrono::microseconds>(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 1c0edc4889..7c9f264327 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 68d9dba794..8751f27f72 100644
--- a/libraries/script-engine/src/ScriptManagerScriptingInterface.h
+++ b/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
diff --git a/libraries/script-engine/src/v8/ScriptEngineV8.cpp b/libraries/script-engine/src/v8/ScriptEngineV8.cpp
index a7d0cd8c8d..8c87c47c96 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 6ffa539a86..9e87edfb62 100644
--- a/libraries/script-engine/src/v8/ScriptEngineV8.h
+++ b/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;
};