add Profiler.increment and Profiler.frame

src/engine/execute.js

@@ -191,6 +191,18 @@ class BlockCached {
          */
         this.mutation = cached.mutation;
 
+        /**
+         * The profiler the block is configured with.
+         * @type {?Profiler}
+         */
+        this._profiler = null;
+
+        /**
+         * Profiler information frame.
+         * @type {?ProfilerFrame}
+         */
+        this._profilerFrame = null;
+
         /**
          * Is the opcode a hat (event responder) block.
          * @type {boolean}
@@ -370,6 +382,25 @@ class BlockCached {
     }
 }
 
+/**
+ * Initialize a BlockCached instance so its command/hat
+ * block and reporters can be profiled during execution.
+ * @param {Profiler} profiler - The profiler that is currently enabled.
+ * @param {BlockCached} blockCached - The blockCached instance to profile.
+ */
+const _prepareBlockProfiling = function (profiler, blockCached) {
+    blockCached._profiler = profiler;
+
+    if (blockFunctionProfilerId === -1) {
+        blockFunctionProfilerId = profiler.idByName(blockFunctionProfilerFrame);
+    }
+
+    const ops = blockCached._ops;
+    for (let i = 0; i < ops.length; i++) {
+        ops[i]._profilerFrame = profiler.frame(blockFunctionProfilerId, ops[i].opcode);
+    }
+};
+
 /**
  * Execute a block.
  * @param {!Sequencer} sequencer Which sequencer is executing.
@@ -466,6 +497,8 @@ const execute = function (sequencer, thread) {
         currentStackFrame.reported = null;
     }
 
+    const start = i;
+
     for (; i < length; i++) {
         const lastOperation = i === length - 1;
         const opCached = ops[i];
@@ -487,27 +520,7 @@ const execute = function (sequencer, thread) {
 
         // Inputs are set during previous steps in the loop.
 
-        let primitiveReportedValue = null;
-        if (runtime.profiler === null) {
-            primitiveReportedValue = blockFunction(argValues, blockUtility);
-        } else {
-            const opcode = opCached.opcode;
-            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, 0);
-
-            primitiveReportedValue = blockFunction(argValues, blockUtility);
-
-            // runtime.profiler.stop(blockFunctionProfilerId);
-            runtime.profiler.records.push(runtime.profiler.STOP, 0);
-        }
+        const primitiveReportedValue = blockFunction(argValues, blockUtility);
 
         // If it's a promise, wait until promise resolves.
         if (isPromise(primitiveReportedValue)) {
@@ -558,6 +571,20 @@ const execute = function (sequencer, thread) {
             }
         }
     }
+
+    if (runtime.profiler !== null) {
+        if (blockCached._profiler !== runtime.profiler) {
+            _prepareBlockProfiling(runtime.profiler, blockCached);
+        }
+        // Determine the index that is after the last executed block. `i` is
+        // currently the block that was just executed. `i + 1` will be the block
+        // after that. `length` with the min call makes sure we don't try to
+        // reference an operation outside of the set of operations.
+        const end = Math.min(i + 1, length);
+        for (let p = start; p < end; p++) {
+            ops[p]._profilerFrame.count += 1;
+        }
+    }
 };
 
 module.exports = execute;

src/engine/profiler.js

@@ -106,6 +106,12 @@ class ProfilerFrame {
          * @type {number}
          */
         this.depth = depth;
+
+        /**
+         * A summarized count of the number of calls to this frame.
+         * @type {number}
+         */
+        this.count = 0;
     }
 }
 
