feat(nevermore-cli): Report per-package pcall duration in aggregated batch test mode

Previously every row in `nevermore batch test` showed the same duration because all
packages awaited the same shared batch execution promise — the outer wall-clock was
identical for every package. The Luau batch runner now measures pcall time per
package, emits it in the END marker and JSON summary, and the result flows through
ScriptRunResult → SingleTestResult → BatchTestResult. batch-runner.ts uses the
inner duration when provided and falls back to wall-clock otherwise (preserves
non-aggregated behavior).

Author: Quenty

tools/nevermore-cli/src/commands/batch-command/batch-test-command.ts

@@ -238,6 +238,10 @@ async function _runAsync(args: BatchTestArgs): Promise<void> {
           placeId: pkg.target.placeId,
           success: result.success,
           logs: result.logs,
+          // Aggregated mode reports per-package pcall time; the outer
+          // wall-clock would otherwise be identical for every package
+          // (they all await the same shared batch execution).
+          durationMs: result.durationMs,
           progressSummary: result.testCounts
             ? { kind: 'test-counts' as const, ...result.testCounts }
             : undefined,

tools/nevermore-cli/src/utils/batch/batch-runner.ts

@@ -7,6 +7,19 @@ import {
 } from '@quenty/cli-output-helpers/reporting';
 import { type TargetPackage } from './changed-packages-utils.js';
 
+/** Partial result returned by executeAsync — durationMs is optional. */
+export type PartialBatchResult<TResult extends PackageResult> = Omit<
+  TResult,
+  'durationMs'
+> & {
+  /**
+   * Inner-measured duration. When provided, overrides the outer wall-clock
+   * timing (useful in aggregated batch mode where every package's outer
+   * await resolves at the same instant).
+   */
+  durationMs?: number;
+};
+
 export interface BatchOptions<TResult extends PackageResult> {
   packages: TargetPackage[];
   concurrency?: number;
@@ -16,7 +29,7 @@ export interface BatchOptions<TResult extends PackageResult> {
   executeAsync: (
     pkg: TargetPackage,
     reporter: Reporter
-  ) => Promise<Omit<TResult, 'durationMs'>>;
+  ) => Promise<PartialBatchResult<TResult>>;
 }
 
 export async function runBatchAsync<TResult extends PackageResult>(
@@ -85,7 +98,7 @@ async function _runOneAsync<TResult extends PackageResult>(
   executeAsync: (
     pkg: TargetPackage,
     reporter: Reporter
-  ) => Promise<Omit<TResult, 'durationMs'>>,
+  ) => Promise<PartialBatchResult<TResult>>,
   reporter: Reporter,
   bufferOutput: boolean,
   stateTracker?: IStateTracker
@@ -96,7 +109,8 @@ async function _runOneAsync<TResult extends PackageResult>(
   const execute = async (): Promise<TResult> => {
     try {
       const partial = await executeAsync(pkg, reporter);
-      return { ...partial, durationMs: Date.now() - startMs } as TResult;
+      const durationMs = partial.durationMs ?? Date.now() - startMs;
+      return { ...partial, durationMs } as TResult;
     } catch (err) {
       const errorMessage = err instanceof Error ? err.message : String(err);
       const currentPhase = stateTracker?.getCurrentPhase(pkg.name);

tools/nevermore-cli/src/utils/job-context/batch-script-job-context.ts

@@ -132,7 +132,7 @@ export class BatchScriptJobContext implements JobContext {
       return { success: false };
     }
 
-    return { success: result.success };
+    return { success: result.success, durationMs: result.durationMs };
   }
 
   async getLogsAsync(deployment: Deployment): Promise<string> {

tools/nevermore-cli/src/utils/job-context/job-context.ts

@@ -17,6 +17,13 @@ export interface RunScriptOptions {
 export interface ScriptRunResult {
   /** Whether the execution infrastructure succeeded (not test assertions). */
   success: boolean;
+  /**
+   * Optional inner script execution time, reported when the context can
+   * measure it directly (e.g. aggregated batch mode reports per-package
+   * pcall durations). When undefined, callers should fall back to their own
+   * wall-clock measurement.
+   */
+  durationMs?: number;
 }
 
 /**

tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.ts

@@ -5,6 +5,8 @@ export interface BatchPackageResult {
   slug: string;
   success: boolean;
   logs: string;
+  /** Inner pcall execution time reported by the Luau batch runner. */
+  durationMs?: number;
   testCounts?: ParsedTestCounts;
 }
 
@@ -15,6 +17,7 @@ const SUMMARY_MARKER = '===BATCH_TEST_SUMMARY===';
 interface SummaryEntry {
   slug: string;
   success: boolean;
+  durationMs?: number;
   error?: string;
 }
 
@@ -24,9 +27,9 @@ interface SummaryEntry {
  * The batch Luau template prints structured markers around each package's output:
  *   ===BATCH_TEST_BEGIN <slug>===
  *   ... test output ...
- *   ===BATCH_TEST_END <slug> PASS|FAIL===
+ *   ===BATCH_TEST_END <slug> PASS|FAIL <durationMs>===
  *   ===BATCH_TEST_SUMMARY===
- *   [{"slug":"maid","success":true}, ...]
+ *   [{"slug":"maid","success":true,"durationMs":1234}, ...]
  *
  * Success is determined from the JSON summary (based on pcall results), which is
  * immune to log reordering. The BEGIN/END markers are used only for splitting logs
@@ -48,10 +51,14 @@ export function parseBatchTestLogs(
   // ── Pass 1: Extract per-package log sections from markers ──
 
   const logSections = new Map<string, string>();
+  const markerDurations = new Map<string, number>();
   let currentSlug: string | null = null;
   let currentLines: string[] = [];
   let summaryLineIndex = -1;
 
+  // Matches "<slug> PASS|FAIL [<durationMs>]" — slugs have no whitespace.
+  const endInnerPattern = /^(\S+)\s+(?:PASS|FAIL)(?:\s+(\d+))?$/;
+
   for (let i = 0; i < lines.length; i++) {
     const trimmed = lines[i].trimEnd();
 
@@ -63,11 +70,15 @@ export function parseBatchTestLogs(
 
     if (trimmed.startsWith(END_MARKER) && trimmed.endsWith('===')) {
       const inner = trimmed.slice(END_MARKER.length, -3);
-      const spaceIndex = inner.lastIndexOf(' ');
-      const endSlug = spaceIndex >= 0 ? inner.slice(0, spaceIndex) : inner;
+      const match = endInnerPattern.exec(inner);
+      const endSlug = match ? match[1] : inner;
+      const durationStr = match?.[2];
 
       if (currentSlug && endSlug === currentSlug) {
         logSections.set(currentSlug, currentLines.join('\n'));
+        if (durationStr !== undefined) {
+          markerDurations.set(currentSlug, parseInt(durationStr, 10));
+        }
         currentSlug = null;
         currentLines = [];
       }
@@ -89,6 +100,7 @@ export function parseBatchTestLogs(
   // ── Pass 2: Parse the JSON summary for authoritative pcall results ──
 
   const summaryResults = new Map<string, boolean>();
+  const summaryDurations = new Map<string, number>();
   if (summaryLineIndex >= 0 && summaryLineIndex + 1 < lines.length) {
     const jsonLine = lines
       .slice(summaryLineIndex + 1)
@@ -98,6 +110,9 @@ export function parseBatchTestLogs(
       const entries = JSON.parse(jsonLine) as SummaryEntry[];
       for (const entry of entries) {
         summaryResults.set(entry.slug, entry.success);
+        if (typeof entry.durationMs === 'number') {
+          summaryDurations.set(entry.slug, entry.durationMs);
+        }
       }
       // Log any pcall failures from the Luau template
       const failures = entries.filter((e) => !e.success);
@@ -144,7 +159,17 @@ export function parseBatchTestLogs(
     }
 
     const testCounts = sectionLogs ? parseTestCounts(sectionLogs) : undefined;
-    results.set(packageName, { slug, success, logs: sectionLogs, testCounts });
+    // Prefer the JSON summary (authoritative, immune to log reordering);
+    // fall back to the END-marker value if the summary was truncated.
+    const durationMs =
+      summaryDurations.get(slug) ?? markerDurations.get(slug);
+    results.set(packageName, {
+      slug,
+      success,
+      logs: sectionLogs,
+      durationMs,
+      testCounts,
+    });
   }
 
   return results;

tools/nevermore-cli/src/utils/testing/runner/test-runner.ts

@@ -12,6 +12,12 @@ export interface SingleTestResult {
   success: boolean;
   logs: string;
   testCounts?: ParsedTestCounts;
+  /**
+   * Inner script execution time, forwarded from the JobContext when it can
+   * measure pcall duration directly (aggregated batch mode). Undefined for
+   * non-aggregated cloud/local runs — callers should fall back to wall-clock.
+   */
+  durationMs?: number;
 }
 
 export interface SingleTestOptions {
@@ -66,6 +72,7 @@ export async function runSingleTestAsync(
       success: result.success && parsed.success,
       logs: parsed.logs,
       testCounts: parseTestCounts(parsed.logs),
+      durationMs: result.durationMs,
     };
   } finally {
     await context.releaseAsync(deployment);

tools/nevermore-cli/templates/batch-test-runner.luau

@@ -32,6 +32,7 @@ end
 type Result = {
 	success: boolean,
 	slug: string,
+	durationMs: number,
 	error: string?,
 }
 
@@ -42,8 +43,8 @@ for _, slug in packageSlugs do
 	if not scriptSource then
 		warn(`[BatchTest] No script for {slug}`)
 		print("===BATCH_TEST_BEGIN " .. slug .. "===")
-		print("===BATCH_TEST_END " .. slug .. " FAIL===")
-		table.insert(results, { slug = slug, success = false, error = "No test script found" })
+		print("===BATCH_TEST_END " .. slug .. " FAIL 0===")
+		table.insert(results, { slug = slug, success = false, durationMs = 0, error = "No test script found" })
 		continue
 	end
 
@@ -71,6 +72,10 @@ for _, slug in packageSlugs do
 
 	print("===BATCH_TEST_BEGIN " .. slug .. "===")
 
+	-- Measure pcall execution time only. The surrounding cleanup/yield cost
+	-- is amortized across all packages and would otherwise dominate fast tests.
+	local startClock = os.clock()
+
 	local testOk, testErr = pcall(function()
 		local fn, compileErr = loadstring(scriptSource, slug)
 		if not fn then
@@ -79,6 +84,8 @@ for _, slug in packageSlugs do
 		fn()
 	end)
 
+	local durationMs = math.floor((os.clock() - startClock) * 1000 + 0.5)
+
 	-- Yield before the END marker for the same reason: leaked deferred
 	-- callbacks may fire during fn() and their output must land before
 	-- the marker in the log stream.
@@ -112,12 +119,12 @@ for _, slug in packageSlugs do
 	end
 
 	if testOk then
-		print("===BATCH_TEST_END " .. slug .. " PASS===")
-		table.insert(results, { slug = slug, success = true })
+		print("===BATCH_TEST_END " .. slug .. " PASS " .. tostring(durationMs) .. "===")
+		table.insert(results, { slug = slug, success = true, durationMs = durationMs })
 	else
 		warn("[BatchTest] " .. slug .. ": " .. tostring(testErr))
-		print("===BATCH_TEST_END " .. slug .. " FAIL===")
-		table.insert(results, { slug = slug, success = false, error = tostring(testErr) })
+		print("===BATCH_TEST_END " .. slug .. " FAIL " .. tostring(durationMs) .. "===")
+		table.insert(results, { slug = slug, success = false, durationMs = durationMs, error = tostring(testErr) })
 	end
 end