fix: expose apply-patch timing summary

2026-06-06 18:12:58 +00:00
parent 3f26f4f359
commit 27acd2a98f
6 changed files with 234 additions and 5 deletions
@@ -50,6 +50,7 @@ export interface ApplyPatchV2Options {
  stdout: Writable;
  stderr?: Writable;
  argv?: string[];
+  timing?: ApplyPatchV2TimingOptions;
 }

 export interface ApplyPatchV2Executor {
@@ -75,6 +76,35 @@ export interface ApplyPatchV2RemoteResult {
  stderr: string;
 }

+export interface ApplyPatchV2TimingOptions {
+  providerId?: string;
+  route?: string;
+  transport?: "backend-core-broker" | "frontend-websocket" | "local" | "virtual";
+  thresholdMs?: number;
+}
+
+export interface ApplyPatchV2TimingSummary {
+  code: "apply-patch-v2-timing";
+  level: "info" | "warning";
+  status: "succeeded" | "failed";
+  providerId?: string;
+  route?: string;
+  transport?: ApplyPatchV2TimingOptions["transport"];
+  durationMs: number;
+  thresholdMs: number;
+  slow: boolean;
+  patchBytes: number;
+  fileCount: number;
+  hunkCount: number;
+  changedCount: number;
+  remoteOperationCount: number;
+  remoteOperationCounts: Record<string, number>;
+  remoteElapsedMs: number;
+  remoteFailureCount: number;
+  message: string;
+  note: string;
+}
+
 export class ApplyPatchV2Error extends Error {
  constructor(message: string, public readonly details: Record<string, unknown> = {}) {
    super(message);
@@ -91,6 +121,13 @@ interface ApplyPatchV2Plan {
  outcomes: ApplyPatchV2Outcome[];
 }

+export interface ApplyPatchV2RemoteMetrics {
+  remoteOperationCount: number;
+  remoteOperationCounts: Record<string, number>;
+  remoteElapsedMs: number;
+  remoteFailureCount: number;
+}
+
 const beginMarker = "*** Begin Patch";
 const endMarker = "*** End Patch";
 const environmentIdMarker = "*** Environment ID: ";
@@ -101,6 +138,7 @@ const moveToMarker = "*** Move to: ";
 const emptyChangeContextMarker = "@@";
 const changeContextMarker = "@@ ";
 const eofMarker = "*** End of File";
+const defaultApplyPatchV2SlowWarningMs = 10_000;

 export function isApplyPatchV2HelpArgs(args: string[] = []): boolean {
  const first = args[0] ?? "";
@@ -121,6 +159,24 @@ export function applyPatchV2HelpPayload() {
      firstLine: beginMarker,
      lastLine: endMarker
    },
+    timing: {
+      stderrPrefix: "UNIDESK_APPLY_PATCH_TIMING",
+      fields: [
+        "durationMs",
+        "patchBytes",
+        "fileCount",
+        "hunkCount",
+        "changedCount",
+        "remoteOperationCount",
+        "remoteOperationCounts",
+        "remoteElapsedMs",
+        "remoteFailureCount",
+        "providerId",
+        "route",
+        "transport"
+      ],
+      stdoutCompatibility: "Timing is written to stderr so success stdout remains Codex apply_patch-compatible."
+    },
    rules: [
      "Add File has no @@ hunk marker: put content immediately after `*** Add File: <path>` and prefix every content line with +.",
      "A blank line in Add File is a line containing only +.",
@@ -302,20 +358,162 @@ export async function runApplyPatchV2(options: ApplyPatchV2Options): Promise<num
    stderr.write("ssh apply-patch requires patch text on stdin.\n");
    return 2;
  }
+  const startedAtMs = Date.now();
+  const metrics = createApplyPatchV2RemoteMetrics();
+  const executor = instrumentApplyPatchV2Executor(options.executor, metrics);
+  let parsed: PatchParseResult | null = null;
+  let plan: ApplyPatchV2Plan | null = null;
  try {
-    const parsed = parseApplyPatchV2(patchText);
-    const plan = await applyPatchV2Hunks(options.executor, parsed.hunks);
+    parsed = parseApplyPatchV2(patchText);
+    plan = await applyPatchV2Hunks(executor, parsed.hunks);
    for (const hint of parsed.hints) stderr.write(`${hint}\n`);
    options.stdout.write("Success. Updated the following files:\n");
    for (const item of plan.changed) options.stdout.write(`${item}\n`);
+    stderr.write(formatApplyPatchV2TimingSummary(applyPatchV2TimingSummary({
+      status: "succeeded",
+      patchText,
+      parsed,
+      plan,
+      metrics,
+      startedAtMs,
+      options: options.timing,
+    })));
    return 0;
  } catch (error) {
+    const failureSummary = applyPatchV2TimingSummary({
+      status: "failed",
+      patchText,
+      parsed,
+      plan,
+      metrics,
+      startedAtMs,
+      options: options.timing,
+    });
    if (options.stderr === undefined) throw error;
    options.stderr.write(formatApplyPatchFailure(error));
+    options.stderr.write(formatApplyPatchV2TimingSummary(failureSummary));
    return 1;
  }
 }

+function createApplyPatchV2RemoteMetrics(): ApplyPatchV2RemoteMetrics {
+  return { remoteOperationCount: 0, remoteOperationCounts: {}, remoteElapsedMs: 0, remoteFailureCount: 0 };
+}
+
+function instrumentApplyPatchV2Executor(executor: ApplyPatchV2Executor, metrics: ApplyPatchV2RemoteMetrics): ApplyPatchV2Executor {
+  return {
+    ...executor,
+    run: executor.run === undefined ? undefined : async (command, input) => {
+      const operation = applyPatchV2OperationName(command);
+      const started = Date.now();
+      metrics.remoteOperationCount += 1;
+      metrics.remoteOperationCounts[operation] = (metrics.remoteOperationCounts[operation] ?? 0) + 1;
+      try {
+        const result = await executor.run!(command, input);
+        metrics.remoteElapsedMs += Math.max(0, Date.now() - started);
+        if (result.exitCode !== 0) metrics.remoteFailureCount += 1;
+        return result;
+      } catch (error) {
+        metrics.remoteElapsedMs += Math.max(0, Date.now() - started);
+        metrics.remoteFailureCount += 1;
+        throw error;
+      }
+    },
+    fs: executor.fs === undefined ? undefined : instrumentApplyPatchV2FileSystem(executor.fs, metrics),
+  };
+}
+
+function instrumentApplyPatchV2FileSystem(fs: ApplyPatchV2FileSystem, metrics: ApplyPatchV2RemoteMetrics): ApplyPatchV2FileSystem {
+  return {
+    stat: (path) => recordApplyPatchV2FsOperation(metrics, "fs.stat", () => fs.stat(path)),
+    readBlock: (path, blockIndex, blockBytes) => recordApplyPatchV2FsOperation(metrics, "fs.readBlock", () => fs.readBlock(path, blockIndex, blockBytes)),
+    writeFile: (path, content) => recordApplyPatchV2FsOperation(metrics, "fs.writeFile", () => fs.writeFile(path, content)),
+    deleteFile: (path) => recordApplyPatchV2FsOperation(metrics, "fs.deleteFile", () => fs.deleteFile(path)),
+  };
+}
+
+async function recordApplyPatchV2FsOperation<T>(metrics: ApplyPatchV2RemoteMetrics, operation: string, run: () => Promise<T>): Promise<T> {
+  const started = Date.now();
+  metrics.remoteOperationCount += 1;
+  metrics.remoteOperationCounts[operation] = (metrics.remoteOperationCounts[operation] ?? 0) + 1;
+  try {
+    const result = await run();
+    metrics.remoteElapsedMs += Math.max(0, Date.now() - started);
+    return result;
+  } catch (error) {
+    metrics.remoteElapsedMs += Math.max(0, Date.now() - started);
+    metrics.remoteFailureCount += 1;
+    throw error;
+  }
+}
+
+function applyPatchV2OperationName(command: string[]): string {
+  const index = command.indexOf("unidesk-apply-patch-v2");
+  return index >= 0 ? command[index + 1] ?? "unknown" : command[0] ?? "unknown";
+}
+
+export function applyPatchV2TimingSummary(options: {
+  status: ApplyPatchV2TimingSummary["status"];
+  patchText: string;
+  parsed: PatchParseResult | null;
+  plan: ApplyPatchV2Plan | null;
+  metrics: ApplyPatchV2RemoteMetrics;
+  startedAtMs: number;
+  finishedAtMs?: number;
+  options?: ApplyPatchV2TimingOptions;
+}): ApplyPatchV2TimingSummary {
+  const finishedAtMs = options.finishedAtMs ?? Date.now();
+  const durationMs = Math.max(0, Math.round(finishedAtMs - options.startedAtMs));
+  const thresholdMs = options.options?.thresholdMs ?? defaultApplyPatchV2SlowWarningMs;
+  const slow = durationMs > thresholdMs;
+  const patchBytes = Buffer.byteLength(options.patchText, "utf8");
+  const fileCount = countApplyPatchV2Files(options.parsed?.hunks ?? []);
+  const hunkCount = options.parsed?.hunks.length ?? 0;
+  const changedCount = options.plan?.changed.length ?? applyPatchV2ChangedCountFromOutcomes(options.plan?.outcomes ?? []);
+  const durationSeconds = Number((durationMs / 1000).toFixed(3));
+  const thresholdSeconds = Number((thresholdMs / 1000).toFixed(3));
+  return {
+    code: "apply-patch-v2-timing",
+    level: slow ? "warning" : "info",
+    status: options.status,
+    ...(options.options?.providerId === undefined ? {} : { providerId: options.options.providerId }),
+    ...(options.options?.route === undefined ? {} : { route: options.options.route }),
+    ...(options.options?.transport === undefined ? {} : { transport: options.options.transport }),
+    durationMs,
+    thresholdMs,
+    slow,
+    patchBytes,
+    fileCount,
+    hunkCount,
+    changedCount,
+    remoteOperationCount: options.metrics.remoteOperationCount,
+    remoteOperationCounts: options.metrics.remoteOperationCounts,
+    remoteElapsedMs: Math.max(0, Math.round(options.metrics.remoteElapsedMs)),
+    remoteFailureCount: options.metrics.remoteFailureCount,
+    message: slow
+      ? `apply-patch completed in ${durationSeconds}s, above the ${thresholdSeconds}s warning threshold; inspect remoteOperationCounts and remoteElapsedMs before repeating high-frequency patch work.`
+      : `apply-patch completed in ${durationSeconds}s.`,
+    note: "Timing summary is written to stderr so stdout remains Codex apply_patch-compatible.",
+  };
+}
+
+export function formatApplyPatchV2TimingSummary(summary: ApplyPatchV2TimingSummary): string {
+  return `UNIDESK_APPLY_PATCH_TIMING ${JSON.stringify(summary)}\n`;
+}
+
+function countApplyPatchV2Files(hunks: PatchHunk[]): number {
+  const files = new Set<string>();
+  for (const hunk of hunks) {
+    files.add(hunk.path);
+    if (hunk.kind === "update" && hunk.movePath !== null) files.add(hunk.movePath);
+  }
+  return files.size;
+}
+
+function applyPatchV2ChangedCountFromOutcomes(outcomes: ApplyPatchV2Outcome[]): number {
+  return outcomes.filter((outcome) => outcome.status === "applied").length;
+}
+
 async function applyPatchV2Hunks(executor: ApplyPatchV2Executor, hunks: PatchHunk[]): Promise<ApplyPatchV2Plan> {
  if (hunks.length === 0) throw new ApplyPatchV2Error("No files were modified.");