From 2797803c0b7a7a264242b19d0f7e5169a6b13d8a Mon Sep 17 00:00:00 2001 From: gsxdsm Date: Sat, 4 Jul 2026 10:39:51 -0700 Subject: [PATCH] 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) --- .changeset/fn-7503-agent-log-timing.md | 7 + docs/storage.md | 1 + .../__tests__/agent-log-file-store.test.ts | 35 +++++ .../__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 + .../app/components/AgentLogViewer.css | 33 +++++ .../app/components/AgentLogViewer.tsx | 39 +++++- .../dashboard/app/components/TaskChatTab.css | 23 +++- .../dashboard/app/components/TaskChatTab.tsx | 17 ++- .../AgentLogViewer.rendering.test.tsx | 24 ++++ .../components/__tests__/TaskChatTab.test.tsx | 18 +++ .../engine/src/__tests__/agent-logger.test.ts | 120 ++++++++++++++++-- packages/engine/src/agent-logger.ts | 97 ++++++++++++-- 15 files changed, 446 insertions(+), 32 deletions(-) create mode 100644 .changeset/fn-7503-agent-log-timing.md diff --git a/.changeset/fn-7503-agent-log-timing.md b/.changeset/fn-7503-agent-log-timing.md new file mode 100644 index 0000000000..2b3c5ff780 --- /dev/null +++ b/.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`. diff --git a/docs/storage.md b/docs/storage.md index 6be057213a..6169caf440 100644 --- a/docs/storage.md +++ b/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 `/.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). diff --git a/packages/core/src/__tests__/agent-log-file-store.test.ts b/packages/core/src/__tests__/agent-log-file-store.test.ts index 57fccd4e34..518d5ae9c1 100644 --- a/packages/core/src/__tests__/agent-log-file-store.test.ts +++ b/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( diff --git a/packages/core/src/__tests__/store-agent-log-file.test.ts b/packages/core/src/__tests__/store-agent-log-file.test.ts index 33cc1e97b7..a6f07f1610 100644 --- a/packages/core/src/__tests__/store-agent-log-file.test.ts +++ b/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(); diff --git a/packages/core/src/agent-log-file-store.ts b/packages/core/src/agent-log-file-store.ts index 17fc385539..8ca29e656c 100644 --- a/packages/core/src/agent-log-file-store.ts +++ b/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), }; diff --git a/packages/core/src/store.ts b/packages/core/src/store.ts index bf543ed627..212b81d49d 100644 --- a/packages/core/src/store.ts +++ b/packages/core/src/store.ts @@ -1703,6 +1703,8 @@ export class TaskStore extends EventEmitter { 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 | null = null; @@ -12792,6 +12794,7 @@ ${TASK_UPSERT_SQL_ASSIGNMENTS} type: AgentLogEntry["type"], detail?: string, agent?: AgentLogEntry["agent"], + timing?: Pick, ): Promise { 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 { 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 }), }); } } diff --git a/packages/core/src/types.ts b/packages/core/src/types.ts index 1f4a9f645d..6b5a2a4cf2 100644 --- a/packages/core/src/types.ts +++ b/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. */ diff --git a/packages/dashboard/app/components/AgentLogViewer.css b/packages/dashboard/app/components/AgentLogViewer.css index a14bd70218..8595438c71 100644 --- a/packages/dashboard/app/components/AgentLogViewer.css +++ b/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; + } } diff --git a/packages/dashboard/app/components/AgentLogViewer.tsx b/packages/dashboard/app/components/AgentLogViewer.tsx index bb50d6cbb8..6793d728d0 100644 --- a/packages/dashboard/app/components/AgentLogViewer.tsx +++ b/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, 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 ( + + {labels.map((label) => ( + {label} + ))} + + ); +} + 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 (
{agentBadge} -
⚡ {entry.text}
+
⚡ {entry.text}
{entry.detail ? : null}
); @@ -678,7 +709,7 @@ export function AgentLogViewer({ return (
{agentBadge} -
✓ {entry.text}
+
✓ {entry.text}
{entry.detail ? : null}
); @@ -688,7 +719,7 @@ export function AgentLogViewer({ return (
{agentBadge} -
✗ {entry.text}
+
✗ {entry.text}
{entry.detail ? : null}
); @@ -703,6 +734,7 @@ export function AgentLogViewer({ return (
{agentBadge} + {renderMarkdown ? (
@@ -719,6 +751,7 @@ export function AgentLogViewer({ return (
{agentBadge} + {renderMarkdown ? (
diff --git a/packages/dashboard/app/components/TaskChatTab.css b/packages/dashboard/app/components/TaskChatTab.css index f788f66a51..6b2076ce62 100644 --- a/packages/dashboard/app/components/TaskChatTab.css +++ b/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; } diff --git a/packages/dashboard/app/components/TaskChatTab.tsx b/packages/dashboard/app/components/TaskChatTab.tsx index c706f59a15..dbb931e640 100644 --- a/packages/dashboard/app/components/TaskChatTab.tsx +++ b/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 ( + + {labels.map((label) => ( + {label} + ))} + + ); +} + function TaskChatTimestampMeta({ timestamp, label }: { timestamp: string | undefined; label: string }) { if (!getRelativeTimestamp(timestamp)) return null; return ( @@ -395,6 +408,7 @@ function TaskChatToolEntry({ entry }: { entry: AgentLogEntry }) { >
{formatEntryLabel(entry, t)} +
{entry.text}
@@ -440,6 +454,7 @@ function TaskChatToolInvocation({ row }: { row: Extract
{completionLabel ? t("taskChat.toolCallTo", "Tool call → {{label}}", { label: completionLabel }) : t("taskChat.toolCall", "Tool call")} +
{row.call.text}
diff --git a/packages/dashboard/app/components/__tests__/AgentLogViewer.rendering.test.tsx b/packages/dashboard/app/components/__tests__/AgentLogViewer.rendering.test.tsx index ab74044203..85836819fd 100644 --- a/packages/dashboard/app/components/__tests__/AgentLogViewer.rendering.test.tsx +++ b/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(); + + 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(); + + rerender(); + + 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" }), diff --git a/packages/dashboard/app/components/__tests__/TaskChatTab.test.tsx b/packages/dashboard/app/components/__tests__/TaskChatTab.test.tsx index ba16d833a2..ce41fec122 100644 --- a/packages/dashboard/app/components/__tests__/TaskChatTab.test.tsx +++ b/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(); + + 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" }), diff --git a/packages/engine/src/__tests__/agent-logger.test.ts b/packages/engine/src/__tests__/agent-logger.test.ts index 4f32677abd..0474b77545 100644 --- a/packages/engine/src/__tests__/agent-logger.test.ts +++ b/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)).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).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).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).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).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"]); }); diff --git a/packages/engine/src/agent-logger.ts b/packages/engine/src/agent-logger.ts index 21aa855351..f8b23bbc07 100644 --- a/packages/engine/src/agent-logger.ts +++ b/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(); + /* + * 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(); 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 = {}; - 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, + ): 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) => - this.store!.appendAgentLog(entry.taskId, entry.text, entry.type, entry.detail, entry.agent).catch((err) => { + entries.map((entry) => { + 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)}`); - }), - ), + }); + }), ); } }