root/fusion
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

perf(engine): add per-phase timing logs and monorepo test warning

Browse Source 
Instrument worktree init, setup script, workflow steps, verification
commands, and in-merge fix retries with [timing] log entries so task
duration bottlenecks are visible in task logs. Also warn when
inferDefaultTestCommand falls back to `pnpm test` inside a pnpm
workspace — users should set an explicit scoped testCommand to avoid
running the whole monorepo suite on every merge.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
gsxdsm
2026-04-24 08:29:17 -07:00
parent 832c32c5ed
commit b8f4c890dc
4 changed files with 43 additions and 16 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
packages/engine/src/executor.test.ts
View File

@@ -451,7 +451,7 @@ describe("TaskExecutor worktreeInitCommand", () => {
// Should log success
expect(store.logEntry).toHaveBeenCalledWith(
"FN-010",
"Worktree init command completed",
expect.stringMatching(/^\[timing\] Worktree init command completed in \d+ms$/),
"pnpm install",
expect.objectContaining({ agentId: "executor" }),
);

11
packages/engine/src/executor.ts
View File

@@ -1326,13 +1326,15 @@ export class TaskExecutor {
// with "@fusion/core entry not found" because monorepo exports point
// to dist/. 5-minute timeout accommodates install + build together.
if (settings.worktreeInitCommand) {
const initStartedAt = Date.now();
try {
const initResult = await runConfiguredCommand(settings.worktreeInitCommand, worktreePath, 300_000);
if (initResult.spawnError || initResult.timedOut || initResult.exitCode !== 0) {
throw new Error(configuredCommandErrorMessage(initResult));
}
await this.store.logEntry(task.id, "Worktree init command completed", settings.worktreeInitCommand, this.currentRunContext);
await this.store.logEntry(task.id, `[timing] Worktree init command completed in ${Date.now() - initStartedAt}ms`, settings.worktreeInitCommand, this.currentRunContext);
} catch (err: unknown) {
await this.store.logEntry(task.id, `[timing] Worktree init command failed after ${Date.now() - initStartedAt}ms`, undefined, this.currentRunContext);
const execError = err instanceof Error ? err : new Error(String(err));
const message = "stderr" in execError && typeof (execError as Record<string, unknown>).stderr === "string"
? String((execError as Record<string, unknown>).stderr)
@@ -1351,12 +1353,13 @@ export class TaskExecutor {
if (settings.setupScript) {
const scriptCommand = settings.scripts?.[settings.setupScript];
if (scriptCommand) {
const setupStartedAt = Date.now();
try {
const setupResult = await runConfiguredCommand(scriptCommand, worktreePath, 120_000);
if (setupResult.spawnError || setupResult.timedOut || setupResult.exitCode !== 0) {
throw new Error(configuredCommandErrorMessage(setupResult));
}
await this.store.logEntry(task.id, `Setup script '${settings.setupScript}' completed`, scriptCommand, this.currentRunContext);
await this.store.logEntry(task.id, `[timing] Setup script '${settings.setupScript}' completed in ${Date.now() - setupStartedAt}ms`, scriptCommand, this.currentRunContext);
} catch (err: unknown) {
const execError = err instanceof Error ? err : new Error(String(err));
const message = "stderr" in execError && typeof (execError as Record<string, unknown>).stderr === "string"
@@ -3427,6 +3430,7 @@ ${failureFeedback}
executorLog.log(`${task.id} — [pre-merge] running workflow step: ${ws.name} (${stepMode} mode)`);
const startedAt = new Date().toISOString();
const stepStartedAtMs = Date.now();
// Push pending entry BEFORE execution so dashboard can show live status
results.push({
@@ -3445,6 +3449,7 @@ ${failureFeedback}
const completedAt = new Date().toISOString();
if (result.success) {
await this.store.logEntry(task.id, `[timing] Workflow step '${ws.name}' completed in ${Date.now() - stepStartedAtMs}ms`);
await this.store.logEntry(task.id, `[pre-merge] Workflow step completed: ${ws.name}`);
executorLog.log(`${task.id} — [pre-merge] workflow step passed: ${ws.name}`);
// Update existing pending entry in place
@@ -3460,6 +3465,7 @@ ${failureFeedback}
await this.store.updateTask(task.id, { workflowStepResults: results });
} else if (result.revisionRequested) {
// Revision requested — this is a structured outcome that routes back to executor
await this.store.logEntry(task.id, `[timing] Workflow step '${ws.name}' requested revision after ${Date.now() - stepStartedAtMs}ms`);
await this.store.logEntry(
task.id,
`[pre-merge] Workflow step requested revision: ${ws.name}`,
@@ -3485,6 +3491,7 @@ ${failureFeedback}
};
} else {
// Hard failure
await this.store.logEntry(task.id, `[timing] Workflow step '${ws.name}' failed after ${Date.now() - stepStartedAtMs}ms`);
await this.store.logEntry(
task.id,
`[pre-merge] Workflow step failed: ${ws.name}`,

2
packages/engine/src/merger.test.ts
View File

@@ -3407,7 +3407,7 @@ describe("aiMergeTask — deterministic merge verification", () => {
expect(store.moveTask).toHaveBeenCalledWith("FN-050", "done");
expect(store.logEntry).toHaveBeenCalledWith(
"FN-050",
"[verification] test command succeeded (exit 0, output exceeded buffer)",
expect.stringMatching(/^\[timing\] \[verification\] test command succeeded \(exit 0, output exceeded buffer\) in \d+ms$/),
);
});

44
packages/engine/src/merger.ts
View File

@@ -397,6 +397,18 @@ export function inferDefaultTestCommand(
// Infer test command from lock files
if (existsSync(join(rootDir, "pnpm-lock.yaml"))) {
// Monorepo heuristic: a pnpm-workspace.yaml means `pnpm test` will fan out
// across every workspace package on every merge, which is usually far slower
// than necessary. Warn so the user sets an explicit scoped testCommand
// (e.g. `pnpm -r --filter "...[main]" test`). We don't auto-scope because
// the default branch name isn't guaranteed and git context may be unavailable.
if (existsSync(join(rootDir, "pnpm-workspace.yaml"))) {
mergerLog.warn(
`Inferred test command "pnpm test" in a pnpm workspace (${rootDir}). ` +
`This runs the full monorepo suite on every merge. Consider setting an explicit ` +
`scoped testCommand in project settings, e.g. \`pnpm -r --filter "...[main]" test\`.`,
);
}
return {
command: "pnpm test",
testSource: "inferred",
@@ -572,6 +584,7 @@ async function runVerificationCommand(
success: false,
};
const verificationStartedAt = Date.now();
try {
const { stdout, stderr } = await execAsync(command, {
cwd: rootDir,
@@ -585,10 +598,12 @@ async function runVerificationCommand(
result.exitCode = 0;
result.success = true;
mergerLog.log(`${taskId}: ${type} command succeeded`);
await store.logEntry(taskId, `[verification] ${type} command succeeded (exit 0)`);
const verificationDurationMs = Date.now() - verificationStartedAt;
mergerLog.log(`${taskId}: ${type} command succeeded in ${verificationDurationMs}ms`);
await store.logEntry(taskId, `[timing] [verification] ${type} command succeeded (exit 0) in ${verificationDurationMs}ms`);
return result;
} catch (error: any) {
const verificationDurationMs = Date.now() - verificationStartedAt;
result.stdout = error?.stdout?.toString?.() || "";
result.stderr = error?.stderr?.toString?.() || "";
result.exitCode = typeof error?.status === "number"
@@ -601,10 +616,10 @@ async function runVerificationCommand(
result.success = maxBufferExceeded && result.exitCode === 0;
if (result.success) {
mergerLog.log(`${taskId}: ${type} command succeeded (exit 0, output exceeded buffer)`);
mergerLog.log(`${taskId}: ${type} command succeeded (exit 0, output exceeded buffer) in ${verificationDurationMs}ms`);
await store.logEntry(
taskId,
`[verification] ${type} command succeeded (exit 0, output exceeded buffer)`,
`[timing] [verification] ${type} command succeeded (exit 0, output exceeded buffer) in ${verificationDurationMs}ms`,
);
return result;
}
@@ -613,10 +628,10 @@ async function runVerificationCommand(
// the task for diagnostics without dumping test output to the engine stdout.
const output = result.stderr || result.stdout || error?.message || "Unknown error";
const summary = summarizeVerificationOutput(output, type);
mergerLog.error(`${taskId}: ${type} command failed (exit ${result.exitCode}); output captured in task log`);
mergerLog.error(`${taskId}: ${type} command failed (exit ${result.exitCode}) in ${verificationDurationMs}ms; output captured in task log`);
await store.logEntry(
taskId,
`[verification] ${type} command failed (exit ${result.exitCode}):\n${summary}`,
`[timing] [verification] ${type} command failed (exit ${result.exitCode}) after ${verificationDurationMs}ms:\n${summary}`,
);
}
@@ -2062,6 +2077,7 @@ export async function aiMergeTask(
if (failedResult) {
let fixSuccess = false;
for (let fixAttempt = 1; fixAttempt <= maxFixRetries; fixAttempt++) {
const fixAttemptStartedAt = Date.now();
mergerLog.log(`${taskId}: in-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`);
await store.logEntry(taskId, `In-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`);
@@ -2076,14 +2092,15 @@ export async function aiMergeTask(
settings, options, effectiveTestCommand, effectiveBuildCommand,
);
const fixAttemptDurationMs = Date.now() - fixAttemptStartedAt;
if (fixSuccess) {
mergerLog.log(`${taskId}: in-merge verification fix succeeded on attempt ${fixAttempt}`);
await store.logEntry(taskId, `In-merge verification fix succeeded — verification now passes`);
mergerLog.log(`${taskId}: in-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms`);
await store.logEntry(taskId, `[timing] In-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms — verification now passes`);
break;
}
mergerLog.warn(`${taskId}: in-merge verification fix attempt ${fixAttempt} — verification still fails`);
await store.logEntry(taskId, `In-merge verification fix attempt ${fixAttempt} — verification still fails`);
mergerLog.warn(`${taskId}: in-merge verification fix attempt ${fixAttempt} — verification still fails (${fixAttemptDurationMs}ms)`);
await store.logEntry(taskId, `[timing] In-merge verification fix attempt ${fixAttempt} — verification still fails (${fixAttemptDurationMs}ms)`);
}
if (fixSuccess) {
@@ -2114,6 +2131,7 @@ export async function aiMergeTask(
let fixSuccess = false;
for (let fixAttempt = 1; fixAttempt <= maxFixRetries; fixAttempt++) {
const fixAttemptStartedAt = Date.now();
mergerLog.log(`${taskId}: in-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`);
await store.logEntry(taskId, `In-merge verification fix attempt ${fixAttempt}/${maxFixRetries}`);
@@ -2128,11 +2146,13 @@ export async function aiMergeTask(
settings, options, effectiveTestCommand, effectiveBuildCommand,
);
const fixAttemptDurationMs = Date.now() - fixAttemptStartedAt;
if (fixSuccess) {
mergerLog.log(`${taskId}: in-merge verification fix succeeded on attempt ${fixAttempt}`);
await store.logEntry(taskId, `In-merge verification fix succeeded`);
mergerLog.log(`${taskId}: in-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms`);
await store.logEntry(taskId, `[timing] In-merge verification fix succeeded on attempt ${fixAttempt} in ${fixAttemptDurationMs}ms`);
break;
}
await store.logEntry(taskId, `[timing] In-merge verification fix attempt ${fixAttempt} — verification still fails (${fixAttemptDurationMs}ms)`);
}
if (fixSuccess) {