Add Profiler events to Runtime, Sequencer and execute

src/engine/execute.js

@@ -9,6 +9,18 @@ const {Map} = require('immutable');
  */
 const blockUtility = new BlockUtility();
 
+/**
+ * Profiler frame name for block functions.
+ * @const {string}
+ */
+const blockFunctionProfilerFrame = 'blockFunction';
+
+/**
+ * Profiler frame ID for 'blockFunction'.
+ * @type {number}
+ */
+let blockFunctionProfilerId = -1;
+
 /**
  * Utility function to determine if a value is a Promise.
  * @param {*} value Value to check for a Promise.
@@ -207,7 +219,23 @@ const execute = function (sequencer, thread) {
     let primitiveReportedValue = null;
     blockUtility.sequencer = sequencer;
     blockUtility.thread = thread;
+    if (runtime.profiler !== null) {
+        if (blockFunctionProfilerId === -1) {
+            blockFunctionProfilerId = runtime.profiler.idByName(blockFunctionProfilerFrame);
+        }
+        // The method commented below has its code inlined underneath to reduce
+        // the bias recorded for the profiler's calls in this time sensitive
+        // execute function.
+        //
+        // runtime.profiler.start(blockFunctionProfilerId, opcode);
+        runtime.profiler.records.push(
+            runtime.profiler.START, blockFunctionProfilerId, opcode, performance.now());
+    }
     primitiveReportedValue = blockFunction(argValues, blockUtility);
+    if (runtime.profiler !== null) {
+        // runtime.profiler.stop(blockFunctionProfilerId);
+        runtime.profiler.records.push(runtime.profiler.STOP, performance.now());
+    }
 
     if (typeof primitiveReportedValue === 'undefined') {
         // No value reported - potentially a command block.

src/engine/runtime.js

@@ -79,6 +79,24 @@ const ScratchBlocksConstants = {
     OUTPUT_SHAPE_SQUARE: 3
 };
 
+/**
+ * Numeric ID for Runtime._step in Profiler instances.
+ * @type {number}
+ */
+let stepProfilerId = -1;
+
+/**
+ * Numeric ID for Sequencer.stepThreads in Profiler instances.
+ * @type {number}
+ */
+let stepThreadsProfilerId = -1;
+
+/**
+ * Numeric ID for RenderWebGL.draw in Profiler instances.
+ * @type {number}
+ */
+let rendererDrawProfilerId = -1;
+
 /**
  * Manages targets, scripts, and the sequencer.
  * @constructor
@@ -234,6 +252,13 @@ class Runtime extends EventEmitter {
             keyboard: new Keyboard(this),
             mouse: new Mouse(this)
         };
+
+        /**
+         * A runtime profiler that records timed events for later playback to
+         * diagnose Scratch performance.
+         * @type {Profiler}
+         */
+        this.profiler = null;
     }
 
     /**
@@ -1055,6 +1080,12 @@ class Runtime extends EventEmitter {
      * inactive threads after each iteration.
      */
     _step () {
+        if (this.profiler !== null) {
+            if (stepProfilerId === -1) {
+                stepProfilerId = this.profiler.idByName('Runtime._step');
+            }
+            this.profiler.start(stepProfilerId);
+        }
         // Find all edge-activated hats, and add them to threads to be evaluated.
         for (const hatType in this._hats) {
             if (!this._hats.hasOwnProperty(hatType)) continue;
@@ -1065,7 +1096,16 @@ class Runtime extends EventEmitter {
         }
         this.redrawRequested = false;
         this._pushMonitors();
+        if (this.profiler !== null) {
+            if (stepThreadsProfilerId === -1) {
+                stepThreadsProfilerId = this.profiler.idByName('Sequencer.stepThreads');
+            }
+            this.profiler.start(stepThreadsProfilerId);
+        }
         const doneThreads = this.sequencer.stepThreads();
+        if (this.profiler !== null) {
+            this.profiler.stop();
+        }
         this._updateGlows(doneThreads);
         // Add done threads so that even if a thread finishes within 1 frame, the green
         // flag will still indicate that a script ran.
@@ -1074,7 +1114,16 @@ class Runtime extends EventEmitter {
                 this._getMonitorThreadCount([...this.threads, ...doneThreads]));
         if (this.renderer) {
             // @todo: Only render when this.redrawRequested or clones rendered.
+            if (this.profiler !== null) {
+                if (rendererDrawProfilerId === -1) {
+                    rendererDrawProfilerId = this.profiler.idByName('RenderWebGL.draw');
+                }
+                this.profiler.start(rendererDrawProfilerId);
+            }
             this.renderer.draw();
+            if (this.profiler !== null) {
+                this.profiler.stop();
+            }
         }
 
         if (this._refreshTargets) {
@@ -1086,6 +1135,11 @@ class Runtime extends EventEmitter {
             this.emit(Runtime.MONITORS_UPDATE, this._monitorState);
             this._prevMonitorState = this._monitorState;
         }
+
+        if (this.profiler !== null) {
+            this.profiler.stop();
+            this.profiler.reportFrames();
+        }
     }
 
     /**

src/engine/sequencer.js

@@ -2,6 +2,42 @@ const Timer = require('../util/timer');
 const Thread = require('./thread');
 const execute = require('./execute.js');
 
+/**
+ * Profiler frame name for stepping a single thread.
+ * @const {string}
+ */
+const stepThreadProfilerFrame = 'Sequencer.stepThread';
+
+/**
+ * Profiler frame name for the inner loop of stepThreads.
+ * @const {string}
+ */
+const stepThreadsInnerProfilerFrame = 'Sequencer.stepThreads#inner';
+
+/**
+ * Profiler frame name for execute.
+ * @const {string}
+ */
+const executeProfilerFrame = 'execute';
+
+/**
+ * Profiler frame ID for stepThreadProfilerFrame.
+ * @type {number}
+ */
+let stepThreadProfilerId = -1;
+
+/**
+ * Profiler frame ID for stepThreadsInnerProfilerFrame.
+ * @type {number}
+ */
+let stepThreadsInnerProfilerId = -1;
+
+/**
+ * Profiler frame ID for executeProfilerFrame.
+ * @type {number}
+ */
+let executeProfilerId = -1;
+
 class Sequencer {
     constructor (runtime) {
         /**
@@ -47,6 +83,13 @@ class Sequencer {
                numActiveThreads > 0 &&
                this.timer.timeElapsed() < WORK_TIME &&
                (this.runtime.turboMode || !this.runtime.redrawRequested)) {
+            if (this.runtime.profiler !== null) {
+                if (stepThreadsInnerProfilerId === -1) {
+                    stepThreadsInnerProfilerId = this.runtime.profiler.idByName(stepThreadsInnerProfilerFrame);
+                }
+                this.runtime.profiler.start(stepThreadsInnerProfilerId);
+            }
+
             numActiveThreads = 0;
             // Attempt to run each thread one time.
             for (let i = 0; i < this.runtime.threads.length; i++) {
@@ -69,7 +112,16 @@ class Sequencer {
                 if (activeThread.status === Thread.STATUS_RUNNING ||
                     activeThread.status === Thread.STATUS_YIELD) {
                     // Normal-mode thread: step.
+                    if (this.runtime.profiler !== null) {
+                        if (stepThreadProfilerId === -1) {
+                            stepThreadProfilerId = this.runtime.profiler.idByName(stepThreadProfilerFrame);
+                        }
+                        this.runtime.profiler.start(stepThreadProfilerId);
+                    }
                     this.stepThread(activeThread);
+                    if (this.runtime.profiler !== null) {
+                        this.runtime.profiler.stop();
+                    }
                     activeThread.warpTimer = null;
                     if (activeThread.isKilled) {
                         i--; // if the thread is removed from the list (killed), do not increase index
@@ -82,6 +134,10 @@ class Sequencer {
             // We successfully ticked once. Prevents running STATUS_YIELD_TICK
             // threads on the next tick.
             ranFirstTick = true;
+
+            if (this.runtime.profiler !== null) {
+                this.runtime.profiler.stop();
+            }
         }
         // Filter inactive threads from `this.runtime.threads`.
         numActiveThreads = 0;
@@ -129,7 +185,23 @@ class Sequencer {
             // Execute the current block.
             // Save the current block ID to notice if we did control flow.
             currentBlockId = thread.peekStack();
+            if (this.runtime.profiler !== null) {
+                if (executeProfilerId === -1) {
+                    executeProfilerId = this.runtime.profiler.idByName(executeProfilerFrame);
+                }
+                // The method commented below has its code inlined underneath to
+                // reduce the bias recorded for the profiler's calls in this
+                // time sensitive stepThread method.
+                //
+                // this.runtime.profiler.start(executeProfilerId, null);
+                this.runtime.profiler.records.push(
+                    this.runtime.profiler.START, executeProfilerId, null, performance.now());
+            }
             execute(this, thread);
+            if (this.runtime.profiler !== null) {
+                // this.runtime.profiler.stop();
+                this.runtime.profiler.records.push(this.runtime.profiler.STOP, performance.now());
+            }
             thread.blockGlowInFrame = currentBlockId;
             // If the thread has yielded or is waiting, yield to other threads.
             if (thread.status === Thread.STATUS_YIELD) {