test/recorder.test.js (4316 bytes)
1 "use strict"; 2 const test = require("node:test"); 3 const assert = require("node:assert/strict"); 4 const fc = require("fast-check"); 5 const {Recorder} = require("../00PluginProfiler.plugin.js").internals; 6 7 const owner = fc.constantFrom("A", "B", "C", null); 8 const {node: callTree} = fc.letrec(tie => ({ 9 node: fc.record({ 10 owner, 11 before: fc.nat({max: 50}), 12 after: fc.nat({max: 50}), 13 throws: fc.nat({max: 9}).map(n => n === 0), 14 children: fc.oneof({depthSize: "small"}, fc.constant([]), fc.array(tie("node"), {maxLength: 3})) 15 }) 16 })); 17 18 /** Runs a call tree through the recorder. The clock moves only when a node does work. */ 19 function execute(recorder, clock, node) { 20 return recorder.run(node.owner, "test", () => { 21 clock.t += node.before; 22 for (const child of node.children) execute(recorder, clock, child); 23 if (node.throws) throw new Error("planned failure"); 24 clock.t += node.after; 25 return node; 26 }, null, []); 27 } 28 29 /** Slow reference: adds up the work of each owner directly. Returns true when the node throws. */ 30 function reference(node, totals) { 31 const key = String(node.owner); 32 totals[key] = totals[key] || {ms: 0, calls: 0}; 33 totals[key].calls += 1; 34 totals[key].ms += node.before; 35 for (const child of node.children) { 36 if (reference(child, totals)) return true; 37 } 38 if (node.throws) return true; 39 totals[key].ms += node.after; 40 return false; 41 } 42 43 test("each owner gets exactly its own work, also when calls throw", () => { 44 fc.assert(fc.property(fc.array(callTree, {minLength: 1, maxLength: 4}), roots => { 45 const clock = {t: 1000}; 46 const recorder = new Recorder(() => clock.t); 47 const expected = {}; 48 for (const root of roots) { 49 let threw = false; 50 try { 51 assert.equal(execute(recorder, clock, root), root); 52 } 53 catch (error) { 54 assert.equal(error.message, "planned failure"); 55 threw = true; 56 } 57 assert.equal(reference(root, expected), threw); 58 assert.equal(recorder.stack.length, 0); 59 } 60 const actual = {}; 61 for (const [name, entry] of recorder.owners) actual[name] = {ms: entry.ms, calls: entry.calls}; 62 const attributed = Object.fromEntries(Object.entries(expected).filter(([key]) => key !== "null")); 63 assert.deepEqual(actual, attributed); 64 assert.equal(recorder.unattributedMs, expected.null ? expected.null.ms : 0); 65 }), {numRuns: 500}); 66 }); 67 68 test("rows are sorted by time and give the share of the elapsed time", () => { 69 fc.assert(fc.property(fc.array(fc.tuple(fc.constantFrom("A", "B", "C", "D"), fc.nat({max: 100})), {maxLength: 30}), calls => { 70 const clock = {t: 0}; 71 const recorder = new Recorder(() => clock.t); 72 for (const [name, ms] of calls) recorder.run(name, "test", () => { clock.t += ms; }, null, []); 73 clock.t += 7; 74 const rows = recorder.rows(); 75 const elapsed = Math.max(1, clock.t); 76 for (let i = 1; i < rows.length; i++) assert.ok(rows[i - 1].ms >= rows[i].ms); 77 for (const row of rows) assert.equal(row.percent, row.ms / elapsed * 100); 78 assert.equal(rows.reduce((sum, row) => sum + row.ms, 0), calls.reduce((sum, [, ms]) => sum + ms, 0)); 79 })); 80 }); 81 82 test("an inactive recorder calls through and records nothing", () => { 83 const clock = {t: 0}; 84 const recorder = new Recorder(() => clock.t); 85 recorder.active = false; 86 const self = {}; 87 const result = recorder.run("A", "test", function (x) { clock.t += 5; return [this, x]; }, self, [3]); 88 assert.deepEqual(result, [self, 3]); 89 assert.equal(recorder.owners.size, 0); 90 }); 91 92 test("the worst call and the main source come from the recorded calls", () => { 93 const clock = {t: 0}; 94 const recorder = new Recorder(() => clock.t); 95 recorder.run("A", "timer", () => { clock.t += 2; }, null, []); 96 recorder.run("A", "patch after", () => { clock.t += 9; }, null, []); 97 recorder.run("A", "timer", () => { clock.t += 3; }, null, []); 98 const [row] = recorder.rows(); 99 assert.deepEqual({ms: row.ms, calls: row.calls, maxMs: row.maxMs, topKind: row.topKind}, {ms: 14, calls: 3, maxMs: 9, topKind: "patch after"}); 100 });