diff --git a/src/engine/execute.js b/src/engine/execute.js index 0661f00b5..f5acf909e 100644 --- a/src/engine/execute.js +++ b/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. diff --git a/src/engine/profiler.js b/src/engine/profiler.js new file mode 100644 index 000000000..1433f36fd --- /dev/null +++ b/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.} + */ +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.} + */ + 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; diff --git a/src/engine/runtime.js b/src/engine/runtime.js index 56fceadfc..39be44db8 100644 --- a/src/engine/runtime.js +++ b/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; + } } /** diff --git a/src/engine/sequencer.js b/src/engine/sequencer.js index f4edc966c..0c796a6ea 100644 --- a/src/engine/sequencer.js +++ b/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) { diff --git a/src/playground/playground.js b/src/playground/playground.js index 321afb151..995502d7a 100644 --- a/src/playground/playground.js +++ b/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.