feat(FN-3622): add canonical task-detail timing calculations and stats pane

The merge lands three commits for FN-3622's canonical task timing calculations, adding `taskTiming.ts` logic and stats timing semantics to `TaskDetailModal` and `TaskTokenStatsPanel`, backed by regression tests across those panels and the root `test-changed.mjs` script. The remaining commits introdu Fusion-Task-Id: FN-3622
2026-05-06 19:07:30 -07:00
parent 7fd40c990f
commit 75341f57d8
6 changed files with 205 additions and 60 deletions
--- a/packages/dashboard/app/components/TaskCard.tsx
+++ b/packages/dashboard/app/components/TaskCard.tsx
@@ -13,7 +13,7 @@ import { getFreshBatchData } from "../hooks/useBatchBadgeFetch";
 import { useTaskDiffStats } from "../hooks/useTaskDiffStats";
 import { isTaskStuck } from "../utils/taskStuck";
 import { getUnifiedTaskProgress } from "../utils/taskProgress";
-import { getTimedDurationMs } from "../utils/taskTiming";
+import { getEndToEndDurationMs, getTimedDurationMs, getWorkflowRuntimeMs, parseTimestampToMs } from "../utils/taskTiming";
 import type { ToastType } from "../hooks/useToast";
 import { useConfirm } from "../hooks/useConfirm";

@@ -124,12 +124,6 @@ function getTaskStatusLabel(status: string): string {
  return status;
 }

