Merge pull request #780 from mzgoddard/runtime-profiler

Runtime profiler

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/profiler.js

@@ -0,0 +1,311 @@
+/**
+ * @fileoverview
+ * A way to profile Scratch internal performance. Like what blocks run during a
+ * step? How much time do they take? How much time is spent inbetween blocks?
+ *
+ * Profiler aims for to spend as little time inside its functions while
+ * recording. For this it has a simple internal record structure that records a
+ * series of values for each START and STOP event in a single array. This lets
+ * all the values be pushed in one call for the array. This simplicity allows
+ * the contents of the start() and stop() calls to be inlined in areas that are
+ * called frequently enough to want even greater performance from Profiler so
+ * what is recorded better reflects on the profiled code and not Profiler
+ * itself.
+ */
+
+/**
+ * The next id returned for a new profile'd function.
+ * @type {number}
+ */
+let nextId = 0;
+
+/**
+ * The mapping of names to ids.
+ * @const {Object.<string, number>}
+ */
+const profilerNames = {};
+
+/**
+ * The START event identifier in Profiler records.
+ * @const {number}
+ */
+const START = 0;
+
+/**
+ * The STOP event identifier in Profiler records.
+ * @const {number}
+ */
+const STOP = 1;
+
+/**
+ * The number of cells used in the records array by a START event.
+ * @const {number}
+ */
+const START_SIZE = 4;
+
+/**
+ * The number of cells used in the records array by a STOP event.
+ * @const {number}
+ */
+const STOP_SIZE = 2;
+
+/**
+ * Stored reference to Performance instance provided by the Browser.
+ * @const {Performance}
+ */
+const performance = typeof window === 'object' && window.performance;
+
+
+/**
+ * Callback handle called by Profiler for each frame it decodes from its
+ * records.
+ * @callback FrameCallback
+ * @param {ProfilerFrame} frame
+ */
+
+/**
+ * A set of information about a frame of execution that was recorded.
+ */
+class ProfilerFrame {
+    /**
+     * @param {number} depth Depth of the frame in the recorded stack.
+     */
+    constructor (depth) {
+        /**
+         * The numeric id of a record symbol like Runtime._step or
+         * blockFunction.
+         * @type {number}
+         */
+        this.id = -1;
+
+        /**
+         * The amount of time spent inside the recorded frame and any deeper
+         * frames.
+         * @type {number}
+         */
+        this.totalTime = 0;
+
+        /**
+         * The amount of time spent only inside this record frame. Not
+         * including time in any deeper frames.
+         * @type {number}
+         */
+        this.selfTime = 0;
+
+        /**
+         * An arbitrary argument for the recorded frame. For example a block
+         * function might record its opcode as an argument.
+         * @type {*}
+         */
+        this.arg = null;
+
+        /**
+         * The depth of the recorded frame. This can help compare recursive
+         * funtions that are recorded. Each level of recursion with have a
+         * different depth value.
+         * @type {number}
+         */
+        this.depth = depth;
+    }
+}
+
+class Profiler {
+    /**
+     * @param {FrameCallback} onFrame a handle called for each recorded frame.
+     * The passed frame value may not be stored as it'll be updated with later
+     * frame information. Any information that is further stored by the handler
+     * should make copies or reduce the information.
+     */
+    constructor (onFrame = function () {}) {
+        /**
+         * A series of START and STOP values followed by arguments. After
+         * recording is complete the full set of records is reported back by
+         * stepping through the series to connect the relative START and STOP
+         * information.
+         * @type {Array.<*>}
+         */
+        this.records = [];
+
+        /**
+         * A cache of ProfilerFrames to reuse when reporting the recorded
+         * frames in records.
+         * @type {Array.<ProfilerFrame>}
+         */
+        this._stack = [new ProfilerFrame(0)];
+
+        /**
+         * A callback handle called with each decoded frame when reporting back
+         * all the recorded times.
+         * @type {FrameCallback}
+         */
+        this.onFrame = onFrame;
+
+        /**
+         * A reference to the START record id constant.
+         * @const {number}
+         */
+        this.START = START;
+
+        /**
+         * A reference to the STOP record id constant.
+         * @const {number}
+         */
+        this.STOP = STOP;
+    }
+
+    /**
+     * Start recording a frame of time for an id and optional argument.
+     * @param {number} id The id returned by idByName for a name symbol like
+     * Runtime._step.
+     * @param {?*} arg An arbitrary argument value to store with the frame.
+     */
+    start (id, arg) {
+        this.records.push(START, id, arg, performance.now());
+    }
+
+    /**
+     * Stop the current frame.
+     */
+    stop () {
+        this.records.push(STOP, performance.now());
+    }
+
+    /**
+     * Decode records and report all frames to `this.onFrame`.
+     */
+    reportFrames () {
+        const stack = this._stack;
+        let depth = 1;
+
+        // Step through the records and initialize Frame instances from the
+        // START and STOP events. START and STOP events are separated by events
+        // for deeper frames run by higher frames. Frames are stored on a stack
+        // and reinitialized for each START event. When a stop event is reach
+        // the Frame for the current depth has its final values stored and its
+        // passed to the current onFrame callback. This way Frames are "pushed"
+        // for each START event and "popped" for each STOP and handed to an
+        // outside handle to any desired reduction of the collected data.
+        for (let i = 0; i < this.records.length;) {
+            if (this.records[i] === START) {
+                if (depth >= stack.length) {
+                    stack.push(new ProfilerFrame(depth));
+                }
+
+                // Store id, arg, totalTime, and initialize selfTime.
+                const frame = stack[depth++];
+                frame.id = this.records[i + 1];
+                frame.arg = this.records[i + 2];
+                // totalTime is first set as the time recorded by this START
+                // event. Once the STOP event is reached the stored start time
+                // is subtracted from the recorded stop time. The resulting
+                // difference is the actual totalTime, and replaces the start
+                // time in frame.totalTime.
+                //
+                // totalTime is used this way as a convenient member to store a
+                // value between the two events without needing additional
+                // members on the Frame or in a shadow map.
+                frame.totalTime = this.records[i + 3];
+                // selfTime is decremented until we reach the STOP event for
+                // this frame. totalTime will be added to it then to get the
+                // time difference.
+                frame.selfTime = 0;
+
+                i += START_SIZE;
+            } else if (this.records[i] === STOP) {
+                const now = this.records[i + 1];
+
+                const frame = stack[--depth];
+                // totalTime is the difference between the start event time
+                // stored in totalTime and the stop event time pulled from this
+                // record.
+                frame.totalTime = now - frame.totalTime;
+                // selfTime is the difference of this frame's totalTime and the
+                // sum of totalTime of deeper frames.
+                frame.selfTime += frame.totalTime;
+
+                // Remove this frames totalTime from the parent's selfTime.
+                stack[depth - 1].selfTime -= frame.totalTime;
+
+                this.onFrame(frame);
+
+                i += STOP_SIZE;
+            } else {
+                this.records.length = 0;
+                throw new Error('Unable to decode Profiler records.');
+            }
+        }
+
+        this.records.length = 0;
+    }
+
+    /**
+     * Lookup or create an id for a frame name.
+     * @param {string} name The name to return an id for.
+     * @return {number} The id for the passed name.
+     */
+    idByName (name) {
+        return Profiler.idByName(name);
+    }
+
+    /**
+     * Reverse lookup the name from a given frame id.
+     * @param {number} id The id to search for.
+     * @return {string} The name for the given id.
+     */
+    nameById (id) {
+        return Profiler.nameById(id);
+    }
+
+    /**
+     * Lookup or create an id for a frame name.
+     * @static
+     * @param {string} name The name to return an id for.
+     * @return {number} The id for the passed name.
+     */
+    static idByName (name) {
+        if (typeof profilerNames[name] !== 'number') {
+            profilerNames[name] = nextId++;
+        }
+        return profilerNames[name];
+    }
+
+    /**
+     * Reverse lookup the name from a given frame id.
+     * @static
+     * @param {number} id The id to search for.
+     * @return {string} The name for the given id.
+     */
+    static nameById (id) {
+        for (const name in profilerNames) {
+            if (profilerNames[name] === id) {
+                return name;
+            }
+        }
+        return null;
+    }
+
+    /**
+     * Profiler is only available on platforms with the Performance API.
+     * @return {boolean} Can the Profiler run in this browser?
+     */
+    static available () {
+        return (
+            typeof window === 'object' &&
+            typeof window.performance !== 'undefined');
+    }
+}
+
+
+/**
+ * A reference to the START record id constant.
+ * @const {number}
+ */
+Profiler.START = START;
+
+/**
+ * A reference to the STOP record id constant.
+ * @const {number}
+ */
+Profiler.STOP = STOP;
+
+module.exports = Profiler;

