perf: migrated timing measurements to Bun.nanoseconds() for higher precision

- Migrated timing measurements from `performance.now()` to `Bun.nanoseconds()` for higher precision benchmarking across all benchmark and timing-sensitive code.
- Updated elapsed time calculations to convert nanoseconds to milliseconds using division by 1e6 to maintain consistent time units.
- Increased benchmark precision from 4 to 6 decimal places for per-operation timing measurements.
- Refactored grep benchmark to use averaged timing values instead of storing individual iteration times, reducing memory overhead.
This commit is contained in:
can1357
2026-02-05 06:19:49 +01:00
parent e131000ed2
commit 37c74bb19d
11 changed files with 56 additions and 67 deletions
+4 -4
View File
@@ -56,7 +56,7 @@ Avoid ports that depend on JS-only state or dynamic imports. N-API exports shoul
- Put benchmarks next to the owning package (`packages/tui/bench`, `packages/natives/bench`, or `packages/coding-agent/bench`).
- Include a JS baseline and native version in the same run.
- Use `performance.now()` and a fixed iteration count.
- Use `Bun.nanoseconds()` and a fixed iteration count.
- Keep the benchmark inputs small and realistic (actual data seen in the hot path).
5. **Build the native binary**
@@ -125,10 +125,10 @@ Keep it simple and owned. `String`, `Vec<String>`, and `Uint8Array` work. Avoid
const ITERATIONS = 2000;
function bench(name: string, fn: () => void): number {
const start = performance.now();
const start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) fn();
const elapsed = performance.now() - start;
console.log(`${name}: ${elapsed.toFixed(2)}ms total (${(elapsed / ITERATIONS).toFixed(4)}ms/op)`);
const elapsed = (Bun.nanoseconds() - start) / 1e6;
console.log(`${name}: ${elapsed.toFixed(2)}ms total (${(elapsed / ITERATIONS).toFixed(6)}ms/op)`);
return elapsed;
}
+4 -4
View File
@@ -386,14 +386,14 @@ describe("agentLoop with AgentMessage", () => {
parameters: toolSchema,
async execute(_toolCallId, params) {
if (params.value === "slow") {
startTimes.slow = performance.now();
startTimes.slow = Bun.nanoseconds();
slowStartedResolve();
await slowContinue;
finishTimes.slow = performance.now();
finishTimes.slow = Bun.nanoseconds();
} else {
await slowStarted;
startTimes.fast = performance.now();
finishTimes.fast = performance.now();
startTimes.fast = Bun.nanoseconds();
finishTimes.fast = Bun.nanoseconds();
fastFinishedResolve();
}
return {
+3 -3
View File
@@ -146,8 +146,8 @@ export class AssistantMessageEventStream extends EventStream<AssistantMessageEve
private scheduleFlush(): void {
if (this.flushTimer) return; // Already scheduled
const now = performance.now();
const timeSinceLastFlush = now - this.lastFlushTime;
const now = Bun.nanoseconds();
const timeSinceLastFlush = (now - this.lastFlushTime) / 1e6;
if (timeSinceLastFlush >= this.throttleMs) {
// Flush immediately if throttle window has passed
@@ -173,7 +173,7 @@ export class AssistantMessageEventStream extends EventStream<AssistantMessageEve
// Merge consecutive deltas for the same content block and type
const merged = this.mergeDeltas(this.deltaBuffer);
this.deltaBuffer = [];
this.lastFlushTime = performance.now();
this.lastFlushTime = Bun.nanoseconds();
for (const event of merged) {
this.deliver(event);
+3 -3
View File
@@ -10,12 +10,12 @@ const longText = Array.from({ length: 200 })
.join("\n");
function bench(name: string, fn: () => void): number {
const start = performance.now();
const start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) {
fn();
}
const elapsed = performance.now() - start;
const perOp = (elapsed / ITERATIONS).toFixed(4);
const elapsed = (Bun.nanoseconds() - start) / 1e6;
const perOp = (elapsed / ITERATIONS).toFixed(6);
console.log(`${name}: ${elapsed.toFixed(2)}ms total (${perOp}ms/op)`);
return elapsed;
}
+2 -2
View File
@@ -314,9 +314,9 @@ export async function createTools(session: ToolSession, toolNames?: string[]): P
const slowTools: Array<{ name: string; ms: number }> = [];
const results = await Promise.all(
entries.map(async ([name, factory]) => {
const start = performance.now();
const start = Bun.nanoseconds();
const tool = await factory(session);
const elapsed = performance.now() - start;
const elapsed = (Bun.nanoseconds() - start) / 1e6;
if (elapsed > 5) {
slowTools.push({ name, ms: Math.round(elapsed) });
}
+27 -38
View File
@@ -25,29 +25,7 @@ await grep({ pattern: "test", path: path.resolve(packages, "tui/src") });
console.log(`Benchmark: ${ITERATIONS} iterations per case\n`);
for (const c of cases) {
// Main thread sequential
const mainTimes: number[] = [];
let mainMatches = 0;
for (let i = 0; i < ITERATIONS; i++) {
const start = performance.now();
const result = await grep({ pattern: c.pattern, path: c.path, glob: c.glob });
mainTimes.push(performance.now() - start);
mainMatches = result.totalMatches;
}
// Main thread concurrent (8x parallel)
const mainConcurrentTimes: number[] = [];
for (let i = 0; i < ITERATIONS; i++) {
const start = performance.now();
await Promise.all(
Array.from({ length: CONCURRENCY }, () => grep({ pattern: c.pattern, path: c.path, glob: c.glob })),
);
mainConcurrentTimes.push(performance.now() - start);
}
// Subprocess rg sequential
const rgTimes: number[] = [];
let rgMatches = 0;
const grepArgs = { pattern: c.pattern, path: c.path, glob: c.glob };
const rgDefaultArgs = ["--hidden", "--no-ignore", "--no-ignore-vcs"];
const globArg = c.glob ? ["-g", c.glob] : [];
@@ -77,31 +55,42 @@ for (const c of cases) {
return matches;
};
// Capture match counts from a single run
const mainMatches = (await grep(grepArgs)).totalMatches;
const rgMatches = countMatches(await runRg());
// Main thread sequential
let start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) await grep(grepArgs);
const mainMs = (Bun.nanoseconds() - start) / 1e6 / ITERATIONS;
// Main thread concurrent (8x parallel)
start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) {
const start = performance.now();
const result = await runRg();
rgTimes.push(performance.now() - start);
rgMatches = countMatches(result);
await Promise.all(Array.from({ length: CONCURRENCY }, () => grep(grepArgs)));
}
const mainConcurrentMs = (Bun.nanoseconds() - start) / 1e6 / ITERATIONS;
// Subprocess rg sequential
start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) await runRg();
const rgMs = (Bun.nanoseconds() - start) / 1e6 / ITERATIONS;
// Subprocess rg concurrent (8x parallel)
const rgConcurrentTimes: number[] = [];
start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) {
const start = performance.now();
await Promise.all(Array.from({ length: CONCURRENCY }, () => runRg()));
rgConcurrentTimes.push(performance.now() - start);
}
const avg = (arr: number[]) => arr.reduce((a, b) => a + b, 0) / arr.length;
const rgConcurrentMs = (Bun.nanoseconds() - start) / 1e6 / ITERATIONS;
console.log(`${c.name}:`);
console.log(` Main thread: ${avg(mainTimes).toFixed(2)}ms (${mainMatches} matches)`);
console.log(` Main thread 8x: ${avg(mainConcurrentTimes).toFixed(2)}ms`);
console.log(` Subprocess rg: ${avg(rgTimes).toFixed(2)}ms (${rgMatches} matches)`);
console.log(` Subprocess rg 8x: ${avg(rgConcurrentTimes).toFixed(2)}ms`);
console.log(` Main thread: ${mainMs.toFixed(2)}ms (${mainMatches} matches)`);
console.log(` Main thread 8x: ${mainConcurrentMs.toFixed(2)}ms`);
console.log(` Subprocess rg: ${rgMs.toFixed(2)}ms (${rgMatches} matches)`);
console.log(` Subprocess rg 8x: ${rgConcurrentMs.toFixed(2)}ms`);
const mainVsRg = avg(rgTimes) / avg(mainTimes);
const mainVsRgConcurrent = avg(rgConcurrentTimes) / avg(mainConcurrentTimes);
const mainVsRg = rgMs / mainMs;
const mainVsRgConcurrent = rgConcurrentMs / mainConcurrentMs;
console.log(
` => Main thread is ${mainVsRg > 1 ? `${mainVsRg.toFixed(1)}x faster` : `${(1 / mainVsRg).toFixed(1)}x slower`} than rg (sequential)`,
);
+3 -3
View File
@@ -25,12 +25,12 @@ function matchesKittySequenceJs(data: string, expectedCodepoint: number, expecte
}
function bench(name: string, fn: () => void): number {
const start = performance.now();
const start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) {
fn();
}
const elapsed = performance.now() - start;
const perOp = (elapsed / ITERATIONS).toFixed(4);
const elapsed = (Bun.nanoseconds() - start) / 1e6;
const perOp = (elapsed / ITERATIONS).toFixed(6);
console.log(`${name}: ${elapsed.toFixed(2)}ms total (${perOp}ms/op)`);
return elapsed;
}
+3 -3
View File
@@ -57,12 +57,12 @@ const samples = [
];
function bench(name: string, fn: () => void): number {
const start = performance.now();
const start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) {
fn();
}
const elapsed = performance.now() - start;
const perOp = (elapsed / ITERATIONS).toFixed(4);
const elapsed = (Bun.nanoseconds() - start) / 1e6;
const perOp = (elapsed / ITERATIONS).toFixed(6);
console.log(`${name}: ${elapsed.toFixed(2)}ms total (${perOp}ms/op)`);
return elapsed;
}
+3 -3
View File
@@ -14,12 +14,12 @@ const samples = {
const wrapWidth = 40;
function bench(name: string, fn: () => void): number {
const start = performance.now();
const start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) {
fn();
}
const elapsed = performance.now() - start;
const perOp = (elapsed / ITERATIONS).toFixed(4);
const elapsed = (Bun.nanoseconds() - start) / 1e6;
const perOp = (elapsed / ITERATIONS).toFixed(6);
console.log(`${name}: ${elapsed.toFixed(2)}ms total (${perOp}ms/op)`);
return elapsed;
}
+2 -2
View File
@@ -70,11 +70,11 @@ function bench(name: string, fn: () => void): BenchResult {
// Warmup
for (let i = 0; i < WARMUP; i++) fn();
const start = performance.now();
const start = Bun.nanoseconds();
for (let i = 0; i < ITERATIONS; i++) {
fn();
}
const totalMs = performance.now() - start;
const totalMs = (Bun.nanoseconds() - start) / 1e6;
const perOpUs = (totalMs / ITERATIONS) * 1000;
return { name, totalMs, perOpUs };
+2 -2
View File
@@ -3,7 +3,7 @@
* Usage: bun --preload ./scripts/trace-loader.ts <script>
*/
const startTime = performance.now();
const startTime = Bun.nanoseconds();
const resolved = new Set<string>();
Bun.plugin({
@@ -17,7 +17,7 @@ Bun.plugin({
}
resolved.add(args.path);
const elapsed = (performance.now() - startTime).toFixed(1);
const elapsed = ((Bun.nanoseconds() - startTime) / 1e6).toFixed(1);
// Only trace local/project files, not node_modules
if (!args.path.includes("node_modules") && !args.path.startsWith("node:")) {
const shortPath = args.path.replace(process.cwd(), ".");