feat(core): per-stage column dwell instrumentation (#1781)
## Why Diagnosing "tasks take too long" showed the dominant end-to-end wall-clock is **waiting**, not work: tasks sit in `todo` (queue) and `in-review` (merge wait) far longer than the agent actually runs. Today only `cumulativeActiveMs` exists, which measures **in-progress time only** — every other stage's dwell had to be reconstructed by hand from agent logs. ## What Adds `columnDwellMs?: Record<string, number>` to `Task` — a per-column accumulator (column name → cumulative ms), recorded at the **same store column-transition seam** as `cumulativeActiveMs` (`moveTaskInternal`). On each move it adds `columnMovedAt(new) − columnMovedAt(prev)` to the bucket for the column being left: - clamped `>= 0` (clock skew safe); - unparseable/missing prior timestamp and zero-dwell moves are skipped (no spurious buckets); - second visits **add** to the existing bucket (multi-visit churn is captured); - flag-independent — keys off the generic `columnMovedAt` delta, so it runs for both the workflow-hook and legacy-inline move paths. This makes per-stage dwell directly queryable, the same way `productivity-analytics.ts` already consumes `cumulativeActiveMs`. ## Persistence JSON-text task column, following the v129 `workspaceWorktrees` precedent exactly: `SCHEMA_SQL` column + `SCHEMA_VERSION` 129→130 + a versioned `addColumnIfMissing` migration. Additive and behavior-preserving — pre-existing rows start NULL and accumulate from their next transition. Survives archive/restore (added to the archive-entry mapping). ## Tests `src/__tests__/store-execution-timing.test.ts` — new regression asserts dwell across `todo→in-progress→in-review→done→todo→in-progress→in-review` accumulates the right per-column ms (second visits add) and survives a `getTask` DB round-trip. ``` pnpm --filter @fusion/core exec vitest run src/__tests__/store-execution-timing.test.ts ... --reporter=dot → store-execution-timing 5/5, schema suites (goals/secrets) green, 17/17 total ``` Migration chain verified end-to-end (secrets-schema test climbs v11/v82 → v130). No hardcoded literal version assertions in the suite; schema tests assert against the `SCHEMA_VERSION` constant. `@fusion/core` is private — no changeset. 🤖 Generated with [Claude Code](https://claude.com/claude-code) <!-- stage-review-badge-begin --> --- <a href="https://stagereview.app/Runfusion/Fusion/pull/1781"> <picture> <source media="(prefers-color-scheme: dark)" srcset="https://stagereview.app/assets/gh-open-in-stage-dark.svg"> <img src="https://stagereview.app/assets/gh-open-in-stage-light.svg" alt="Open in Stage"> </picture> </a> <!-- stage-review-badge-end --> <!-- This is an auto-generated comment: release notes by coderabbit.ai --> ## Summary by CodeRabbit * **New Features** * Added per-column dwell timing to tasks, showing how long work spent in each column across multiple visits. * Preserved this timing data when tasks are archived and restored. * **Bug Fixes** * Task timing now updates correctly during column moves, including repeated returns to the same column. * Existing data can be upgraded to the new timing format without breaking stored tasks. * **Tests** * Added coverage for multi-step task movement and data reloading to verify timing totals stay accurate. <!-- end of auto-generated comment: release notes by coderabbit.ai -->
This commit is contained in:
@@ -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);
|
||||
});
|
||||
});
|
||||
|
||||
@@ -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");
|
||||
});
|
||||
}
|
||||
|
||||
}
|
||||
|
||||
/**
|
||||
|
||||
@@ -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<TaskStoreEvents> {
|
||||
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<Record<string, number>>(row.columnDwellMs);
|
||||
return d && Object.keys(d).length > 0 ? d : undefined;
|
||||
})(),
|
||||
executionStartedAt: row.executionStartedAt || undefined,
|
||||
executionCompletedAt: row.executionCompletedAt || undefined,
|
||||
dependencies: fromJson<string[]>(row.dependencies) || [],
|
||||
@@ -2266,6 +2277,7 @@ export class TaskStore extends EventEmitter<TaskStoreEvents> {
|
||||
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<TaskStoreEvents> {
|
||||
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<TaskStoreEvents> {
|
||||
"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<TaskStoreEvents> {
|
||||
"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,
|
||||
|
||||
@@ -2668,6 +2668,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<string, number>;
|
||||
/** 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. */
|
||||
@@ -4906,6 +4918,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<string, number>;
|
||||
/** Current-attempt execution anchor; may be cleared on reopen. */
|
||||
executionStartedAt?: string;
|
||||
/** First-time completion anchor; may be cleared on reopen. */
|
||||
|
||||
Reference in New Issue
Block a user