FN-7503: add agent log timing metrics

Record and surface request first-token latency and tool processing duration in task logs.

- Add optional agent log timing fields and persist them in file-backed task logs.
- Track Time To First Token from the first visible model output per agent logger request.
- Track FIFO tool durations for tool result and error rows without storing sensitive payloads.
- Render TTFT and duration badges in task chat and agent log viewers with regression coverage.
- Document the new persisted timing fields and add a patch changeset for the CLI package.

Files changed:
 .changeset/fn-7503-agent-log-timing.md             |   7 ++
 docs/storage.md                                    |   1 +
 .../src/__tests__/agent-log-file-store.test.ts     |  35 ++++++
 .../src/__tests__/store-agent-log-file.test.ts     |  28 +++++
 packages/core/src/agent-log-file-store.ts          |  19 ++++
 packages/core/src/store.ts                         |  13 +++
 packages/core/src/types.ts                         |   4 +
 .../dashboard/app/components/AgentLogViewer.css    |  33 ++++++
 .../dashboard/app/components/AgentLogViewer.tsx    |  39 ++++++-
 packages/dashboard/app/components/TaskChatTab.css  |  23 +++-
 packages/dashboard/app/components/TaskChatTab.tsx  |  17 ++-
 .../__tests__/AgentLogViewer.rendering.test.tsx    |  24 +++++
 .../app/components/__tests__/TaskChatTab.test.tsx  |  18 ++++
 packages/engine/src/__tests__/agent-logger.test.ts | 120 ++++++++++++++++++---
 packages/engine/src/agent-logger.ts                |  97 ++++++++++++++---
 15 files changed, 446 insertions(+), 32 deletions(-)

Fusion-Task-Id: FN-7503

Fusion-Task-Lineage: 7e62034f-4c35-420d-a670-3f7f4a7948df

Co-authored-by: Fusion (runfusion.ai) <noreply@runfusion.ai>

.changeset/fn-7503-agent-log-timing.md

@@ -0,0 +1,7 @@
+---
+"@runfusion/fusion": patch
+---
+
+summary: Show first-token and tool processing durations in task agent logs.
+category: feature
+dev: Adds optional agent-log timing fields `timeToFirstTokenMs` and `durationMs`.

docs/storage.md

@@ -26,6 +26,7 @@
 ### Agent log storage + soft-delete visibility (FN-5143 / FN-5911)
 
 - Agent logs are no longer stored in SQLite. Each task now appends newline-delimited JSON records to `<rootDir>/.fusion/tasks/{ID}/agent-log.jsonl`.
+- Agent-log JSONL rows may include optional numeric timing metadata: `timeToFirstTokenMs` on the first visible model-output row for a request, and `durationMs` on tool/request completion rows such as `tool_result` or `tool_error`. These fields are additive, non-sensitive millisecond values; legacy rows may omit them and readers must continue to treat omission as normal.
 - `TaskStore.deleteTask` keeps that JSONL file on disk for forensics, but all live read APIs (`getAgentLogs*`, `getAgentLogCount`) gate on task liveness and return zero entries once `deletedAt` is set.
 - Archived-task snapshot behavior (`taskToArchiveEntry` / `archiveTask`) is unchanged in spirit: archive payloads still embed a capped agent-log snapshot, now sourced from the JSONL file instead of `fusion.db`.
 - Retention is now independent from SQLite operational-log pruning. `settings.agentLogFileRetentionDays` controls age-based pruning of JSONL entries for soft-deleted and archived tasks only. Default: `0` (disabled).

packages/core/src/__tests__/agent-log-file-store.test.ts

@@ -43,6 +43,41 @@ describe("agent-log-file-store", () => {
     expect(readAgentLogEntries(taskDir)).toEqual(appended);
   });
 
