mirror of
https://github.com/scratchfoundation/scratch-vm.git
synced 2025-07-25 13:39:03 -04:00
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.
This commit is contained in:
parent
11b52c4e60
commit
d3ae00292f
4 changed files with 161 additions and 61 deletions
src
|
@ -191,6 +191,18 @@ class BlockCached {
|
||||||
*/
|
*/
|
||||||
this.mutation = cached.mutation;
|
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.
|
* Is the opcode a hat (event responder) block.
|
||||||
* @type {boolean}
|
* @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.
|
* Execute a block.
|
||||||
* @param {!Sequencer} sequencer Which sequencer is executing.
|
* @param {!Sequencer} sequencer Which sequencer is executing.
|
||||||
|
@ -466,6 +497,8 @@ const execute = function (sequencer, thread) {
|
||||||
currentStackFrame.reported = null;
|
currentStackFrame.reported = null;
|
||||||
}
|
}
|
||||||
|
|
||||||
|
const start = i;
|
||||||
|
|
||||||
for (; i < length; i++) {
|
for (; i < length; i++) {
|
||||||
const lastOperation = i === length - 1;
|
const lastOperation = i === length - 1;
|
||||||
const opCached = ops[i];
|
const opCached = ops[i];
|
||||||
|
@ -487,27 +520,7 @@ const execute = function (sequencer, thread) {
|
||||||
|
|
||||||
// Inputs are set during previous steps in the loop.
|
// Inputs are set during previous steps in the loop.
|
||||||
|
|
||||||
let primitiveReportedValue = null;
|
const primitiveReportedValue = blockFunction(argValues, blockUtility);
|
||||||
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);
|
|
||||||
}
|
|
||||||
|
|
||||||
// If it's a promise, wait until promise resolves.
|
// If it's a promise, wait until promise resolves.
|
||||||
if (isPromise(primitiveReportedValue)) {
|
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;
|
module.exports = execute;
|
||||||
|
|
|
@ -106,6 +106,12 @@ class ProfilerFrame {
|
||||||
* @type {number}
|
* @type {number}
|
||||||
*/
|
*/
|
||||||
this.depth = depth;
|
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 = [];
|
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
|
* A cache of ProfilerFrames to reuse when reporting the recorded
|
||||||
* frames in records.
|
* frames in records.
|
||||||
|
@ -170,6 +197,41 @@ class Profiler {
|
||||||
this.records.push(STOP, performance.now());
|
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`.
|
* Decode records and report all frames to `this.onFrame`.
|
||||||
*/
|
*/
|
||||||
|
@ -226,6 +288,9 @@ class Profiler {
|
||||||
// Remove this frames totalTime from the parent's selfTime.
|
// Remove this frames totalTime from the parent's selfTime.
|
||||||
stack[depth - 1].selfTime -= frame.totalTime;
|
stack[depth - 1].selfTime -= frame.totalTime;
|
||||||
|
|
||||||
|
// This frame occured once.
|
||||||
|
frame.count = 1;
|
||||||
|
|
||||||
this.onFrame(frame);
|
this.onFrame(frame);
|
||||||
|
|
||||||
i += STOP_SIZE;
|
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;
|
this.records.length = 0;
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|
|
@ -121,12 +121,11 @@ class Sequencer {
|
||||||
if (stepThreadProfilerId === -1) {
|
if (stepThreadProfilerId === -1) {
|
||||||
stepThreadProfilerId = this.runtime.profiler.idByName(stepThreadProfilerFrame);
|
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);
|
this.stepThread(activeThread);
|
||||||
if (this.runtime.profiler !== null) {
|
|
||||||
this.runtime.profiler.stop();
|
|
||||||
}
|
|
||||||
activeThread.warpTimer = null;
|
activeThread.warpTimer = null;
|
||||||
if (activeThread.isKilled) {
|
if (activeThread.isKilled) {
|
||||||
i--; // if the thread is removed from the list (killed), do not increase index
|
i--; // if the thread is removed from the list (killed), do not increase index
|
||||||
|
@ -203,23 +202,15 @@ class Sequencer {
|
||||||
if (executeProfilerId === -1) {
|
if (executeProfilerId === -1) {
|
||||||
executeProfilerId = this.runtime.profiler.idByName(executeProfilerFrame);
|
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
|
// Increment the number of times execute is called.
|
||||||
// time sensitive stepThread method.
|
this.runtime.profiler.increment(executeProfilerId);
|
||||||
//
|
|
||||||
// this.runtime.profiler.start(executeProfilerId, null);
|
|
||||||
this.runtime.profiler.records.push(
|
|
||||||
this.runtime.profiler.START, executeProfilerId, null, 0);
|
|
||||||
}
|
}
|
||||||
if (thread.target === null) {
|
if (thread.target === null) {
|
||||||
this.retireThread(thread);
|
this.retireThread(thread);
|
||||||
} else {
|
} else {
|
||||||
execute(this, thread);
|
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;
|
thread.blockGlowInFrame = currentBlockId;
|
||||||
// If the thread has yielded or is waiting, yield to other threads.
|
// If the thread has yielded or is waiting, yield to other threads.
|
||||||
if (thread.status === Thread.STATUS_YIELD) {
|
if (thread.status === Thread.STATUS_YIELD) {
|
||||||
|
|
|
@ -260,8 +260,8 @@ class StatView {
|
||||||
this.totalTime = 0;
|
this.totalTime = 0;
|
||||||
}
|
}
|
||||||
|
|
||||||
update (selfTime, totalTime) {
|
update (selfTime, totalTime, count) {
|
||||||
this.executions++;
|
this.executions += count;
|
||||||
this.selfTime += selfTime;
|
this.selfTime += selfTime;
|
||||||
this.totalTime += totalTime;
|
this.totalTime += totalTime;
|
||||||
}
|
}
|
||||||
|
@ -277,20 +277,29 @@ class StatView {
|
||||||
}
|
}
|
||||||
|
|
||||||
cell = document.createElement('td');
|
cell = document.createElement('td');
|
||||||
|
cell.style.textAlign = 'right';
|
||||||
|
cell.innerText = '---';
|
||||||
// Truncate selfTime. Value past the microsecond are floating point
|
// Truncate selfTime. Value past the microsecond are floating point
|
||||||
// noise.
|
// noise.
|
||||||
this.selfTime = Math.floor(this.selfTime * 1000) / 1000;
|
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);
|
row.appendChild(cell);
|
||||||
|
|
||||||
cell = document.createElement('td');
|
cell = document.createElement('td');
|
||||||
|
cell.style.textAlign = 'right';
|
||||||
|
cell.innerText = '---';
|
||||||
// Truncate totalTime. Value past the microsecond are floating point
|
// Truncate totalTime. Value past the microsecond are floating point
|
||||||
// noise.
|
// noise.
|
||||||
this.totalTime = Math.floor(this.totalTime * 1000) / 1000;
|
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);
|
row.appendChild(cell);
|
||||||
|
|
||||||
cell = document.createElement('td');
|
cell = document.createElement('td');
|
||||||
|
cell.style.textAlign = 'right';
|
||||||
cell.innerText = this.executions;
|
cell.innerText = this.executions;
|
||||||
row.appendChild(cell);
|
row.appendChild(cell);
|
||||||
|
|
||||||
|
@ -311,13 +320,13 @@ class RunningStats {
|
||||||
};
|
};
|
||||||
}
|
}
|
||||||
|
|
||||||
update (id, selfTime, totalTime) {
|
update (id, arg, selfTime, totalTime, count) {
|
||||||
if (id === this.stpeThreadsId) {
|
if (id === this.stpeThreadsId) {
|
||||||
this.recordedTime += totalTime;
|
this.recordedTime += totalTime;
|
||||||
} else if (id === this.stepThreadsInnerId) {
|
} else if (id === this.stepThreadsInnerId) {
|
||||||
this.executed.steps++;
|
this.executed.steps += count;
|
||||||
} else if (id === this.blockFunctionId) {
|
} else if (id === this.blockFunctionId) {
|
||||||
this.executed.blocks++;
|
this.executed.blocks += count;
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
@ -360,11 +369,12 @@ class Frames {
|
||||||
this.frames = [];
|
this.frames = [];
|
||||||
}
|
}
|
||||||
|
|
||||||
update (id, selfTime, totalTime) {
|
update (id, arg, selfTime, totalTime, count) {
|
||||||
|
if (id < 0) return;
|
||||||
if (!this.frames[id]) {
|
if (!this.frames[id]) {
|
||||||
this.frames[id] = new StatView(this.profiler.nameById(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'
|
'Runtime._step'
|
||||||
];
|
];
|
||||||
|
|
||||||
const trackSlowFrames = [
|
|
||||||
'Sequencer.stepThreads',
|
|
||||||
'Sequencer.stepThreads#inner',
|
|
||||||
'Sequencer.stepThread',
|
|
||||||
'execute'
|
|
||||||
];
|
|
||||||
|
|
||||||
class FramesTable extends StatTable {
|
class FramesTable extends StatTable {
|
||||||
constructor (options) {
|
constructor (options) {
|
||||||
super(options);
|
super(options);
|
||||||
|
@ -404,9 +407,8 @@ class FramesTable extends StatTable {
|
||||||
return this.frames.frames[this.profiler.idByName(key)];
|
return this.frames.frames[this.profiler.idByName(key)];
|
||||||
}
|
}
|
||||||
|
|
||||||
isSlow (key, frame) {
|
isSlow () {
|
||||||
return (trackSlowFrames.indexOf(key) > 0 &&
|
return false;
|
||||||
frame.selfTime / frame.totalTime > SLOW);
|
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
@ -417,12 +419,12 @@ class Opcodes {
|
||||||
this.opcodes = {};
|
this.opcodes = {};
|
||||||
}
|
}
|
||||||
|
|
||||||
update (id, selfTime, totalTime, arg) {
|
update (id, arg, selfTime, totalTime, count) {
|
||||||
if (id === this.blockFunctionId) {
|
if (id === this.blockFunctionId) {
|
||||||
if (!this.opcodes[arg]) {
|
if (!this.opcodes[arg]) {
|
||||||
this.opcodes[arg] = new StatView(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');
|
const stepId = profiler.idByName('Runtime._step');
|
||||||
profiler.onFrame = ({id, selfTime, totalTime, arg}) => {
|
profiler.onFrame = ({id, arg, selfTime, totalTime, count}) => {
|
||||||
if (id === stepId) {
|
if (id === stepId) {
|
||||||
runningStatsView.render();
|
runningStatsView.render();
|
||||||
}
|
}
|
||||||
runningStats.update(id, selfTime, totalTime, arg);
|
|
||||||
opcodes.update(id, selfTime, totalTime, arg);
|
runningStats.update(id, arg, selfTime, totalTime, count);
|
||||||
frames.update(id, selfTime, totalTime, arg);
|
opcodes.update(id, arg, selfTime, totalTime, count);
|
||||||
|
frames.update(id, arg, selfTime, totalTime, count);
|
||||||
};
|
};
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|
Loading…
Add table
Add a link
Reference in a new issue