perf(dashboard): cache gh CLI checks and defer SQLite integrity scan

Cold-start dashboard responsiveness went from ~99s to ~6-11s. CPU profiling
identified two synchronous-spawn hotspots blocking the event loop:

- `GitHubTrackingReconciler` scanned up to 200 done tasks per startup,
  each call into `getIssue` invoking `isGhAvailable()` + `isGhAuthenticated()`
  via `execFileSync`. `gh auth status` makes a network roundtrip, so 400
  sync spawns ≈ 71s of pure event-loop blocking (69% of cold-start CPU).
  Memoized both checks with a 60s TTL; `resetGhAvailabilityCache()` is
  exported for login/logout flows that need immediate invalidation.

- `PRAGMA integrity_check(100)` walks every page of the SQLite file (~7s
  per database, multiple DBs × projects). The deferred check was scheduled
  3s after init — right in the responsiveness-critical window. Pushed to
  60s so the user is already interacting before it runs; check itself is
  unchanged.

Also yields the event loop between major InProcessRuntime init phases and
between self-healing recovery steps (34 per project), defers orphan-task
AI agent resumption by 30s (env-overridable, auto-zero under Vitest), and
ships an opt-in `FUSION_TRACE_EL_LAG=/path/to/file` event-loop lag tracer
that diagnosed all of the above.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
gsxdsm
2026-05-26 23:41:28 -07:00
parent cac08d733b
commit 390bd7f923
10 changed files with 184 additions and 25 deletions

View File

@@ -2,6 +2,7 @@
"@runfusion/fusion": patch
"@fusion/dashboard": patch
"@fusion/engine": patch
"@fusion/core": patch
---
Dashboard startup and request-storm fixes:
@@ -13,3 +14,9 @@ Dashboard startup and request-storm fixes:
- **Live isolation-mode transition**: PATCH `/api/projects/:id` with an `isolationMode` change now returns a 503 with actionable guidance when HybridExecutor is unavailable (local-only single-node), instead of silently persisting a config that the live runtime won't honor.
- **Error handling regression**: restored try/catch around `HybridExecutor.initialize` and `engineManager.ensureEngine` in the parallel engine setup so a paused or broken cwd project no longer aborts dashboard startup.
- **TaskStore migration race**: sequenced the SQLite store inits (TaskStore → AutomationStore → PluginStore → AgentStore) since they all open the same `.fusion/fusion.db` and run `addColumnIfMissing` migrations with a TOCTOU `hasColumn``ALTER` pattern.
- **`gh` CLI invocation storm**: `isGhAvailable()` and `isGhAuthenticated()` now memoize their results with a 60s TTL. `GitHubTrackingReconciler` was scanning up to 200 done tasks at startup and calling `hasGhAuth()` per task — each call shelled out to `gh --version` and `gh auth status` (which makes a network roundtrip), pinning the event loop for ~60s of synchronous `spawnSync` work. CPU-profile-confirmed: dropped from 71s (69% of cold-start CPU) to 2s. The cache benefits all 28+ call sites in `dashboard/src/github.ts`, the engine PR monitor, the research provider, and the API routes automatically. `resetGhAvailabilityCache()` is exported for login/logout flows that need to invalidate immediately.
- **SQLite integrity check delay**: `PRAGMA integrity_check(100)` walks every page of the database file and was scheduled 3 seconds after init — landing right in the responsiveness-critical window for ~7s per database. Pushed the deferred-check timer to 60 seconds so the user is already interacting with the dashboard by the time it runs. The check itself is unchanged; corruption detection still works.
- **Engine init event-loop yields**: `InProcessRuntime.start()` now awaits a `setImmediate`-based yield between major init phases (TaskStore → Plugins → WorktreePool → AgentStore → Scheduler → Executor → HeartbeatMonitor → SelfHealing) so HTTP requests can be processed between them instead of waiting on the entire stack. Same yield is now interleaved between each step of `SelfHealingManager.runStartupRecovery()` (34 steps per project) and its periodic maintenance batches.
- **Deferred startup recovery**: `InProcessRuntime.start()` no longer awaits `resumeStartupRecoverySequence()` or `workerManager.reconcileOrphaned()` — both are correctness-preserving background operations and their git/SQLite work was blocking server-listen for several seconds.
- **Deferred orphan-task AI agent resumption**: orphaned in-progress tasks resumed at engine restart now wait 30 seconds before spawning their AI agent session (worktree setup + pi-coding-agent session creation is heavy and saturates the event loop). Override via `FUSION_RESUME_ORPHAN_DELAY_MS=<ms>`; auto-zeroes under Vitest.
- **Event-loop lag tracer**: opt-in debug aid for diagnosing cold-start regressions. Set `FUSION_TRACE_EL_LAG=/path/to/file.txt` to capture every block >150ms with a timestamp relative to process start.

