From 98298f79319fb8914330300f3768dfa1faa04c90 Mon Sep 17 00:00:00 2001 From: Vincent Koc Date: Thu, 19 Mar 2026 14:02:19 -0700 Subject: [PATCH] fix(ci): trace test runner memory retention --- scripts/test-parallel-memory.mjs | 103 +++++++++++++++++++++++ scripts/test-parallel.mjs | 128 +++++++++++++++++++++++++++++ test/scripts/test-parallel.test.ts | 33 ++++++++ 3 files changed, 264 insertions(+) create mode 100644 scripts/test-parallel-memory.mjs diff --git a/scripts/test-parallel-memory.mjs b/scripts/test-parallel-memory.mjs new file mode 100644 index 00000000000..a4fa2602cd1 --- /dev/null +++ b/scripts/test-parallel-memory.mjs @@ -0,0 +1,103 @@ +import { spawnSync } from "node:child_process"; + +const ESCAPE = String.fromCodePoint(27); +const BELL = String.fromCodePoint(7); +const ANSI_ESCAPE_PATTERN = new RegExp( + // Strip CSI/OSC-style control sequences from Vitest output before parsing file lines. + `${ESCAPE}(?:\\][^${BELL}]*(?:${BELL}|${ESCAPE}\\\\)|\\[[0-?]*[ -/]*[@-~]|[@-Z\\\\-_])`, + "g", +); + +const COMPLETED_TEST_FILE_LINE_PATTERN = + /(?(?:src|extensions|test|ui)\/\S+?\.(?:live\.test|e2e\.test|test)\.ts)\s+\(.*\)\s+(?\d+(?:\.\d+)?)(?ms|s)\s*$/; + +const PS_COLUMNS = ["pid=", "ppid=", "rss="]; + +function parseDurationMs(rawValue, unit) { + const parsed = Number.parseFloat(rawValue); + if (!Number.isFinite(parsed)) { + return null; + } + return unit === "s" ? Math.round(parsed * 1000) : Math.round(parsed); +} + +function stripAnsi(text) { + return text.replaceAll(ANSI_ESCAPE_PATTERN, ""); +} + +export function parseCompletedTestFileLines(text) { + return stripAnsi(text) + .split(/\r?\n/u) + .map((line) => { + const match = line.match(COMPLETED_TEST_FILE_LINE_PATTERN); + if (!match?.groups) { + return null; + } + return { + file: match.groups.file, + durationMs: parseDurationMs(match.groups.duration, match.groups.unit), + }; + }) + .filter((entry) => entry !== null); +} + +export function sampleProcessTreeRssKb(rootPid) { + if (!Number.isInteger(rootPid) || rootPid <= 0 || process.platform === "win32") { + return null; + } + + const result = spawnSync("ps", ["-axo", PS_COLUMNS.join(",")], { + encoding: "utf8", + }); + if (result.status !== 0 || result.error) { + return null; + } + + const childPidsByParent = new Map(); + const rssByPid = new Map(); + for (const line of result.stdout.split(/\r?\n/u)) { + const trimmed = line.trim(); + if (!trimmed) { + continue; + } + const [pidRaw, parentRaw, rssRaw] = trimmed.split(/\s+/u); + const pid = Number.parseInt(pidRaw ?? "", 10); + const parentPid = Number.parseInt(parentRaw ?? "", 10); + const rssKb = Number.parseInt(rssRaw ?? "", 10); + if (!Number.isInteger(pid) || !Number.isInteger(parentPid) || !Number.isInteger(rssKb)) { + continue; + } + const siblings = childPidsByParent.get(parentPid) ?? []; + siblings.push(pid); + childPidsByParent.set(parentPid, siblings); + rssByPid.set(pid, rssKb); + } + + if (!rssByPid.has(rootPid)) { + return null; + } + + let rssKb = 0; + let processCount = 0; + const queue = [rootPid]; + const visited = new Set(); + while (queue.length > 0) { + const pid = queue.shift(); + if (pid === undefined || visited.has(pid)) { + continue; + } + visited.add(pid); + const currentRssKb = rssByPid.get(pid); + if (currentRssKb !== undefined) { + rssKb += currentRssKb; + processCount += 1; + } + for (const childPid of childPidsByParent.get(pid) ?? []) { + if (!visited.has(childPid)) { + queue.push(childPid); + } + } + } + + return { rssKb, processCount }; +} diff --git a/scripts/test-parallel.mjs b/scripts/test-parallel.mjs index 78fcf35f6d1..841132d69e0 100644 --- a/scripts/test-parallel.mjs +++ b/scripts/test-parallel.mjs @@ -4,6 +4,7 @@ import os from "node:os"; import path from "node:path"; import { channelTestPrefixes } from "../vitest.channel-paths.mjs"; import { isUnitConfigTestFile } from "../vitest.unit-paths.mjs"; +import { parseCompletedTestFileLines, sampleProcessTreeRssKb } from "./test-parallel-memory.mjs"; import { appendCapturedOutput, hasFatalTestRunOutput, @@ -184,6 +185,7 @@ const countExplicitEntryFilters = (entryArgs) => { const { fileFilters } = parsePassthroughArgs(entryArgs.slice(2)); return fileFilters.length > 0 ? fileFilters.length : null; }; +const getExplicitEntryFilters = (entryArgs) => parsePassthroughArgs(entryArgs.slice(2)).fileFilters; const passthroughRequiresSingleRun = passthroughOptionArgs.some((arg) => { if (!arg.startsWith("-")) { return false; @@ -707,6 +709,22 @@ const maxOldSpaceSizeMb = (() => { })(); const formatElapsedMs = (elapsedMs) => elapsedMs >= 1000 ? `${(elapsedMs / 1000).toFixed(1)}s` : `${Math.round(elapsedMs)}ms`; +const formatMemoryKb = (rssKb) => + rssKb >= 1024 ** 2 + ? `${(rssKb / 1024 ** 2).toFixed(2)}GiB` + : rssKb >= 1024 + ? `${(rssKb / 1024).toFixed(1)}MiB` + : `${rssKb}KiB`; +const formatMemoryDeltaKb = (rssKb) => + `${rssKb >= 0 ? "+" : "-"}${formatMemoryKb(Math.abs(rssKb))}`; +const rawMemoryTrace = process.env.OPENCLAW_TEST_MEMORY_TRACE?.trim().toLowerCase(); +const memoryTraceEnabled = + process.platform !== "win32" && + (rawMemoryTrace === "1" || + rawMemoryTrace === "true" || + (rawMemoryTrace !== "0" && rawMemoryTrace !== "false" && isCI)); +const memoryTracePollMs = Math.max(250, parseEnvNumber("OPENCLAW_TEST_MEMORY_TRACE_POLL_MS", 1000)); +const memoryTraceTopCount = Math.max(1, parseEnvNumber("OPENCLAW_TEST_MEMORY_TRACE_TOP_COUNT", 6)); const runOnce = (entry, extraArgs = []) => new Promise((resolve) => { @@ -718,6 +736,7 @@ const runOnce = (entry, extraArgs = []) => entry.name === "extensions" && maxWorkers === 1 && entry.args.includes("--pool=vmForks") ? entry.args.map((arg) => (arg === "--pool=vmForks" ? "--pool=forks" : arg)) : entry.args; + const explicitEntryFilters = getExplicitEntryFilters(entryArgs); const args = maxWorkers ? [ ...entryArgs, @@ -749,12 +768,115 @@ const runOnce = (entry, extraArgs = []) => let fatalSeen = false; let childError = null; let child; + let pendingLine = ""; + let memoryPollTimer = null; + const memoryFileRecords = []; + let initialTreeSample = null; + let latestTreeSample = null; + let peakTreeSample = null; + const updatePeakTreeSample = (sample, reason) => { + if (!sample) { + return; + } + if (!peakTreeSample || sample.rssKb > peakTreeSample.rssKb) { + peakTreeSample = { ...sample, reason }; + } + }; + const captureTreeSample = (reason) => { + if (!memoryTraceEnabled || !child?.pid) { + return null; + } + const sample = sampleProcessTreeRssKb(child.pid); + if (!sample) { + return null; + } + latestTreeSample = sample; + if (!initialTreeSample) { + initialTreeSample = sample; + } + updatePeakTreeSample(sample, reason); + return sample; + }; + const logMemoryTraceForText = (text) => { + if (!memoryTraceEnabled) { + return; + } + const combined = `${pendingLine}${text}`; + const lines = combined.split(/\r?\n/u); + pendingLine = lines.pop() ?? ""; + const completedFiles = parseCompletedTestFileLines(lines.join("\n")); + for (const completedFile of completedFiles) { + const sample = captureTreeSample(completedFile.file); + if (!sample) { + continue; + } + const previousRssKb = + memoryFileRecords.length > 0 + ? (memoryFileRecords.at(-1)?.rssKb ?? initialTreeSample?.rssKb ?? sample.rssKb) + : (initialTreeSample?.rssKb ?? sample.rssKb); + const deltaKb = sample.rssKb - previousRssKb; + const record = { + ...completedFile, + rssKb: sample.rssKb, + processCount: sample.processCount, + deltaKb, + }; + memoryFileRecords.push(record); + console.log( + `[test-parallel][mem] ${entry.name} file=${record.file} rss=${formatMemoryKb( + record.rssKb, + )} delta=${formatMemoryDeltaKb(record.deltaKb)} peak=${formatMemoryKb( + peakTreeSample?.rssKb ?? record.rssKb, + )} procs=${record.processCount}${record.durationMs ? ` duration=${formatElapsedMs(record.durationMs)}` : ""}`, + ); + } + }; + const logMemoryTraceSummary = () => { + if (!memoryTraceEnabled) { + return; + } + captureTreeSample("close"); + const fallbackRecord = + memoryFileRecords.length === 0 && + explicitEntryFilters.length === 1 && + latestTreeSample && + initialTreeSample + ? [ + { + file: explicitEntryFilters[0], + deltaKb: latestTreeSample.rssKb - initialTreeSample.rssKb, + }, + ] + : []; + const totalDeltaKb = + initialTreeSample && latestTreeSample + ? latestTreeSample.rssKb - initialTreeSample.rssKb + : 0; + const topGrowthFiles = [...memoryFileRecords, ...fallbackRecord] + .filter((record) => record.deltaKb > 0 && typeof record.file === "string") + .toSorted((left, right) => right.deltaKb - left.deltaKb) + .slice(0, memoryTraceTopCount) + .map((record) => `${record.file}:${formatMemoryDeltaKb(record.deltaKb)}`); + console.log( + `[test-parallel][mem] summary ${entry.name} files=${memoryFileRecords.length} peak=${formatMemoryKb( + peakTreeSample?.rssKb ?? 0, + )} totalDelta=${formatMemoryDeltaKb(totalDeltaKb)} peakAt=${ + peakTreeSample?.reason ?? "n/a" + } top=${topGrowthFiles.length > 0 ? topGrowthFiles.join(", ") : "none"}`, + ); + }; try { child = spawn(pnpm, args, { stdio: ["inherit", "pipe", "pipe"], env: { ...process.env, VITEST_GROUP: entry.name, NODE_OPTIONS: resolvedNodeOptions }, shell: isWindows, }); + captureTreeSample("spawn"); + if (memoryTraceEnabled) { + memoryPollTimer = setInterval(() => { + captureTreeSample("poll"); + }, memoryTracePollMs); + } } catch (err) { console.error(`[test-parallel] spawn failed: ${String(err)}`); resolve(1); @@ -765,12 +887,14 @@ const runOnce = (entry, extraArgs = []) => const text = chunk.toString(); fatalSeen ||= hasFatalTestRunOutput(`${output}${text}`); output = appendCapturedOutput(output, text); + logMemoryTraceForText(text); process.stdout.write(chunk); }); child.stderr?.on("data", (chunk) => { const text = chunk.toString(); fatalSeen ||= hasFatalTestRunOutput(`${output}${text}`); output = appendCapturedOutput(output, text); + logMemoryTraceForText(text); process.stderr.write(chunk); }); child.on("error", (err) => { @@ -778,8 +902,12 @@ const runOnce = (entry, extraArgs = []) => console.error(`[test-parallel] child error: ${String(err)}`); }); child.on("close", (code, signal) => { + if (memoryPollTimer) { + clearInterval(memoryPollTimer); + } children.delete(child); const resolvedCode = resolveTestRunExitCode({ code, signal, output, fatalSeen, childError }); + logMemoryTraceSummary(); console.log( `[test-parallel] done ${entry.name} code=${String(resolvedCode)} elapsed=${formatElapsedMs(Date.now() - startedAt)}`, ); diff --git a/test/scripts/test-parallel.test.ts b/test/scripts/test-parallel.test.ts index c2c217ad181..5d88f50e9e1 100644 --- a/test/scripts/test-parallel.test.ts +++ b/test/scripts/test-parallel.test.ts @@ -1,4 +1,5 @@ import { describe, expect, it } from "vitest"; +import { parseCompletedTestFileLines } from "../../scripts/test-parallel-memory.mjs"; import { appendCapturedOutput, hasFatalTestRunOutput, @@ -44,3 +45,35 @@ describe("scripts/test-parallel fatal output guard", () => { expect(appendCapturedOutput(output, "defg", 5)).toBe("cdefg"); }); }); + +describe("scripts/test-parallel memory trace parsing", () => { + it("extracts completed test file lines from colored Vitest output", () => { + const output = [ + "\u001B[32m✓\u001B[39m src/config/doc-baseline.test.ts \u001B[2m(\u001B[22m\u001B[2m8 tests\u001B[22m\u001B[2m)\u001B[22m\u001B[33m 46424\u001B[2mms\u001B[22m\u001B[39m", + " \u001B[32m✓\u001B[39m src/infra/restart.test.ts (5 tests) 4.2s", + ].join("\n"); + + expect(parseCompletedTestFileLines(output)).toEqual([ + { + file: "src/config/doc-baseline.test.ts", + durationMs: 46_424, + }, + { + file: "src/infra/restart.test.ts", + durationMs: 4_200, + }, + ]); + }); + + it("ignores non-file summary lines", () => { + expect( + parseCompletedTestFileLines( + [ + " Test Files 2 passed (2)", + " Tests 30 passed (30)", + "[test-parallel] done unit code=0 elapsed=68.8s", + ].join("\n"), + ), + ).toEqual([]); + }); +});