diff --git a/test/e2e/live/rebuild-hermes-progress.ts b/test/e2e/live/rebuild-hermes-progress.ts index f04eb960697..ac73c21437e 100644 --- a/test/e2e/live/rebuild-hermes-progress.ts +++ b/test/e2e/live/rebuild-hermes-progress.ts @@ -6,6 +6,7 @@ import os from "node:os"; import { REPO_ROOT } from "../fixtures/paths.ts"; import type { ShellProbeOutputEvent } from "../fixtures/shell-probe.ts"; +import type { RebuildHermesTimeline, RebuildHermesTimingPhase } from "./rebuild-hermes-timing.ts"; interface RebuildHermesResourceSnapshot { freeMemoryBytes: number; @@ -32,6 +33,7 @@ export interface RebuildHermesProgress { onOutput: (event: ShellProbeOutputEvent) => void; phase: (label: string) => void; stop: () => void; + timeline: () => RebuildHermesTimeline; } const DEFAULT_HEARTBEAT_INTERVAL_MS = 60_000; @@ -80,10 +82,17 @@ export function startRebuildHermesProgress( const clearTimer = options.clearTimer ?? ((timer) => clearInterval(timer as NodeJS.Timeout)); const logLine = options.logLine ?? ((line) => process.stdout.write(`${line}\n`)); const sampleResources = options.sampleResources ?? defaultResourceSnapshot; + const overallStartedAt = now(); + const completedPhases: RebuildHermesTimingPhase[] = []; let phaseLabel = initialPhase; - let phaseStartedAt = now(); + let phaseStartedAt = overallStartedAt; let lastOutputAt: number | null = null; let stopped = false; + let stoppedAt = overallStartedAt; + + const completeActivePhase = (completedAt = now()) => { + completedPhases.push({ label: phaseLabel, elapsedMs: completedAt - phaseStartedAt }); + }; const logBestEffort = (state: "started" | "running" | "finished") => { try { @@ -115,6 +124,7 @@ export function startRebuildHermesProgress( phase(label) { if (stopped) return; logBestEffort("finished"); + completeActivePhase(); phaseLabel = label; phaseStartedAt = now(); lastOutputAt = null; @@ -123,8 +133,17 @@ export function startRebuildHermesProgress( stop() { if (stopped) return; stopped = true; + stoppedAt = now(); + completeActivePhase(stoppedAt); clearTimer(timer); logBestEffort("finished"); }, + timeline() { + const current = now(); + const phases = stopped + ? [...completedPhases] + : [...completedPhases, { label: phaseLabel, elapsedMs: current - phaseStartedAt }]; + return { phases, totalMs: (stopped ? stoppedAt : current) - overallStartedAt }; + }, }; } diff --git a/test/e2e/live/rebuild-hermes-timing.ts b/test/e2e/live/rebuild-hermes-timing.ts new file mode 100644 index 00000000000..85ba1d31433 --- /dev/null +++ b/test/e2e/live/rebuild-hermes-timing.ts @@ -0,0 +1,99 @@ +// SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +import os from "node:os"; + +export interface RebuildHermesTimingPhase { + label: string; + elapsedMs: number; +} + +export interface RebuildHermesTimeline { + phases: readonly RebuildHermesTimingPhase[]; + totalMs: number; +} + +export interface RebuildHermesRunnerClass { + platform: string; + arch: string; + cpuCount: number; + cpuModel: string; + totalMemoryBytes: number; +} + +export type RebuildHermesLane = "normal" | "stale-base"; + +export interface RebuildHermesTimingSummary { + schema: 1; + lane: RebuildHermesLane; + runnerClass: RebuildHermesRunnerClass; + phases: RebuildHermesTimingPhase[]; + totalMs: number; + capturedAtIso: string; +} + +interface RunnerClassSample { + platform: string; + arch: string; + cpus: ReadonlyArray<{ model: string }>; + totalMemoryBytes: number; +} + +function defaultRunnerClassSample(): RunnerClassSample { + return { + platform: os.platform(), + arch: os.arch(), + cpus: os.cpus().map((cpu) => ({ model: cpu.model })), + totalMemoryBytes: os.totalmem(), + }; +} + +/** + * Fingerprint the runner so before/after timings can be confirmed to come from + * the same runner class before any comparison. The comparison itself lives with + * whoever reads the artifacts; this only records the identifying fields. + */ +export function describeRunnerClass( + sample: () => RunnerClassSample = defaultRunnerClassSample, +): RebuildHermesRunnerClass { + const snapshot = sample(); + return { + platform: snapshot.platform, + arch: snapshot.arch, + cpuCount: snapshot.cpus.length, + cpuModel: snapshot.cpus[0]?.model.trim() || "unknown", + totalMemoryBytes: snapshot.totalMemoryBytes, + }; +} + +function normalizeMs(value: number): number { + return Number.isFinite(value) && value > 0 ? Math.round(value) : 0; +} + +export interface BuildRebuildHermesTimingSummaryInput { + lane: RebuildHermesLane; + timeline: RebuildHermesTimeline; + runnerClass: RebuildHermesRunnerClass; + capturedAtIso: string; +} + +/** + * Shape the recorded timeline into the stable timing artifact. Durations are + * normalized to non-negative whole milliseconds so repeated runs on the same + * runner class stay directly comparable. + */ +export function buildRebuildHermesTimingSummary( + input: BuildRebuildHermesTimingSummaryInput, +): RebuildHermesTimingSummary { + return { + schema: 1, + lane: input.lane, + runnerClass: input.runnerClass, + phases: input.timeline.phases.map((phase) => ({ + label: phase.label, + elapsedMs: normalizeMs(phase.elapsedMs), + })), + totalMs: normalizeMs(input.timeline.totalMs), + capturedAtIso: input.capturedAtIso, + }; +} diff --git a/test/e2e/live/rebuild-hermes.test.ts b/test/e2e/live/rebuild-hermes.test.ts index a46dae51434..1868ec9260b 100644 --- a/test/e2e/live/rebuild-hermes.test.ts +++ b/test/e2e/live/rebuild-hermes.test.ts @@ -30,6 +30,7 @@ import { requireRebuildHermesInitialImageTag, } from "./rebuild-hermes-image-state.ts"; import { startRebuildHermesProgress } from "./rebuild-hermes-progress.ts"; +import { buildRebuildHermesTimingSummary, describeRunnerClass } from "./rebuild-hermes-timing.ts"; // The migrated scope is the legacy non-interactive shell regression: install.sh, // Docker base-image builds, OpenShell provider/sandbox commands, direct Hermes @@ -950,5 +951,19 @@ test(STALE_BASE_REBUILD backupRoot: sandboxBackupRoot, leaks, }); + + // Capture per-phase and total wall time tagged with the runner class so + // before/after comparisons for #7144 stay on the same runner class. Written + // before the final gate so the timing artifact survives an assertion failure. + await artifacts.writeJson( + "rebuild-hermes-timing.json", + buildRebuildHermesTimingSummary({ + lane: STALE_BASE_REBUILD ? "stale-base" : "normal", + timeline: progress.timeline(), + runnerClass: describeRunnerClass(), + capturedAtIso: new Date().toISOString(), + }), + ); + expect(leaks, "backup files must not contain credential-shaped values").toEqual([]); }); diff --git a/test/e2e/support/rebuild-hermes-timing.test.ts b/test/e2e/support/rebuild-hermes-timing.test.ts new file mode 100644 index 00000000000..eaf74e122a3 --- /dev/null +++ b/test/e2e/support/rebuild-hermes-timing.test.ts @@ -0,0 +1,139 @@ +// SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +import { describe, expect, it } from "vitest"; +import { + type RebuildHermesProgressOptions, + startRebuildHermesProgress, +} from "../live/rebuild-hermes-progress.ts"; +import { + buildRebuildHermesTimingSummary, + describeRunnerClass, +} from "../live/rebuild-hermes-timing.ts"; + +function timelineHarness() { + const state = { clockMs: 1_000 }; + const options: RebuildHermesProgressOptions = { + now: () => state.clockMs, + setTimer: () => ({ unref() {} }), + clearTimer: () => {}, + logLine: () => {}, + sampleResources: () => ({ + freeMemoryBytes: 0, + processRssBytes: 0, + totalMemoryBytes: 0, + workspaceFreeBytes: 0, + loadAverage1m: 0, + }), + }; + return { options, state }; +} + +describe("Hermes rebuild timing timeline", () => { + it("records each completed phase and closes the in-flight phase on snapshot", () => { + const { options, state } = timelineHarness(); + const progress = startRebuildHermesProgress("setup", options); + + state.clockMs = 4_000; + progress.phase("phase 6 nemoclaw rebuild"); + state.clockMs = 9_000; + + expect(progress.timeline()).toEqual({ + phases: [ + { label: "setup", elapsedMs: 3_000 }, + { label: "phase 6 nemoclaw rebuild", elapsedMs: 5_000 }, + ], + totalMs: 8_000, + }); + }); + + it("freezes the timeline at stop and ignores post-stop transitions", () => { + const { options, state } = timelineHarness(); + const progress = startRebuildHermesProgress("phase 7 verification", options); + + state.clockMs = 6_000; + progress.stop(); + state.clockMs = 60_000; + progress.phase("after stop"); + + expect(progress.timeline()).toEqual({ + phases: [{ label: "phase 7 verification", elapsedMs: 5_000 }], + totalMs: 5_000, + }); + }); + + it("uses the same stop timestamp for the final phase and total", () => { + const { options } = timelineHarness(); + let clockMs = 1_000; + options.now = () => { + const current = clockMs; + clockMs += 1_000; + return current; + }; + const progress = startRebuildHermesProgress("phase 7 verification", options); + + progress.stop(); + + expect(progress.timeline()).toEqual({ + phases: [{ label: "phase 7 verification", elapsedMs: 2_000 }], + totalMs: 2_000, + }); + }); +}); + +describe("Hermes rebuild timing summary", () => { + const runnerClass = describeRunnerClass(() => ({ + platform: "linux", + arch: "x64", + cpus: [{ model: " Model A " }, { model: "Model A" }], + totalMemoryBytes: 16 * 1024 ** 3, + })); + + it("derives a runner-class fingerprint from the sampled host", () => { + expect(runnerClass).toEqual({ + platform: "linux", + arch: "x64", + cpuCount: 2, + cpuModel: "Model A", + totalMemoryBytes: 16 * 1024 ** 3, + }); + }); + + it("labels the lane and normalizes durations to whole non-negative ms", () => { + const summary = buildRebuildHermesTimingSummary({ + lane: "stale-base", + runnerClass, + capturedAtIso: "2026-07-18T00:00:00.000Z", + timeline: { + phases: [ + { label: "setup", elapsedMs: 1_499.6 }, + { label: "phase 6 nemoclaw rebuild", elapsedMs: -5 }, + ], + totalMs: 12_345.4, + }, + }); + + expect(summary).toEqual({ + schema: 1, + lane: "stale-base", + runnerClass, + phases: [ + { label: "setup", elapsedMs: 1_500 }, + { label: "phase 6 nemoclaw rebuild", elapsedMs: 0 }, + ], + totalMs: 12_345, + capturedAtIso: "2026-07-18T00:00:00.000Z", + }); + }); + + it("falls back to a placeholder model when no CPU is reported", () => { + expect( + describeRunnerClass(() => ({ + platform: "linux", + arch: "arm64", + cpus: [], + totalMemoryBytes: 0, + })).cpuModel, + ).toBe("unknown"); + }); +});