From 2a8d22efc99122aaccbe59ad97b4c33795d2421d Mon Sep 17 00:00:00 2001 From: "paseo-bot[bot]" <266920839+paseo-bot[bot]@users.noreply.github.com> Date: Fri, 30 Oct 2026 15:04:27 +0000 Subject: [PATCH] test(server): correlate config profiles with long callbacks --- .../src/utils/paseo-config-file.test.ts | 2 +- .../test-fixtures/config-responsiveness.ts | 35 ++++++++++++++++--- 2 files changed, 32 insertions(+), 5 deletions(-) diff --git a/packages/server/src/utils/paseo-config-file.test.ts b/packages/server/src/utils/paseo-config-file.test.ts index e13f1869bf..2e4b23ea24 100644 --- a/packages/server/src/utils/paseo-config-file.test.ts +++ b/packages/server/src/utils/paseo-config-file.test.ts @@ -138,7 +138,7 @@ describe("paseo config file substrate", () => { }); it.each( - Array.from({ length: 150 }, (_, repetition) => + Array.from({ length: 500 }, (_, repetition) => [false, true].map((profile) => ({ repetition, profile })), ).flat(), )( diff --git a/packages/server/src/utils/test-fixtures/config-responsiveness.ts b/packages/server/src/utils/test-fixtures/config-responsiveness.ts index 3ea54accbf..495148f1d3 100644 --- a/packages/server/src/utils/test-fixtures/config-responsiveness.ts +++ b/packages/server/src/utils/test-fixtures/config-responsiveness.ts @@ -13,11 +13,28 @@ const directory = process.argv[2]; assert.ok(directory, "Config directory is required"); await nextTurn(); let workerMessages = 0; +const threadCpuUsage: (previous?: NodeJS.CpuUsage) => NodeJS.CpuUsage = Reflect.get( + process, + "threadCpuUsage", +); +const callbackStarts = new Map(); +const spans: { start: number; end: number; cpuMs: number }[] = []; +const currentMicros = () => Number(process.hrtime.bigint() / 1000n); const activity = createHook({ - before() { + before(id) { + callbackStarts.set(id, { start: currentMicros(), cpu: threadCpuUsage() }); if (executionAsyncResource() instanceof MessagePort) workerMessages++; }, -}).enable(); + after(id) { + const start = callbackStarts.get(id); + if (!start) return; + callbackStarts.delete(id); + const end = currentMicros(); + const cpu = threadCpuUsage(start.cpu); + if (end - start.start > 8000) + spans.push({ start: start.start, end, cpuMs: (cpu.user + cpu.system) / 1000 }); + }, +}); const profiler = process.argv[3] === "profile" ? new Session() : null; if (profiler) { profiler.connect(); @@ -25,6 +42,8 @@ if (profiler) { await profiler.post("Profiler.setSamplingInterval", { interval: 100 }); await profiler.post("Profiler.start"); } +await nextTurn(); +activity.enable(); const measured = await measureMainThreadWork("project config main-thread work", () => readPaseoConfigForEdit(directory), ); @@ -32,16 +51,24 @@ activity.disable(); process.stderr.write(`Config profiling: ${Boolean(profiler)}\n`); const profile = profiler ? (await profiler.post("Profiler.stop")).profile : null; profiler?.disconnect(); -if (profile && measured.blockingMs >= 20) { +if (profile && spans.length > 0) { const nodes = new Map(profile.nodes.map((node) => [node.id, node])); const parents = new Map(); for (const node of profile.nodes) { for (const child of node.children ?? []) parents.set(child, node.id); } const samples = new Map(); + let sampleTime = profile.startTime; for (const [index, id] of (profile.samples ?? []).entries()) { - samples.set(id, (samples.get(id) ?? 0) + (profile.timeDeltas?.[index] ?? 0)); + const delta = profile.timeDeltas?.[index] ?? 0; + sampleTime += delta; + if (spans.some((span) => sampleTime >= span.start && sampleTime <= span.end)) { + samples.set(id, (samples.get(id) ?? 0) + delta); + } } + process.stderr.write( + `Config long callbacks: ${JSON.stringify(spans.map(({ start, end, cpuMs }) => ({ wallMs: (end - start) / 1000, cpuMs })))}\n`, + ); const hottest = [...samples] .sort((a, b) => b[1] - a[1]) .slice(0, 20)