@@ -126,6 +132,27 @@ class Profiler {
          */
         this.records = [];
 
+        /**
+         * An array of frames incremented on demand instead as part of start
+         * and stop.
+         * @type {Array.<ProfilerFrame>}
+         */
+        this.increments = [];
+
+        /**
+         * An array of profiler frames separated by counter argument. Generally
+         * for Scratch these frames are separated by block function opcode.
+         * This tracks each time an opcode is called.
+         * @type {Array.<ProfilerFrame>}
+         */
+        this.counters = [];
+
+        /**
+         * A frame with no id or argument.
+         * @type {ProfilerFrame}
+         */
+        this.nullFrame = new ProfilerFrame(-1);
+
         /**
          * A cache of ProfilerFrames to reuse when reporting the recorded
          * frames in records.
@@ -170,6 +197,41 @@ class Profiler {
         this.records.push(STOP, performance.now());
     }
 
+    /**
+     * Increment the number of times this symbol is called.
+     * @param {number} id The id returned by idByName for a name symbol.
+     */
+    increment (id) {
+        if (!this.increments[id]) {
+            this.increments[id] = new ProfilerFrame(-1);
+            this.increments[id].id = id;
+        }
+        this.increments[id].count += 1;
+    }
+
+    /**
+     * Find or create a ProfilerFrame-like object whose counter can be
+     * incremented outside of the Profiler.
+     * @param {number} id The id returned by idByName for a name symbol.
+     * @param {*} arg The argument for a frame that identifies it in addition
+     *   to the id.
+     * @return {{count: number}} A ProfilerFrame-like whose count should be
+     *   incremented for each call.
+     */
+    frame (id, arg) {
+        for (let i = 0; i < this.counters.length; i++) {
+            if (this.counters[i].id === id && this.counters[i].arg === arg) {
+                return this.counters[i];
+            }
+        }
+
+        const newCounter = new ProfilerFrame(-1);
+        newCounter.id = id;
+        newCounter.arg = arg;
+        this.counters.push(newCounter);
+        return newCounter;
+    }
+
     /**
      * Decode records and report all frames to `this.onFrame`.
      */
@@ -226,6 +288,9 @@ class Profiler {
                 // Remove this frames totalTime from the parent's selfTime.
                 stack[depth - 1].selfTime -= frame.totalTime;
 
+                // This frame occured once.
+                frame.count = 1;
+
                 this.onFrame(frame);
 
                 i += STOP_SIZE;
@@ -235,6 +300,20 @@ class Profiler {
             }
         }
 
+        for (let j = 0; j < this.increments.length; j++) {
+            if (this.increments[j] && this.increments[j].count > 0) {
+                this.onFrame(this.increments[j]);
+                this.increments[j].count = 0;
+            }
+        }
+
+        for (let k = 0; k < this.counters.length; k++) {
+            if (this.counters[k].count > 0) {
+                this.onFrame(this.counters[k]);
+                this.counters[k].count = 0;
+            }
+        }
+
         this.records.length = 0;
     }
 

src/engine/sequencer.js

