From cacfe65542b0c944cf494adf38d5e95100a3b834 Mon Sep 17 00:00:00 2001 From: "Bender (Fable)" Date: Sun, 11 Oct 2026 20:11:11 +0000 Subject: [PATCH] fix(build): lower the TypeScript steps' priority under cargo and fix three review findings The first measured run of the overlapped Runner build showed cargo slowing from 36s to 55s while the TypeScript steps competed for the runner's four cores, so the overlap saved nothing (runner build 55.7s against 52-54s on like-for-like master runs). The steps that run while cargo compiles now start at below-normal priority (os.setPriority, inherited by the nested pnpm, tsc and node), so cargo keeps the cores it would have had alone and the steps fill the single-threaded tail of codegen and linking. The timing line gains steps_priority so the next run shows whether it applied. Review findings, all valid: - A standalone pnpm points npm_execpath at a native executable; it is now run directly, and only a .cjs/.mjs/.js entry goes through Node, the same rule as the CLI's resolvePnpmInstallInvocation. - The start-order test raced: the first step's stand-in logged its start before waiting for cargo's marker. Stand-ins now wait before logging, and the test also asserts the parent's own launch order. - The stop grace timer is cleared once cargo exits, so a build that failed early no longer keeps the process alive for five seconds. Tests: 8 node:test cases (was 7), ten consecutive runs clean; each of the three fixes has a case that fails against the previous code. Co-Authored-By: Claude Fable 5.1 --- .../scripts/build-runner-package.mjs | 79 ++++++++-- .../scripts/build-runner-package.test.mjs | 142 ++++++++++++------ 2 files changed, 161 insertions(+), 60 deletions(-) diff --git a/packages/paperclip-runner/scripts/build-runner-package.mjs b/packages/paperclip-runner/scripts/build-runner-package.mjs index 6a9dffcfc7d..5cb382bba35 100644 --- a/packages/paperclip-runner/scripts/build-runner-package.mjs +++ b/packages/paperclip-runner/scripts/build-runner-package.mjs @@ -15,10 +15,17 @@ // This build sits on the critical path of `pnpm -r build`: every adapter, // plugin package and the server wait for it. // +// cargo saturates the four cores of the CI runner, so the TypeScript steps +// run at a lower scheduling priority: cargo keeps the cores it would have +// had alone and the steps fill whatever it leaves (the single-threaded tail +// of codegen and linking). Without that, the first measured run had cargo +// slow from 36s to 55s under the competition and the overlap saved nothing. +// // PAPERCLIP_RUNNER_BUILD_SERIAL=1 runs cargo after the TypeScript steps // instead, for a machine that cannot afford both at once. import { spawn } from "node:child_process"; +import os from "node:os"; import path from "node:path"; import { fileURLToPath } from "node:url"; @@ -61,6 +68,11 @@ export const STEPS_AFTER_BINARY = Object.freeze([ export const TIMING_LINE_PREFIX = "paperclip.runner-build.timing.v1"; +// Scheduling priority for the TypeScript steps while cargo runs. On POSIX +// this is the nice value; children of a step (the nested pnpm, tsc, node) +// inherit it. Raising a process's own nice value needs no privilege. +export const STEP_PRIORITY_DURING_CARGO = os.constants.priority.PRIORITY_BELOW_NORMAL; + const STOP_GRACE_MS = 5_000; export function describeStep(step) { @@ -83,11 +95,17 @@ export class RunnerBuildError extends Error { function pnpmCommand(env) { // pnpm sets npm_execpath to its own entry point while it runs this script, - // so a nested `pnpm run` uses the same pnpm. Outside pnpm, use the one on - // PATH; Windows needs a shell to resolve the .cmd shim. + // so a nested `pnpm run` uses the same pnpm. That entry point is a + // JavaScript file under corepack or an npm install, and a native + // executable under the standalone pnpm build: only the former goes + // through Node (same rule as the CLI's resolvePnpmInstallInvocation). + // Outside pnpm, use the one on PATH; Windows needs a shell to resolve the + // .cmd shim. const execPath = env.npm_execpath; - if (execPath && /pnpm/.test(path.basename(execPath))) { - return { command: process.execPath, args: [execPath] }; + if (execPath && /pnpm/i.test(path.basename(execPath))) { + return /\.(cjs|mjs|js)$/i.test(execPath) + ? { command: process.execPath, args: [execPath] } + : { command: execPath, args: [] }; } return process.platform === "win32" ? { command: "pnpm", args: [], shell: true } @@ -106,8 +124,20 @@ export function defaultCargoCommand() { return { command: "cargo", args: [...CARGO_BUILD_ARGS] }; } -function launch({ command, args, shell }, { cwd, env }) { +function launch({ command, args, shell }, { cwd, env, priority }) { const child = spawn(command, args, { cwd, env, stdio: "inherit", shell: shell === true }); + let priorityApplied = false; + if (priority !== undefined && child.pid) { + try { + // Never raise the child above the parent: a parent already running + // at a lower priority would need privilege to do that. + os.setPriority(child.pid, Math.max(os.getPriority(), priority)); + priorityApplied = true; + } catch { + // The child is already gone or the platform refused; it runs at the + // parent's priority, which is what happened before this script. + } + } let settled = null; const exit = new Promise((resolve) => { const settle = (result) => { @@ -119,7 +149,7 @@ function launch({ command, args, shell }, { cwd, env }) { child.once("error", (error) => settle({ error })); child.once("exit", (code, signal) => settle({ code, signal })); }); - return { child, exit, result: () => settled }; + return { child, exit, result: () => settled, priorityApplied }; } const succeeded = (result) => !result.error && result.code === 0 && !result.signal; @@ -131,13 +161,22 @@ async function stop(running) { } catch { // Already gone. } - const timer = new Promise((resolve) => setTimeout(resolve, STOP_GRACE_MS, "timeout")); - if ((await Promise.race([running.exit, timer])) === "timeout" && !running.result()) { - try { - running.child.kill("SIGKILL"); - } catch { - // Already gone. + // The grace timer is cleared once the child exits so a build that failed + // early does not keep the process alive for the full grace period. + let handle = null; + const timer = new Promise((resolve) => { + handle = setTimeout(resolve, STOP_GRACE_MS, "timeout"); + }); + try { + if ((await Promise.race([running.exit, timer])) === "timeout" && !running.result()) { + try { + running.child.kill("SIGKILL"); + } catch { + // Already gone. + } } + } finally { + clearTimeout(handle); } return running.exit; } @@ -157,6 +196,9 @@ export async function runRunnerBuild({ const startedAt = Date.now(); const timing = { cargoStartedAt: null, cargoEndedAt: null, stepsEndedAt: null }; let cargo = null; + // Steps that overlap cargo yield the cores to it; everything else runs at + // the parent's priority. Set from the first overlapped step that starts. + let stepsPriority = "normal"; const startCargo = () => { const spec = cargoCommand(); @@ -168,10 +210,16 @@ export async function runRunnerBuild({ }); }; - const runStep = async (step) => { + const runStep = async (step, { duringCargo = false } = {}) => { const name = describeStep(step); log(`[runner build] ${name}`); - const result = await launch(commandFor(step), { cwd, env }).exit; + const running = launch(commandFor(step), { + cwd, + env, + priority: duringCargo ? STEP_PRIORITY_DURING_CARGO : undefined, + }); + if (duringCargo && running.priorityApplied) stepsPriority = "below_normal"; + const result = await running.exit; if (!succeeded(result)) throw new RunnerBuildError(name, result); }; @@ -187,7 +235,7 @@ export async function runRunnerBuild({ // next step, instead of after the whole TypeScript chain. const failure = cargoFailure(); if (failure) throw failure; - await runStep(step); + await runStep(step, { duringCargo: !serial }); } } catch (error) { if (cargo) await stop(cargo); @@ -205,6 +253,7 @@ export async function runRunnerBuild({ const endedAt = Date.now(); const summary = { mode: serial ? "serial" : "overlap", + steps_priority: stepsPriority, cargo_ms: timing.cargoEndedAt - timing.cargoStartedAt, steps_ms: timing.stepsEndedAt - startedAt, // How long the build waited on cargo alone after the TypeScript steps. diff --git a/packages/paperclip-runner/scripts/build-runner-package.test.mjs b/packages/paperclip-runner/scripts/build-runner-package.test.mjs index fa80d00f7bf..2776b71fd9b 100644 --- a/packages/paperclip-runner/scripts/build-runner-package.test.mjs +++ b/packages/paperclip-runner/scripts/build-runner-package.test.mjs @@ -1,6 +1,6 @@ import assert from "node:assert/strict"; import { existsSync, mkdtempSync, readFileSync, rmSync } from "node:fs"; -import { tmpdir } from "node:os"; +import os from "node:os"; import path from "node:path"; import { test } from "node:test"; import { @@ -9,6 +9,7 @@ import { STAGE_BINARY_STEP, STEPS_AFTER_BINARY, STEPS_DURING_CARGO, + STEP_PRIORITY_DURING_CARGO, TIMING_LINE_PREFIX, defaultCargoCommand, defaultCommandFor, @@ -16,23 +17,32 @@ import { runRunnerBuild, } from "./build-runner-package.mjs"; -// Every stand-in appends " start" and " end" to a shared event -// log, so a test can assert what ran before what. Its arguments: -// log, name, exit code, marker to write at start, file to wait for before -// ending, marker to write at the end. The cargo stand-in also records its -// pid so a test can check that the build stopped it. +// Every stand-in appends " start", " priority " and +// " end" to a shared event log, so a test can assert what ran before +// what and at which scheduling priority. Its arguments, after the log and +// the name: exit code, marker to write at start, file to wait for before +// logging its start, file to wait for before ending, marker to write at the +// end. Waiting before the start line is what makes the order between two +// processes launched back to back deterministic. The cargo stand-in also +// records its pid so a test can check that the build stopped it. const STAND_IN = ` const fs = require("node:fs"); -const [log, name, exitCode, startMarker, waitFor, endMarker] = process.argv.slice(1); +const os = require("node:os"); +const [log, name, exitCode, startMarker, waitBeforeStart, waitBeforeEnd, endMarker] = process.argv.slice(1); const append = (line) => fs.appendFileSync(log, line + "\\n"); +const waitFor = (file) => { + const deadline = Date.now() + 15000; + while (file && !fs.existsSync(file)) { + if (Date.now() > deadline) { append(name + " timeout"); process.exit(3); } + Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, 20); + } +}; if (name === "cargo") fs.writeFileSync(log + ".cargo.pid", String(process.pid)); -append(name + " start"); if (startMarker) fs.writeFileSync(startMarker, ""); -const deadline = Date.now() + 15000; -while (waitFor && !fs.existsSync(waitFor)) { - if (Date.now() > deadline) { append(name + " timeout"); process.exit(3); } - Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, 20); -} +waitFor(waitBeforeStart); +append(name + " start"); +append(name + " priority " + os.getPriority()); +waitFor(waitBeforeEnd); if (endMarker) fs.writeFileSync(endMarker, ""); append(name + " end"); process.exit(Number(exitCode)); @@ -41,37 +51,49 @@ process.exit(Number(exitCode)); const FIRST_STEP = describeStep(STEPS_DURING_CARGO[0]); const RELEASE_STEP = describeStep(STEPS_DURING_CARGO[STEPS_DURING_CARGO.length - 1]); -function harness({ exitCodes = {}, cargoExit = 0, cargoWaitsForRelease = true } = {}) { - const root = mkdtempSync(path.join(tmpdir(), "runner-build-")); +function harness({ exitCodes = {}, cargoExit = 0, cargoWaitsForRelease = true, cargoEndMarker = "", firstStepWaitsFor } = {}) { + const root = mkdtempSync(path.join(os.tmpdir(), "runner-build-")); const log = path.join(root, "events.log"); const cargoStarted = path.join(root, "cargo.started"); const release = path.join(root, "release"); - const standIn = (name, exitCode, startMarker = "", waitFor = "", endMarker = "") => ({ + const launches = []; + const standIn = (name, exitCode, { startMarker = "", waitBeforeStart = "", waitBeforeEnd = "", endMarker = "" } = {}) => ({ command: process.execPath, - args: ["-e", STAND_IN, log, name, String(exitCode), startMarker, waitFor, endMarker], + args: ["-e", STAND_IN, log, name, String(exitCode), startMarker, waitBeforeStart, waitBeforeEnd, endMarker], }); return { root, log, + launches, events: () => (existsSync(log) ? readFileSync(log, "utf8").trim().split("\n") : []), + priorityOf(name) { + const line = this.events().find((entry) => entry.startsWith(`${name} priority `)); + assert.ok(line, `missing priority line for ${name}`); + return Number(line.slice(`${name} priority `.length)); + }, cargoPid: () => Number(readFileSync(`${log}.cargo.pid`, "utf8")), options: { cwd: root, env: { ...process.env, PAPERCLIP_RUNNER_BUILD_SERIAL: "" }, log: () => {}, - cargoCommand: () => standIn("cargo", cargoExit, cargoStarted, cargoWaitsForRelease ? release : ""), + cargoCommand: () => { + launches.push("cargo"); + return standIn("cargo", cargoExit, { + startMarker: cargoStarted, + waitBeforeEnd: cargoWaitsForRelease ? release : "", + endMarker: cargoEndMarker, + }); + }, commandFor: (step) => { const name = describeStep(step); - // The first step waits for cargo's start marker so the event order - // between two processes started back to back is not left to chance. - // The last step during cargo releases the cargo stand-in. - return standIn( - name, - exitCodes[name] ?? 0, - "", - name === FIRST_STEP && cargoWaitsForRelease ? cargoStarted : "", - name === RELEASE_STEP ? release : "", - ); + launches.push(name); + // The first step logs its start only once cargo's start marker + // exists; the last step during cargo releases the cargo stand-in. + return standIn(name, exitCodes[name] ?? 0, { + waitBeforeStart: + name === FIRST_STEP ? (firstStepWaitsFor ?? (cargoWaitsForRelease ? cargoStarted : "")) : "", + endMarker: name === RELEASE_STEP ? release : "", + }); }, }, cleanup: () => rmSync(root, { recursive: true, force: true }), @@ -95,10 +117,14 @@ async function waitUntilGone(pid) { return !alive(pid); } +const activeTimeouts = () => process.getActiveResourcesInfo().filter((kind) => kind === "Timeout").length; + test("cargo starts before the first TypeScript step and is joined before the binary is staged", async () => { const h = harness(); try { const summary = await runRunnerBuild(h.options); + // What the build controls: it launched cargo before it launched any step. + assert.deepEqual(h.launches.slice(0, 2), ["cargo", FIRST_STEP]); const events = h.events(); const at = (line) => { const index = events.indexOf(line); @@ -128,9 +154,30 @@ test("cargo starts before the first TypeScript step and is joined before the bin } }); +test("the TypeScript steps yield the cores to cargo while it runs", async () => { + const h = harness(); + try { + const summary = await runRunnerBuild(h.options); + const parent = os.getPriority(); + const expectedStepPriority = Math.max(parent, STEP_PRIORITY_DURING_CARGO); + assert.equal(h.priorityOf("cargo"), parent, "cargo must keep the parent's priority"); + for (const step of STEPS_DURING_CARGO) { + assert.equal(h.priorityOf(describeStep(step)), expectedStepPriority, `${describeStep(step)} priority`); + } + // Nothing competes with the steps after cargo: they run at the parent's priority. + for (const step of [STAGE_BINARY_STEP, ...STEPS_AFTER_BINARY]) { + assert.equal(h.priorityOf(describeStep(step)), parent, `${describeStep(step)} priority`); + } + assert.equal(summary.steps_priority, "below_normal"); + } finally { + h.cleanup(); + } +}); + test("a failing TypeScript step stops cargo and names the step", async () => { const failing = describeStep(STEPS_DURING_CARGO[1]); const h = harness({ exitCodes: { [failing]: 7 } }); + const timeoutsBefore = activeTimeouts(); try { await assert.rejects(runRunnerBuild(h.options), (error) => { assert.ok(error instanceof RunnerBuildError); @@ -139,6 +186,9 @@ test("a failing TypeScript step stops cargo and names the step", async () => { return true; }); assert.ok(await waitUntilGone(h.cargoPid()), "cargo stand-in outlived the failed build"); + // The stop grace timer is cleared once cargo is gone, so a failed build + // does not keep the process alive for the grace period. + assert.equal(activeTimeouts(), timeoutsBefore, "the stop grace timer is still pending"); const events = h.events(); assert.ok(!events.includes("cargo end"), "cargo ran to completion after the failure"); assert.ok(!events.some((line) => line.startsWith(describeStep(STEPS_DURING_CARGO[2]))), "a later step ran after the failure"); @@ -167,23 +217,11 @@ test("a failing cargo build fails the build before the binary is staged", async }); test("a cargo failure that surfaces early ends the TypeScript chain at the next step", async () => { - const h = harness({ cargoExit: 2, cargoWaitsForRelease: false }); // The cargo stand-in fails at once and leaves a marker; the first step // holds until that marker exists, so cargo's failure is known before the // second step would start. - const cargoDone = path.join(h.root, "cargo.done"); - const innerCargo = h.options.cargoCommand; - h.options.cargoCommand = () => { - const spec = innerCargo(); - spec.args[spec.args.length - 1] = cargoDone; - return spec; - }; - const innerStep = h.options.commandFor; - h.options.commandFor = (step) => { - const spec = innerStep(step); - if (describeStep(step) === FIRST_STEP) spec.args[spec.args.length - 2] = cargoDone; - return spec; - }; + const cargoDone = path.join(os.tmpdir(), `runner-build-cargo-done-${process.pid}-${Date.now()}`); + const h = harness({ cargoExit: 2, cargoWaitsForRelease: false, cargoEndMarker: cargoDone, firstStepWaitsFor: cargoDone }); try { await assert.rejects(runRunnerBuild(h.options), (error) => { assert.equal(error.step, "cargo build"); @@ -193,11 +231,12 @@ test("a cargo failure that surfaces early ends the TypeScript chain at the next assert.ok(events.includes(`${FIRST_STEP} end`), `first step should have run to its end: ${events.join(" | ")}`); assert.ok(!events.some((line) => line.startsWith(describeStep(STEPS_DURING_CARGO[1]))), "the second step ran after cargo had failed"); } finally { + rmSync(cargoDone, { force: true }); h.cleanup(); } }); -test("PAPERCLIP_RUNNER_BUILD_SERIAL=1 runs cargo after the TypeScript steps", async () => { +test("PAPERCLIP_RUNNER_BUILD_SERIAL=1 runs cargo after the TypeScript steps at one priority", async () => { const h = harness({ cargoWaitsForRelease: false }); h.options.env = { ...process.env, PAPERCLIP_RUNNER_BUILD_SERIAL: "1" }; try { @@ -205,7 +244,13 @@ test("PAPERCLIP_RUNNER_BUILD_SERIAL=1 runs cargo after the TypeScript steps", as const events = h.events(); assert.ok(events.indexOf(`${RELEASE_STEP} end`) < events.indexOf("cargo start")); assert.ok(events.indexOf("cargo end") < events.indexOf(`${describeStep(STAGE_BINARY_STEP)} start`)); + assert.equal(h.launches[0], FIRST_STEP); + const parent = os.getPriority(); + for (const step of STEPS_DURING_CARGO) { + assert.equal(h.priorityOf(describeStep(step)), parent, `${describeStep(step)} priority`); + } assert.equal(summary.mode, "serial"); + assert.equal(summary.steps_priority, "normal"); } finally { h.cleanup(); } @@ -232,11 +277,18 @@ test("the plan compiles the TypeScript surface once and keeps the binary readers "node scripts/generate-semantic-action-catalog.mjs --check", ]); assert.equal(typeof TIMING_LINE_PREFIX, "string"); + assert.equal(STEP_PRIORITY_DURING_CARGO, os.constants.priority.PRIORITY_BELOW_NORMAL); }); test("nested pnpm runs use the pnpm that started the build", () => { - const viaPnpm = defaultCommandFor({ run: "build:typescript" }, { npm_execpath: "/opt/pnpm/bin/pnpm.cjs" }); - assert.deepEqual(viaPnpm, { command: process.execPath, args: ["/opt/pnpm/bin/pnpm.cjs", "run", "build:typescript"], shell: undefined }); + // corepack and an npm-installed pnpm point npm_execpath at a JavaScript entry. + const viaScript = defaultCommandFor({ run: "build:typescript" }, { npm_execpath: "/opt/pnpm/bin/pnpm.cjs" }); + assert.deepEqual(viaScript, { command: process.execPath, args: ["/opt/pnpm/bin/pnpm.cjs", "run", "build:typescript"], shell: undefined }); + // The standalone pnpm build points it at a native executable, which Node cannot run. + const viaExecutable = defaultCommandFor({ run: "build:typescript" }, { npm_execpath: "/home/ci/.local/share/pnpm/pnpm" }); + assert.deepEqual(viaExecutable, { command: "/home/ci/.local/share/pnpm/pnpm", args: ["run", "build:typescript"], shell: undefined }); + const viaWindowsExecutable = defaultCommandFor({ run: "build:typescript" }, { npm_execpath: "C:\\pnpm\\pnpm.exe" }); + assert.deepEqual(viaWindowsExecutable, { command: "C:\\pnpm\\pnpm.exe", args: ["run", "build:typescript"], shell: undefined }); const viaPath = defaultCommandFor({ run: "build:typescript" }, {}); assert.equal(viaPath.command, "pnpm"); assert.deepEqual(viaPath.args, ["run", "build:typescript"]);