commit c96196ed57634a9180aec847f1f8f0a47faaa1b0 equwal <13551856+equwal@users.noreply.github.com> 2026-09-26 20:45:02 -0700 Add PluginProfiler BetterDiscord plugin The plugin measures the main-thread time of each BetterDiscord plugin. It wraps BetterDiscord patch callbacks, the plugin callbacks that BDFDB runs, the plugin hook methods, and the timers and observers that plugins make. It also shows the CPU of all Discord processes, the renderer JS heap, and long animation frames. Property tests check the time accounting. Other tests check the hooks against the patcher of the installed BetterDiscord and the suppress function of the installed BDFDB.
.gitignore | 2 + 00PluginProfiler.plugin.js | 567 +++++++++++++++++++++++++++++++++++++++++++++ README.md | 26 +++ package-lock.json | 53 +++++ package.json | 1 + test/bd-patcher.test.js | 101 ++++++++ test/helpers/installed.js | 50 ++++ test/hooks.test.js | 174 ++++++++++++++ test/lifecycle.test.js | 82 +++++++ test/recorder.test.js | 100 ++++++++ 10 files changed, 1156 insertions(+)
diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..d653a28 --- /dev/null +++ b/.gitignore @@ -0,0 +1,2 @@ +node_modules/ +.mutants/ diff --git a/00PluginProfiler.plugin.js b/00PluginProfiler.plugin.js new file mode 100644 index 0000000..a4256a6 --- /dev/null +++ b/00PluginProfiler.plugin.js @@ -0,0 +1,567 @@ +/** + * @name PluginProfiler + * @description Measures the main-thread time of each plugin and shows the CPU and memory use of Discord. Open the plugin settings to see the report. + * @version 1.0.0 + */ + +"use strict"; + +const NAME = "PluginProfiler"; +const VERSION = "1.0.0"; +// BetterDiscord gives each plugin file this source URL. Old versions do not have "betterdiscord/". +const PLUGIN_URL = /^betterdiscord:\/\/(?:betterdiscord\/)?plugins\/(.+)$/; +// A timer that a library makes for a plugin belongs to that plugin, not to the library. +const LIBRARY_FILES = new Set(["0BDFDB.plugin.js", "0PluginLibrary.plugin.js", "1XenoLib.plugin.js"]); +// BetterDiscord and BDFDB call these plugin methods by name, so a wrapper on the instance sees each call. +const INSTANCE_HOOKS = /^(observer|onSwitch|process[A-Z]\w*)$/; +const OBSERVERS = [ + ["MutationObserver", "mutation observer"], + ["ResizeObserver", "resize observer"], + ["IntersectionObserver", "intersection observer"] +]; +const ORIGINAL = Symbol("PluginProfiler.original"); +const SAMPLE_MS = 1000; +const RESCAN_EVERY = 5; +const MAX_SCRIPTS = 500; +const NOTE = "The table counts synchronous work in patches, plugin hooks, timers, and observers. " + + "Plugin time is wall time on the main thread. It includes waits for disk and for paged-out memory, so it can be more than the CPU time. " + + "It does not count event listeners, async work, CSS, or memory per plugin. " + + "Reload Discord (Ctrl+R) to also count the timers that plugins make when they start."; + +/** Adds up the self time of each owner. The time of a nested call goes to the nested owner only. */ +class Recorder { + constructor(now) { + this.now = now; + this.active = true; + this.reset(); + } + + reset() { + this.startedAt = this.now(); + this.owners = new Map(); + this.unattributedMs = 0; + this.stack = []; + } + + /** Calls fn and adds its self time to owner. A null owner marks time that no plugin owns. */ + run(owner, kind, fn, thisArg, args) { + if (!this.active) return Reflect.apply(fn, thisArg, args); + const stack = this.stack; + const frame = {start: this.now(), child: 0}; + stack.push(frame); + try { + return Reflect.apply(fn, thisArg, args); + } + finally { + const total = this.now() - frame.start; + stack.pop(); + if (stack.length) stack[stack.length - 1].child += total; + const self = total - frame.child; + if (owner === null) this.unattributedMs += self; + else this.add(owner, kind, self); + } + } + + add(owner, kind, ms) { + let entry = this.owners.get(owner); + if (!entry) this.owners.set(owner, entry = {ms: 0, calls: 0, maxMs: 0, kinds: new Map()}); + entry.ms += ms; + entry.calls += 1; + if (ms > entry.maxMs) entry.maxMs = ms; + entry.kinds.set(kind, (entry.kinds.get(kind) || 0) + ms); + } + + /** Returns one row for each owner. The row with the most CPU time is first. */ + rows() { + const elapsed = Math.max(1, this.now() - this.startedAt); + return [...this.owners].map(([name, entry]) => ({ + name, + ms: entry.ms, + calls: entry.calls, + maxMs: entry.maxMs, + percent: entry.ms / elapsed * 100, + topKind: [...entry.kinds].sort((a, b) => b[1] - a[1])[0][0] + })).sort((a, b) => b.ms - a.ms); + } +} + +function timed(recorder, owner, kind, fn) { + const wrapper = function (...args) { + return recorder.run(owner, kind, fn, this, args); + }; + wrapper[ORIGINAL] = fn; + return wrapper; +} + +/** Returns the file of each plugin frame on the stack, innermost first. */ +function pluginFilesOnStack() { + const prepare = Error.prepareStackTrace; + const limit = Error.stackTraceLimit; + const holder = {}; + let sites; + try { + // Call sites cost less than a formatted stack string. + Error.prepareStackTrace = (_, callSites) => callSites; + Error.stackTraceLimit = 40; + Error.captureStackTrace(holder, pluginFilesOnStack); + sites = holder.stack; + } + finally { + Error.prepareStackTrace = prepare; + Error.stackTraceLimit = limit; + } + const files = []; + if (!Array.isArray(sites)) return files; + for (const site of sites) { + const match = PLUGIN_URL.exec(site.getScriptNameOrSourceURL() || ""); + if (match) files.push(match[1]); + } + return files; +} + +/** Picks the innermost plugin that is not a library. If only libraries are on the stack, picks the innermost library. */ +function ownerFile(files, ownFile) { + let library = null; + for (const file of files) { + if (file === ownFile) continue; + if (!LIBRARY_FILES.has(file)) return file; + if (!library) library = file; + } + return library; +} + +function hookTimers(scope, recorder, resolveOwner, undo) { + for (const name of ["setTimeout", "setInterval"]) { + const original = scope[name]; + if (typeof original !== "function") continue; + const hooked = function (handler, ...rest) { + if (typeof handler === "function" && recorder.active) { + const owner = recorder.run(NAME, "stack capture", resolveOwner, null, []); + if (owner) handler = timed(recorder, owner, "timer", handler); + } + return Reflect.apply(original, scope, [handler, ...rest]); + }; + hooked[ORIGINAL] = original; + scope[name] = hooked; + undo.push(() => { + if (scope[name] === hooked) scope[name] = original; + }); + } +} + +function hookObservers(scope, recorder, resolveOwner, undo) { + for (const [name, kind] of OBSERVERS) { + const Original = scope[name]; + if (typeof Original !== "function") continue; + const Hooked = class extends Original { + constructor(callback, ...rest) { + if (typeof callback === "function" && recorder.active) { + const owner = recorder.run(NAME, "stack capture", resolveOwner, null, []); + if (owner) callback = timed(recorder, owner, kind, callback); + } + super(callback, ...rest); + } + }; + Object.defineProperty(Hooked, "name", {value: name}); + scope[name] = Hooked; + undo.push(() => { + if (scope[name] === Hooked) scope[name] = Original; + }); + } +} + +/** Wraps the plugin methods that BetterDiscord and BDFDB call by name. */ +function hookInstance(recorder, instance, owner, undo) { + const seen = new Set(); + for (let proto = instance; proto && proto !== Object.prototype; proto = Object.getPrototypeOf(proto)) { + for (const key of Object.getOwnPropertyNames(proto)) { + if (seen.has(key) || !INSTANCE_HOOKS.test(key)) continue; + seen.add(key); + const current = Object.getOwnPropertyDescriptor(proto, key).value; + if (typeof current !== "function" || current[ORIGINAL]) continue; + const wrapper = timed(recorder, owner, key.startsWith("process") ? "BDFDB process" : key, current); + const hadOwn = proto === instance; + try { + instance[key] = wrapper; + } + catch { + continue; + } + undo.push(() => { + if (instance[key] !== wrapper) return; + if (hadOwn) instance[key] = current; + else delete instance[key]; + }); + } + } +} + +/** Wraps the callback of one BetterDiscord patch. BetterDiscord reads the callback on each call. */ +function wrapPatchChild(recorder, child, owner) { + const original = child.callback; + if (typeof original !== "function" || original[ORIGINAL]) return false; + const kind = `patch ${child.type}`; + const wrapper = child.type === "instead" + ? function (thisObject, args, next) { + // "next" runs the original function or the next plugin. That time is not the time of this plugin. + const timedNext = typeof next === "function" ? timed(recorder, null, "original", next) : next; + return recorder.run(owner, kind, original, this, [thisObject, args, timedNext]); + } + : function (...args) { + return recorder.run(owner, kind, original, this, args); + }; + wrapper[ORIGINAL] = original; + child.callback = wrapper; + return true; +} + +function unwrapPatchChild(child) { + const original = child.callback && child.callback[ORIGINAL]; + if (original) child.callback = original; +} + +/** + * BDFDB puts all its plugins behind one BetterDiscord patch. It calls each plugin callback + * through TimeUtils.suppress with the plugin name, so a hook there splits the time per plugin. + */ +function hookSuppress(recorder, bdfdb, canonicalName, undo) { + const timeUtils = bdfdb && bdfdb.TimeUtils; + const original = timeUtils && timeUtils.suppress; + if (typeof original !== "function" || original[ORIGINAL]) return false; + const hooked = function (callback, strings, config) { + const inner = Reflect.apply(original, this, [callback, strings, config]); + const name = config && typeof config.name === "string" ? config.name : ""; + if (!name || typeof inner !== "function") return inner; + // BDFDB uses the name "Discord" when it calls the original Discord function. + return timed(recorder, name === "Discord" ? null : canonicalName(name), "BDFDB hook", inner); + }; + hooked[ORIGINAL] = original; + timeUtils.suppress = hooked; + undo.push(() => { + if (timeUtils.suppress === hooked) timeUtils.suppress = original; + }); + return true; +} + +/** Returns the names that a plugin can use as the caller of its patches. */ +function callerNames(addon) { + const names = new Set([addon.name, addon.id]); + if (typeof addon.name === "string") names.add(addon.name.replace(/\s+/g, "")); + if (typeof addon.filename === "string") names.add(addon.filename.replace(/\.plugin\.js$/, "")); + try { + if (addon.instance && typeof addon.instance.getName === "function") names.add(addon.instance.getName()); + } + catch { + // A broken getName does not stop the scan. + } + return [...names].filter(name => typeof name === "string" && name); +} + +function formatDuration(ms) { + const seconds = Math.floor(ms / 1000); + return `${Math.floor(seconds / 60)}m ${seconds % 60}s`; +} + +function percent(value, digits = 1) { + return `${value.toFixed(digits)}%`; +} + +function megabytes(bytes) { + return `${(bytes / 1048576).toFixed(0)} MB`; +} + +const COLUMNS = [ + {label: "Plugin", align: "left", value: row => row.name}, + {label: "Main thread ms", align: "right", value: row => row.ms.toFixed(1)}, + {label: "% of time", align: "right", value: row => row.percent.toFixed(2)}, + {label: "Calls", align: "right", value: row => String(row.calls)}, + {label: "Worst call ms", align: "right", value: row => row.maxMs.toFixed(1)}, + {label: "Main source", align: "left", value: row => row.topKind} +]; + +function summaryLines(snap) { + const samples = snap.samples; + const frames = snap.frames; + const lines = [`Session: ${formatDuration(snap.elapsedMs)}. All plugins: ${snap.pluginMs.toFixed(0)} ms on the main thread, ${percent(snap.pluginMs / snap.elapsedMs * 100, 2)} of the time.`]; + if (samples.count) { + lines.push(`Discord CPU, all processes: now ${percent(samples.cpuNow)}, average ${percent(samples.cpuSum / samples.count)}, max ${percent(samples.cpuMax)} of one core.`); + const types = [...samples.types].map(([type, sum]) => `${type} ${percent(sum / samples.count)}`).join(", "); + if (types) lines.push(`Average CPU by process type: ${types}.`); + } + else { + lines.push("Discord CPU: no data yet."); + } + if (samples.heapNow !== null) { + const blink = samples.blinkKB ? ` Blink memory: ${megabytes(samples.blinkKB * 1024)}.` : ""; + lines.push(`Renderer JS heap: ${megabytes(samples.heapNow)} (max ${megabytes(samples.heapMax)}).${blink}`); + } + if (snap.framesSupported) { + lines.push(`Long frames (over 50 ms): ${frames.count}, worst ${frames.worstMs.toFixed(0)} ms, blocking time ${frames.blockingMs.toFixed(0)} ms.`); + } + return lines; +} + +const STYLE = { + root: {color: "var(--text-default, var(--text-normal, #dbdee1))", fontSize: 14, lineHeight: 1.45, userSelect: "text"}, + buttons: {display: "flex", gap: 8, marginBottom: 12}, + button: {padding: "6px 14px", borderRadius: 4, border: 0, cursor: "pointer", color: "#fff", background: "var(--button-secondary-background, #4e5058)"}, + scroll: {overflowX: "auto", marginTop: 12}, + table: {width: "100%", borderCollapse: "collapse", fontVariantNumeric: "tabular-nums"}, + th: {padding: "4px 8px", fontWeight: 600, whiteSpace: "nowrap", borderBottom: "1px solid var(--background-modifier-accent, #4e5058)"}, + td: {padding: "4px 8px", whiteSpace: "nowrap", borderBottom: "1px solid var(--background-modifier-accent, #3f4147)"}, + heading: {fontWeight: 600, marginTop: 14}, + note: {opacity: 0.7, fontSize: 12, marginTop: 14} +}; + +function Panel({plugin}) { + const {createElement: h, useEffect, useState} = BdApi.React; + const [, setTick] = useState(0); + useEffect(() => { + const id = setInterval(() => setTick(n => n + 1), SAMPLE_MS); + return () => clearInterval(id); + }, []); + const snap = plugin.snapshot(); + if (!snap) return h("div", {style: STYLE.root}, "Enable the plugin to start the profiler."); + const cell = (column, content, base) => h(base === STYLE.th ? "th" : "td", {key: column.label, style: {...base, textAlign: column.align}}, content); + return h("div", {style: STYLE.root}, + h("div", {style: STYLE.buttons}, + h("button", {style: STYLE.button, onClick: () => { plugin.reset(); setTick(n => n + 1); }}, "Reset"), + h("button", {style: STYLE.button, onClick: () => plugin.copyReport()}, "Copy report")), + summaryLines(snap).map((line, i) => h("div", {key: i}, line)), + h("div", {style: STYLE.scroll}, + h("table", {style: STYLE.table}, + h("thead", null, h("tr", null, COLUMNS.map(column => cell(column, column.label, STYLE.th)))), + h("tbody", null, snap.rows.map(row => h("tr", {key: row.name}, COLUMNS.map(column => cell(column, column.value(row), STYLE.td))))))), + snap.scripts.length ? h("div", {style: STYLE.heading}, "Scripts in long frames") : null, + snap.scripts.map(([label, ms]) => h("div", {key: label}, `${ms.toFixed(0)} ms: ${label}`)), + h("div", {style: STYLE.note}, NOTE)); +} + +class PluginProfiler { + constructor(meta) { + this.meta = meta || {}; + this.ownFile = this.meta.filename || pluginFilesOnStack()[0] || ""; + this.recorder = null; + } + + start() { + const recorder = this.recorder = new Recorder(() => performance.now()); + this.undo = []; + this.callers = new Set(); + this.fileOwners = new Map(); + this.names = new Map(); + this.bdfdbGlobal = null; + this.ticks = 0; + this.resetStats(); + const resolveOwner = () => { + const file = ownerFile(pluginFilesOnStack(), this.ownFile); + return file ? this.fileOwners.get(file) || file : null; + }; + try { + recorder.run(NAME, "setup", () => { + hookTimers(window, recorder, resolveOwner, this.undo); + hookObservers(window, recorder, resolveOwner, this.undo); + this.rescan(); + this.observeFrames(); + }, null, []); + } + catch (error) { + // BetterDiscord does not call stop() after a failed start(), so remove the hooks here. + this.stop(); + throw error; + } + this.timer = setInterval(() => recorder.run(NAME, "sampling", () => this.tick(), null, []), SAMPLE_MS); + } + + stop() { + if (!this.recorder) return; + clearInterval(this.timer); + if (this.frameObserver) this.frameObserver.disconnect(); + this.frameObserver = null; + this.recorder.active = false; + for (const caller of this.callers) { + for (const child of BdApi.Patcher.getPatchesByCaller(caller)) unwrapPatchChild(child); + } + while (this.undo.length) { + try { + this.undo.pop()(); + } + catch (error) { + console.error(NAME, "could not remove a hook", error); + } + } + this.recorder = null; + } + + getSettingsPanel() { + return BdApi.React.createElement(Panel, {plugin: this}); + } + + resetStats() { + this.samples = {count: 0, cpuNow: 0, cpuSum: 0, cpuMax: 0, types: new Map(), heapNow: null, heapMax: 0, blinkKB: 0}; + this.frames = {count: 0, totalMs: 0, blockingMs: 0, worstMs: 0, scripts: new Map()}; + } + + reset() { + if (!this.recorder) return; + this.recorder.reset(); + this.resetStats(); + } + + tick() { + this.ticks += 1; + if (this.ticks % RESCAN_EVERY === 0) this.rescan(); + this.sample(); + } + + /** Finds new patches, plugin instances, and a new BDFDB. Plugins can patch at any time. */ + rescan() { + this.fileOwners = new Map(); + this.names = new Map(); + for (const addon of BdApi.Plugins.getAll()) { + if (!addon || addon.name === NAME) continue; + if (addon.filename) this.fileOwners.set(addon.filename, addon.name); + this.names.set(String(addon.name).toLowerCase(), addon.name); + for (const caller of callerNames(addon)) { + this.callers.add(caller); + for (const child of BdApi.Patcher.getPatchesByCaller(caller)) wrapPatchChild(this.recorder, child, addon.name); + } + if (addon.instance) hookInstance(this.recorder, addon.instance, addon.name, this.undo); + } + this.hookBdfdb(); + } + + hookBdfdb() { + const global = window.BDFDB_Global; + if (!global || !global.loaded || global === this.bdfdbGlobal) return; + this.bdfdbGlobal = global; + let bdfdb; + try { + // buildPlugin only makes a class and returns it with the library object. + bdfdb = global.PluginUtils.buildPlugin({})[1]; + } + catch { + return; + } + hookSuppress(this.recorder, bdfdb, name => this.names.get(name.toLowerCase()) || name, this.undo); + } + + sample() { + const samples = this.samples; + const utils = window.DiscordNative && window.DiscordNative.processUtils; + if (utils && typeof utils.getCurrentCPUUsagePercent === "function") { + // Discord adds up the CPU of all its processes. 100 means one full core. + const cpu = Number(utils.getCurrentCPUUsagePercent()); + if (Number.isFinite(cpu)) { + samples.count += 1; + samples.cpuNow = cpu; + samples.cpuSum += cpu; + samples.cpuMax = Math.max(samples.cpuMax, cpu); + const types = typeof utils.getCpuUsageElectronProcessTypeDetails === "function" ? utils.getCpuUsageElectronProcessTypeDetails() : null; + for (const [type, detail] of Object.entries(types || {})) { + const value = Number(detail && detail.percent_cpu); + if (Number.isFinite(value)) samples.types.set(type, (samples.types.get(type) || 0) + value); + } + } + } + if (performance.memory) { + samples.heapNow = performance.memory.usedJSHeapSize; + samples.heapMax = Math.max(samples.heapMax, samples.heapNow); + } + if (utils && typeof utils.getBlinkMemoryInfo === "function") { + const blink = utils.getBlinkMemoryInfo(); + if (blink && Number.isFinite(blink.allocated)) samples.blinkKB = blink.allocated; + } + } + + observeFrames() { + const types = typeof PerformanceObserver === "function" ? PerformanceObserver.supportedEntryTypes || [] : []; + this.framesSupported = types.includes("long-animation-frame"); + if (!this.framesSupported) return; + const recorder = this.recorder; + this.frameObserver = new PerformanceObserver(list => recorder.run(NAME, "frame stats", () => this.addFrames(list.getEntries()), null, [])); + this.frameObserver.observe({type: "long-animation-frame"}); + } + + addFrames(entries) { + const frames = this.frames; + for (const entry of entries) { + frames.count += 1; + frames.totalMs += entry.duration; + frames.blockingMs += entry.blockingDuration || 0; + frames.worstMs = Math.max(frames.worstMs, entry.duration); + for (const script of entry.scripts || []) { + const label = this.scriptLabel(script); + if (frames.scripts.has(label) || frames.scripts.size < MAX_SCRIPTS) { + frames.scripts.set(label, (frames.scripts.get(label) || 0) + script.duration); + } + } + } + } + + scriptLabel(script) { + const url = script.sourceURL || ""; + const match = PLUGIN_URL.exec(url); + const file = url.split(/[?#]/)[0].split("/").pop(); + // A URL that is not a .js file is the page itself. It can hold a channel ID, so the label does not show it. + const where = match ? this.fileOwners.get(match[1]) || match[1] : /\.js$/.test(file) ? file : "page"; + const invoker = script.sourceFunctionName || script.invoker || ""; + const what = invoker.includes("://") ? "" : invoker; + return what ? `${where} (${what})` : where; + } + + snapshot() { + if (!this.recorder) return null; + const elapsedMs = Math.max(1, this.recorder.now() - this.recorder.startedAt); + const rows = this.recorder.rows(); + const pluginMs = rows.filter(row => row.name !== NAME).reduce((sum, row) => sum + row.ms, 0); + const scripts = [...this.frames.scripts].sort((a, b) => b[1] - a[1]).slice(0, 5); + return {elapsedMs, rows, pluginMs, samples: this.samples, frames: this.frames, framesSupported: this.framesSupported, scripts}; + } + + report() { + const snap = this.snapshot(); + if (!snap) return `${NAME}: the plugin is not running.`; + const table = [COLUMNS.map(column => column.label), ...snap.rows.map(row => COLUMNS.map(column => column.value(row)))]; + const widths = COLUMNS.map((_, i) => Math.max(...table.map(cells => cells[i].length))); + const lines = [`${NAME} ${VERSION} report`, ...summaryLines(snap), ""]; + for (const cells of table) { + lines.push(cells.map((text, i) => COLUMNS[i].align === "right" ? text.padStart(widths[i]) : text.padEnd(widths[i])).join(" ").trimEnd()); + } + if (snap.scripts.length) { + lines.push("", "Scripts in long frames:"); + for (const [label, ms] of snap.scripts) lines.push(`${ms.toFixed(0).padStart(7)} ms ${label}`); + } + lines.push("", NOTE); + return lines.join("\n"); + } + + copyReport() { + const text = this.report(); + const done = () => BdApi.UI.showToast("Profiler report copied.", {type: "success"}); + const fail = error => { + console.error(NAME, "could not copy the report", error); + BdApi.UI.showToast("Could not copy the report. The console has the error.", {type: "error"}); + }; + try { + const clipboard = window.DiscordNative && window.DiscordNative.clipboard; + if (clipboard && typeof clipboard.copy === "function") { + clipboard.copy(text); + done(); + } + else { + navigator.clipboard.writeText(text).then(done, fail); + } + } + catch (error) { + fail(error); + } + } +} + +PluginProfiler.internals = { + Recorder, timed, pluginFilesOnStack, ownerFile, hookTimers, hookObservers, hookInstance, + wrapPatchChild, unwrapPatchChild, hookSuppress, callerNames, ORIGINAL +}; + +module.exports = PluginProfiler; diff --git a/README.md b/README.md new file mode 100644 index 0000000..30f8e61 --- /dev/null +++ b/README.md @@ -0,0 +1,26 @@ +# PluginProfiler + +PluginProfiler is a BetterDiscord plugin. It measures the main-thread time that each plugin uses. It also shows the CPU and memory use of Discord. + +## Install + +1. Copy `00PluginProfiler.plugin.js` into the BetterDiscord plugins folder (`%APPDATA%\BetterDiscord\plugins`). +2. In Discord, open Settings > Plugins and turn on PluginProfiler. +3. Press Ctrl+R. The file name starts with `00`, so the profiler starts before the other plugins. Then it also sees the timers that the other plugins make when they start. +4. Open the settings of PluginProfiler to see the table. Click "Copy report" to copy the data as text. + +## What it measures + +- Time in BetterDiscord patch callbacks, per plugin. The time of the original Discord function does not count. +- Time in the plugin callbacks that the BDFDB library runs, per plugin. +- Time in the `observer`, `onSwitch`, and BDFDB `process*` methods of each plugin. +- Time in the timers and observers that a plugin makes. The profiler finds the plugin from the call stack. +- The CPU of all Discord processes, the renderer JS heap, and long animation frames. + +The time is wall time on the main thread. It includes waits for disk and for paged-out memory, so it can be more than the CPU time. + +The profiler does not measure event listeners, async work, CSS, or memory per plugin. + +## Tests + +Run `npm test` with Node 22 or later. The tests load the patcher of the installed BetterDiscord and `TimeUtils.suppress` of the installed BDFDB, so both must be installed. diff --git a/package-lock.json b/package-lock.json new file mode 100644 index 0000000..0ec38d2 --- /dev/null +++ b/package-lock.json @@ -0,0 +1,53 @@ +{ + "name": "plugin-profiler", + "lockfileVersion": 3, + "requires": true, + "packages": { + "": { + "name": "plugin-profiler", + "devDependencies": { + "fast-check": "^4.10.2" + } + }, + "node_modules/fast-check": { + "version": "4.10.2", + "resolved": "https://registry.npmjs.org/fast-check/-/fast-check-4.10.2.tgz", + "integrity": "sha512-iK2f+YrcmoeGqk6fA0ea2bptcu/itMIm4NfEozq6N25+aG6h7s5HZbB/k1aV7b5w5sFLMCbbtRUsTVR+BgC3xw==", + "dev": true, + "funding": [ + { + "type": "individual", + "url": "https://github.com/sponsors/dubzzz" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fast-check" + } + ], + "license": "MIT", + "dependencies": { + "pure-rand": "^8.0.0" + }, + "engines": { + "node": ">=12.17.0" + } + }, + "node_modules/pure-rand": { + "version": "8.4.2", + "resolved": "https://registry.npmjs.org/pure-rand/-/pure-rand-8.4.2.tgz", + "integrity": "sha512-vvuOGgcuPJAirlHvuQw1TrOiw7ptaIXXmIbNuiNOY6lNGJJH49PQ1Kj4nd783nPdQhQdicgOjVI2yI/9BD6/Ng==", + "dev": true, + "funding": [ + { + "type": "individual", + "url": "https://github.com/sponsors/dubzzz" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fast-check" + } + ], + "license": "MIT" + } + } +} diff --git a/package.json b/package.json new file mode 100644 index 0000000..5ae868a --- /dev/null +++ b/package.json @@ -0,0 +1 @@ +{"name":"plugin-profiler","private":true,"scripts":{"test":"node --test test/*.test.js"},"devDependencies":{"fast-check":"^4.10.2"}} \ No newline at end of file diff --git a/test/bd-patcher.test.js b/test/bd-patcher.test.js new file mode 100644 index 0000000..5dcb72f --- /dev/null +++ b/test/bd-patcher.test.js @@ -0,0 +1,101 @@ +"use strict"; +const test = require("node:test"); +const assert = require("node:assert/strict"); +const {loadBdPatcher} = require("./helpers/installed.js"); +const {Recorder, wrapPatchChild, unwrapPatchChild} = require("../00PluginProfiler.plugin.js").internals; + +function setup() { + const errors = []; + const Patcher = loadBdPatcher({err: (...args) => errors.push(args)}); + const clock = {t: 0}; + const recorder = new Recorder(() => clock.t); + const msByOwner = () => Object.fromEntries([...recorder.owners].map(([name, entry]) => [name, entry.ms])); + const wrapAll = callers => { + const children = callers.flatMap(caller => Patcher.getPatchesByCaller(caller)); + for (const child of children) assert.equal(wrapPatchChild(recorder, child, child.caller), true); + return children; + }; + return {Patcher, errors, clock, recorder, msByOwner, wrapAll}; +} + +test("patch time goes to the plugin, the original function time does not, and results stay the same", () => { + const {Patcher, errors, clock, recorder, msByOwner, wrapAll} = setup(); + const target = {work(x) { clock.t += 100; return x * 2; }}; + Patcher.before("A", target, "work", () => { clock.t += 5; }); + Patcher.instead("B", target, "work", (self, args, next) => { clock.t += 7; return next(...args) + 1; }); + Patcher.after("C", target, "work", (self, args, value) => { clock.t += 3; return value + 10; }); + const expected = target.work(4); + assert.equal(expected, 19); + + const children = wrapAll(["A", "B", "C"]); + assert.equal(target.work(4), expected); + assert.deepEqual(msByOwner(), {A: 5, B: 7, C: 3}); + assert.equal(recorder.unattributedMs, 100); + + // A second scan must not wrap a wrapper. + for (const child of children) assert.equal(wrapPatchChild(recorder, child, child.caller), false); + for (const child of children) unwrapPatchChild(child); + assert.equal(target.work(4), expected); + assert.deepEqual(errors, []); +}); + +test("unwrap puts back the exact callbacks", () => { + const {Patcher, wrapAll} = setup(); + const target = {work() { return 1; }}; + const before = () => {}; + const after = (self, args, value) => value; + Patcher.before("A", target, "work", before); + Patcher.after("A", target, "work", after); + const children = wrapAll(["A"]); + assert.notEqual(children[0].callback, before); + for (const child of children) unwrapPatchChild(child); + assert.deepEqual(children.map(child => child.callback), [before, after]); +}); + +test("chained instead patches each get only their own time", () => { + const {Patcher, clock, recorder, msByOwner, wrapAll} = setup(); + const target = {work(x) { clock.t += 40; return x; }}; + Patcher.instead("B1", target, "work", (self, args, next) => { clock.t += 2; const value = next(...args); clock.t += 1; return value + 1; }); + Patcher.instead("B2", target, "work", (self, args, next) => { clock.t += 4; return next(...args) * 10; }); + const expected = target.work(1); + wrapAll(["B1", "B2"]); + assert.equal(target.work(1), expected); + assert.deepEqual(msByOwner(), {B1: 3, B2: 4}); + assert.equal(recorder.unattributedMs, 40); +}); + +test("a patch that calls a patched function pays for the Discord work but not for the other plugin", () => { + const {Patcher, clock, msByOwner, wrapAll} = setup(); + const inner = {step() { clock.t += 10; }}; + const outer = {work() { clock.t += 1; }}; + Patcher.after("C", inner, "step", () => { clock.t += 6; }); + Patcher.before("A", outer, "work", () => { clock.t += 2; inner.step(); }); + wrapAll(["A", "C"]); + outer.work(); + // Without plugin A, Discord does not call inner.step here. So A owns those 10 ms. Plugin C owns its 6 ms. + assert.deepEqual(msByOwner(), {A: 12, C: 6}); +}); + +test("a plugin can unpatch while the profiler wraps its callback", () => { + const {Patcher, clock, msByOwner, wrapAll} = setup(); + const target = {work() { return "original"; }}; + const unpatch = Patcher.after("A", target, "work", () => { clock.t += 1; return "patched"; }); + wrapAll(["A"]); + assert.equal(target.work(), "patched"); + unpatch(); + assert.equal(target.work(), "original"); + assert.deepEqual(Patcher.getPatchesByCaller("A"), []); + assert.deepEqual(msByOwner(), {A: 1}); +}); + +test("an error in a wrapped callback reaches the BetterDiscord logger as before", () => { + const {Patcher, errors, recorder, wrapAll} = setup(); + const target = {work() { return 5; }}; + Patcher.before("A", target, "work", () => { throw new Error("plugin bug"); }); + wrapAll(["A"]); + assert.equal(target.work(), 5); + assert.equal(errors.length, 1); + assert.equal(errors[0][2].message, "plugin bug"); + assert.equal(recorder.stack.length, 0); + assert.equal(recorder.owners.get("A").calls, 1); +}); diff --git a/test/helpers/installed.js b/test/helpers/installed.js new file mode 100644 index 0000000..7b6fea0 --- /dev/null +++ b/test/helpers/installed.js @@ -0,0 +1,50 @@ +"use strict"; +// Loads code from the installed BetterDiscord and BDFDB, so the tests check the versions that Discord runs. +const fs = require("node:fs"); +const path = require("node:path"); + +const BD_FOLDER = path.join(process.env.APPDATA || "", "BetterDiscord"); +const BD_ASAR = path.join(BD_FOLDER, "data", "betterdiscord.asar"); +const BDFDB_FILE = path.join(BD_FOLDER, "plugins", "0BDFDB.plugin.js"); + +/** Reads one top-level file from an asar archive. */ +function readAsarFile(archive, name) { + const buffer = fs.readFileSync(archive); + const headerPickleSize = buffer.readUInt32LE(4); + const jsonLength = buffer.readUInt32LE(12); + const header = JSON.parse(buffer.toString("utf8", 16, 16 + jsonLength)); + const entry = header.files[name]; + const start = 8 + headerPickleSize + Number(entry.offset); + return buffer.toString("utf8", start, start + entry.size); +} + +/** Returns the index of the brace that closes the brace at openIndex. */ +function closingBrace(text, openIndex) { + let depth = 0; + for (let i = openIndex; i < text.length; i++) { + if (text[i] === "{") depth++; + else if (text[i] === "}" && --depth === 0) return i; + } + throw new Error("no closing brace"); +} + +/** Returns the internal Patcher class of the installed BetterDiscord. */ +function loadBdPatcher(logger) { + const source = readAsarFile(BD_ASAR, "betterdiscord.js"); + const marker = source.indexOf("static getPatchesByCaller("); + if (marker < 0) throw new Error("BetterDiscord Patcher not found"); + const classStart = source.lastIndexOf("=class{", marker) + 1; + const body = source.slice(classStart, closingBrace(source, classStart + "class".length) + 1); + // The minified class uses g (logger), w (module cache), and ae (module search) from its bundle. + return new Function("g", "w", "ae", `return ${body};`)(logger, {}, () => null); +} + +/** Returns BDFDB.TimeUtils.suppress from the installed BDFDB library. */ +function loadBdfdbSuppress(logUtils) { + const source = fs.readFileSync(BDFDB_FILE, "utf8"); + const match = /BDFDB\.TimeUtils\.suppress = (function \(callback, strings, config\) \{[\s\S]*?\n\t*\}\};)/.exec(source); + if (!match) throw new Error("BDFDB TimeUtils.suppress not found"); + return new Function("BDFDB", `return ${match[1].slice(0, -1)}`)({LogUtils: logUtils}); +} + +module.exports = {BD_ASAR, BDFDB_FILE, loadBdPatcher, loadBdfdbSuppress}; diff --git a/test/hooks.test.js b/test/hooks.test.js new file mode 100644 index 0000000..0792e86 --- /dev/null +++ b/test/hooks.test.js @@ -0,0 +1,174 @@ +"use strict"; +const test = require("node:test"); +const assert = require("node:assert/strict"); +const {loadBdfdbSuppress} = require("./helpers/installed.js"); +const { + Recorder, pluginFilesOnStack, ownerFile, hookTimers, hookObservers, hookInstance, hookSuppress, callerNames, ORIGINAL +} = require("../00PluginProfiler.plugin.js").internals; + +const OWN_FILE = "00PluginProfiler.plugin.js"; + +/** Makes a function whose code has the source URL that BetterDiscord gives to a plugin file. */ +function inPluginFile(url, param, body) { + return new Function(param, `${body}\n//# sourceURL=${url}`); +} + +function setup() { + const clock = {t: 0}; + const recorder = new Recorder(() => clock.t); + const entry = name => recorder.owners.get(name); + return {clock, recorder, entry, undo: []}; +} + +test("the stack gives the plugin file, and a library gives way to the plugin that called it", () => { + const library = inPluginFile("betterdiscord://betterdiscord/plugins/0BDFDB.plugin.js", "callback", "return function libraryHelper() { return callback(); };")(pluginFilesOnStack); + const plugin = inPluginFile("betterdiscord://betterdiscord/plugins/FriendNotifications.plugin.js", "library", "return function pluginWork() { return library(); };")(library); + const files = plugin(); + assert.deepEqual(files, ["0BDFDB.plugin.js", "FriendNotifications.plugin.js"]); + assert.equal(ownerFile(files, OWN_FILE), "FriendNotifications.plugin.js"); + assert.equal(ownerFile(["0BDFDB.plugin.js"], OWN_FILE), "0BDFDB.plugin.js"); + assert.equal(ownerFile([OWN_FILE, OWN_FILE], OWN_FILE), null); + assert.equal(ownerFile([], OWN_FILE), null); +}); + +test("old BetterDiscord source URLs also match", () => { + const plugin = inPluginFile("betterdiscord://plugins/Old.plugin.js", "capture", "return function oldWork() { return capture(); };")(pluginFilesOnStack); + assert.deepEqual(plugin(), ["Old.plugin.js"]); +}); + +test("the stack capture puts back Error.prepareStackTrace and Error.stackTraceLimit", () => { + const prepare = () => "custom"; + const savedPrepare = Error.prepareStackTrace; + const savedLimit = Error.stackTraceLimit; + try { + Error.prepareStackTrace = prepare; + Error.stackTraceLimit = 7; + pluginFilesOnStack(); + assert.equal(Error.prepareStackTrace, prepare); + assert.equal(Error.stackTraceLimit, 7); + assert.equal(new Error("x").stack, "custom"); + } + finally { + Error.prepareStackTrace = savedPrepare; + Error.stackTraceLimit = savedLimit; + } +}); + +test("timer callbacks count for the plugin that made the timer", () => { + const {clock, recorder, entry, undo} = setup(); + const calls = []; + const setTimeout = (handler, ms, ...args) => { calls.push({handler, ms, args}); return 7; }; + const setInterval = (handler, ms) => { calls.push({handler, ms}); return 8; }; + const scope = {setTimeout, setInterval}; + let owner = "FriendNotifications"; + hookTimers(scope, recorder, () => owner, undo); + + assert.equal(scope.setTimeout(() => { clock.t += 4; return "done"; }, 50, "x"), 7); + assert.deepEqual([calls[0].ms, calls[0].args], [50, ["x"]]); + assert.equal(calls[0].handler(), "done"); + assert.equal(entry("FriendNotifications").ms, 4); + assert.equal(entry("FriendNotifications").kinds.get("timer"), 4); + assert.ok(entry("PluginProfiler").kinds.has("stack capture")); + + // A string handler and a handler that no plugin owns pass through unchanged. + scope.setInterval("code()", 5); + assert.equal(calls[1].handler, "code()"); + owner = null; + const discordHandler = () => {}; + scope.setTimeout(discordHandler, 1); + assert.equal(calls[2].handler, discordHandler); + + while (undo.length) undo.pop()(); + assert.equal(scope.setTimeout, setTimeout); + assert.equal(scope.setInterval, setInterval); +}); + +test("observer callbacks count for the plugin that made the observer", () => { + const {clock, recorder, entry, undo} = setup(); + class FakeObserver { + constructor(callback, options) { this.callback = callback; this.options = options; } + } + const scope = {MutationObserver: FakeObserver, ResizeObserver: FakeObserver}; + hookObservers(scope, recorder, () => "SpellCheck", undo); + const observer = new scope.MutationObserver(() => { clock.t += 6; }, {subtree: true}); + assert.ok(observer instanceof FakeObserver); + assert.equal(scope.MutationObserver.name, "MutationObserver"); + assert.deepEqual(observer.options, {subtree: true}); + observer.callback(); + assert.equal(entry("SpellCheck").kinds.get("mutation observer"), 6); + while (undo.length) undo.pop()(); + assert.equal(scope.MutationObserver, FakeObserver); + assert.equal(scope.ResizeObserver, FakeObserver); +}); + +test("plugin methods that BetterDiscord and BDFDB call by name count for the plugin", () => { + const {clock, recorder, entry, undo} = setup(); + class Base { + processMessageToolbar(e) { clock.t += 2; return e + 1; } + start() {} + } + class Plugin extends Base { + observer() { clock.t += 3; } + } + const instance = new Plugin(); + const ownSwitch = function () { clock.t += 1; return this; }; + instance.onSwitch = ownSwitch; + hookInstance(recorder, instance, "SpellCheck", undo); + const undoCount = undo.length; + hookInstance(recorder, instance, "SpellCheck", undo); + assert.equal(undo.length, undoCount, "a second scan adds no hooks"); + + assert.equal(instance.processMessageToolbar(1), 2); + instance.observer(); + assert.equal(instance.onSwitch(), instance); + assert.equal(instance.start, Base.prototype.start); + const kinds = Object.fromEntries(entry("SpellCheck").kinds); + assert.deepEqual(kinds, {"BDFDB process": 2, observer: 3, onSwitch: 1}); + + while (undo.length) undo.pop()(); + assert.equal(Object.hasOwn(instance, "processMessageToolbar"), false); + assert.equal(Object.hasOwn(instance, "observer"), false); + assert.equal(instance.onSwitch, ownSwitch); +}); + +test("BDFDB callbacks count for each plugin, and the original Discord call counts for no plugin", () => { + const {clock, recorder, entry, undo} = setup(); + const logged = []; + const originalSuppress = loadBdfdbSuppress({error: (...args) => logged.push(args)}); + const bdfdb = {TimeUtils: {suppress: originalSuppress}}; + const names = {spellcheck: "SpellCheck"}; + assert.equal(hookSuppress(recorder, bdfdb, name => names[name.toLowerCase()] || name, undo), true); + assert.equal(hookSuppress(recorder, bdfdb, name => name, undo), false, "no second hook"); + + // The same loop shape as BDFDB.PatchUtils.patch: one BetterDiscord patch calls all plugin callbacks. + const callbacks = [ + Object.assign(() => { clock.t += 9; }, {pluginName: "spellcheck"}), + Object.assign(() => { clock.t += 4; throw new Error("plugin bug"); }, {pluginName: "Translator"}) + ]; + const dispatcher = () => { + clock.t += 1; + for (const callback of callbacks) bdfdb.TimeUtils.suppress(callback, "after callback", {name: callback.pluginName})({}); + bdfdb.TimeUtils.suppress(() => { clock.t += 50; }, "originalMethod", {name: "Discord"})(); + }; + recorder.run("BDFDB", "patch after", dispatcher, null, []); + assert.equal(entry("SpellCheck").ms, 9); + assert.equal(entry("Translator").ms, 4); + assert.equal(entry("BDFDB").ms, 1); + assert.equal(recorder.unattributedMs, 50); + assert.equal(logged.length, 1, "BDFDB still logs the plugin error"); + + const plain = bdfdb.TimeUtils.suppress(() => 3, "no config"); + assert.equal(plain[ORIGINAL], undefined); + assert.equal(plain(), 3); + while (undo.length) undo.pop()(); + assert.equal(bdfdb.TimeUtils.suppress, originalSuppress); +}); + +test("caller names cover the forms that plugins use", () => { + const names = callerNames({ + name: "Hide Channels", id: "Hide Channels", filename: "HideChannels.plugin.js", + instance: {getName: () => "HideChannelsPlugin"} + }); + assert.deepEqual(names.sort(), ["Hide Channels", "HideChannels", "HideChannelsPlugin"]); + assert.deepEqual(callerNames({name: "X", instance: {getName() { throw new Error("broken"); }}}), ["X"]); +}); diff --git a/test/lifecycle.test.js b/test/lifecycle.test.js new file mode 100644 index 0000000..82d188b --- /dev/null +++ b/test/lifecycle.test.js @@ -0,0 +1,82 @@ +"use strict"; +const test = require("node:test"); +const assert = require("node:assert/strict"); +const {loadBdPatcher} = require("./helpers/installed.js"); +const PluginProfiler = require("../00PluginProfiler.plugin.js"); + +const META = {filename: "00PluginProfiler.plugin.js", name: "PluginProfiler"}; + +function fakeWindow() { + return { + setTimeout: () => 1, + setInterval: () => 2, + MutationObserver: class {}, + ResizeObserver: class {}, + IntersectionObserver: class {} + }; +} + +test.afterEach(() => { + delete globalThis.window; + delete globalThis.BdApi; +}); + +test("long-frame labels show script files and plugin names, but never the page URL", () => { + const plugin = new PluginProfiler(META); + plugin.fileOwners = new Map([["Foo.plugin.js", "Foo"]]); + const page = "https://discord.com/channels/@me/123456789012345678"; + assert.equal(plugin.scriptLabel({sourceURL: page, invoker: page, invokerType: "classic-script"}), "page"); + assert.equal(plugin.scriptLabel({sourceURL: page, invoker: "DIV.onclick"}), "page (DIV.onclick)"); + assert.equal(plugin.scriptLabel({sourceURL: "https://discord.com/assets/8fe5.js", invoker: "https://discord.com/assets/8fe5.js"}), "8fe5.js"); + assert.equal(plugin.scriptLabel({sourceURL: "https://discord.com/assets/5567.js?v=1", sourceFunctionName: "r"}), "5567.js (r)"); + assert.equal(plugin.scriptLabel({sourceURL: "betterdiscord://betterdiscord/plugins/Foo.plugin.js", invoker: "Window.setTimeout"}), "Foo (Window.setTimeout)"); +}); + +test("a failed start removes every hook", () => { + const scope = globalThis.window = fakeWindow(); + const originals = {...scope}; + globalThis.BdApi = { + Plugins: {getAll() { throw new Error("broken API"); }}, + Patcher: {getPatchesByCaller: () => []} + }; + const plugin = new PluginProfiler(META); + assert.throws(() => plugin.start(), /broken API/); + for (const key of Object.keys(originals)) assert.equal(scope[key], originals[key], key); + assert.equal(plugin.recorder, null); +}); + +test("start wraps patches and hooks of other plugins, and stop removes all of them", () => { + const Patcher = loadBdPatcher({err() {}}); + const target = {work() { return 1; }}; + const callback = () => 2; + Patcher.after("Foo", target, "work", callback); + const observer = () => {}; + const instance = {observer, start() {}, stop() {}}; + const scope = globalThis.window = fakeWindow(); + const originals = {...scope}; + globalThis.BdApi = { + Plugins: {getAll: () => [{name: "Foo", id: "Foo", filename: "Foo.plugin.js", instance}, {...META, id: META.name, instance: {}}]}, + Patcher: {getPatchesByCaller: caller => Patcher.getPatchesByCaller(caller)} + }; + + const plugin = new PluginProfiler(META); + plugin.start(); + try { + assert.notEqual(Patcher.getPatchesByCaller("Foo")[0].callback, callback); + assert.notEqual(instance.observer, observer); + assert.notEqual(scope.setTimeout, originals.setTimeout); + assert.equal(target.work(), 2); + instance.observer(); + const row = plugin.snapshot().rows.find(r => r.name === "Foo"); + assert.equal(row.calls, 2); + assert.match(plugin.report(), /^PluginProfiler 1\.0\.0 report/); + assert.match(plugin.report(), /\nFoo /); + } + finally { + plugin.stop(); + } + assert.equal(Patcher.getPatchesByCaller("Foo")[0].callback, callback); + assert.equal(instance.observer, observer); + for (const key of Object.keys(originals)) assert.equal(scope[key], originals[key], key); + assert.equal(plugin.snapshot(), null); +}); diff --git a/test/recorder.test.js b/test/recorder.test.js new file mode 100644 index 0000000..fc290ad --- /dev/null +++ b/test/recorder.test.js @@ -0,0 +1,100 @@ +"use strict"; +const test = require("node:test"); +const assert = require("node:assert/strict"); +const fc = require("fast-check"); +const {Recorder} = require("../00PluginProfiler.plugin.js").internals; + +const owner = fc.constantFrom("A", "B", "C", null); +const {node: callTree} = fc.letrec(tie => ({ + node: fc.record({ + owner, + before: fc.nat({max: 50}), + after: fc.nat({max: 50}), + throws: fc.nat({max: 9}).map(n => n === 0), + children: fc.oneof({depthSize: "small"}, fc.constant([]), fc.array(tie("node"), {maxLength: 3})) + }) +})); + +/** Runs a call tree through the recorder. The clock moves only when a node does work. */ +function execute(recorder, clock, node) { + return recorder.run(node.owner, "test", () => { + clock.t += node.before; + for (const child of node.children) execute(recorder, clock, child); + if (node.throws) throw new Error("planned failure"); + clock.t += node.after; + return node; + }, null, []); +} + +/** Slow reference: adds up the work of each owner directly. Returns true when the node throws. */ +function reference(node, totals) { + const key = String(node.owner); + totals[key] = totals[key] || {ms: 0, calls: 0}; + totals[key].calls += 1; + totals[key].ms += node.before; + for (const child of node.children) { + if (reference(child, totals)) return true; + } + if (node.throws) return true; + totals[key].ms += node.after; + return false; +} + +test("each owner gets exactly its own work, also when calls throw", () => { + fc.assert(fc.property(fc.array(callTree, {minLength: 1, maxLength: 4}), roots => { + const clock = {t: 1000}; + const recorder = new Recorder(() => clock.t); + const expected = {}; + for (const root of roots) { + let threw = false; + try { + assert.equal(execute(recorder, clock, root), root); + } + catch (error) { + assert.equal(error.message, "planned failure"); + threw = true; + } + assert.equal(reference(root, expected), threw); + assert.equal(recorder.stack.length, 0); + } + const actual = {}; + for (const [name, entry] of recorder.owners) actual[name] = {ms: entry.ms, calls: entry.calls}; + const attributed = Object.fromEntries(Object.entries(expected).filter(([key]) => key !== "null")); + assert.deepEqual(actual, attributed); + assert.equal(recorder.unattributedMs, expected.null ? expected.null.ms : 0); + }), {numRuns: 500}); +}); + +test("rows are sorted by time and give the share of the elapsed time", () => { + fc.assert(fc.property(fc.array(fc.tuple(fc.constantFrom("A", "B", "C", "D"), fc.nat({max: 100})), {maxLength: 30}), calls => { + const clock = {t: 0}; + const recorder = new Recorder(() => clock.t); + for (const [name, ms] of calls) recorder.run(name, "test", () => { clock.t += ms; }, null, []); + clock.t += 7; + const rows = recorder.rows(); + const elapsed = Math.max(1, clock.t); + for (let i = 1; i < rows.length; i++) assert.ok(rows[i - 1].ms >= rows[i].ms); + for (const row of rows) assert.equal(row.percent, row.ms / elapsed * 100); + assert.equal(rows.reduce((sum, row) => sum + row.ms, 0), calls.reduce((sum, [, ms]) => sum + ms, 0)); + })); +}); + +test("an inactive recorder calls through and records nothing", () => { + const clock = {t: 0}; + const recorder = new Recorder(() => clock.t); + recorder.active = false; + const self = {}; + const result = recorder.run("A", "test", function (x) { clock.t += 5; return [this, x]; }, self, [3]); + assert.deepEqual(result, [self, 3]); + assert.equal(recorder.owners.size, 0); +}); + +test("the worst call and the main source come from the recorded calls", () => { + const clock = {t: 0}; + const recorder = new Recorder(() => clock.t); + recorder.run("A", "timer", () => { clock.t += 2; }, null, []); + recorder.run("A", "patch after", () => { clock.t += 9; }, null, []); + recorder.run("A", "timer", () => { clock.t += 3; }, null, []); + const [row] = recorder.rows(); + assert.deepEqual({ms: row.ms, calls: row.calls, maxMs: row.maxMs, topKind: row.topKind}, {ms: 14, calls: 3, maxMs: 9, topKind: "patch after"}); +});