@@ -121,12 +121,11 @@ class Sequencer {
                         if (stepThreadProfilerId === -1) {
                             stepThreadProfilerId = this.runtime.profiler.idByName(stepThreadProfilerFrame);
                         }
-                        this.runtime.profiler.start(stepThreadProfilerId);
+
+                        // Increment the number of times stepThread is called.
+                        this.runtime.profiler.increment(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
@@ -203,23 +202,15 @@ class Sequencer {
                 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, 0);
+
+                // Increment the number of times execute is called.
+                this.runtime.profiler.increment(executeProfilerId);
             }
             if (thread.target === null) {
                 this.retireThread(thread);
             } else {
                 execute(this, thread);
             }
-            if (this.runtime.profiler !== null) {
-                // this.runtime.profiler.stop();
-                this.runtime.profiler.records.push(this.runtime.profiler.STOP, 0);
-            }
             thread.blockGlowInFrame = currentBlockId;
             // If the thread has yielded or is waiting, yield to other threads.
             if (thread.status === Thread.STATUS_YIELD) {

src/playground/benchmark.js

@@ -260,8 +260,8 @@ class StatView {
         this.totalTime = 0;
     }
 
-    update (selfTime, totalTime) {
-        this.executions++;
+    update (selfTime, totalTime, count) {
+        this.executions += count;
         this.selfTime += selfTime;
         this.totalTime += totalTime;
     }
@@ -277,20 +277,29 @@ class StatView {
         }
 
         cell = document.createElement('td');
+        cell.style.textAlign = 'right';
+        cell.innerText = '---';
         // Truncate selfTime. Value past the microsecond are floating point
         // noise.
         this.selfTime = Math.floor(this.selfTime * 1000) / 1000;
-        cell.innerText = (this.selfTime / 1000).toPrecision(3);
+        if (this.selfTime > 0) {
+            cell.innerText = (this.selfTime / 1000).toFixed(3);
+        }
         row.appendChild(cell);
 
         cell = document.createElement('td');
+        cell.style.textAlign = 'right';
+        cell.innerText = '---';
         // Truncate totalTime. Value past the microsecond are floating point
         // noise.
         this.totalTime = Math.floor(this.totalTime * 1000) / 1000;
-        cell.innerText = (this.totalTime / 1000).toPrecision(3);
+        if (this.totalTime > 0) {
+            cell.innerText = (this.totalTime / 1000).toFixed(3);
+        }
         row.appendChild(cell);
 
         cell = document.createElement('td');
+        cell.style.textAlign = 'right';
         cell.innerText = this.executions;
         row.appendChild(cell);
 
@@ -311,13 +320,13 @@ class RunningStats {
         };
     }
 
-    update (id, selfTime, totalTime) {
+    update (id, arg, selfTime, totalTime, count) {
         if (id === this.stpeThreadsId) {
             this.recordedTime += totalTime;
         } else if (id === this.stepThreadsInnerId) {
-            this.executed.steps++;
+            this.executed.steps += count;
         } else if (id === this.blockFunctionId) {
-            this.executed.blocks++;
+            this.executed.blocks += count;
         }
     }
 }
@@ -360,11 +369,12 @@ class Frames {
         this.frames = [];
     }
 
-    update (id, selfTime, totalTime) {
+    update (id, arg, selfTime, totalTime, count) {
+        if (id < 0) return;
         if (!this.frames[id]) {
             this.frames[id] = new StatView(this.profiler.nameById(id));
         }
-        this.frames[id].update(selfTime, totalTime);
+        this.frames[id].update(selfTime, totalTime, count);
     }
 }
 
@@ -378,13 +388,6 @@ const frameOrder = [
     'Runtime._step'
 ];
 
-const trackSlowFrames = [
-    'Sequencer.stepThreads',
-    'Sequencer.stepThreads#inner',
-    'Sequencer.stepThread',
-    'execute'
-];
-
 class FramesTable extends StatTable {
     constructor (options) {
         super(options);
@@ -404,9 +407,8 @@ class FramesTable extends StatTable {
         return this.frames.frames[this.profiler.idByName(key)];
     }
 
-    isSlow (key, frame) {
-        return (trackSlowFrames.indexOf(key) > 0 &&
-        frame.selfTime / frame.totalTime > SLOW);
+    isSlow () {
+        return false;
     }
 }
 
@@ -417,12 +419,12 @@ class Opcodes {
         this.opcodes = {};
     }
 
-    update (id, selfTime, totalTime, arg) {
+    update (id, arg, selfTime, totalTime, count) {
         if (id === this.blockFunctionId) {
             if (!this.opcodes[arg]) {
                 this.opcodes[arg] = new StatView(arg);
             }
-            this.opcodes[arg].update(selfTime, totalTime);
+            this.opcodes[arg].update(selfTime, totalTime, count);
         }
     }
 }
@@ -494,13 +496,14 @@ class ProfilerRun {
         });
 
         const stepId = profiler.idByName('Runtime._step');
-        profiler.onFrame = ({id, selfTime, totalTime, arg}) => {
+        profiler.onFrame = ({id, arg, selfTime, totalTime, count}) => {
             if (id === stepId) {
                 runningStatsView.render();
             }
-            runningStats.update(id, selfTime, totalTime, arg);
-            opcodes.update(id, selfTime, totalTime, arg);
-            frames.update(id, selfTime, totalTime, arg);
+
+            runningStats.update(id, arg, selfTime, totalTime, count);
+            opcodes.update(id, arg, selfTime, totalTime, count);
+            frames.update(id, arg, selfTime, totalTime, count);
         };
     }