src/engine/runtime.js

@@ -7,6 +7,7 @@ const Blocks = require('./blocks');
 const BlockType = require('../extension-support/block-type');
 const Sequencer = require('./sequencer');
 const Thread = require('./thread');
+const Profiler = require('./profiler');
 
 // Virtual I/O devices.
 const Clock = require('../io/clock');
@@ -79,6 +80,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 +253,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 +1081,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 +1097,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 +1115,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 +1136,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();
+        }
     }
 
     /**
@@ -1413,6 +1468,24 @@ class Runtime extends EventEmitter {
             this._step();
         }, interval);
     }
+
+    /**
+     * Turn on profiling.
+     * @param {Profiler/FrameCallback} onFrame A callback handle passed a
+     * profiling frame when the profiler reports its collected data.
+     */
+    enableProfiling (onFrame) {
+        if (Profiler.available()) {
+            this.profiler = new Profiler(onFrame);
+        }
+    }
+
+    /**
+     * Turn off profiling.
+     */
+    disableProfiling () {
+        this.profiler = null;
+    }
 }
 
 /**

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) {

src/playground/playground.js

@@ -40,6 +40,72 @@ const getAssetUrl = function (asset) {
     return assetUrlParts.join('');
 };
 
+const addProfilerPanels = function (
+    stats, vm, panelName = 'BLK%', panelFg = '#fff', panelBg = '#111') {
+
+    vm.runtime.enableProfiling();
+    if (vm.runtime.profiler === null) {
+        // Profiler isn't available on the local system.
+        return;
+    }
+
+    const blockPercentPanel = stats.addPanel(new window.Stats.Panel(panelName, panelFg, panelBg));
+
+    // Store the profiler reference for later.
+    const profiler = vm.runtime.profiler;
+    // Set profiler to null to disable profiling until later.
+    vm.runtime.profiler = null;
+
+    const stepThreadsProfilerId = profiler.idByName('Sequencer.stepThreads');
+    const blockFunctionProfilerId = profiler.idByName('blockFunction');
+
+    let blockFunctionTime = 0;
+    const stepValues = [];
+    let lastUpdate = Date.now();
+
+    // Collect time used by `blockFunction` calls in `execute` and add a column
+    // to the stats graph of the average for the last second of recordings.
+    profiler.onFrame = function ({id, totalTime}) {
+        if (id === stepThreadsProfilerId && totalTime > 0) {
+            // This frame wraps Sequencer.stepThreads.
+
+            // Push the most recently summed blockFunctionTime.
+            stepValues.push(blockFunctionTime / totalTime * 100);
+            // Every second, average the pushed values and render that as a new
+            // column in the stats graph.
+            if (Date.now() - lastUpdate > 1000) {
+                lastUpdate = Date.now();
+                const average = stepValues.reduce(
+                    (a, b) => a + b,
+                    0) / stepValues.length;
+                blockPercentPanel.update(average, 100);
+                stepValues.length = 0;
+            }
+            blockFunctionTime = 0;
+        } else if (id === blockFunctionProfilerId) {
+            // This frame wraps around each blockFunction call.
+            blockFunctionTime += totalTime;
+        }
+    };
+
+    // Set the stats panel to not display by default.
+    blockPercentPanel.dom.style.display = 'none';
+
+    // When the parent of the stats graphs is clicked, check if the
+    // blockPercentPanel is visible. If it is visible, enable profiling by
+    // setting the runtime's profiler to the stored Profiler instance. If it is
+    // not visible, disable profiling by setting the profiler to null.
+    stats.dom.addEventListener('click', () => {
+        if (blockPercentPanel.dom.style.display === 'block') {
+            vm.runtime.profiler = profiler;
+        } else {
+            vm.runtime.profiler = null;
+        }
+    });
+
+    return blockPercentPanel;
+};
+
 window.onload = function () {
     // Lots of global variables to make debugging easier
     // Instantiate the VM.
@@ -99,6 +165,7 @@ window.onload = function () {
     const stats = new window.Stats();
     document.getElementById('tab-renderexplorer').appendChild(stats.dom);
     stats.dom.style.position = 'relative';
+    addProfilerPanels(stats, vm, 'BLK%', '#fff', '#111');
     stats.begin();
 
     // Playground data tabs.