From 516d4f6f30daeb4aabfc378ecb225d2610f914f6 Mon Sep 17 00:00:00 2001 From: "Michael \"Z\" Goddard" Date: Thu, 9 Nov 2017 17:27:49 -0500 Subject: [PATCH] Add Profiler events to Runtime, Sequencer and execute --- src/engine/execute.js | 28 ++++++++++++++++ src/engine/runtime.js | 54 +++++++++++++++++++++++++++++++ src/engine/sequencer.js | 72 +++++++++++++++++++++++++++++++++++++++++ 3 files changed, 154 insertions(+) diff --git a/src/engine/execute.js b/src/engine/execute.js index df9b5964b..07541c122 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/runtime.js b/src/engine/runtime.js index 56fceadfc..3ba173718 100644 --- a/src/engine/runtime.js +++ b/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(); + } } /** 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) {