+  it("round-trips optional timing metadata while legacy rows can omit it", () => {
+    const taskDir = createTaskDir();
+    appendAgentLogEntriesSync(taskDir, [
+      { timestamp: "2026-01-01T00:00:00.000Z", taskId: "FN-1", text: "legacy", type: "text" },
+      { timestamp: "2026-01-01T00:00:01.000Z", taskId: "FN-1", text: "first", type: "text", timeToFirstTokenMs: 1234.4 },
+      { timestamp: "2026-01-01T00:00:02.000Z", taskId: "FN-1", text: "Bash", type: "tool_result", durationMs: 842.2 },
+    ]);
+
+    const entries = readAgentLogEntries(taskDir);
+    expect(entries).toMatchObject([
+      { text: "legacy" },
+      { text: "first", timeToFirstTokenMs: 1234 },
+      { text: "Bash", durationMs: 842 },
+    ]);
+    expect(entries[0]).not.toHaveProperty("timeToFirstTokenMs");
+    expect(entries[0]).not.toHaveProperty("durationMs");
+    expect(entries[1]).not.toHaveProperty("durationMs");
+    expect(entries[2]).not.toHaveProperty("timeToFirstTokenMs");
+  });
+
+  it("ignores invalid legacy timing fields", () => {
+    const taskDir = createTaskDir();
+    const filePath = getAgentLogFilePath(taskDir);
+    writeFileSync(
+      filePath,
+      `${JSON.stringify({ timestamp: "2026-01-01T00:00:00.000Z", taskId: "FN-1", text: "bad timing", type: "text", durationMs: -1, timeToFirstTokenMs: "secret" })}\n`,
+      "utf8",
+    );
+
+    const [entry] = readAgentLogEntries(taskDir);
+    expect(entry).toMatchObject({ text: "bad timing" });
+    expect(entry).not.toHaveProperty("durationMs");
+    expect(entry).not.toHaveProperty("timeToFirstTokenMs");
+  });
+
   it("supports most-recent tail pagination with offset", () => {
     const taskDir = createTaskDir();
     appendAgentLogEntriesSync(

packages/core/src/__tests__/store-agent-log-file.test.ts

@@ -1,5 +1,6 @@
 import { afterEach, beforeEach, describe, expect, it } from "vitest";
 
+import type { AgentLogEntry } from "../types.js";
 import { createTaskStoreTestHarness } from "./store-test-helpers.js";
 
 describe("TaskStore file-backed agent logs", () => {
@@ -61,6 +62,33 @@ describe("TaskStore file-backed agent logs", () => {
     ).resolves.toMatchObject([{ text: "tool" }, { text: "third" }]);
   });
 
+  it("persists and emits optional timing metadata for single and batch appends", async () => {
+    const store = harness.store();
+    const task = await harness.createTestTask();
+    const events: AgentLogEntry[] = [];
+    store.on("agent:log", (entry) => events.push(entry));
+
+    await store.appendAgentLog(task.id, "first visible output", "text", undefined, "executor", { timeToFirstTokenMs: 1200 });
+    await store.appendAgentLogBatch([
+      { taskId: task.id, text: "Bash", type: "tool_result", agent: "executor", durationMs: 842 },
+    ]);
+
+    expect(events).toMatchObject([
+      { text: "first visible output", timeToFirstTokenMs: 1200 },
+      { text: "Bash", type: "tool_result", durationMs: 842 },
+    ]);
+    await expect(store.getAgentLogs(task.id)).resolves.toMatchObject([
+      { text: "first visible output", timeToFirstTokenMs: 1200 },
+      { text: "Bash", type: "tool_result", durationMs: 842 },
+    ]);
+    await expect(
+      store.getAgentLogsByTimeRange(task.id, "2026-01-01T00:00:00.000Z", new Date(Date.now() + 1_000).toISOString()),
+    ).resolves.toMatchObject([
+      { text: "first visible output", timeToFirstTokenMs: 1200 },
+      { text: "Bash", type: "tool_result", durationMs: 842 },
+    ]);
+  });
+
   it("emits SSE-facing agent:log events per single and batch append while skipping persistence for deleted tasks", async () => {
     const store = harness.store();
     const liveTask = await harness.createTestTask();

packages/core/src/agent-log-file-store.ts

@@ -31,6 +31,8 @@ export interface AgentLogFileAppendInput {
   type: AgentLogEntry["type"];
   detail?: string | null;
   agent?: AgentLogEntry["agent"] | null;
+  durationMs?: number | null;
+  timeToFirstTokenMs?: number | null;
 }
 
 interface AgentLogJsonlRow {
@@ -40,6 +42,8 @@ interface AgentLogJsonlRow {
   type: AgentLogEntry["type"];
   detail?: string;
   agent?: AgentLogEntry["agent"];
+  durationMs?: number;
+  timeToFirstTokenMs?: number;
 }
 
 export function getAgentLogFilePath(taskDir: string): string {
@@ -147,8 +151,17 @@ function readAllAgentLogEntries(
   return entries;
 }
 
+function normalizeTimingMs(value: number | null | undefined): number | undefined {
+  if (typeof value !== "number" || !Number.isFinite(value) || value < 0) {
+    return undefined;
+  }
+  return Math.round(value);
+}
+
 function serializeEntry(entry: AgentLogFileAppendInput): string {
   const normalizedDetail = truncateAgentLogDetail(entry.detail, entry.type);
+  const durationMs = normalizeTimingMs(entry.durationMs);
+  const timeToFirstTokenMs = normalizeTimingMs(entry.timeToFirstTokenMs);
   const row: AgentLogJsonlRow = {
     timestamp: entry.timestamp,
     taskId: entry.taskId,
@@ -156,12 +169,16 @@ function serializeEntry(entry: AgentLogFileAppendInput): string {
     type: entry.type,
     ...(normalizedDetail !== undefined && { detail: normalizedDetail }),
     ...(entry.agent != null && { agent: entry.agent }),
+    ...(durationMs !== undefined && { durationMs }),
+    ...(timeToFirstTokenMs !== undefined && { timeToFirstTokenMs }),
   };
   return `${JSON.stringify(row)}\n`;
 }
 
 function materializeEntry(entry: AgentLogFileAppendInput, lineNo: number): StoredAgentLogEntry {
   const normalizedDetail = truncateAgentLogDetail(entry.detail, entry.type);
+  const durationMs = normalizeTimingMs(entry.durationMs);
+  const timeToFirstTokenMs = normalizeTimingMs(entry.timeToFirstTokenMs);
   return {
     timestamp: entry.timestamp,
     taskId: entry.taskId,
@@ -169,6 +186,8 @@ function materializeEntry(entry: AgentLogFileAppendInput, lineNo: number): Store
     type: entry.type,
     ...(normalizedDetail !== undefined && { detail: normalizedDetail }),
     ...(entry.agent != null && { agent: entry.agent }),
+    ...(durationMs !== undefined && { durationMs }),
+    ...(timeToFirstTokenMs !== undefined && { timeToFirstTokenMs }),
     lineNo,
     sourceRef: buildAgentLogSourceRef(entry.taskId, lineNo),
   };

packages/core/src/store.ts

@@ -1703,6 +1703,8 @@ export class TaskStore extends EventEmitter<TaskStoreEvents> {
     type: AgentLogEntry["type"];
     detail: string | null;
     agent: AgentLogEntry["agent"] | null;
+    durationMs: number | null;
+    timeToFirstTokenMs: number | null;
   }> = [];
   /** Timer for flushing the agent log buffer. */
   private agentLogFlushTimer: ReturnType<typeof setTimeout> | null = null;
@@ -12792,6 +12794,7 @@ ${TASK_UPSERT_SQL_ASSIGNMENTS}
     type: AgentLogEntry["type"],
     detail?: string,
     agent?: AgentLogEntry["agent"],
+    timing?: Pick<AgentLogEntry, "durationMs" | "timeToFirstTokenMs">,
   ): Promise<void> {
     const timestamp = new Date().toISOString();
     const normalizedDetail = truncateAgentLogDetail(detail, type);
@@ -12802,6 +12805,8 @@ ${TASK_UPSERT_SQL_ASSIGNMENTS}
       type,
       ...(normalizedDetail !== undefined && { detail: normalizedDetail }),
       ...(agent !== undefined && { agent }),
+      ...(timing?.durationMs !== undefined && { durationMs: timing.durationMs }),
+      ...(timing?.timeToFirstTokenMs !== undefined && { timeToFirstTokenMs: timing.timeToFirstTokenMs }),
     };
 
     // Buffer the entry for batched insertion to reduce WAL pressure.
@@ -12820,6 +12825,8 @@ ${TASK_UPSERT_SQL_ASSIGNMENTS}
       type,
       detail: normalizedDetail ?? null,
       agent: agent ?? null,
+      durationMs: timing?.durationMs ?? null,
+      timeToFirstTokenMs: timing?.timeToFirstTokenMs ?? null,
     });
     this.emit("agent:log", entry);
 
@@ -12958,6 +12965,8 @@ ${TASK_UPSERT_SQL_ASSIGNMENTS}
       type: AgentLogEntry["type"];
       detail?: string;
       agent?: AgentLogEntry["agent"];
+      durationMs?: number;
+      timeToFirstTokenMs?: number;
     }>,
   ): Promise<void> {
     if (entries.length === 0) {
@@ -13003,6 +13012,8 @@ ${TASK_UPSERT_SQL_ASSIGNMENTS}
           type: entry.type,
           detail: entry.detail ?? null,
           agent: entry.agent ?? null,
+          durationMs: entry.durationMs ?? null,
+          timeToFirstTokenMs: entry.timeToFirstTokenMs ?? null,
         })),
       );
       for (const entry of appended) {
@@ -13041,6 +13052,8 @@ ${TASK_UPSERT_SQL_ASSIGNMENTS}
         type: entry.type,
         ...(entry.detail !== undefined && { detail: entry.detail }),
         ...(entry.agent !== undefined && { agent: entry.agent }),
+        ...(entry.durationMs !== undefined && { durationMs: entry.durationMs }),
+        ...(entry.timeToFirstTokenMs !== undefined && { timeToFirstTokenMs: entry.timeToFirstTokenMs }),
       });
     }
   }

