Skip to content

Instantly share code, notes, and snippets.

@tomhicks
Last active April 9, 2024 16:42
Show Gist options
  • Save tomhicks/c3f7310343537cc0496d883aa61a3c54 to your computer and use it in GitHub Desktop.
Save tomhicks/c3f7310343537cc0496d883aa61a3c54 to your computer and use it in GitHub Desktop.
Aggregate function calls or named code blocks over a single frame. Like console.time/timeEnd but aggregated across many calls.
/* eslint-disable import/no-unused-modules */
/**
Usage:
// logs out the calls per frame, mean time, etc, under "myFunction"
const myFunction = instrumentPerFrame(function myFunction() {...});
// pass the name as the first parameter to wrap around methods and give them a name.
// if you don't do this, the name is the stringified function!
const object = {
method: instrumentPerFrame("method", () => {...});
}
// you can use timePerFrame.start/end like console.time/timeEnd except it
// aggregates the accumulated time over all the calls in a frame.
function someOtherFunctionThatIsCalledALot() {
timePerFrame.start("thing a");
doThingA();
anotherAThing();
timePerFrame.end("thing a");
timePerFrame.start("thing b");
doThingB();
anotherBThing();
timePerFrame.end("thing b");
}
*/
// Record call usage per frame.
let isInstrumentingCalls = false;
type LoggingThreshold = {
property: "count" | "time";
value: number;
};
type TrackedCall = {
key: string;
threshold: LoggingThreshold;
count: number;
time: number;
lastStartTimes: number[];
};
const calls: Map<string, TrackedCall> = new Map();
function logInstrumentedCalls() {
const tableData: Record<
string,
{ count: number; "total time (ms)": number; "mean time (ms)": number }
> = {};
for (const [, entry] of calls) {
if (entry.lastStartTimes.length) {
// eslint-disable-next-line no-console
console.warn(
`Unfinsihed timePerFrame.start("${entry.key}"). It looks like you forgot to call timePerFrame.end("${entry.key}").`
);
entry.lastStartTimes = [];
}
if (
(entry.threshold.property === "count" &&
entry.count > entry.threshold.value) ||
(entry.threshold.property === "time" &&
entry.time > entry.threshold.value)
) {
tableData[entry.key] = {
"total time (ms)": +entry.time.toFixed(5),
"mean time (ms)": +(entry.time / entry.count).toFixed(5),
count: entry.count,
};
}
entry.count = 0;
entry.time = 0;
}
if (Object.keys(tableData).length) {
// eslint-disable-next-line no-console
console.table(tableData);
}
if (logInstrumentedCalls) {
window.requestAnimationFrame(logInstrumentedCalls);
}
}
function getOrCreate(key: string, threshold?: TrackedCall["threshold"]) {
const existing = calls.get(key);
if (existing) return existing;
const newCall: TrackedCall = {
key,
count: 0,
time: 0,
lastStartTimes: [],
threshold: threshold ?? { property: "count", value: 0 },
};
calls.set(key, newCall);
return newCall;
}
function startTrackingCall(key: string) {
const trackEntry = getOrCreate(key);
trackEntry.lastStartTimes.push(performance.now());
}
function endTrackingCall(key: string) {
const trackEntry = getOrCreate(key);
const start = trackEntry.lastStartTimes.pop();
if (!start) {
// eslint-disable-next-line no-console
console.error(new Error("No tracking call found"));
return;
}
trackEntry.count += 1;
trackEntry.time += performance.now() - start;
}
function startInstrumenting() {
if (!isInstrumentingCalls) {
// eslint-disable-next-line no-console
console.log("Starting instrumentation");
isInstrumentingCalls = true;
window.requestAnimationFrame(logInstrumentedCalls);
}
}
// eslint-disable-next-line @typescript-eslint/no-explicit-any
type AnyFn = (this: any, ...args: any[]) => unknown;
type Options = {
key?: string;
threshold?: LoggingThreshold;
};
export function instrumentPerFrame<F extends AnyFn>(fn: F): F;
export function instrumentPerFrame<F extends AnyFn>(options: Options, fn: F): F;
export function instrumentPerFrame<F extends AnyFn>(key: string, fn: F): F;
export function instrumentPerFrame<F extends AnyFn>(
fnOrOptions: F | Options | string,
nothingOrFn?: typeof fnOrOptions extends AnyFn ? never : F
): F {
startInstrumenting();
const fn = nothingOrFn ?? (fnOrOptions as F);
const options =
typeof fnOrOptions === "function"
? {}
: typeof fnOrOptions === "string"
? { key: fnOrOptions }
: fnOrOptions;
if (!options?.key && !fn.name) {
// eslint-disable-next-line no-console
console.warn(
`Instrumented function does not have a name: ${fn
.toString()
.slice(0, 100)}`
);
}
const key =
options?.key ?? (fn.name || fn.toString().split("\n")[0]) ?? "(anonymous)";
const alreadyInstrumented = calls.has(key);
if (typeof fnOrOptions === "function" && alreadyInstrumented) {
// eslint-disable-next-line no-console
console.warn(
`There is already an instrumented function with the key "${key}". This might be a mistake. If you really mean to instrument different functions under the same grouping, give them an explicit key by passing a key as the first parameter.`
);
}
if (!alreadyInstrumented) {
// eslint-disable-next-line no-console
console.log(`Instrumenting ${calls.get(key)?.key}`);
getOrCreate(key, options?.threshold);
}
return function (
this: ThisParameterType<F>,
...args: Parameters<F>
): ReturnType<F> {
startTrackingCall(key);
const result = fn.apply(this, args) as ReturnType<F>;
endTrackingCall(key);
return result;
} as F;
}
export const timePerFrame = {
start: (key: string) => {
startInstrumenting();
startTrackingCall(key);
},
end: endTrackingCall,
};
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment