feat(core): per-stage column dwell instrumentation
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`. 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) <noreply@anthropic.com>
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,
|
||||
|
||||
@@ -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<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. */
|
||||
@@ -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<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