packages/core/src/types.ts

@@ -1204,6 +1204,10 @@ export interface AgentLogEntry {
   detail?: string;
   /** Which agent produced this entry. Absent in logs written before this field was added. */
   agent?: AgentRole;
+  /** Request/tool processing duration in milliseconds. Absent for legacy rows and entries without bounded timing. */
+  durationMs?: number;
+  /** Time to first visible model output in milliseconds. Absent after the first visible output and on legacy rows. */
+  timeToFirstTokenMs?: number;
 }
 
 /** How much of `.fusion/tasks/{ID}/agent.log` is copied into cold archive storage. */

packages/dashboard/app/components/AgentLogViewer.css

@@ -200,11 +200,40 @@ Keep each block full-width and float the role/timestamp badge as a sticky overla
 }
 
 .agent-log-tool-title {
+  display: flex;
+  align-items: center;
+  flex-wrap: wrap;
+  gap: var(--space-xs);
   white-space: pre-wrap;
   word-break: break-word;
   overflow-wrap: anywhere;
 }
 
+/*
+FNXC:AgentLogging 2026-07-04-09:49:
+Agent-log timing labels are metadata, not timestamps. Keep TTFT and duration compact, token-colored, and inline with the affected entry so operators can compare latency without disrupting grouped markdown/tool output.
+*/
+.agent-log-timing-labels {
+  display: inline-flex;
+  align-items: center;
+  flex-wrap: wrap;
+  gap: var(--space-xs);
+  margin-inline-start: var(--space-xs);
+  color: var(--text-muted);
+  font-size: var(--font-size-xs);
+  white-space: nowrap;
+  vertical-align: baseline;
+}
+
+.agent-log-timing-label {
+  display: inline-flex;
+  align-items: center;
+  border: 1px solid var(--border);
+  border-radius: var(--radius-pill);
+  padding: 0 var(--space-xs);
+  background: var(--bg-secondary);
+}
+
 .agent-log-tool-detail-wrapper {
   margin-top: var(--space-xs);
 }
@@ -425,4 +454,8 @@ Keep each block full-width and float the role/timestamp badge as a sticky overla
   .agent-log-tool-detail-toggle {
     min-height: calc(var(--space-lg) + var(--space-lg) + var(--space-xs));
   }
+
+  .agent-log-timing-labels {
+    white-space: normal;
+  }
 }

packages/dashboard/app/components/AgentLogViewer.tsx

@@ -109,6 +109,35 @@ function isNearBottom(container: HTMLDivElement): boolean {
   return container.scrollHeight - (container.scrollTop + container.clientHeight) <= BOTTOM_FOLLOW_THRESHOLD_PX;
 }
 
