From 8a03e4fc23843adfa9157787ece4dcd8cd338b93 Mon Sep 17 00:00:00 2001 From: gsxdsm Date: Thu, 25 Jun 2026 19:38:03 -0700 Subject: [PATCH] feat(core): per-stage column dwell instrumentation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds `columnDwellMs?: Record` to Task — a per-column accumulator (column name -> cumulative ms) recorded at the same store column-transition seam as `cumulativeActiveMs`. On every move it adds `columnMovedAt(new) - columnMovedAt(prev)` to the bucket for the column being left, clamped >= 0; unparseable/missing prior timestamps and 0-dwell moves are skipped, and second visits add to the existing bucket. Motivation: `cumulativeActiveMs` only measures in-progress time. Diagnosis of slow tasks showed the dominant wall-clock is *waiting* (queue time in todo, review wait in in-review), which previously had to be reconstructed from agent logs. This makes per-stage dwell directly queryable, like productivity-analytics already consumes cumulativeActiveMs. Persisted as a JSON-text task column following the v129 workspaceWorktrees precedent: SCHEMA_SQL column + SCHEMA_VERSION 129->130 + versioned addColumnIfMissing migration. Additive and behavior-preserving; pre-existing rows start NULL and accumulate from their next transition. Survives archive/restore. @fusion/core is private — no changeset. Co-Authored-By: Claude Opus 4.8 (1M context) --- .../__tests__/store-execution-timing.test.ts | 52 +++++++++++++++++++ packages/core/src/db.ts | 19 ++++++- packages/core/src/store.ts | 46 +++++++++++++++- packages/core/src/types.ts | 15 ++++++ 4 files changed, 129 insertions(+), 3 deletions(-) diff --git a/packages/core/src/__tests__/store-execution-timing.test.ts b/packages/core/src/__tests__/store-execution-timing.test.ts index 515e8e01ac..f288c884c8 100644 --- a/packages/core/src/__tests__/store-execution-timing.test.ts +++ b/packages/core/src/__tests__/store-execution-timing.test.ts @@ -88,4 +88,56 @@ describe("TaskStore execution timing semantics", () => { expect(done.cumulativeActiveMs).toBe(5 * 60_000); }); + + /* + FNXC:TaskTiming 2026-06-26-10:14: + Per-stage dwell instrumentation regression. Asserts columnDwellMs accumulates the correct + wall-clock per column across a full todo->in-progress->in-review->done sequence, that a + re-entered column (second in-progress / second todo visit) ADDS to the existing bucket rather + than overwriting it, and that the JSON map survives the SQLite round-trip (getTask rehydration). + */ + it("accumulates per-column dwell across a multi-column, multi-visit sequence", async () => { + vi.useFakeTimers(); + // todo entry anchor. Create + first move share this instant => leaving the + // creation column is a 0ms dwell and records no spurious bucket. + vi.setSystemTime(new Date("2026-06-26T10:00:00.000Z")); + + const task = await store.createTask({ description: "per-stage dwell" }); + await store.moveTask(task.id, "todo"); + + // todo dwell visit #1: 5 min + vi.setSystemTime(new Date("2026-06-26T10:05:00.000Z")); + await store.moveTask(task.id, "in-progress"); + + // in-progress dwell visit #1: 3 min + vi.setSystemTime(new Date("2026-06-26T10:08:00.000Z")); + await store.moveTask(task.id, "in-review"); + + // in-review dwell: 10 min + vi.setSystemTime(new Date("2026-06-26T10:18:00.000Z")); + await store.moveTask(task.id, "done"); + + // done dwell: 2 min (reopen leaves done) + vi.setSystemTime(new Date("2026-06-26T10:20:00.000Z")); + await store.moveTask(task.id, "todo", { moveSource: "user" }); + + // todo dwell visit #2: 1 min => bucket adds to the prior 5 min + vi.setSystemTime(new Date("2026-06-26T10:21:00.000Z")); + await store.moveTask(task.id, "in-progress"); + + // in-progress dwell visit #2: 4 min => bucket adds to the prior 3 min + vi.setSystemTime(new Date("2026-06-26T10:25:00.000Z")); + const final = await store.moveTask(task.id, "in-review"); + + expect(final.columnDwellMs).toEqual({ + todo: 6 * 60_000, // 5 + 1 + "in-progress": 7 * 60_000, // 3 + 4 + "in-review": 10 * 60_000, + done: 2 * 60_000, + }); + + // JSON map survives the DB round-trip. + const reloaded = await store.getTask(task.id); + expect(reloaded?.columnDwellMs).toEqual(final.columnDwellMs); + }); }); diff --git a/packages/core/src/db.ts b/packages/core/src/db.ts index 025f77e1bb..415a7fe4a9 100644 --- a/packages/core/src/db.ts +++ b/packages/core/src/db.ts @@ -162,7 +162,7 @@ export function isFts5CorruptionError(error: unknown): boolean { // ── Schema Definition ──────────────────────────────────────────────── -const SCHEMA_VERSION = 129; +const SCHEMA_VERSION = 130; const TASKS_FTS_AUTOMERGE = 8; const TASKS_FTS_CRISISMERGE = 16; @@ -296,6 +296,12 @@ CREATE TABLE IF NOT EXISTS tasks ( columnMovedAt TEXT, firstExecutionAt TEXT, cumulativeActiveMs INTEGER, + -- FNXC:TaskTiming 2026-06-26-10:14: per-column dwell map (JSON text) accumulated at the + -- column-transition seam (store.ts moveTaskInternal). Fills the gap left by cumulativeActiveMs + -- (in-progress only) so todo/in-review/done wall-clock is queryable per stage. Source of truth + -- for getSchemaCompatibilityTableSchemas(); fresh DBs get it here, existing DBs are backfilled + -- by the version-130 migration / ensureSchemaCompatibility() at boot. + columnDwellMs TEXT, executionStartedAt TEXT, executionCompletedAt TEXT, -- JSON columns for nested arrays/objects @@ -5339,6 +5345,17 @@ export class Database { }); } + if (version < 130) { + // FNXC:TaskTiming 2026-06-26-10:14: add the columnDwellMs column so existing DBs durably + // persist per-stage dwell going forward. Backfill is also covered by ensureSchemaCompatibility() + // (SCHEMA_SQL is its source of truth); this versioned migration keeps migrated and + // fresh-from-SCHEMA_SQL DBs converged. No data backfill: pre-existing rows start with NULL + // (= undefined map) and accumulate from their next column transition. + this.applyMigration(130, () => { + this.addColumnIfMissing("tasks", "columnDwellMs", "TEXT"); + }); + } + } /** diff --git a/packages/core/src/store.ts b/packages/core/src/store.ts index 9b4eeb08fd..3ea0fcf63a 100644 --- a/packages/core/src/store.ts +++ b/packages/core/src/store.ts @@ -283,6 +283,10 @@ interface TaskRow { columnMovedAt: string | null; firstExecutionAt: string | null; cumulativeActiveMs: number | null; + // FNXC:TaskTiming 2026-06-26-10:14: per-column dwell map (JSON text), populated by the + // column-transition seam in moveTaskInternal. Persisted alongside cumulativeActiveMs so + // per-stage wall-clock survives the SQLite round-trip getChangedTaskColumns/rowToTask use. + columnDwellMs: string | null; executionStartedAt: string | null; executionCompletedAt: string | null; dependencies: string | null; @@ -442,6 +446,8 @@ const TASK_COLUMN_DESCRIPTORS: TaskColumnDescriptor[] = [ defineTaskColumn("columnMovedAt", (task) => task.columnMovedAt ?? null), defineTaskColumn("firstExecutionAt", (task) => task.firstExecutionAt ?? null), defineTaskColumn("cumulativeActiveMs", (task) => task.cumulativeActiveMs ?? null), + // FNXC:TaskTiming 2026-06-26-10:14: serialize per-column dwell map as JSON text (same as mergeDetails/workspaceWorktrees). + defineTaskColumn("columnDwellMs", (task) => toJsonNullable(task.columnDwellMs)), defineTaskColumn("executionStartedAt", (task) => task.executionStartedAt ?? null), defineTaskColumn("executionCompletedAt", (task) => task.executionCompletedAt ?? null), defineTaskColumn("dependencies", (task) => toJson(task.dependencies || [])), @@ -2084,6 +2090,11 @@ export class TaskStore extends EventEmitter { columnMovedAt: row.columnMovedAt || undefined, firstExecutionAt: row.firstExecutionAt || undefined, cumulativeActiveMs: row.cumulativeActiveMs ?? undefined, + // FNXC:TaskTiming 2026-06-26-10:14: rehydrate per-column dwell map; drop empty maps to undefined like workspaceWorktrees. + columnDwellMs: (() => { + const d = fromJson>(row.columnDwellMs); + return d && Object.keys(d).length > 0 ? d : undefined; + })(), executionStartedAt: row.executionStartedAt || undefined, executionCompletedAt: row.executionCompletedAt || undefined, dependencies: fromJson(row.dependencies) || [], @@ -2266,6 +2277,7 @@ export class TaskStore extends EventEmitter { columnMovedAt: entry.columnMovedAt, firstExecutionAt: entry.firstExecutionAt, cumulativeActiveMs: entry.cumulativeActiveMs, + columnDwellMs: entry.columnDwellMs, executionStartedAt: entry.executionStartedAt, executionCompletedAt: entry.executionCompletedAt, modelPresetId: entry.modelPresetId, @@ -2402,6 +2414,7 @@ export class TaskStore extends EventEmitter { columnMovedAt: task.columnMovedAt, firstExecutionAt: task.firstExecutionAt, cumulativeActiveMs: task.cumulativeActiveMs, + columnDwellMs: task.columnDwellMs, executionStartedAt: task.executionStartedAt, executionCompletedAt: task.executionCompletedAt, archivedAt, @@ -2612,7 +2625,7 @@ export class TaskStore extends EventEmitter { "mergeRetries", "workflowStepRetries", "stuckKillCount", "resumeLimboCount", "graphResumeRetryCount", "resumeLimboTipSha", "resumeLimboStepSignature", "postReviewFixCount", "recoveryRetryCount", "taskDoneRetryCount", "worktreeSessionRetryCount", "completionHandoffLimboRecoveryCount", "verificationFailureCount", "mergeConflictBounceCount", "mergeAuditBounceCount", "mergeTransientRetryCount", "branchConflictRecoveryCount", "reviewerContextRetryCount", "reviewerFallbackRetryCount", "nextRecoveryAt", "error", "summary", "thinkingLevel", "executionMode", "tokenUsageInputTokens", "tokenUsageOutputTokens", "tokenUsageCachedTokens", "tokenUsageCacheWriteTokens", "tokenUsageTotalTokens", "tokenUsageFirstUsedAt", "tokenUsageLastUsedAt", "tokenUsageModelProvider", "tokenUsageModelId", "tokenUsagePerModel", "tokenBudgetSoftAlertedAt", "tokenBudgetHardAlertedAt", "tokenBudgetOverride", - "createdAt", "updatedAt", "columnMovedAt", "firstExecutionAt", "cumulativeActiveMs", "executionStartedAt", "executionCompletedAt", + "createdAt", "updatedAt", "columnMovedAt", "firstExecutionAt", "cumulativeActiveMs", "columnDwellMs", "executionStartedAt", "executionCompletedAt", "dependencies", "steps", "customFields", "comments", "review", "reviewState", "workflowStepResults", "steeringComments", "attachments", "prInfo", "prInfos", "issueInfo", "githubTracking", "sourceIssueProvider", "sourceIssueRepository", "sourceIssueExternalIssueId", "sourceIssueNumber", "sourceIssueUrl", "sourceIssueClosedAt", "mergeDetails", "workspaceWorktrees", "breakIntoSubtasks", "noCommitsExpected", "enabledWorkflowSteps", "modifiedFiles", @@ -2661,7 +2674,7 @@ export class TaskStore extends EventEmitter { "mergeRetries", "workflowStepRetries", "stuckKillCount", "resumeLimboCount", "graphResumeRetryCount", "resumeLimboTipSha", "resumeLimboStepSignature", "postReviewFixCount", "recoveryRetryCount", "taskDoneRetryCount", "worktreeSessionRetryCount", "completionHandoffLimboRecoveryCount", "verificationFailureCount", "mergeConflictBounceCount", "mergeAuditBounceCount", "mergeTransientRetryCount", "branchConflictRecoveryCount", "reviewerContextRetryCount", "reviewerFallbackRetryCount", "nextRecoveryAt", "error", "summary", "thinkingLevel", "executionMode", "tokenUsageInputTokens", "tokenUsageOutputTokens", "tokenUsageCachedTokens", "tokenUsageCacheWriteTokens", "tokenUsageTotalTokens", "tokenUsageFirstUsedAt", "tokenUsageLastUsedAt", "tokenUsageModelProvider", "tokenUsageModelId", "tokenUsagePerModel", "tokenBudgetSoftAlertedAt", "tokenBudgetHardAlertedAt", "tokenBudgetOverride", - "createdAt", "updatedAt", "columnMovedAt", "firstExecutionAt", "cumulativeActiveMs", "executionStartedAt", "executionCompletedAt", + "createdAt", "updatedAt", "columnMovedAt", "firstExecutionAt", "cumulativeActiveMs", "columnDwellMs", "executionStartedAt", "executionCompletedAt", "dependencies", "steps", "customFields", "attachments", "steeringComments", "comments", "review", "reviewState", "workflowStepResults", "prInfo", "prInfos", "issueInfo", "githubTracking", "sourceIssueProvider", "sourceIssueRepository", "sourceIssueExternalIssueId", "sourceIssueNumber", "sourceIssueUrl", "sourceIssueClosedAt", "mergeDetails", "workspaceWorktrees", "breakIntoSubtasks", "noCommitsExpected", "enabledWorkflowSteps", "modifiedFiles", @@ -7361,10 +7374,39 @@ ${TASK_UPSERT_SQL_ASSIGNMENTS} } const movedAt = internal.now ?? new Date().toISOString(); + /* + FNXC:TaskTiming 2026-06-26-10:14: + Capture the previous column-entry timestamp BEFORE it is overwritten so we can record + per-stage dwell. `cumulativeActiveMs` only covers `in-progress`; this seam fills the gap + for todo / in-review / done so per-stage wall-clock is measurable going forward without + reconstructing it from agent logs. + */ + const previousColumnMovedAt = task.columnMovedAt; task.column = toColumn; task.columnMovedAt = movedAt; task.updatedAt = movedAt; + /* + FNXC:TaskTiming 2026-06-26-10:14: + Accumulate dwell for the column being LEFT into `columnDwellMs[fromColumn]`, mirroring the + `cumulativeActiveMs` accumulation pattern. Flag-INDEPENDENT (runs for both the workflow-hook + and legacy-inline paths) because it keys off the generic columnMovedAt delta, not in-progress + execution timestamps. Skip when the previous timestamp is missing/unparseable (e.g. first move + or legacy rows), and clamp to >= 0 to defend against clock skew / out-of-order `internal.now`. + Multi-visit columns add to the existing bucket, never decrement. + */ + { + const prevMs = Date.parse(previousColumnMovedAt ?? ""); + const nowMs = Date.parse(movedAt); + if (Number.isFinite(prevMs) && Number.isFinite(nowMs)) { + const dwellMs = Math.max(0, nowMs - prevMs); + if (dwellMs > 0) { + const buckets = (task.columnDwellMs ??= {}); + buckets[fromColumn] = Math.max(0, buckets[fromColumn] ?? 0) + dwellMs; + } + } + } + if (useWorkflow) { // ── Flag-ON: route the legacy per-column side effects through the // default-workflow trait hooks (timing, reset-on-entry, abort-on-exit, diff --git a/packages/core/src/types.ts b/packages/core/src/types.ts index 40af737a30..8c39fcfd1d 100644 --- a/packages/core/src/types.ts +++ b/packages/core/src/types.ts @@ -2667,6 +2667,18 @@ export interface Task { * Incremented whenever the task leaves `in-progress`; never decremented and * never cleared by reopen flows. */ cumulativeActiveMs?: number; + /* + FNXC:TaskTiming 2026-06-26-10:14: + Per-stage dwell-time instrumentation. `cumulativeActiveMs` only measures `in-progress`, + so "how long did a task sit in todo / in-review" was unrecoverable without reconstructing + it from agent logs. This map records cumulative wall-clock milliseconds spent in EACH + column (column name -> total ms), accumulated at the column-transition seam in store.ts + exactly like `cumulativeActiveMs`: on every transition we add the dwell of the column being + LEFT (newColumnMovedAt - previousColumnMovedAt, clamped >= 0). Multi-visit columns add to + the existing bucket; never decremented and never cleared by reopen flows. Directly queryable + per stage by consumers like productivity-analytics.ts. + */ + columnDwellMs?: Record; /** ISO-8601 wall-clock timestamp for the current execution attempt. * Set when entering `in-progress`; may be cleared on reopen to * todo/triage when resume state is not preserved. */ @@ -4844,6 +4856,9 @@ export interface ArchivedTaskEntry { firstExecutionAt?: string; /** Accumulated active runtime spent in `in-progress` across attempts. */ cumulativeActiveMs?: number; + /** FNXC:TaskTiming 2026-06-26-10:14: per-column cumulative dwell (ms) carried through + * archive/restore so per-stage wall-clock survives archival. See Task.columnDwellMs. */ + columnDwellMs?: Record; /** Current-attempt execution anchor; may be cleared on reopen. */ executionStartedAt?: string; /** First-time completion anchor; may be cleared on reopen. */