Skip to content

Commit

Permalink
add Profiler.increment and Profiler.frame
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@mzgoddard
mzgoddard committed Jul 17, 2019
1 parent 11b52c4 commit 081b6b4
Show file tree
Hide file tree
Showing 4 changed files with 161 additions and 61 deletions.
69 changes: 48 additions & 21 deletions src/engine/execute.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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}
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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];
Expand All @@ -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)) {
Expand Down Expand Up @@ -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;
79 changes: 79 additions & 0 deletions src/engine/profiler.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
}

Expand All @@ -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.
Expand Down Expand Up @@ -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`.
*/
Expand Down Expand Up @@ -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;
Expand All @@ -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;
}

Expand Down
21 changes: 6 additions & 15 deletions src/engine/sequencer.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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) {
Expand Down
53 changes: 28 additions & 25 deletions src/playground/benchmark.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand All @@ -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);

Expand All @@ -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;
}
}
}
Expand Down Expand Up @@ -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);
}
}

Expand All @@ -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);
Expand All @@ -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;
}
}

Expand All @@ -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);
}
}
}
Expand Down Expand Up @@ -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);
};
}

Expand Down

0 comments on commit 081b6b4

Please sign in to comment.