+export function formatAgentLogDuration(ms: number): string {
+  if (ms < 1000) return `${Math.round(ms)}ms`;
+  return `${(ms / 1000).toFixed(ms < 10_000 ? 1 : 0)}s`;
+}
+
+export function formatAgentLogTimingLabels(entry: Pick<AgentLogEntry, "durationMs" | "timeToFirstTokenMs">, t: TFunction<"app">): string[] {
+  const labels: string[] = [];
+  if (typeof entry.timeToFirstTokenMs === "number" && Number.isFinite(entry.timeToFirstTokenMs)) {
+    labels.push(t("agentLog.timeToFirstToken", "TTFT {{duration}}", { duration: formatAgentLogDuration(entry.timeToFirstTokenMs) }));
+  }
+  if (typeof entry.durationMs === "number" && Number.isFinite(entry.durationMs)) {
+    labels.push(t("agentLog.duration", "Duration {{duration}}", { duration: formatAgentLogDuration(entry.durationMs) }));
+  }
+  return labels;
+}
+
+function AgentLogTimingLabels({ entry }: { entry: AgentLogEntry }): ReactElement | null {
+  const { t } = useTranslation("app");
+  const labels = formatAgentLogTimingLabels(entry, t as TFunction<"app">);
+  if (labels.length === 0) return null;
+  return (
+    <span className="agent-log-timing-labels" data-testid="agent-log-timing-labels" aria-label={labels.join(", ")}>
+      {labels.map((label) => (
+        <span key={label} className="agent-log-timing-label">{label}</span>
+      ))}
+    </span>
+  );
+}
+
 function getEntrySignature(entry: AgentLogEntry): string {
   return [
     entry.taskId,
@@ -117,6 +146,8 @@ function getEntrySignature(entry: AgentLogEntry): string {
     entry.type,
     entry.text,
     entry.detail ?? "",
+    entry.durationMs ?? "",
+    entry.timeToFirstTokenMs ?? "",
   ].join("|");
 }
 
@@ -668,7 +699,7 @@ export function AgentLogViewer({
               return (
                 <div key={group.key} className="agent-log-tool">
                   {agentBadge}
-                  <div className="agent-log-tool-title">⚡ {entry.text}</div>
+                  <div className="agent-log-tool-title">⚡ {entry.text}<AgentLogTimingLabels entry={entry} /></div>
                   {entry.detail ? <CollapsibleToolDetail detail={entry.detail} type="tool" /> : null}
                 </div>
               );
@@ -678,7 +709,7 @@ export function AgentLogViewer({
               return (
                 <div key={group.key} className="agent-log-tool-result">
                   {agentBadge}
-                  <div className="agent-log-tool-title">✓ {entry.text}</div>
+                  <div className="agent-log-tool-title">✓ {entry.text}<AgentLogTimingLabels entry={entry} /></div>
                   {entry.detail ? <CollapsibleToolDetail detail={entry.detail} type="tool_result" /> : null}
                 </div>
               );
@@ -688,7 +719,7 @@ export function AgentLogViewer({
               return (
                 <div key={group.key} className="agent-log-tool-error">
                   {agentBadge}
-                  <div className="agent-log-tool-title">✗ {entry.text}</div>
+                  <div className="agent-log-tool-title">✗ {entry.text}<AgentLogTimingLabels entry={entry} /></div>
                   {entry.detail ? <CollapsibleToolDetail detail={entry.detail} type="tool_error" /> : null}
                 </div>
               );
@@ -703,6 +734,7 @@ export function AgentLogViewer({
             return (
               <div key={group.key} className="agent-log-thinking">
                 {agentBadge}
+                <AgentLogTimingLabels entry={firstEntry} />
                 {renderMarkdown ? (
                   <div className="markdown-body">
                     <ReactMarkdown remarkPlugins={[remarkGfm]} components={markdownComponents}>
@@ -719,6 +751,7 @@ export function AgentLogViewer({
           return (
             <div key={group.key} className="agent-log-text">
               {agentBadge}
+              <AgentLogTimingLabels entry={firstEntry} />
               {renderMarkdown ? (
                 <div className="markdown-body">
                   <ReactMarkdown remarkPlugins={[remarkGfm]} components={markdownComponents}>

packages/dashboard/app/components/TaskChatTab.css

@@ -425,6 +425,26 @@ FN-7241 adds timestamps inside individual task-detail transcript blocks. Keep bl
   justify-content: flex-end;
 }
 
+/* FNXC:AgentLogging 2026-07-04-09:52: Task chat tool groups surface completion duration inline with existing quiet metadata so collapsed/expanded transcripts show request processing time without adding a second timestamp concept. */
+.task-chat-timing-labels {
+  display: inline-flex;
+  align-items: center;
+  flex-wrap: wrap;
+  gap: var(--space-xs);
+  color: var(--text-muted);
+  font-size: var(--font-size-xs);
+  white-space: nowrap;
+}
+
+.task-chat-timing-label {
+  display: inline-flex;
+  align-items: center;
+  border: 1px solid var(--border);
+  border-radius: var(--radius-pill);
+  padding: 0 var(--space-xs);
+  background: var(--bg-secondary);
+}
+
 .task-chat-entry-kicker {
   color: var(--text-muted);
   font-size: var(--space-md);
@@ -574,7 +594,8 @@ FN-6660 corrects the repeated mobile sizing misses from FN-6507, FN-6604, and FN
     justify-content: flex-end;
   }
 
-  .task-chat-timestamp {
+  .task-chat-timestamp,
+  .task-chat-timing-labels {
     white-space: normal;
   }
 

packages/dashboard/app/components/TaskChatTab.tsx

@@ -13,7 +13,7 @@ import { linkifyFilePaths } from "../utils/filePathLinkify";
 import { formatRelativeTimeAgo } from "../utils/relativeTimeAgo";
 import { ProviderIcon } from "./ProviderIcon";
 import { clampChatInputHeight, resolveChatInputOverflowY } from "../utils/chatInputAutosize";
-import { markdownComponents } from "./AgentLogViewer";
+import { formatAgentLogTimingLabels, markdownComponents } from "./AgentLogViewer";
 import { parseRuntimeModelMarker } from "./effective-model-resolution";
 import "./TaskChatTab.css";
 
@@ -194,6 +194,19 @@ function TaskChatTimestamp({ timestamp, testId = "task-chat-block-time", label =
   );
 }
 
+function TaskChatTimingLabels({ entry }: { entry: AgentLogEntry }) {
+  const { t } = useTranslation("app");
+  const labels = formatAgentLogTimingLabels(entry, t as TFunction<"app">);
+  if (labels.length === 0) return null;
+  return (
+    <span className="task-chat-timing-labels" data-testid="task-chat-timing-labels" aria-label={labels.join(", ")}>
+      {labels.map((label) => (
+        <span key={label} className="task-chat-timing-label">{label}</span>
+      ))}
+    </span>
+  );
+}
+
 function TaskChatTimestampMeta({ timestamp, label }: { timestamp: string | undefined; label: string }) {
   if (!getRelativeTimestamp(timestamp)) return null;
   return (
@@ -395,6 +408,7 @@ function TaskChatToolEntry({ entry }: { entry: AgentLogEntry }) {
     >
       <div className="task-chat-entry-label-row">
         <span className="task-chat-entry-kicker">{formatEntryLabel(entry, t)}</span>
+        <TaskChatTimingLabels entry={entry} />
         <TaskChatTimestamp timestamp={entry.timestamp} label="Tool entry timestamp" />
       </div>
       <div className="task-chat-entry-text">{entry.text}</div>
@@ -440,6 +454,7 @@ function TaskChatToolInvocation({ row }: { row: Extract<TaskChatToolGroupRow, {
     <article className={className} data-testid="task-chat-tool-invocation">
       <div className="task-chat-entry-label-row">
         <span className="task-chat-entry-kicker">{completionLabel ? t("taskChat.toolCallTo", "Tool call → {{label}}", { label: completionLabel }) : t("taskChat.toolCall", "Tool call")}</span>
+        <TaskChatTimingLabels entry={completion ?? row.call} />
         <TaskChatTimestamp timestamp={completion?.timestamp ?? row.call.timestamp} label="Tool invocation timestamp" />
       </div>
       <div className="task-chat-entry-text">{row.call.text}</div>

packages/dashboard/app/components/__tests__/AgentLogViewer.rendering.test.tsx

@@ -140,6 +140,30 @@ describe("AgentLogViewer", () => {
     expect(openFile).toHaveBeenCalledWith("packages/engine/src/scheduler.ts", { line: undefined, col: undefined });
   });
 
+  it("renders compact timing labels and omits them for legacy entries", () => {
+    const entries = [
+      makeEntry({ text: "first token", type: "text", timeToFirstTokenMs: 1200, agent: "executor" }),
+      makeEntry({ text: "legacy", type: "text", timestamp: "2026-01-01T00:00:01Z", agent: "reviewer" }),
+      makeEntry({ text: "Bash", type: "tool_result", durationMs: 842, timestamp: "2026-01-01T00:00:02Z" }),
+    ];
+
+    const { container } = render(<AgentLogViewer entries={entries} loading={false} />);
+
+    expect(screen.getByText("TTFT 1.2s")).toBeInTheDocument();
+    expect(screen.getByText("Duration 842ms")).toBeInTheDocument();
+    expect(container.querySelectorAll(".agent-log-timing-label")).toHaveLength(2);
+  });
+
+  it("keeps timing labels stable for duplicate entries", () => {
+    const duplicateEntry = makeEntry({ text: "Bash", type: "tool_result", durationMs: 25, timestamp: "2026-01-01T00:00:00Z" });
+    const { container, rerender } = render(<AgentLogViewer entries={[duplicateEntry, { ...duplicateEntry }]} loading={false} />);
+
+    rerender(<AgentLogViewer entries={[duplicateEntry, { ...duplicateEntry }, { ...duplicateEntry }]} loading={false} />);
+
+    expect(screen.getAllByText("Duration 25ms")).toHaveLength(3);
+    expect(container.querySelectorAll(".agent-log-tool-result")).toHaveLength(3);
+  });
+
   it("renders tool entries with distinct styling", () => {
     const entries = [
       makeEntry({ text: "Read", type: "tool" }),

packages/dashboard/app/components/__tests__/TaskChatTab.test.tsx

@@ -877,6 +877,24 @@ describe("TaskChatTab", () => {
     expect(screen.getByText("ok")).toBeVisible();
   });
 
+  it("shows Bash tool duration in the expanded invocation and omits legacy timing labels", async () => {
+    const user = userEvent.setup();
+    mockLogs([
+      makeEntry({ agent: "executor", type: "tool", text: "Bash", detail: "pnpm test" }),
+      makeEntry({ agent: "executor", type: "tool_result", text: "Bash", detail: "ok", durationMs: 842 }),
+      makeEntry({ agent: "executor", type: "tool", text: "Read", detail: "file.ts" }),
+      makeEntry({ agent: "executor", type: "tool_result", text: "Read", detail: "contents" }),
+    ]);
+
+    render(<TaskChatTab task={makeTask()} active addToast={vi.fn()} />);
+
+    expect(screen.queryByText("Duration 842ms")).not.toBeVisible();
+    await user.click(screen.getByText("2 tool calls"));
+
+    expect(screen.getByText("Duration 842ms")).toBeVisible();
+    expect(screen.getAllByTestId("task-chat-timing-labels")).toHaveLength(1);
+  });
+
   it("summarizes multiple invocations with deduped names and overflow", () => {
     mockLogs([
       makeEntry({ agent: "executor", type: "tool", text: "bash", detail: "run tests" }),

packages/engine/src/__tests__/agent-logger.test.ts

@@ -83,7 +83,7 @@ describe("AgentLogger", () => {
     await vi.advanceTimersByTimeAsync(0);
 
     expect(store.appendAgentLogBatch).toHaveBeenCalledWith([
-      { taskId: "FN-BATCH", text: "hello", type: "text", detail: undefined, agent: undefined },
+      { taskId: "FN-BATCH", text: "hello", type: "text", detail: undefined, agent: undefined, timeToFirstTokenMs: 0 },
     ]);
     expect((store.appendAgentLog as ReturnType<typeof vi.fn>)).not.toHaveBeenCalled();
   });
@@ -105,7 +105,7 @@ describe("AgentLogger", () => {
     logger.onText("worldextra");
     // Allow async flush
     await vi.advanceTimersByTimeAsync(0);
-    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-001", "helloworldextra", "text", undefined, undefined);
+    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-001", "helloworldextra", "text", undefined, undefined, { durationMs: undefined, timeToFirstTokenMs: 0 });
   });
 
   it("flushes on timer when under size threshold", async () => {
@@ -121,7 +121,7 @@ describe("AgentLogger", () => {
     expect(store.appendAgentLog).not.toHaveBeenCalled();
 
     await vi.advanceTimersByTimeAsync(500);
-    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-002", "small", "text", undefined, undefined);
+    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-002", "small", "text", undefined, undefined, { durationMs: undefined, timeToFirstTokenMs: 0 });
   });
 
   it("flushes text before logging tool start", async () => {
@@ -140,7 +140,7 @@ describe("AgentLogger", () => {
     const calls = (store.appendAgentLog as ReturnType<typeof vi.fn>).mock.calls;
     expect(calls.length).toBe(2);
     // Text flushed first
-    expect(calls[0]).toEqual(["FN-003", "pending text", "text", undefined, undefined]);
+    expect(calls[0]).toEqual(["FN-003", "pending text", "text", undefined, undefined, { durationMs: undefined, timeToFirstTokenMs: 0 }]);
     // Tool logged second without detail by default.
     expect(calls[1]).toEqual(["FN-003", "Bash", "tool", undefined, undefined]);
   });
@@ -155,7 +155,7 @@ describe("AgentLogger", () => {
     await vi.advanceTimersByTimeAsync(0);
 
     expect(store.appendAgentLog).toHaveBeenNthCalledWith(1, "FN-004", "Read", "tool", undefined, undefined);
-    expect(store.appendAgentLog).toHaveBeenNthCalledWith(2, "FN-004", "Read", "tool_result", undefined, undefined);
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(2, "FN-004", "Read", "tool_result", undefined, undefined, { durationMs: 0, timeToFirstTokenMs: undefined });
     expect(store.appendAgentLog).toHaveBeenNthCalledWith(3, "FN-004", "Read", "tool_error", undefined, undefined);
   });
 
@@ -183,7 +183,7 @@ describe("AgentLogger", () => {
     await vi.advanceTimersByTimeAsync(0);
 
     expect(store.appendAgentLog).toHaveBeenNthCalledWith(1, "FN-004B", "Read", "tool", undefined, undefined);
-    expect(store.appendAgentLog).toHaveBeenNthCalledWith(2, "FN-004B", "Read", "tool_result", undefined, undefined);
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(2, "FN-004B", "Read", "tool_result", undefined, undefined, { durationMs: 0, timeToFirstTokenMs: undefined });
     expect(store.appendAgentLog).toHaveBeenNthCalledWith(3, "FN-004B", "Read", "tool_error", undefined, undefined);
   });
 
@@ -209,7 +209,7 @@ describe("AgentLogger", () => {
     logger.onText("remaining");
     await logger.flush();
 
-    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-006", "remaining", "text", undefined, undefined);
+    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-006", "remaining", "text", undefined, undefined, { durationMs: undefined, timeToFirstTokenMs: 0 });
   });
 
   it("flush() is safe to call when buffer is empty", async () => {
@@ -255,7 +255,101 @@ describe("AgentLogger", () => {
 
     // All text should be flushed in a single call
     expect(store.appendAgentLog).toHaveBeenCalledTimes(1);
-    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-009", "abc", "text", undefined, undefined);
+    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-009", "abc", "text", undefined, undefined, { durationMs: undefined, timeToFirstTokenMs: 0 });
+  });
+
+  // ── Timing metadata ──────────────────────────────────────────────
+
+  it("records TTFT on the first text entry only", async () => {
+    const store = createMockStore();
+    const logger = new AgentLogger({
+      store,
+      taskId: "FN-TTFT-1",
+      flushSizeBytes: 1024,
+      flushIntervalMs: 500,
+    });
+
+    await vi.advanceTimersByTimeAsync(125);
+    logger.onText("first");
+    await vi.advanceTimersByTimeAsync(500);
+    logger.onText(" second");
+    await vi.advanceTimersByTimeAsync(500);
+
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(
+      1,
+      "FN-TTFT-1",
+      "first",
+      "text",
+      undefined,
+      undefined,
+      { durationMs: undefined, timeToFirstTokenMs: 125 },
+    );
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(2, "FN-TTFT-1", " second", "text", undefined, undefined);
+  });
+
+  it("records TTFT on persisted thinking when thinking is first visible output", async () => {
+    const store = createMockStore();
+    const logger = new AgentLogger({
+      store,
+      taskId: "FN-TTFT-THINKING",
+      agent: "executor",
+      persistAgentThinkingLog: true,
+      flushSizeBytes: 1024,
+      flushIntervalMs: 500,
+    });
+
+    await vi.advanceTimersByTimeAsync(75);
+    logger.onThinking("thought");
+    await vi.advanceTimersByTimeAsync(500);
+    logger.onText("answer");
+    await vi.advanceTimersByTimeAsync(500);
+
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(
+      1,
+      "FN-TTFT-THINKING",
+      "thought",
+      "thinking",
+      undefined,
+      "executor",
+      { durationMs: undefined, timeToFirstTokenMs: 75 },
+    );
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(2, "FN-TTFT-THINKING", "answer", "text", undefined, "executor");
+  });
+
+  it("records tool duration on success and error without leaking payload into timing", async () => {
+    const store = createMockStore();
+    const logger = new AgentLogger({ store, taskId: "FN-DURATION", agent: "executor", persistAgentToolOutput: true });
+
+    logger.onToolStart("Bash", { command: "echo secret-args" });
+    await vi.advanceTimersByTimeAsync(842);
+    logger.onToolEnd("Bash", false, "secret-output");
+    logger.onToolStart("Read", { path: "secret.txt" });
+    await vi.advanceTimersByTimeAsync(13);
+    logger.onToolEnd("Read", true, "secret-error");
+    await vi.advanceTimersByTimeAsync(0);
+
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(2, "FN-DURATION", "Bash", "tool_result", "secret-output", "executor", { durationMs: 842, timeToFirstTokenMs: undefined });
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(4, "FN-DURATION", "Read", "tool_error", "secret-error", "executor", { durationMs: 13, timeToFirstTokenMs: undefined });
+    const timingPayload = JSON.stringify((store.appendAgentLog as ReturnType<typeof vi.fn>).mock.calls.map((call) => call[6]));
+    expect(timingPayload).not.toContain("secret-output");
+    expect(timingPayload).not.toContain("secret-args");
+  });
+
+  it("matches duplicate same-name tool completions with FIFO durations", async () => {
+    const store = createMockStore();
+    const logger = new AgentLogger({ store, taskId: "FN-DUP-TOOLS", agent: "executor" });
+
+    logger.onToolStart("Bash", { command: "first" });
+    await vi.advanceTimersByTimeAsync(10);
+    logger.onToolStart("Bash", { command: "second" });
+    await vi.advanceTimersByTimeAsync(20);
+    logger.onToolEnd("Bash", false, "first done");
+    await vi.advanceTimersByTimeAsync(5);
+    logger.onToolEnd("Bash", false, "second done");
+    await vi.advanceTimersByTimeAsync(0);
+
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(3, "FN-DUP-TOOLS", "Bash", "tool_result", undefined, "executor", { durationMs: 30, timeToFirstTokenMs: undefined });
+    expect(store.appendAgentLog).toHaveBeenNthCalledWith(4, "FN-DUP-TOOLS", "Bash", "tool_result", undefined, "executor", { durationMs: 25, timeToFirstTokenMs: undefined });
   });
 
   // ── Agent field propagation ──────────────────────────────────────
@@ -272,7 +366,7 @@ describe("AgentLogger", () => {
     // Text flush
     logger.onText("hello world");
     await vi.advanceTimersByTimeAsync(0);
-    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-010", "hello world", "text", undefined, "executor");
+    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-010", "hello world", "text", undefined, "executor", { durationMs: undefined, timeToFirstTokenMs: 0 });
 
     // Tool start
     (store.appendAgentLog as ReturnType<typeof vi.fn>).mockClear();
@@ -316,7 +410,7 @@ describe("AgentLogger", () => {
     expect(store.appendAgentLog).not.toHaveBeenCalled();
 
     await vi.advanceTimersByTimeAsync(500);
-    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-011A", "thought 1 thought 2", "thinking", undefined, "executor");
+    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-011A", "thought 1 thought 2", "thinking", undefined, "executor", { durationMs: undefined, timeToFirstTokenMs: 0 });
   });
 
   it("flushes thinking on size threshold", async () => {
@@ -334,7 +428,7 @@ describe("AgentLogger", () => {
 
     logger.onThinking("enough to flush");
     await vi.advanceTimersByTimeAsync(0);
-    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-012", "shortenough to flush", "thinking", undefined, "triage");
+    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-012", "shortenough to flush", "thinking", undefined, "triage", { durationMs: undefined, timeToFirstTokenMs: 0 });
   });
 
   it("flushes thinking buffer on flush()", async () => {
@@ -349,7 +443,7 @@ describe("AgentLogger", () => {
 
     logger.onThinking("remaining thinking");
     await logger.flush();
-    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-013", "remaining thinking", "thinking", undefined, "reviewer");
+    expect(store.appendAgentLog).toHaveBeenCalledWith("FN-013", "remaining thinking", "thinking", undefined, "reviewer", { durationMs: undefined, timeToFirstTokenMs: 0 });
   });
 
   it("flushes thinking buffer before tool start", async () => {
@@ -368,7 +462,7 @@ describe("AgentLogger", () => {
 
     await vi.advanceTimersByTimeAsync(0);
     const calls = (store.appendAgentLog as ReturnType<typeof vi.fn>).mock.calls;
-    expect(calls[0]).toEqual(["FN-014", "pre-tool thought", "thinking", undefined, "executor"]);
+    expect(calls[0]).toEqual(["FN-014", "pre-tool thought", "thinking", undefined, "executor", { durationMs: undefined, timeToFirstTokenMs: 0 }]);
     expect(calls[1]).toEqual(["FN-014", "Read", "tool", "file.ts", "executor"]);
   });
 

packages/engine/src/agent-logger.ts

@@ -221,8 +221,19 @@ export class AgentLogger {
   private readonly persistAgentToolOutput: boolean;
   private readonly persistAgentThinkingLog: boolean;
   private usageContext?: AgentLoggerUsageContext;
-  /** Tracks tool start times so tool_result/tool_error can record a duration. */
+  /*
-  private readonly toolStartedAt = new Map<string, number>();
+   * FNXC:AgentLogging 2026-07-04-09:40:
+   * Task logs must expose Time To First Token once per logger/request on the first persisted visible model output. Capture the arrival time at onText/onThinking instead of flush time so buffered writes do not inflate TTFT.
+   */
+  private readonly requestStartedAtMs = Date.now();
+  private firstVisibleOutputRecorded = false;
+  private textTimeToFirstTokenMs: number | undefined;
+  private thinkingTimeToFirstTokenMs: number | undefined;
+  /*
+   * FNXC:AgentLogging 2026-07-04-09:41:
+   * Tool completion rows need non-sensitive processing duration for Bash and every other tool. Store only start timestamps in FIFO order per tool name so overlapping same-name calls do not leak arguments/results or collapse into one duration.
+   */
+  private readonly toolStartedAt = new Map<string, number[]>();
 
   constructor(options: AgentLoggerOptions) {
     this.store = options.store;
@@ -300,6 +311,9 @@ export class AgentLogger {
    */
   onText(delta: string): void {
     this.externalTextCb?.(this.taskId, delta);
+    if (delta.length > 0 && !this.firstVisibleOutputRecorded) {
+      this.textTimeToFirstTokenMs = this.markFirstVisibleOutput();
+    }
     this.textBuffer += delta;
     if (this.textBuffer.length >= this.flushSizeBytes) {
       if (this.flushTimer) { clearTimeout(this.flushTimer); this.flushTimer = null; }
@@ -317,6 +331,9 @@ export class AgentLogger {
     if (!this.persistAgentThinkingLog) {
       return;
     }
+    if (delta.length > 0 && !this.firstVisibleOutputRecorded) {
+      this.thinkingTimeToFirstTokenMs = this.markFirstVisibleOutput();
+    }
     this.thinkingBuffer += delta;
     if (this.thinkingBuffer.length >= this.flushSizeBytes) {
       if (this.thinkingFlushTimer) { clearTimeout(this.thinkingFlushTimer); this.thinkingFlushTimer = null; }
@@ -341,7 +358,9 @@ export class AgentLogger {
     this.writeEntry(name, "tool", detail, `Failed to log tool start "${name}" for ${this.taskId}`);
     // agent-log type "tool" maps to usage_events kind "tool_call". meta carries
     // only non-sensitive descriptors (category) — never the tool arguments.
-    this.toolStartedAt.set(name, Date.now());
+    const starts = this.toolStartedAt.get(name) ?? [];
+    starts.push(Date.now());
+    this.toolStartedAt.set(name, starts);
     this.emitToolUsageEvent("tool_call", name);
   }
 
@@ -357,13 +376,13 @@ export class AgentLogger {
   onToolEnd(name: string, isError: boolean, result?: unknown): void {
     const type = isError ? "tool_error" : "tool_result";
     const detail = summarizeToolResultDetail(result);
-    this.writeEntry(name, type, detail, `Failed to log tool end "${name}" (${type}) for ${this.taskId}`);
+    const startedAt = this.shiftToolStart(name);
+    const durationMs = startedAt !== undefined ? Math.max(0, Date.now() - startedAt) : undefined;
+    this.writeEntry(name, type, detail, `Failed to log tool end "${name}" (${type}) for ${this.taskId}`, false, durationMs !== undefined ? { durationMs } : undefined);
     // Record completion as tool_result/tool_error with a duration descriptor.
     // meta NEVER includes the tool result payload — only non-sensitive metrics.
-    const startedAt = this.toolStartedAt.get(name);
-    if (startedAt !== undefined) this.toolStartedAt.delete(name);
     const meta: Record<string, unknown> = {};
-    if (startedAt !== undefined) meta.durationMs = Date.now() - startedAt;
+    if (durationMs !== undefined) meta.durationMs = durationMs;
     if (isError) meta.isError = true;
     this.emitToolUsageEvent(
       isError ? "tool_error" : "tool_result",
@@ -393,7 +412,29 @@ export class AgentLogger {
    * When only `appendLogCb` is set (no store/taskId), only the callback is used.
    * @param storeWarnMsg - Warning message prefix used when the task-store write fails.
    */
-  private writeEntry(text: string, type: AgentLogEntry["type"], detail: string | undefined, _storeWarnMsg: string, immediate = false): void {
+  private markFirstVisibleOutput(): number {
+    this.firstVisibleOutputRecorded = true;
+    return Math.max(0, Date.now() - this.requestStartedAtMs);
+  }
+
+  private shiftToolStart(name: string): number | undefined {
+    const starts = this.toolStartedAt.get(name);
+    if (!starts || starts.length === 0) return undefined;
+    const startedAt = starts.shift();
+    if (starts.length === 0) {
+      this.toolStartedAt.delete(name);
+    }
+    return startedAt;
+  }
+
+  private writeEntry(
+    text: string,
+    type: AgentLogEntry["type"],
+    detail: string | undefined,
+    _storeWarnMsg: string,
+    immediate = false,
+    timing?: Pick<AgentLogEntry, "durationMs" | "timeToFirstTokenMs">,
+  ): void {
     const isToolEntry = type === "tool" || type === "tool_result" || type === "tool_error";
     const includeDetail = !isToolEntry || this.persistAgentToolOutput;
     const entry: AgentLogEntry = {
@@ -403,6 +444,8 @@ export class AgentLogger {
       type,
       ...(detail !== undefined && includeDetail && { detail }),
       ...(this.agent !== undefined && { agent: this.agent }),
+      ...(timing?.durationMs !== undefined && { durationMs: timing.durationMs }),
+      ...(timing?.timeToFirstTokenMs !== undefined && { timeToFirstTokenMs: timing.timeToFirstTokenMs }),
     };
 
     this.pendingEntries.push(entry);
@@ -431,7 +474,16 @@ export class AgentLogger {
     if (this.textBuffer.length === 0) return Promise.resolve();
     const chunk = this.textBuffer;
     this.textBuffer = "";
-    this.writeEntry(chunk, "text", undefined, `Failed to flush text buffer for ${this.taskId}`, true);
+    const timeToFirstTokenMs = this.textTimeToFirstTokenMs;
+    this.textTimeToFirstTokenMs = undefined;
+    this.writeEntry(
+      chunk,
+      "text",
+      undefined,
+      `Failed to flush text buffer for ${this.taskId}`,
+      true,
+      timeToFirstTokenMs !== undefined ? { timeToFirstTokenMs } : undefined,
+    );
     return this.flushPendingEntries();
   }
 
@@ -442,7 +494,16 @@ export class AgentLogger {
     if (!this.persistAgentThinkingLog) {
       return Promise.resolve();
     }
-    this.writeEntry(chunk, "thinking", undefined, `Failed to flush thinking buffer for ${this.taskId}`, true);
+    const timeToFirstTokenMs = this.thinkingTimeToFirstTokenMs;
+    this.thinkingTimeToFirstTokenMs = undefined;
+    this.writeEntry(
+      chunk,
+      "thinking",
+      undefined,
+      `Failed to flush thinking buffer for ${this.taskId}`,
+      true,
+      timeToFirstTokenMs !== undefined ? { timeToFirstTokenMs } : undefined,
+    );
     return this.flushPendingEntries();
   }
 
@@ -488,6 +549,8 @@ export class AgentLogger {
               type: entry.type,
               detail: entry.detail,
               agent: entry.agent,
+              ...(entry.durationMs !== undefined && { durationMs: entry.durationMs }),
+              ...(entry.timeToFirstTokenMs !== undefined && { timeToFirstTokenMs: entry.timeToFirstTokenMs }),
             })),
           )
           .catch((err) => {
@@ -495,11 +558,17 @@ export class AgentLogger {
           });
       } else {
         await Promise.all(
-          entries.map((entry) =>
+          entries.map((entry) => {
-            this.store!.appendAgentLog(entry.taskId, entry.text, entry.type, entry.detail, entry.agent).catch((err) => {
+            const timing = entry.durationMs !== undefined || entry.timeToFirstTokenMs !== undefined
+              ? { durationMs: entry.durationMs, timeToFirstTokenMs: entry.timeToFirstTokenMs }
+              : undefined;
+            const write = timing === undefined
+              ? this.store!.appendAgentLog(entry.taskId, entry.text, entry.type, entry.detail, entry.agent)
+              : this.store!.appendAgentLog(entry.taskId, entry.text, entry.type, entry.detail, entry.agent, timing);
+            return write.catch((err) => {
               this.log.warn(`Failed to flush agent log entry for ${this.taskId}: ${err instanceof Error ? err.message : String(err)}`);
-            }),
+            });
-          ),
+          }),
         );
       }
     }