From 2da1c201bc0c6c23478241ca1a4cc21fc1421704 Mon Sep 17 00:00:00 2001 From: "Michael \"Z\" Goddard" Date: Wed, 8 May 2019 20:19:51 -0400 Subject: [PATCH] add Profiler.increment and Profiler.frame Let profiled code track frames and arguments called by incrementing a counter for a frame id or frame id and argument. This replaces the same counting by recording the call as part of a history of calls and returns. Updating the array for all calls counted takes enough time to bias the profiled run towards less overall executions. --- src/engine/execute.js | 59 ++++++++++++++++++++++------------ src/engine/profiler.js | 64 +++++++++++++++++++++++++++++++++++++ src/engine/sequencer.js | 21 ++++-------- src/playground/benchmark.js | 53 +++++++++++++++--------------- 4 files changed, 136 insertions(+), 61 deletions(-) diff --git a/src/engine/execute.js b/src/engine/execute.js index c8638d01ab8..b9a10be4de5 100644 --- a/src/engine/execute.js +++ b/src/engine/execute.js @@ -191,6 +191,18 @@ class BlockCached { */ this.mutation = cached.mutation; + /** + * Profiler 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,19 @@ class BlockCached { } } +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 +491,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 +514,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 +565,16 @@ const execute = function (sequencer, thread) { } } } + + if (runtime.profiler !== null) { + if (blockCached._profiler !== runtime.profiler) { + prepareBlockProfiling(runtime.profiler, blockCached); + } + const end = Math.min(i + 1, length); + for (let p = start; p < end; p++) { + ops[p]._profilerFrame.count += 1; + } + } }; module.exports = execute; diff --git a/src/engine/profiler.js b/src/engine/profiler.js index 1433f36fd13..2c54e591f10 100644 --- a/src/engine/profiler.js +++ b/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 = 1; } } @@ -126,6 +132,12 @@ class Profiler { */ this.records = []; + this.increments = []; + + this.counters = []; + + this.nullFrame = new ProfilerFrame(-1); + /** * A cache of ProfilerFrames to reuse when reporting the recorded * frames in records. @@ -170,6 +182,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 +273,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 +285,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; } diff --git a/src/engine/sequencer.js b/src/engine/sequencer.js index 54d4870a5c5..504a3e078d1 100644 --- a/src/engine/sequencer.js +++ b/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) { diff --git a/src/playground/benchmark.js b/src/playground/benchmark.js index ed95510231e..aa70d154cf8 100644 --- a/src/playground/benchmark.js +++ b/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); }; }