View File

@@ -2180,6 +2180,31 @@ export async function runDashboard(port: number, opts: { paused?: boolean; dev?:
});
}
// ── Event-loop lag tracer (debug aid) ──
// Polls every 50ms and logs whenever the loop was blocked by >150ms since
// the previous tick. Pinpoints which synchronous operation is hogging the
// event loop during startup. Disabled unless FUSION_TRACE_EL_LAG is set
// to a file path (writes to that file with raw timestamps so log output
// doesn't pollute the analysis).
if (process.env.FUSION_TRACE_EL_LAG) {
const lagPath = process.env.FUSION_TRACE_EL_LAG;
const fs = await import("node:fs");
const lagStream = fs.createWriteStream(lagPath, { flags: "w" });
const LAG_THRESHOLD_MS = 150;
const POLL_MS = 50;
const traceStart = performance.now();
let last = traceStart;
setInterval(() => {
const now = performance.now();
const delta = now - last - POLL_MS;
last = now;
if (delta > LAG_THRESHOLD_MS) {
const tSinceStart = Math.round(now - traceStart);
lagStream.write(`t+${tSinceStart}ms: blocked ${Math.round(delta)}ms\n`);
}
}, POLL_MS).unref();
}
const server = app.listen(selectedPort, selectedHost);
server.on("error", (err: NodeJS.ErrnoException) => {

View File

@@ -433,7 +433,7 @@ describe("Database", () => {
expect(freshDb.integrityCheckPending).toBe(true);
expect(integritySpy).not.toHaveBeenCalled();
vi.advanceTimersByTime(3000);
vi.advanceTimersByTime(60_000);
expect(integritySpy).toHaveBeenCalledTimes(1);
expect(freshDb.integrityCheckPending).toBe(false);
@@ -458,7 +458,7 @@ describe("Database", () => {
expect(freshDb.integrityCheckPending).toBe(true);
freshDb.init();
vi.advanceTimersByTime(3000);
vi.advanceTimersByTime(60_000);
expect(integritySpy).toHaveBeenCalledTimes(1);
} finally {
@@ -484,7 +484,7 @@ describe("Database", () => {
expect(dbA.integrityCheckPending).toBe(true);
expect(dbB.integrityCheckPending).toBe(true);
vi.advanceTimersByTime(3000);
vi.advanceTimersByTime(60_000);
expect(integritySpy).toHaveBeenCalledTimes(1);
expect(dbA.integrityCheckPending).toBe(false);
@@ -519,7 +519,7 @@ describe("Database", () => {
dbA.init();
dbB.init();
vi.advanceTimersByTime(3000);
vi.advanceTimersByTime(60_000);
expect(integritySpy).toHaveBeenCalledTimes(1);
expect(dbA.integrityCheckPending).toBe(false);

View File

@@ -3733,6 +3733,9 @@ export class Database {
running: false,
};
// PRAGMA integrity_check walks every page of the database file and
// blocks the event loop for several seconds per DB. Delay it well past
// cold start so the dashboard is interactive before the check lands.
shared.timer = setTimeout(() => {
shared.timer = null;
shared.running = true;
@@ -3761,7 +3764,7 @@ export class Database {
}
Database.sharedIntegrityChecks.delete(this.dbPath);
}, 3000);
}, 60_000);
Database.sharedIntegrityChecks.set(this.dbPath, shared);
}

View File

@@ -56,19 +56,52 @@ function normalizeRunGhOptions(opts: string | RunGhOptions | undefined): RunGhOp
return opts ?? {};
}
// Both isGhAvailable() and isGhAuthenticated() are deterministic for the
// lifetime of a process (the gh binary doesn't get uninstalled, and the
// auth state doesn't change without explicit user action) but they each
// shell out via execFileSync — `gh auth status` in particular performs a
// network roundtrip to GitHub. At startup the GitHubTrackingReconciler
// scans up to 200 done tasks and calls hasGhAuth() per-task, producing
// hundreds of synchronous spawns that pin the event loop for ~60s and
// make the dashboard unresponsive during cold start.
//
// Cache the result with a short TTL so callers still notice if the user
// runs `gh auth login` mid-session, but a tight loop of N callers in the
// same second pays for at most one spawn.
const GH_CHECK_TTL_MS = 60_000;
let cachedAvailable: { value: boolean; at: number } | undefined;
let cachedAuthenticated: { value: boolean; at: number } | undefined;
/**
* Reset the in-memory cache. Call after operations that legitimately change
* gh auth state (login/logout) so the next check observes the new state
* without waiting for the TTL.
*/
export function resetGhAvailabilityCache(): void {
cachedAvailable = undefined;
cachedAuthenticated = undefined;
}
/**
* Check if the `gh` CLI is installed and available.
*/
export function isGhAvailable(): boolean {
if (cachedAvailable && Date.now() - cachedAvailable.at < GH_CHECK_TTL_MS) {
return cachedAvailable.value;
}
let value = false;
try {
execFileSync("gh", ["--version"], {
encoding: "utf-8",
stdio: ["pipe", "pipe", "ignore"],
});
return true;
value = true;
} catch {
return false;
value = false;
}
cachedAvailable = { value, at: Date.now() };
return value;
}
/**
@@ -76,16 +109,22 @@ export function isGhAvailable(): boolean {
* Returns true if authenticated, false if not.
*/
export function isGhAuthenticated(): boolean {
if (cachedAuthenticated && Date.now() - cachedAuthenticated.at < GH_CHECK_TTL_MS) {
return cachedAuthenticated.value;
}
let value = false;
try {
const result = execFileSync("gh", ["auth", "status"], {
encoding: "utf-8",
stdio: ["pipe", "pipe", "ignore"],
});
// gh auth status returns 0 and outputs "Logged in" if authenticated
return result.includes("Logged in") || result.includes("Authenticated");
value = result.includes("Logged in") || result.includes("Authenticated");
} catch {
return false;
value = false;
}
cachedAuthenticated = { value, at: Date.now() };
return value;
}
/**

View File

@@ -331,9 +331,10 @@ export type {
TaskAgeStalenessThresholds,
} from "./task-age-staleness.js";
export {
isGhAvailable,
isGhAuthenticated,
runGh,
isGhAvailable,
isGhAuthenticated,
resetGhAvailabilityCache,
runGh,
runGhAsync,
runGhJson,
runGhJsonAsync,

View File

@@ -1,6 +1,7 @@
// port-4040-allowlist: this file embeds the "never kill port 4040" rule in the executor prompt.
import { exec, execSync } from "node:child_process";
import { promisify } from "node:util";
import { setImmediate as setImmediateCb } from "node:timers";
// Internal git plumbing intentionally bypasses sandbox backends.
const execAsync = promisify(exec);
@@ -168,6 +169,34 @@ export {
taskLogParams,
} from "./agent-tools.js";
const yieldEventLoop = (): Promise<void> => new Promise((resolve) => setImmediateCb(resolve));
/**
* How long to wait after engine startup before spawning AI agent sessions for
* orphaned in-progress tasks. The work itself (worktree setup, pi-coding-agent
* session creation, child process spawn) is heavy and saturates the event
* loop, which makes the dashboard unresponsive during cold start when there
* are orphaned tasks from a prior run. Pushing this work past the initial
* load window keeps the UI snappy; the tasks still resume — just after the
* user has had time to see the board.
*
* Override via FUSION_RESUME_ORPHAN_DELAY_MS. Defaults to 0 under Vitest so
* existing tests that expect immediate resumption keep passing without
* needing per-test plumbing.
*
* Read lazily so an env-var change between module load and resumeOrphaned()
* call (e.g. set in a test setup file) is observed.
*/
function getResumeOrphanDelayMs(): number {
const raw = process.env.FUSION_RESUME_ORPHAN_DELAY_MS;
if (raw !== undefined) {
const parsed = Number.parseInt(raw, 10);
if (Number.isFinite(parsed) && parsed >= 0) return parsed;
}
if (process.env.VITEST || process.env.NODE_ENV === "test") return 0;
return 30_000;
}
const tokenCacheMetricsLog = createLogger("token-cache-metrics");
const STEP_STATUSES: StepStatus[] = ["pending", "in-progress", "done", "skipped"];
@@ -2893,7 +2922,22 @@ export class TaskExecutor {
if (inProgress.length === 0) return;
executorLog.log(`Found ${inProgress.length} orphaned in-progress task(s)`);
const resumeDelayMs = getResumeOrphanDelayMs();
if (resumeDelayMs > 0) {
executorLog.log(
`Deferring orphan task resumption for ${resumeDelayMs}ms to keep dashboard responsive during cold start`,
);
}
// When the delay is zero (default in tests and when explicitly disabled),
// skip the setTimeout indirection so the spawn happens on the current
// microtask — matching the legacy behavior callers may rely on.
const scheduleResume = resumeDelayMs > 0
? (fn: () => void) => { setTimeout(fn, resumeDelayMs); }
: (fn: () => void) => { fn(); };
let yieldNext = false;
for (const task of inProgress) {
if (yieldNext) await yieldEventLoop();
yieldNext = true;
// Fast-path: if the task already completed its work (all steps done),
// move it directly to in-review instead of re-executing from scratch.
if (this.isTaskWorkComplete(task) && !task.mergeDetails) {
@@ -2903,13 +2947,15 @@ export class TaskExecutor {
}
executorLog.log(`${task.id} is already complete — fast-pathing to in-review`);
this.recoveringCompleted.add(task.id);
void this.recoverCompletedTask(task)
.catch((err) =>
executorLog.error(`Failed to recover completed orphan ${task.id}:`, err),
)
.finally(() => {
this.recoveringCompleted.delete(task.id);
});
scheduleResume(() => {
void this.recoverCompletedTask(task)
.catch((err) =>
executorLog.error(`Failed to recover completed orphan ${task.id}:`, err),
)
.finally(() => {
this.recoveringCompleted.delete(task.id);
});
});
continue;
}
@@ -2926,9 +2972,11 @@ export class TaskExecutor {
} catch (err) {
executorLog.error(`Failed to write resume log for ${task.id}:`, err);
}
this.execute(task).catch((err) =>
executorLog.error(`Failed to resume ${task.id}:`, err),
);
scheduleResume(() => {
this.execute(task).catch((err) =>
executorLog.error(`Failed to resume ${task.id}:`, err),
);
});
}
}

View File

@@ -1,8 +1,10 @@
import type { Task, TaskStore } from "@fusion/core";
import type { TaskExecutor } from "./executor.js";
import { createLogger } from "./logger.js";
import { setImmediate as setImmediateCb } from "node:timers";
const log = createLogger("restart-recovery");
const yieldEventLoop = (): Promise<void> => new Promise((resolve) => setImmediateCb(resolve));
export function hasStepProgress(task: Task): boolean {
const steps = Array.isArray(task.steps) ? task.steps : [];
@@ -102,6 +104,7 @@ export class RestartRecoveryCoordinator {
if (!this.mustSafeRetry(task)) continue;
await this.safeRequeue(task);
requeued++;
await yieldEventLoop();
}
if (requeued > 0) {

View File

@@ -44,6 +44,9 @@ import { EphemeralWorkerManager } from "../ephemeral-worker-manager.js";
import { validateProjectNodeMapping } from "../node-dispatch-validation.js";
import { attachAgentLinkSync } from "../task-agent-sync.js";
import { createRunAuditor, generateSyntheticRunId } from "../run-audit.js";
import { setImmediate as setImmediateCb } from "node:timers";
const yieldEventLoop = (): Promise<void> => new Promise((resolve) => setImmediateCb(resolve));
/**
* InProcessRuntime runs a project within the main process.
@@ -187,6 +190,8 @@ export class InProcessRuntime
// Initialize MessageStore early so TaskExecutor receives send_message capability.
this.messageStore = new MessageStoreClass(this.taskStore.getDatabase());
await yieldEventLoop();
// 2. Initialize Plugin system (PluginStore + PluginLoader + PluginRunner)
this.pluginStore = new PluginStoreClass(this.config.workingDirectory);
await this.pluginStore.init();
@@ -205,6 +210,8 @@ export class InProcessRuntime
await this.pluginRunner.init();
runtimeLog.log(`PluginRunner initialized`);
await yieldEventLoop();
// 3. Initialize WorktreePool
// Reap half-initialized orphan worktree directories before doing anything
@@ -249,6 +256,8 @@ export class InProcessRuntime
);
}
await yieldEventLoop();
// 4. Initialize global semaphore — use shared one from ProjectManager if provided,
// otherwise create a local one from CentralCore (single-project mode).
if (this.config.globalSemaphore) {
@@ -269,6 +278,8 @@ export class InProcessRuntime
}
}
await yieldEventLoop();
// 5a. Initialize AgentStore (required for scheduler assignment, reflection service, and heartbeat monitoring)
let agentStoreForReflection: import("@fusion/core").AgentStore | undefined;
try {
@@ -281,6 +292,8 @@ export class InProcessRuntime
}
this.agentStore = agentStoreForReflection;
await yieldEventLoop();
// 5. Initialize Scheduler
const missionStore = this.taskStore.getMissionStore();
this.missionAutopilot = missionStore
@@ -358,6 +371,8 @@ export class InProcessRuntime
});
await yieldEventLoop();
// 5b. Initialize TaskExecutor
this.stuckTaskDetector = new StuckTaskDetector(this.taskStore, {
beforeRequeue: (taskId, reason, event) => this.selfHealingManager?.checkStuckBudget(taskId, reason, event) ?? Promise.resolve(true),
@@ -497,6 +512,8 @@ export class InProcessRuntime
})();
});
await yieldEventLoop();
// 6. Initialize HeartbeatMonitor (reuses AgentStore from step 5a)
if (this.heartbeatMonitor) {
// Already started — nothing to do
@@ -589,7 +606,9 @@ export class InProcessRuntime
}
if (this.workerManager) {
this.workerManager.attachStateChangeListener();
await this.workerManager.reconcileOrphaned();
void this.workerManager.reconcileOrphaned().catch((err) => {
runtimeLog.warn(`Deferred workerManager.reconcileOrphaned failed: ${err instanceof Error ? err.message : String(err)}`);
});
}
// Register existing non-ephemeral, heartbeat-enabled agents in tickable states.
@@ -682,6 +701,8 @@ export class InProcessRuntime
runtimeLog.warn("RoutineScheduler initialization skipped:", routineErr instanceof Error ? routineErr.message : routineErr);
}
await yieldEventLoop();
// 7. Initialize SelfHealingManager
this.chatStore ??= new ChatStore(this.taskStore.getFusionDir(), this.taskStore.getDatabase());
this.selfHealingManager = new SelfHealingManager(this.taskStore, {
@@ -744,8 +765,14 @@ export class InProcessRuntime
);
} else {
this.startupRecoveryDeferred = false;
await this.resumeStartupRecoverySequence();
// Defer recovery sequence so the runtime start() returns quickly.
// The sequence runs git operations and may resume orphaned tasks,
// both of which can block the event loop for several seconds.
// Running it in the background lets the HTTP server become
// responsive sooner while still performing the recovery work.
void this.resumeStartupRecoverySequence().catch((err) => {
runtimeLog.error("Deferred startup recovery sequence failed:", err);
});
}
// 11. Start scheduler and triage processor

View File

@@ -25,6 +25,7 @@
import { exec, execSync } from "node:child_process";
import { promisify } from "node:util";
import { setImmediate as setImmediateCb } from "node:timers";
import { existsSync, mkdirSync, readdirSync, readFileSync, realpathSync, rmSync, statSync, writeFileSync } from "node:fs";
import { isAbsolute, join, relative, resolve } from "node:path";
import { IN_REVIEW_STALL_DEADLOCK_LOG_PREFIX, IN_REVIEW_STALL_LOG_PREFIX, countRecentIdenticalStallEntries, detectDependencyCycle, detectSelfDefeatingDependency, getInReviewStalledSignal, getInReviewStallReason, getPrimaryPrInfo, getStalePausedReviewSignal, getStalePausedTodoSignal, getTaskHardMergeBlocker, getTaskMergeBlocker, isEphemeralAgent, parseExplicitDuplicateMarker, type AgentStore, type ChatStore, type MessageStore, type TaskStore, type Settings, type Task, type MergeDetails, type TaskPriority, type MergeResult } from "@fusion/core";
@@ -64,6 +65,7 @@ import { DependencyBlockedTodoReporter } from "./dependency-blocked-todo-reporte
const log = createLogger("self-healing");
const worktreeMetadataReconcileLog = createLogger("worktree-metadata-reconcile");
const execAsync = promisify(exec);
const yieldEventLoop = (): Promise<void> => new Promise((resolve) => setImmediateCb(resolve));
const DONE_TASK_INTEGRITY_SWEEP_LIMIT = 50;
const BOARD_STALL_NOTIFICATION_COOLDOWN_MS = 60 * 60_000;
const DB_CORRUPTION_NOTIFICATION_COOLDOWN_MS = 60 * 60 * 1000;
@@ -828,6 +830,7 @@ export class SelfHealingManager {
const stepErrMessage = stepErr instanceof Error ? stepErr.message : String(stepErr);
log.error(`Startup recovery step "${step.name}" failed: ${stepErrMessage} — continuing with remaining steps`);
}
await yieldEventLoop();
}
}
@@ -1416,6 +1419,7 @@ export class SelfHealingManager {
} catch (stepErr) {
log.error(`Maintenance batch 1 step "${fn.name}" failed: ${stepErr instanceof Error ? stepErr.message : String(stepErr)}`);
}
await yieldEventLoop();
}
const recoverySettings = await this.store.getSettings();
@@ -1489,6 +1493,7 @@ export class SelfHealingManager {
} catch (stepErr) {
log.error(`Maintenance batch 2 step "${fn.name}" failed: ${stepErr instanceof Error ? stepErr.message : String(stepErr)}`);
}
await yieldEventLoop();
}
}
@@ -1503,6 +1508,7 @@ export class SelfHealingManager {
} catch (stepErr) {
log.error(`Maintenance batch 3 step "${fn.name}" failed: ${stepErr instanceof Error ? stepErr.message : String(stepErr)}`);
}
await yieldEventLoop();
}
const elapsedMs = Date.now() - startMs;