test(server): probe config timing under CPU contention

This commit is contained in:
paseo-bot[bot]
2026-10-30 15:32:36 +00:00
parent 2a8d22efc9
commit 0ad71cf37b
2 changed files with 36 additions and 8 deletions
@@ -1,6 +1,8 @@
import { mkdirSync, mkdtempSync, readFileSync, realpathSync, rmSync, writeFileSync } from "node:fs";
import { execFile } from "node:child_process";
import { promisify } from "node:util";
import { Worker } from "node:worker_threads";
import { once } from "node:events";
import { fileURLToPath } from "node:url";
import { writeFile, truncate, rm } from "node:fs/promises";
import { tmpdir } from "node:os";
@@ -62,6 +64,25 @@ async function measureConfigRead(directory: string, profile = false) {
};
}
// Temporary diagnostic: keep scheduling pressure present throughout the paired
// cold reads, rather than depending on which other CI files are still running.
async function withCpuContention<T>(action: () => Promise<T>): Promise<T> {
const workers = Array.from(
{ length: 3 },
() =>
new Worker(
'require("node:worker_threads").parentPort.postMessage("ready"); while (true) { Math.sqrt(Math.random()); }',
{ eval: true },
),
);
try {
await Promise.all(workers.map((worker) => once(worker, "message")));
return await action();
} finally {
await Promise.all(workers.map((worker) => worker.terminate()));
}
}
describe("paseo config file substrate", () => {
let tempDir: string;
@@ -138,7 +159,7 @@ describe("paseo config file substrate", () => {
});
it.each(
Array.from({ length: 500 }, (_, repetition) =>
Array.from({ length: 100 }, (_, repetition) =>
[false, true].map((profile) => ({ repetition, profile })),
).flat(),
)(
@@ -152,7 +173,7 @@ describe("paseo config file substrate", () => {
};
await writeFile(join(tempDir, "paseo.json"), JSON.stringify(config));
const { result, blockingMs, filesystemRequests, yields, workerMessages } =
await measureConfigRead(tempDir, profile);
await withCpuContention(() => measureConfigRead(tempDir, profile));
expect(result).toEqual({ ok: true, config, revision: await statPaseoConfigPath(tempDir) });
expect(blockingMs).toBeLessThan(20);
expect(filesystemRequests).toBeGreaterThan(0);
@@ -51,6 +51,11 @@ activity.disable();
process.stderr.write(`Config profiling: ${Boolean(profiler)}\n`);
const profile = profiler ? (await profiler.post("Profiler.stop")).profile : null;
profiler?.disconnect();
if (spans.length > 0) {
process.stderr.write(
`Config long callbacks: ${JSON.stringify(spans.map(({ start, end, cpuMs }) => ({ wallMs: (end - start) / 1000, cpuMs })))}\n`,
);
}
if (profile && spans.length > 0) {
const nodes = new Map(profile.nodes.map((node) => [node.id, node]));
const parents = new Map<number, number>();
@@ -62,13 +67,15 @@ if (profile && spans.length > 0) {
for (const [index, id] of (profile.samples ?? []).entries()) {
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);
}
const overlap = spans.reduce(
(total, span) =>
total +
Math.max(0, Math.min(sampleTime, span.end) - Math.max(sampleTime - delta, span.start)),
0,
);
if (overlap > 0) samples.set(id, (samples.get(id) ?? 0) + overlap);
}
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)