-function parseTimestampToMs(value?: string): number | null {
-  if (!value) return null;
-  const parsed = Date.parse(value);
-  return Number.isFinite(parsed) ? parsed : null;
-}
-
 function getDoneCompletionMs(task: Task): number | null {
  const completionMs = parseTimestampToMs(task.columnMovedAt ?? task.updatedAt);
  if (completionMs == null) return null;
@@ -153,13 +147,8 @@ function getInProgressElapsedMs(task: Task, nowMs: number): number | null {
 // timer reflects how long the task actually took, not just the time spent
 // inside instrumented code paths. Returns null on legacy tasks that completed
 // before `executionStartedAt` was tracked, so callers can fall back.
-function getEndToEndDurationMs(task: Task, nowMs: number): number | null {
-  const startedMs = parseTimestampToMs(task.executionStartedAt);
-  if (startedMs == null) return null;
-
-  const completedMs = parseTimestampToMs(task.executionCompletedAt);
-  const endMs = completedMs != null && completedMs >= startedMs ? completedMs : nowMs;
-  return Math.max(0, endMs - startedMs);
+function getTaskEndToEndDurationMs(task: Task, nowMs: number): number | null {
+  return getEndToEndDurationMs(task.executionStartedAt, task.executionCompletedAt, nowMs);
 }

 function getInReviewCompletionMs(task: Task): number | null {
@@ -176,7 +165,7 @@ function getMergeElapsedMs(task: Task, nowMs: number): number | null {
 }

 function getActiveMergeTotalMs(task: Task, nowMs: number): number | null {
-  const endToEndMs = getEndToEndDurationMs(task, nowMs);
+  const endToEndMs = getTaskEndToEndDurationMs(task, nowMs);
  if (endToEndMs != null) {
    return endToEndMs;
  }
@@ -190,43 +179,17 @@ function getActiveMergeTotalMs(task: Task, nowMs: number): number | null {
  return mergeElapsedMs;
 }

-// Mirrors summarizeWorkflowTiming in TaskTokenStatsPanel: completed steps use
-// completedAt-startedAt; in-progress steps contribute live elapsed (now-startedAt).
-function getWorkflowRuntimeMs(task: Task, nowMs: number): number | null {
-  const results = task.workflowStepResults;
-  if (!results || results.length === 0) return null;
-
-  let total = 0;
-  let counted = 0;
-  for (const step of results) {
-    if (!step.startedAt) continue;
-    const startedMs = parseTimestampToMs(step.startedAt);
-    if (startedMs == null) continue;
-
-    let endMs: number;
-    if (step.completedAt) {
-      const completedMs = parseTimestampToMs(step.completedAt);
-      if (completedMs == null || completedMs < startedMs) continue;
-      endMs = completedMs;
-    } else {
-      endMs = Math.max(startedMs, nowMs);
-    }
-    total += endMs - startedMs;
-    counted += 1;
-  }
-  return counted > 0 ? total : null;
-}

 function getInstrumentedDurationMs(task: Task, nowMs: number): number | null {
-  // Prefer the server-aggregated `timedExecutionMs` (populated for slim board
-  // listings, where `task.log` is stripped to keep the wire payload small).
-  // Fall back to client-side parsing of the full log for the detail-modal
-  // path where the slim aggregate is absent but the log is loaded.
-  const timed =
-    typeof task.timedExecutionMs === "number"
-      ? task.timedExecutionMs
-      : getTimedDurationMs(task.log);
-  const workflow = getWorkflowRuntimeMs(task, nowMs);
+  // Prefer server aggregate when present: it is the canonical persisted runtime
+  // and may already include workflow execution. Avoid adding workflow runtime
+  // again in that case.
+  if (typeof task.timedExecutionMs === "number") {
+    return task.timedExecutionMs;
+  }
+
+  const timed = getTimedDurationMs(task.log);
+  const workflow = getWorkflowRuntimeMs(task.workflowStepResults, nowMs);
  if (timed == null && workflow == null) return null;
  return (timed ?? 0) + (workflow ?? 0);
 }
@@ -777,7 +740,7 @@ function TaskCardComponent({
    const merging = task.status != null && ACTIVE_MERGE_STATUSES.has(task.status);

    if (task.column === "in-progress") {
-      const endToEndMs = getEndToEndDurationMs(task, Date.now());
+      const endToEndMs = getTaskEndToEndDurationMs(task, Date.now());
      const elapsedMs = getInProgressElapsedMs(task, Date.now());
      const instrumentedMs = getInstrumentedDurationMs(task, Date.now());
      if (endToEndMs == null && elapsedMs == null && instrumentedMs == null) {
@@ -786,7 +749,7 @@ function TaskCardComponent({
    }

    if (!merging && task.column === "in-review") {
-      const endToEndMs = getEndToEndDurationMs(task, Date.now());
+      const endToEndMs = getTaskEndToEndDurationMs(task, Date.now());
      const instrumentedMs = getInstrumentedDurationMs(task, Date.now());
      if (endToEndMs == null && instrumentedMs == null) {
        return;
@@ -833,7 +796,7 @@ function TaskCardComponent({
      // in-progress, never reset on retry-loop bounces). Fall back to the
      // columnMovedAt heuristic for legacy tasks predating the new field.
      const elapsedMs =
-        getEndToEndDurationMs(task, timeIndicatorNowMs)
+        getTaskEndToEndDurationMs(task, timeIndicatorNowMs)
        ?? getInProgressElapsedMs(task, timeIndicatorNowMs)
        ?? getInstrumentedDurationMs(task, timeIndicatorNowMs);
      if (elapsedMs == null) {
@@ -855,7 +818,7 @@ function TaskCardComponent({
    // in-review and done: show wall-clock end-to-end runtime. Falls back to
    // the instrumented `[timing]` aggregate for tasks completed before
    // `executionStartedAt`/`executionCompletedAt` were tracked.
-    const endToEndMs = getEndToEndDurationMs(task, timeIndicatorNowMs);
+    const endToEndMs = getTaskEndToEndDurationMs(task, timeIndicatorNowMs);
    const totalMs = endToEndMs ?? getInstrumentedDurationMs(task, timeIndicatorNowMs);
    if (totalMs == null) {
      return null;
--- a/packages/dashboard/app/components/TaskTokenStatsPanel.tsx
+++ b/packages/dashboard/app/components/TaskTokenStatsPanel.tsx
@@ -1,5 +1,5 @@
 import type { Task, TaskTokenUsage, WorkflowStepResult } from "@fusion/core";
-import { extractTimingEvents, type TimingEvent } from "../utils/taskTiming";
+import { extractTimingEvents, getEndToEndDurationMs, getTimedDurationMs, getWorkflowRuntimeMs, type TimingEvent } from "../utils/taskTiming";
 import "./TaskTokenStatsPanel.css";

 interface TaskTokenStatsPanelProps {
@@ -26,6 +26,8 @@ interface TaskTokenStatsPanelProps {
    | "assignedAgentId"
    | "blockedBy"
    | "sessionFile"
+    | "executionStartedAt"
+    | "executionCompletedAt"
  >;
 }

@@ -71,7 +73,6 @@ function summarizeWorkflowTiming(results: WorkflowStepResult[]): WorkflowTimingS
      if (Number.isNaN(startedMs)) {
        return null;
      }
-      // Completed step → use completedAt. In-progress step → live elapsed.
      let endMs: number;
      if (step.completedAt) {
        const completedMs = new Date(step.completedAt).getTime();
@@ -89,7 +90,7 @@ function summarizeWorkflowTiming(results: WorkflowStepResult[]): WorkflowTimingS
    })
    .filter((value): value is { name: string; durationMs: number } => value !== null);

-  const totalDurationMs = timedResults.reduce((sum, step) => sum + step.durationMs, 0);
+  const totalDurationMs = getWorkflowRuntimeMs(results, nowMs) ?? 0;
  const longestStep = timedResults.reduce<{ name: string; durationMs: number } | undefined>((longest, step) => {
    if (!longest || step.durationMs > longest.durationMs) {
      return step;
@@ -105,10 +106,14 @@ function summarizeWorkflowTiming(results: WorkflowStepResult[]): WorkflowTimingS
 }

 export function TaskTokenStatsPanel({ tokenUsage, loading, task }: TaskTokenStatsPanelProps) {
+  const nowMs = Date.now();
  const timingEvents = extractTimingEvents(task?.log ?? []);
  const timedTimingEvents = timingEvents.filter((event) => typeof event.durationMs === "number");
  const logTimingDurationMs = timedTimingEvents.reduce((sum, event) => sum + (event.durationMs ?? 0), 0);
-  const totalTimingDurationMs = Math.max(logTimingDurationMs, task?.timedExecutionMs ?? 0);
+  const parsedTimingDurationMs = getTimedDurationMs(task?.log) ?? 0;
+  const totalTimingDurationMs = typeof task?.timedExecutionMs === "number"
+    ? task.timedExecutionMs
+    : Math.max(logTimingDurationMs, parsedTimingDurationMs);
  const longestTimingEvent = timedTimingEvents.reduce<TimingEvent | undefined>((longest, event) => {
    if (!longest || (event.durationMs ?? 0) > (longest.durationMs ?? 0)) {
      return event;
@@ -117,6 +122,15 @@ export function TaskTokenStatsPanel({ tokenUsage, loading, task }: TaskTokenStat
  }, undefined);

  const workflowTiming = summarizeWorkflowTiming(task?.workflowStepResults ?? []);
+  const endToEndDurationMs = getEndToEndDurationMs(task?.executionStartedAt, task?.executionCompletedAt, nowMs);
+  // Canonical fallback order for Task Detail Stats total runtime:
+  // 1) durable wall-clock execution window (`executionStartedAt` → `executionCompletedAt`),
+  // 2) server aggregate `timedExecutionMs` when present,
+  // 3) legacy local aggregate (`[timing]` sum + workflow runtime).
+  // This avoids double counting when workflow timings appear in both `[timing]`
+  // logs and `workflowStepResults`.
+  const totalExecutionMs = endToEndDurationMs
+    ?? (typeof task?.timedExecutionMs === "number" ? task.timedExecutionMs : totalTimingDurationMs + workflowTiming.totalDurationMs);
  const taskStepCount = task?.steps?.length ?? 0;

  return (
@@ -144,7 +158,7 @@ export function TaskTokenStatsPanel({ tokenUsage, loading, task }: TaskTokenStat
          </div>
          <div className="task-token-stats-panel__metric" role="listitem">
            <span className="task-token-stats-panel__label">Total execution time</span>
-            <span className="task-token-stats-panel__value">{formatDuration(totalTimingDurationMs + workflowTiming.totalDurationMs)}</span>
+            <span className="task-token-stats-panel__value">{formatDuration(totalExecutionMs)}</span>
          </div>
        </div>

--- a/packages/dashboard/app/components/tests/TaskDetailModal.rendering.test.tsx
+++ b/packages/dashboard/app/components/tests/TaskDetailModal.rendering.test.tsx
@@ -1409,5 +1409,43 @@ describe("TaskDetailModal", () => {
    });
  });

+  it("renders corrected stats timing totals in Stats tab", () => {
+    render(
+      <TaskDetailModal
+        task={makeTask({
+          executionStartedAt: "2026-04-24T09:00:00.000Z",
+          executionCompletedAt: "2026-04-24T09:04:00.000Z",
+          timedExecutionMs: 120_000,
+          log: [
+            { timestamp: "2026-04-24T09:00:00.000Z", action: "[timing] AI execution completed in 120000ms" },
+          ],
+          workflowStepResults: [
+            {
+              workflowStepId: "WS-401",
+              workflowStepName: "Workflow QA",
+              status: "passed",
+              startedAt: "2026-04-24T09:01:00.000Z",
+              completedAt: "2026-04-24T09:02:00.000Z",
+            },
+          ],
+        })}
+        onClose={noop}
+        onMoveTask={noopMove}
+        onDeleteTask={noopDelete}
+        onMergeTask={noopMerge}
+        onOpenDetail={noopOpenDetail}
+        addToast={noop}
+      />,
+    );
+
+    fireEvent.click(screen.getByRole("button", { name: "Stats" }));
+
+    const totalMetric = screen.getByText("Total execution time").closest(".task-token-stats-panel__metric");
+    const workflowMetric = screen.getByText("Workflow runtime").closest(".task-token-stats-panel__metric");
+
+    expect(totalMetric).toHaveTextContent("4m 0s");
+    expect(screen.getByText("Timed duration").closest(".task-token-stats-panel__metric")).toHaveTextContent("2m 0s");
+    expect(workflowMetric).toHaveTextContent("1m 0s");
+  });

 });
--- a/packages/dashboard/app/components/tests/TaskTokenStatsPanel.test.tsx
+++ b/packages/dashboard/app/components/tests/TaskTokenStatsPanel.test.tsx
@@ -133,4 +133,85 @@ describe("TaskTokenStatsPanel", () => {
    expect(screen.getByText("Timed duration")).toBeInTheDocument();
    expect(screen.getAllByText("4m 0s").length).toBeGreaterThan(0);
  });
+
+  it("uses end-to-end execution window for total execution time when available", () => {
+    render(
+      <TaskTokenStatsPanel
+        loading={false}
+        tokenUsage={undefined}
+        task={makeTask({
+          executionStartedAt: "2026-04-24T09:00:00.000Z",
+          executionCompletedAt: "2026-04-24T09:05:00.000Z",
+          timedExecutionMs: 120_000,
+          workflowStepResults: [
+            {
+              workflowStepId: "WS-900",
+              workflowStepName: "Review",
+              status: "passed",
+              startedAt: "2026-04-24T09:03:00.000Z",
+              completedAt: "2026-04-24T09:04:00.000Z",
+            },
+          ],
+        })}
+      />,
+    );
+
+    expect(screen.getByText("Total execution time")).toBeInTheDocument();
+    expect(screen.getByText("5m 0s")).toBeInTheDocument();
+  });
+
+  it("does not double count workflow runtime when timedExecutionMs is present", () => {
+    render(
+      <TaskTokenStatsPanel
+        loading={false}
+        tokenUsage={undefined}
+        task={makeTask({
+          log: [
+            { timestamp: "2026-04-24T09:00:00.000Z", action: "[timing] AI execution completed in 120000ms" },
+          ],
+          timedExecutionMs: 120_000,
+          workflowStepResults: [
+            {
+              workflowStepId: "WS-200",
+              workflowStepName: "Workflow QA",
+              status: "passed",
+              startedAt: "2026-04-24T09:01:00.000Z",
+              completedAt: "2026-04-24T09:02:00.000Z",
+            },
+          ],
+        })}
+      />,
+    );
+
+    const metric = screen.getByText("Total execution time").closest(".task-token-stats-panel__metric");
+    expect(metric).toHaveTextContent("2m 0s");
+    expect(screen.getByText("Workflow runtime").closest(".task-token-stats-panel__metric")).toHaveTextContent("1m 0s");
+  });
+
+  it("uses legacy timed plus workflow fallback when end-to-end and timedExecutionMs are unavailable", () => {
+    render(
+      <TaskTokenStatsPanel
+        loading={false}
+        tokenUsage={undefined}
+        task={makeTask({
+          timedExecutionMs: undefined,
+          log: [
+            { timestamp: "2026-04-24T09:00:00.000Z", action: "[timing] setup completed in 120000ms" },
+          ],
+          workflowStepResults: [
+            {
+              workflowStepId: "WS-300",
+              workflowStepName: "Workflow QA",
+              status: "passed",
+              startedAt: "2026-04-24T09:01:00.000Z",
+              completedAt: "2026-04-24T09:02:00.000Z",
+            },
+          ],
+        })}
+      />,
+    );
+
+    const metric = screen.getByText("Total execution time").closest(".task-token-stats-panel__metric");
+    expect(metric).toHaveTextContent("3m 0s");
+  });
 });
--- a/packages/dashboard/app/utils/taskTiming.ts
+++ b/packages/dashboard/app/utils/taskTiming.ts
@@ -1,4 +1,4 @@
-import type { TaskLogEntry } from "@fusion/core";
+import type { TaskLogEntry, WorkflowStepResult } from "@fusion/core";

 export interface TimingEvent {
  timestamp: string;
@@ -47,3 +47,48 @@ export function getTimedDurationMs(logEntries: TaskLogEntry[] | undefined): numb
  }
  return counted > 0 ? total : null;
 }
+
+export function parseTimestampToMs(value?: string): number | null {
+  if (!value) return null;
+  const parsed = Date.parse(value);
+  return Number.isFinite(parsed) ? parsed : null;
+}
+
+export function getWorkflowRuntimeMs(results: WorkflowStepResult[] | undefined, nowMs: number): number | null {
+  if (!results || results.length === 0) return null;
+
+  let total = 0;
+  let counted = 0;
+  for (const step of results) {
+    if (!step.startedAt) continue;
+    const startedMs = parseTimestampToMs(step.startedAt);
+    if (startedMs == null) continue;
+
+    let endMs: number;
+    if (step.completedAt) {
+      const completedMs = parseTimestampToMs(step.completedAt);
+      if (completedMs == null || completedMs < startedMs) continue;
+      endMs = completedMs;
+    } else {
+      endMs = Math.max(startedMs, nowMs);
+    }
+
+    total += endMs - startedMs;
+    counted += 1;
+  }
+
+  return counted > 0 ? total : null;
+}
+
+export function getEndToEndDurationMs(
+  executionStartedAt: string | undefined,
+  executionCompletedAt: string | undefined,
+  nowMs: number,
+): number | null {
+  const startedMs = parseTimestampToMs(executionStartedAt);
+  if (startedMs == null) return null;
+
+  const completedMs = parseTimestampToMs(executionCompletedAt);
+  const endMs = completedMs != null && completedMs >= startedMs ? completedMs : nowMs;
+  return Math.max(0, endMs - startedMs);
+}