diff --git a/packages/cli/index.d.ts b/packages/cli/index.d.ts index 7b4f93c19f..f684c82085 100644 --- a/packages/cli/index.d.ts +++ b/packages/cli/index.d.ts @@ -126,6 +126,48 @@ interface TestAssertion { message?: string; } +/** + * Run the registered benchmarks + */ +export function mainBenchFn(meta: ImportMeta): void; + +/** + * Top level bench mark registering function + */ +export function bench(name: string, callback: BenchCallback): void; + +/** + * Argument to bench mark functions + */ +export interface BenchRunner { + /** + * Amount of iterations this call should do + */ + N: number; + + /** + * Reset the start time + * This can be used if a benchmark needs some setup + */ + resetTime(): void; +} + +/** + * Callback function executed while benchmarking + */ +export type BenchCallback = (BenchRunner) => void | Promise; + +/** + * @private + */ +interface BenchState { + name: string; + N: number; + operationTimeNs: string; + callback: BenchCallback; + caughtException?: Error; +} + /** * Represents either a file in the `scripts` directory or a script from the package.json * Depending on the type contains either script or path diff --git a/packages/cli/index.js b/packages/cli/index.js index 11d9d075a5..7ced82397a 100755 --- a/packages/cli/index.js +++ b/packages/cli/index.js @@ -1,2 +1,3 @@ export { collectScripts } from "./src/utils.js"; export { test, mainTestFn } from "./src/testing/index.js"; +export { bench, mainBenchFn } from "./src/benchmarking/index.js"; diff --git a/packages/cli/scripts/bench.js b/packages/cli/scripts/bench.js index a1b77dd187..04ab766b78 100644 --- a/packages/cli/scripts/bench.js +++ b/packages/cli/scripts/bench.js @@ -1,13 +1,13 @@ import { filenameForModule, - logBenchResults, mainFn, processDirectoryRecursive, } from "@lbu/stdlib"; +import { mainBenchFn } from "../index.js"; const __filename = filenameForModule(import.meta); -const contentHandler = async (logger, file) => { +const contentHandler = async (file) => { // Skip this index file if (file === __filename) { return; @@ -15,17 +15,12 @@ const contentHandler = async (logger, file) => { if (!file.endsWith(".bench.js")) { return; } - const imported = await import(file); - if (imported && imported.runBench) { - await imported.runBench(logger); - } + await import(file); }; mainFn(import.meta, main); -async function main(logger) { - await processDirectoryRecursive(process.cwd(), (file) => - contentHandler(logger, file), - ); - logBenchResults(logger); +async function main() { + await processDirectoryRecursive(process.cwd(), contentHandler); + mainBenchFn(import.meta); } diff --git a/packages/cli/src/benchmarking/index.js b/packages/cli/src/benchmarking/index.js new file mode 100644 index 0000000000..90d5f24258 --- /dev/null +++ b/packages/cli/src/benchmarking/index.js @@ -0,0 +1,2 @@ +export { bench } from "./runner.js"; +export { mainBenchFn } from "./utils.js"; diff --git a/packages/cli/src/benchmarking/printer.js b/packages/cli/src/benchmarking/printer.js new file mode 100644 index 0000000000..70906b9678 --- /dev/null +++ b/packages/cli/src/benchmarking/printer.js @@ -0,0 +1,117 @@ +import { AppError, isNil } from "@lbu/stdlib"; +import { benchLogger, state } from "./state.js"; + +export function printBenchResults() { + const total = state.length; + let success = 0; + + for (const bench of state) { + if (!bench.caughtException) { + success += 1; + } + } + + benchLogger.info(state); + + const result = []; + + result.push(""); + result.push(`Total benchmarks: ${total}`); + result.push(` Passed: ${success}`); + result.push(` Failed: ${total - success}`); + result.push(`-----------`); + + printSuccessResults( + result, + state.filter((it) => isNil(it.caughtException)), + ); + printErrorResults( + result, + state.filter((it) => !isNil(it.caughtException)), + ); + + let exitCode = 0; + let logFn = benchLogger.info; + + if (total !== success) { + exitCode = 1; + logFn = benchLogger.error; + } + + logFn(result.join("\n")); + + return exitCode; +} + +/** + * @param {string[]} result + * @param {BenchState[]} state + */ +function printSuccessResults(result, state) { + if (state.length === 0) { + return; + } + + let longestName = 0; + let longestOperationTimeBeforeDot = 0; + + for (const bench of state) { + if (bench.name.length > longestName) { + longestName = bench.name.length; + } + + // We also line out on the '.' + // This results in easier to interpret results + const operationTimeSplit = bench.operationTimeNs.split("."); + bench.operationTimeBeforeDot = operationTimeSplit[0]; + + if (bench.operationTimeBeforeDot.length > longestOperationTimeBeforeDot) { + longestOperationTimeBeforeDot = bench.operationTimeBeforeDot.length; + } + } + + for (const bench of state) { + result.push( + `${bench.name.padEnd(longestName, " ")} ${String(bench.N).padStart( + 10, + " ", + )} iterations ${bench.operationTimeBeforeDot.padStart( + longestOperationTimeBeforeDot, + " ", + )} ns/op`, + ); + } +} + +/** + * @param {string[]} result + * @param {BenchState[]} state + */ +function printErrorResults(result, state) { + if (state.length === 0) { + return; + } + + for (const bench of state) { + result.push(bench.name); + + const indent = " "; + const stack = bench.caughtException.stack + .split("\n") + .map((it, idx) => indent + (idx !== 0 ? " " : "") + it.trim()); + + if (AppError.instanceOf(bench.caughtException)) { + result.push( + `${indent}AppError: ${bench.caughtException.key} - ${bench.caughtException.status}`, + ); + } else { + result.push( + `${indent}${bench.caughtException.name} - ${bench.caughtException.message}`, + ); + } + + for (const item of stack) { + result.push(item); + } + } +} diff --git a/packages/cli/src/benchmarking/runner.js b/packages/cli/src/benchmarking/runner.js new file mode 100644 index 0000000000..84d162d515 --- /dev/null +++ b/packages/cli/src/benchmarking/runner.js @@ -0,0 +1,117 @@ +/** + * @param {BenchState[]} state + * @returns {Promise} + */ +import { isNil } from "@lbu/stdlib"; +import { state } from "./state.js"; + +export async function runBenchmarks(state) { + let i = 0; + + // eslint-disable-next-line no-constant-condition + while (true) { + if (isNil(state[i])) { + // Give a chance for async imports to run + await new Promise((r) => { + setTimeout(r, 2); + }); + + if (isNil(state[i])) { + break; + } + } + + try { + const b = new InternalRunner(state[i]); + await b.exec(); + } catch (e) { + state[i].caughtException = e; + } + i++; + } +} + +/** + * @param {string} name + * @param {BenchCallback} callback + */ +export function bench(name, callback) { + state.push({ name, callback }); +} + +class InternalRunner { + static iterationBase = [1, 2, 5]; + + /** + * All iterations we can try to execute + */ + static iterations = Array.from( + { length: InternalRunner.iterationBase.length * 9 }, + (_, idx) => { + const base = + InternalRunner.iterationBase[idx % InternalRunner.iterationBase.length]; + const times = Math.max( + 1, + Math.pow(10, Math.floor(idx / InternalRunner.iterationBase.length)), + ); + + return base * times; + }, + ); + + N = 0; + start = BigInt(0); + + constructor(state) { + /** + * @type {BenchState} + */ + this.state = state; + } + + async exec() { + let i = 0; + while (i < InternalRunner.iterations.length) { + this.start = process.hrtime.bigint(); + this.N = InternalRunner.iterations[i]; + + const res = this.state.callback(createBenchRunner(this)); + if (res && typeof res.then === "function") { + await res; + } + + const diff = process.hrtime.bigint() - this.start; + if (diff >= 1_000_000_000 || i === InternalRunner.iterations.length - 1) { + this.state.N = this.N; + this.state.operationTimeNs = (Number(diff) / this.N).toFixed(0); + break; + } + + if (diff < 50_00_000) { + i = Math.min(i + 5, InternalRunner.iterations.length - 1); + } else if (diff < 100_000_000) { + i = Math.min(i + 4, InternalRunner.iterations.length - 1); + } else if (diff < 200_000_000) { + i = Math.min(i + 3, InternalRunner.iterations.length - 1); + } else if (diff < 300_000_000) { + i = Math.min(i + 2, InternalRunner.iterations.length - 1); + } else { + i++; + } + } + } +} + +/** + * + * @param {InternalRunner} runner + * @returns {BenchRunner} + */ +function createBenchRunner(runner) { + return { + N: runner.N, + resetTime: () => { + runner.start = process.hrtime.bigint(); + }, + }; +} diff --git a/packages/cli/src/benchmarking/state.js b/packages/cli/src/benchmarking/state.js new file mode 100644 index 0000000000..bb9df11167 --- /dev/null +++ b/packages/cli/src/benchmarking/state.js @@ -0,0 +1,30 @@ +/** + * @type {Logger} + */ +export let benchLogger = undefined; + +/** + * @type {boolean} + */ +export let areBenchRunning = false; + +/** + * @type {BenchState[]} + */ +export const state = []; + +/** + * Mutate the global areBenchRunning + * @param {boolean} running + */ +export function setAreBenchRunning(running) { + areBenchRunning = running; +} + +/** + * Set the bench logger + * @param {Logger} logger + */ +export function setBenchLogger(logger) { + benchLogger = logger; +} diff --git a/packages/cli/src/benchmarking/utils.js b/packages/cli/src/benchmarking/utils.js new file mode 100644 index 0000000000..85acb10bf4 --- /dev/null +++ b/packages/cli/src/benchmarking/utils.js @@ -0,0 +1,36 @@ +import { mainFn } from "@lbu/stdlib"; +import { printBenchResults } from "./printer.js"; +import { runBenchmarks } from "./runner.js"; +import { + areBenchRunning, + setAreBenchRunning, + setBenchLogger, + state, +} from "./state.js"; + +/** + * Wraps `mainFn` and `areBenchRunning + * @param {ImportMeta} meta + */ +export function mainBenchFn(meta) { + if (areBenchRunning) { + return; + } + + mainFn(meta, async (logger) => { + setBenchLogger(logger); + setAreBenchRunning(true); + + // Used when `mainBenchFn` is called the first thing of the process, + // which results in no benchmarks registered yet + await new Promise((r) => { + setTimeout(r, 2); + }); + + await runBenchmarks(state); + + const exitCode = printBenchResults(); + + process.exit(exitCode); + }); +} diff --git a/packages/cli/src/testing/printer.js b/packages/cli/src/testing/printer.js index a57c730dba..2665150ae6 100644 --- a/packages/cli/src/testing/printer.js +++ b/packages/cli/src/testing/printer.js @@ -17,6 +17,7 @@ export function printTestResults() { result.push(`Total assertions: ${passed + failed}`); result.push(` Passed: ${passed}`); result.push(` Failed: ${failed}`); + result.push(`-----------`); if (state.hasFailure) { for (const child of state.children) { diff --git a/packages/cli/src/testing/utils.js b/packages/cli/src/testing/utils.js index e1b1526780..b55b39f0d6 100644 --- a/packages/cli/src/testing/utils.js +++ b/packages/cli/src/testing/utils.js @@ -22,7 +22,6 @@ export function mainTestFn(meta) { setTestLogger(logger); setAreTestRunning(true); - // TODO: Convert to process.nextTick // Used when `mainTestFn` is called the first thing of the process, // which results in no tests registered yet await new Promise((r) => { diff --git a/packages/code-gen/test/e2e.bench.js b/packages/code-gen/test/e2e.bench.js index dc61798ea0..2302ed54d6 100644 --- a/packages/code-gen/test/e2e.bench.js +++ b/packages/code-gen/test/e2e.bench.js @@ -1,59 +1,63 @@ +import { bench, mainBenchFn } from "@lbu/cli"; import { TypeCreator } from "@lbu/code-gen"; -import { bench, isNil, logBenchResults, mainFn } from "@lbu/stdlib"; +import { AppError, isNil } from "@lbu/stdlib"; import { generateAndLoad } from "./utils.js"; -mainFn(import.meta, async (logger) => { - await runBench(); - logBenchResults(logger); +mainBenchFn(import.meta); + +bench("object validator simple", async (b) => { + const appValidators = await setup(); + b.resetTime(); + + let y; + for (let i = 0; i < b.N; ++i) { + // eslint-disable-next-line no-unused-vars + y = appValidators.simple({ + foo: "true", + bar: "5", + baz: "Ok", + }); + } }); -export async function runBench() { +bench("object validator nested", async (b) => { + const appValidators = await setup(); + b.resetTime(); + + let y; + for (let i = 0; i < b.N; ++i) { + // eslint-disable-next-line no-unused-vars + y = appValidators.nested({ + foo: true, + bar: 5, + nest: [ + "foo", + { + foo: true, + bar: 15, + baz: "Yes ", + }, + { + foo: true, + bar: 15, + baz: "Yes ", + }, + "bar", + ], + }); + } +}); + +async function setup() { const imports = await generateAndLoad( "code-gen/e2e/bench/validator", applyStructure, ); if (isNil(imports?.validator?.appValidators)) { - return; + throw new AppError("generateAndLoad.missingValidators", 500); } - const { appValidators } = imports["validator"]; - - await bench("object validator simple", (N) => { - let y; - for (let i = 0; i < N; ++i) { - // eslint-disable-next-line no-unused-vars - y = appValidators.simple({ - foo: "true", - bar: "5", - baz: "Ok", - }); - } - }); - - await bench("object validator nested", (N) => { - let y; - for (let i = 0; i < N; ++i) { - // eslint-disable-next-line no-unused-vars - y = appValidators.nested({ - foo: true, - bar: 5, - nest: [ - "foo", - { - foo: true, - bar: 15, - baz: "Yes ", - }, - { - foo: true, - bar: 15, - baz: "Yes ", - }, - "bar", - ], - }); - } - }); + return imports.validator.appValidators; } function applyStructure(app) { diff --git a/packages/insight/src/logger.bench.js b/packages/insight/src/logger.bench.js index 9e82ea2ba3..b0819f9c70 100644 --- a/packages/insight/src/logger.bench.js +++ b/packages/insight/src/logger.bench.js @@ -1,69 +1,64 @@ import { createWriteStream } from "fs"; -import { bench, logBenchResults, mainFn } from "@lbu/stdlib"; +import { bench, mainBenchFn } from "@lbu/cli"; import { newLogger } from "./logger.js"; -mainFn(import.meta, async (logger) => { - await runBench(); - logBenchResults(logger); -}); +mainBenchFn(import.meta); -export async function runBench() { - await bench("logger - strings", (N) => { - const stream = createWriteStream("/tmp/logger_bench_lbu.txt", "utf-8"); - const logger = newLogger({ - pretty: false, - stream, - }); +bench("logger - strings", (b) => { + const stream = createWriteStream("/tmp/logger_bench_lbu.txt", "utf-8"); + const logger = newLogger({ + pretty: false, + stream, + }); - for (let i = 0; i < N; ++i) { - logger.info("My simple string"); - } + for (let i = 0; i < b.N; ++i) { + logger.info("My simple string"); + } - stream.end(); + stream.end(); +}); + +bench("logger - objects", (b) => { + const stream = createWriteStream("/tmp/logger_bench_lbu.txt", "utf-8"); + const logger = newLogger({ + pretty: false, + stream, }); - await bench("logger - objects", (N) => { - const stream = createWriteStream("/tmp/logger_bench_lbu.txt", "utf-8"); - const logger = newLogger({ - pretty: false, - stream, + for (let i = 0; i < b.N; ++i) { + logger.info({ + my: { + simple: "object", + }, }); + } - for (let i = 0; i < N; ++i) { - logger.info({ - my: { - simple: "object", - }, - }); - } + stream.end(); +}); - stream.end(); +bench("logger - deep objects", (b) => { + const stream = createWriteStream("/tmp/logger_bench_lbu.txt", "utf-8"); + const logger = newLogger({ + pretty: false, + stream, }); - await bench("logger - deep objects", (N) => { - const stream = createWriteStream("/tmp/logger_bench_lbu.txt", "utf-8"); - const logger = newLogger({ - pretty: false, - stream, - }); - - for (let i = 0; i < N; ++i) { - logger.info({ - my: { - more: [ - { - advanced: { - object: "with", - multiple: "keys", - foo: 5, - }, + for (let i = 0; i < b.N; ++i) { + logger.info({ + my: { + more: [ + { + advanced: { + object: "with", + multiple: "keys", + foo: 5, }, - ], - }, - bar: true, - }); - } + }, + ], + }, + bar: true, + }); + } - stream.end(); - }); -} + stream.end(); +}); diff --git a/packages/stdlib/index.d.ts b/packages/stdlib/index.d.ts index d6cf5805f3..9cace54d1a 100644 --- a/packages/stdlib/index.d.ts +++ b/packages/stdlib/index.d.ts @@ -365,21 +365,6 @@ export function filenameForModule(meta: ImportMeta): string; */ export function dirnameForModule(meta: ImportMeta): string; -/** - * Benchmark helper - * Note that results should be taken with a grain of salt since V8 is doing JIT stuff and - * garbage collection, so it's more of an indication than something reproducible - */ -export function bench( - name: string, - cb: (N: number) => void | Promise, -): void | Promise; - -/** - * Formats the results of the benchmarks and logs them. - */ -export function logBenchResults(logger: Logger): void; - /** * Returns whether NODE_ENV === "production" */ diff --git a/packages/stdlib/index.js b/packages/stdlib/index.js index 0177873459..4aad75b94a 100644 --- a/packages/stdlib/index.js +++ b/packages/stdlib/index.js @@ -29,8 +29,6 @@ export { noop, filenameForModule, dirnameForModule, - bench, - logBenchResults, isProduction, isStaging, } from "./src/utils.js"; diff --git a/packages/stdlib/src/datatypes.bench.js b/packages/stdlib/src/datatypes.bench.js index 89827507a7..f92cd96d4c 100644 --- a/packages/stdlib/src/datatypes.bench.js +++ b/packages/stdlib/src/datatypes.bench.js @@ -1,26 +1,21 @@ +import { bench, mainBenchFn } from "@lbu/cli"; import { uuid } from "./datatypes.js"; -import { bench, logBenchResults, mainFn } from "./utils.js"; -mainFn(import.meta, async (logger) => { - await runBench(); - logBenchResults(logger); -}); +mainBenchFn(import.meta); -export async function runBench() { - await bench("uuid", (N) => { - let y; - for (let i = 0; i < N; ++i) { - // eslint-disable-next-line no-unused-vars - y = uuid(); - } - }); +bench("uuid", (b) => { + let y; + for (let i = 0; i < b.N; ++i) { + // eslint-disable-next-line no-unused-vars + y = uuid(); + } +}); - await bench("uuid.isValid", (N) => { - const id = uuid(); - let y; - for (let i = 0; i < N; ++i) { - // eslint-disable-next-line no-unused-vars - y = uuid.isValid(id); - } - }); -} +bench("uuid.isValid", (b) => { + const id = uuid(); + let y; + for (let i = 0; i < b.N; ++i) { + // eslint-disable-next-line no-unused-vars + y = uuid.isValid(id); + } +}); diff --git a/packages/stdlib/src/lodash.bench.js b/packages/stdlib/src/lodash.bench.js index 7258bedf5d..4134f10e9e 100644 --- a/packages/stdlib/src/lodash.bench.js +++ b/packages/stdlib/src/lodash.bench.js @@ -1,27 +1,22 @@ +import { bench, mainBenchFn } from "@lbu/cli"; import { isNil, isPlainObject } from "./lodash.js"; -import { bench, logBenchResults, mainFn } from "./utils.js"; -mainFn(import.meta, async (logger) => { - await runBench(); - logBenchResults(logger); -}); +mainBenchFn(import.meta); -export async function runBench() { - await bench("isNil", (N) => { - let y; - for (let i = 0; i < N; ++i) { - y = isNil(true); - // eslint-disable-next-line no-unused-vars - y = isNil(undefined); - } - }); +bench("isNil", (b) => { + let y; + for (let i = 0; i < b.N; ++i) { + y = isNil(true); + // eslint-disable-next-line no-unused-vars + y = isNil(undefined); + } +}); - await bench("isPlainObject", (N) => { - let y; - for (let i = 0; i < N; ++i) { - y = isPlainObject({}); - // eslint-disable-next-line no-unused-vars - y = isPlainObject(true); - } - }); -} +bench("isPlainObject", (b) => { + let y; + for (let i = 0; i < b.N; ++i) { + y = isPlainObject({}); + // eslint-disable-next-line no-unused-vars + y = isPlainObject(true); + } +}); diff --git a/packages/stdlib/src/utils.js b/packages/stdlib/src/utils.js index 2b2f002289..40d224a305 100644 --- a/packages/stdlib/src/utils.js +++ b/packages/stdlib/src/utils.js @@ -152,129 +152,6 @@ export function isMainFnAndReturnName(meta) { }; } -/** - * @name BenchResult - * @typedef {object} - * @property {string} name - * @property {number} N - * @property {string} operationTimeNs - */ - -/** - * Global type, for easier formatting down the line - * @type {BenchResult[]} - */ -const benchmarkResults = []; - -class Benchmarker { - static iterationBase = [1, 2, 5]; - - /** - * All iterations we can try to execute - */ - static iterations = Array.from( - { length: Benchmarker.iterationBase.length * 9 }, - (_, idx) => { - const base = - Benchmarker.iterationBase[idx % Benchmarker.iterationBase.length]; - const times = Math.max( - 1, - Math.pow(10, Math.floor(idx / Benchmarker.iterationBase.length)), - ); - - return base * times; - }, - ); - - currentIdx = 0; - N = 0; - start = BigInt(0); - - constructor(name, cb) { - this.name = name; - this.cb = cb; - } - - async exec() { - for (let i = 0; i < Benchmarker.iterations.length; ++i) { - this.currentIdx = i; - this.start = process.hrtime.bigint(); - this.N = Benchmarker.iterations[this.currentIdx]; - - const res = this.cb(this.N); - if (res && typeof res.then === "function") { - await res; - } - - const diff = process.hrtime.bigint() - this.start; - if (diff >= 1_000_000_000 || i === Benchmarker.iterations.length - 1) { - benchmarkResults.push({ - name: this.name, - N: this.N, - operationTimeNs: (Number(diff) / this.N).toFixed(0), - }); - break; - } - - if (diff < 50_00_000) { - i += 4; - } else if (diff < 100_000_000) { - i += 3; - } else if (diff < 200_000_000) { - i += 2; - } else if (diff < 300_000_000) { - i += 1; - } - } - } -} - -/** - * @param {string} name - * @param {function(number): (void | Promise)} cb - * @returns {Promise} - */ -export function bench(name, cb) { - const b = new Benchmarker(name, cb); - return b.exec(); -} - -/** - * Formats the benchmark results and lines them out for easier consumption - * @param {Logger} logger - */ -export function logBenchResults(logger) { - let longestName = 0; - let longestOperationTimeBeforeDot = 0; - - for (const bench of benchmarkResults) { - if (bench.name.length > longestName) { - longestName = bench.name.length; - } - - // We also line out on the '.' - // This results in easier to interpret results - const operationTimeSplit = bench.operationTimeNs.split("."); - bench.operationTimeBeforeDot = operationTimeSplit[0]; - - if (bench.operationTimeBeforeDot.length > longestOperationTimeBeforeDot) { - longestOperationTimeBeforeDot = bench.operationTimeBeforeDot.length; - } - } - - for (const bench of benchmarkResults) { - logger.info( - `${bench.name.padEnd(longestName, " ")} ${String(bench.N).padStart( - 10, - " ", - )} iterations ${bench.operationTimeBeforeDot.padStart( - longestOperationTimeBeforeDot, - " ", - )} ns/op`, - ); - } -} - /** * @returns {boolean} */