From 2ce6d3ef3a25d80932e9de4e209ffa9a0a9880c1 Mon Sep 17 00:00:00 2001 From: Junmo Kim Date: Thu, 16 Jul 2026 13:32:00 +0900 Subject: [PATCH] feat(web): show tool call duration in the detail dialog (#1036) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * refactor(web): export formatDuration for reuse * feat(web): show tool call duration in the detail dialog Show a completed tool's execution duration at the top of its detail dialog. The value is derived from the Claude entry's own timestamps (the execution machine's wall clock) rather than the hub's message-receive time, and is used only when both the tool_use and tool_result entries carry a real timestamp — otherwise it falls back to the hub receive times on both sides, so the two clocks are never mixed. Running/pending tools show nothing, the running-state live timer is unchanged, and clock skew is guarded against. Reuses the existing formatDuration formatter. No schema changes. * fix(web): backfill hub startedAt on reorder so duration isn't 0.0s When a tool_result entry is reduced before its tool_use, the tool block is created from the result, so the hub startedAt is the result receive time. The tool_use path only lowered the exec start, not the hub startedAt, so a timestamp-less pair (no exec duration available) fell back to startedAt === completedAt and the detail dialog showed 0.0s. Lower the hub startedAt to the earlier tool_use receive time as well. --- web/src/chat/agentTimestamp.test.ts | 25 ++++ web/src/chat/agentTimestamp.ts | 14 ++ web/src/chat/normalizeAgent.test.ts | 74 +++++++++++ web/src/chat/normalizeAgent.ts | 19 ++- web/src/chat/presentation.ts | 2 +- web/src/chat/reconcile.ts | 2 + web/src/chat/reducerTimeline.test.ts | 120 +++++++++++++++++ web/src/chat/reducerTimeline.ts | 54 +++++++- web/src/chat/reducerTools.ts | 7 + web/src/chat/toolGroups.test.ts | 14 ++ web/src/chat/types.ts | 20 +++ web/src/components/ToolCard/ToolCard.tsx | 9 ++ .../ToolCard/ToolGroupCard.test.tsx | 2 + .../components/ToolCard/checklist.test.tsx | 2 + .../ToolCard/groupedPresentation.test.ts | 2 + .../ToolCard/toolDetailDuration.test.tsx | 124 ++++++++++++++++++ .../components/ToolCard/toolDuration.test.ts | 123 +++++++++++++++++ web/src/components/ToolCard/toolDuration.ts | 27 ++++ web/src/components/ToolCard/trace.test.tsx | 8 ++ .../ToolCard/views/_results.test.tsx | 8 ++ web/src/lib/assistant-runtime.test.ts | 2 + web/src/lib/locales/en.ts | 1 + web/src/lib/locales/zh-CN.ts | 1 + 23 files changed, 652 insertions(+), 8 deletions(-) create mode 100644 web/src/chat/agentTimestamp.test.ts create mode 100644 web/src/chat/agentTimestamp.ts create mode 100644 web/src/chat/normalizeAgent.test.ts create mode 100644 web/src/components/ToolCard/toolDetailDuration.test.tsx create mode 100644 web/src/components/ToolCard/toolDuration.test.ts create mode 100644 web/src/components/ToolCard/toolDuration.ts diff --git a/web/src/chat/agentTimestamp.test.ts b/web/src/chat/agentTimestamp.test.ts new file mode 100644 index 00000000..5424145b --- /dev/null +++ b/web/src/chat/agentTimestamp.test.ts @@ -0,0 +1,25 @@ +import { describe, expect, it } from 'vitest' +import { parseAgentTimestampMs } from '@/chat/agentTimestamp' + +describe('parseAgentTimestampMs', () => { + it('parses a valid ISO-8601 timestamp to epoch ms', () => { + // Real shape emitted by the Claude CLI's sdkToLogConverter (data.timestamp). + expect(parseAgentTimestampMs('2026-07-13T14:37:57.372Z')).toBe(Date.parse('2026-07-13T14:37:57.372Z')) + }) + + it('returns null when the value is undefined (field absent)', () => { + expect(parseAgentTimestampMs(undefined)).toBeNull() + }) + + it('returns null when the value is not a string', () => { + expect(parseAgentTimestampMs(1783953477372)).toBeNull() + }) + + it('returns null for an unparseable string', () => { + expect(parseAgentTimestampMs('not-a-timestamp')).toBeNull() + }) + + it('returns null for an empty string', () => { + expect(parseAgentTimestampMs('')).toBeNull() + }) +}) diff --git a/web/src/chat/agentTimestamp.ts b/web/src/chat/agentTimestamp.ts new file mode 100644 index 00000000..8d525237 --- /dev/null +++ b/web/src/chat/agentTimestamp.ts @@ -0,0 +1,14 @@ +/** + * Parses the ISO-8601 `timestamp` field emitted by the Claude CLI's + * sdkToLogConverter (e.g. `"2026-07-13T14:37:57.372Z"`) into epoch + * milliseconds. This is the execution-machine wall clock at the moment the + * CLI stamped the SDK message, as opposed to the hub's receive time. + * + * Returns null for missing/non-string/unparseable values so callers can + * fall back to the hub-received `createdAt` instead. + */ +export function parseAgentTimestampMs(value: unknown): number | null { + if (typeof value !== 'string' || value.trim() === '') return null + const ms = Date.parse(value) + return Number.isFinite(ms) ? ms : null +} diff --git a/web/src/chat/normalizeAgent.test.ts b/web/src/chat/normalizeAgent.test.ts new file mode 100644 index 00000000..5251247b --- /dev/null +++ b/web/src/chat/normalizeAgent.test.ts @@ -0,0 +1,74 @@ +import { describe, expect, it } from 'vitest' +import { normalizeAgentRecord } from '@/chat/normalizeAgent' + +describe('normalizeAgentRecord — agentTimestamp exposure', () => { + it('parses data.timestamp into agentTimestamp for an assistant tool_use record', () => { + const normalized = normalizeAgentRecord('msg-1', null, 1_783_953_478_235, { + type: 'output', + data: { + type: 'assistant', + uuid: 'c93919e3', + timestamp: '2026-07-13T14:37:57.372Z', + message: { + role: 'assistant', + content: [{ type: 'tool_use', id: 'toolu_1', name: 'Read', input: { file_path: '/tmp/marker.txt' } }] + } + } + }) + + expect(normalized).toMatchObject({ + role: 'agent', + agentTimestamp: Date.parse('2026-07-13T14:37:57.372Z') + }) + }) + + it('parses data.timestamp into agentTimestamp for a user tool_result record', () => { + const normalized = normalizeAgentRecord('msg-2', null, 1_783_953_478_237, { + type: 'output', + data: { + type: 'user', + uuid: '242b5485', + timestamp: '2026-07-13T14:37:57.379Z', + message: { + role: 'user', + content: [{ type: 'tool_result', tool_use_id: 'toolu_1', content: 'hello' }] + } + } + }) + + expect(normalized).toMatchObject({ + role: 'agent', + agentTimestamp: Date.parse('2026-07-13T14:37:57.379Z') + }) + }) + + it('falls back to null (not the hub createdAt) when data.timestamp is absent', () => { + const normalized = normalizeAgentRecord('msg-3', null, 1_783_953_478_237, { + type: 'output', + data: { + type: 'assistant', + uuid: 'no-ts', + message: { + role: 'assistant', + content: [{ type: 'tool_use', id: 'toolu_2', name: 'Bash', input: { command: 'sleep 2' } }] + } + } + }) + + expect(normalized).toMatchObject({ role: 'agent', agentTimestamp: null }) + }) + + it('returns null when data.timestamp is an unparseable string', () => { + const normalized = normalizeAgentRecord('msg-4', null, 1_783_953_478_237, { + type: 'output', + data: { + type: 'assistant', + uuid: 'bad-ts', + timestamp: 'not-a-timestamp', + message: { role: 'assistant', content: [{ type: 'text', text: 'hi' }] } + } + }) + + expect(normalized).toMatchObject({ role: 'agent', agentTimestamp: null }) + }) +}) diff --git a/web/src/chat/normalizeAgent.ts b/web/src/chat/normalizeAgent.ts index 3f2bf881..1378af90 100644 --- a/web/src/chat/normalizeAgent.ts +++ b/web/src/chat/normalizeAgent.ts @@ -1,6 +1,7 @@ import type { AgentEvent, CodexReview, CodexReviewFinding, NormalizedAgentContent, NormalizedMessage, ToolResultPermission } from '@/chat/types' import { AGENT_MESSAGE_PAYLOAD_TYPE, asNumber, asString, isObject } from '@hapi/protocol' import { isClaudeChatVisibleMessage } from '@hapi/protocol/messages' +import { parseAgentTimestampMs } from '@/chat/agentTimestamp' function normalizeToolResultPermissions(value: unknown): ToolResultPermission | undefined { if (!isObject(value)) return undefined @@ -226,6 +227,7 @@ function normalizeAssistantOutput( const uuid = asString(data.uuid) ?? messageId const parentUUID = asString(data.parentUuid) ?? null const isSidechain = Boolean(data.isSidechain) + const agentTimestamp = parseAgentTimestampMs(data.timestamp) const message = isObject(data.message) ? data.message : null if (!message) return null @@ -269,6 +271,7 @@ function normalizeAssistantOutput( isSidechain, content: blocks, meta, + agentTimestamp, usage: inputTokens !== null && outputTokens !== null ? { input_tokens: inputTokens, output_tokens: outputTokens, @@ -290,6 +293,7 @@ function normalizeUserOutput( const uuid = asString(data.uuid) ?? messageId const parentUUID = asString(data.parentUuid) ?? null const isSidechain = Boolean(data.isSidechain) + const agentTimestamp = parseAgentTimestampMs(data.timestamp) const message = isObject(data.message) ? data.message : null if (!message) return null @@ -303,7 +307,8 @@ function normalizeUserOutput( createdAt, role: 'agent', isSidechain: true, - content: [{ type: 'sidechain', uuid, parentUUID, prompt: messageContent }] + content: [{ type: 'sidechain', uuid, parentUUID, prompt: messageContent }], + agentTimestamp } } @@ -322,7 +327,8 @@ function normalizeUserOutput( createdAt, role: 'agent', isSidechain: true, - content: [{ type: 'sidechain', uuid, parentUUID, prompt: messageContent }] + content: [{ type: 'sidechain', uuid, parentUUID, prompt: messageContent }], + agentTimestamp } } @@ -341,7 +347,8 @@ function normalizeUserOutput( createdAt, role: 'agent', isSidechain: true, - content: [{ type: 'sidechain', uuid, parentUUID, prompt: textParts.join('\n\n') }] + content: [{ type: 'sidechain', uuid, parentUUID, prompt: textParts.join('\n\n') }], + agentTimestamp } } } @@ -362,7 +369,8 @@ function normalizeUserOutput( role: 'user', isSidechain: false, content: { type: 'text', text: textParts.join('\n\n') }, - meta + meta, + agentTimestamp } } } @@ -403,7 +411,8 @@ function normalizeUserOutput( role: 'agent', isSidechain, content: blocks, - meta + meta, + agentTimestamp } } diff --git a/web/src/chat/presentation.ts b/web/src/chat/presentation.ts index 168693dc..c9450f6e 100644 --- a/web/src/chat/presentation.ts +++ b/web/src/chat/presentation.ts @@ -63,7 +63,7 @@ function formatLimitType(limitType: string | undefined): string { return limitType.replace(/_/g, ' ') } -function formatDuration(ms: number): string { +export function formatDuration(ms: number): string { const seconds = ms / 1000 if (seconds < 60) return `${seconds.toFixed(1)}s` const mins = Math.floor(seconds / 60) diff --git a/web/src/chat/reconcile.ts b/web/src/chat/reconcile.ts index e4d9a480..0b48e4f9 100644 --- a/web/src/chat/reconcile.ts +++ b/web/src/chat/reconcile.ts @@ -173,6 +173,8 @@ function areToolCallsEqual(left: ToolCallBlock, right: ToolCallBlock, childrenSa && left.tool.createdAt === right.tool.createdAt && left.tool.startedAt === right.tool.startedAt && left.tool.completedAt === right.tool.completedAt + && left.tool.execStartedAt === right.tool.execStartedAt + && left.tool.execCompletedAt === right.tool.execCompletedAt && arePermissionsEqual(left.tool.permission, right.tool.permission) } diff --git a/web/src/chat/reducerTimeline.test.ts b/web/src/chat/reducerTimeline.test.ts index 20e57835..6687b60b 100644 --- a/web/src/chat/reducerTimeline.test.ts +++ b/web/src/chat/reducerTimeline.test.ts @@ -1,5 +1,6 @@ import { describe, expect, it } from 'vitest' import { reduceTimeline } from './reducerTimeline' +import { toolDurationMs } from '@/components/ToolCard/toolDuration' import type { TracedMessage } from './tracer' function makeContext() { @@ -364,6 +365,125 @@ describe('reduceTimeline', () => { expect(toolBlock.invokedAt).toBe(1_700_000_000_500) }) + describe('exec-timestamp (Claude entry clock) tool duration source', () => { + function toolUse(agentTimestamp?: number): TracedMessage { + return { + id: 'msg-call', + localId: null, + createdAt: 1_700_000_000_000, + role: 'agent', + agentTimestamp, + content: [{ + type: 'tool-call', + id: 'tc-exec', + name: 'Bash', + input: { command: 'sleep 2' }, + description: null, + uuid: 'u-call', + parentUUID: null + }], + isSidechain: false + } as TracedMessage + } + + function toolResult(agentTimestamp?: number): TracedMessage { + return { + id: 'msg-result', + localId: null, + createdAt: 1_700_000_001_800, + role: 'agent', + agentTimestamp, + content: [{ + type: 'tool-result', + tool_use_id: 'tc-exec', + content: 'ok', + is_error: false, + uuid: 'u-result', + parentUUID: null + }], + isSidechain: false + } as TracedMessage + } + + it('records the Claude exec timestamps distinct from the hub receive times', () => { + const { blocks } = reduceTimeline([ + toolUse(1_700_000_000_100), + toolResult(1_700_000_002_100) + ], makeContext()) + const toolBlock = blocks.find(b => b.kind === 'tool-call') as any + // hub receive times (createdAt) differ from the Claude entry stamps + expect(toolBlock.tool.startedAt).toBe(1_700_000_000_000) + expect(toolBlock.tool.completedAt).toBe(1_700_000_001_800) + expect(toolBlock.tool.execStartedAt).toBe(1_700_000_000_100) + expect(toolBlock.tool.execCompletedAt).toBe(1_700_000_002_100) + }) + + it('leaves exec timestamps null when no Claude timestamp is present (non-Claude flavor → hub fallback)', () => { + const { blocks } = reduceTimeline([toolUse(), toolResult()], makeContext()) + const toolBlock = blocks.find(b => b.kind === 'tool-call') as any + expect(toolBlock.tool.execStartedAt).toBeNull() + expect(toolBlock.tool.execCompletedAt).toBeNull() + // hub times still recorded so the legacy duration path works + expect(toolBlock.tool.startedAt).toBe(1_700_000_000_000) + expect(toolBlock.tool.completedAt).toBe(1_700_000_001_800) + }) + + it('never coalesces a missing Claude timestamp to the hub receive time (both-or-neither)', () => { + // tool_use has a real Claude stamp, tool_result does not (e.g. a + // hub-synthesized result). execCompletedAt must stay null so the + // duration helper does not subtract two different clocks. + const { blocks } = reduceTimeline([ + toolUse(1_700_000_000_100), + toolResult() + ], makeContext()) + const toolBlock = blocks.find(b => b.kind === 'tool-call') as any + expect(toolBlock.tool.execStartedAt).toBe(1_700_000_000_100) + expect(toolBlock.tool.execCompletedAt).toBeNull() + }) + + it('backfills execStartedAt when the tool_result entry is reduced before the tool_use', () => { + // Reorder: result first, then the use. execStartedAt must still land + // on the tool_use Claude stamp (earliest), not the result stamp. + const { blocks } = reduceTimeline([ + toolResult(1_700_000_002_100), + toolUse(1_700_000_000_100) + ], makeContext()) + const toolBlock = blocks.find(b => b.kind === 'tool-call') as any + expect(toolBlock.tool.execStartedAt).toBe(1_700_000_000_100) + expect(toolBlock.tool.execCompletedAt).toBe(1_700_000_002_100) + }) + + it('leaves execStartedAt null on reorder when the tool_use entry has no timestamp (both-or-neither → legacy fallback)', () => { + // Case C: result reduced before a tool_use that carries no Claude + // stamp. execStartedAt must NOT be seeded from the result entry — it + // stays null so toolDurationMs falls back to hub times instead of + // collapsing to a bogus zero (execStartedAt === execCompletedAt). + const { blocks } = reduceTimeline([ + toolResult(1_700_000_002_100), + toolUse() + ], makeContext()) + const toolBlock = blocks.find(b => b.kind === 'tool-call') as any + expect(toolBlock.tool.execStartedAt).toBeNull() + expect(toolBlock.tool.execCompletedAt).toBe(1_700_000_002_100) + }) + + it('backfills the hub startedAt on reorder so a timestamp-less pair is not shown as 0.0s', () => { + // Reorder + no Claude timestamps: the block is created from the + // tool_result, so the hub startedAt is the result receive time. + // Without lowering it to the later tool_use's (earlier) receive + // time, both hub ends equal the result time and the duration row + // would read 0.0s instead of the real hub receive window. + const { blocks } = reduceTimeline([ + toolResult(), + toolUse() + ], makeContext()) + const toolBlock = blocks.find(b => b.kind === 'tool-call') as any + expect(toolBlock.tool.startedAt).toBe(1_700_000_000_000) + expect(toolBlock.tool.completedAt).toBe(1_700_000_001_800) + expect(toolDurationMs(toolBlock.tool)).toBe(1_800) + }) + }) + it('populates block.children for Agent tool (same as Task)', () => { // Agent tool_use message with a sidechain group const agentToolMsg: TracedMessage = { diff --git a/web/src/chat/reducerTimeline.ts b/web/src/chat/reducerTimeline.ts index 6b95d193..84c6b095 100644 --- a/web/src/chat/reducerTimeline.ts +++ b/web/src/chat/reducerTimeline.ts @@ -33,6 +33,21 @@ function setEarliestStartedAt(block: ToolCallBlock, startedAt: number | null): v } } +// Mirror of setEarliestStartedAt for the Claude-entry execution-machine start +// timestamp. Only ever fed a real Claude `agentTimestamp` (never the hub +// receive time) so the both-or-neither contract in `toolDurationMs` holds; a +// null argument is a no-op. Takes the earliest so it also backfills correctly +// when the tool_result entry was processed before the tool_use entry. +function setEarliestExecStartedAt(block: ToolCallBlock, execStartedAt: number | null): void { + if (execStartedAt === null) return + const nextExecStartedAt = block.tool.execStartedAt === null + ? execStartedAt + : Math.min(block.tool.execStartedAt, execStartedAt) + if (nextExecStartedAt !== block.tool.execStartedAt) { + block.tool = { ...block.tool, execStartedAt: nextExecStartedAt } + } +} + function getAgentRunCardId(event: Record, fallback: string): string { return getEventString(event, 'cardId') ?? getEventString(event, 'card_id') ?? fallback } @@ -384,6 +399,19 @@ export function reduceTimeline( ? fromBlock.tool.completedAt : Math.max(toBlock.tool.completedAt, fromBlock.tool.completedAt) } + // Keep the exec-timestamp pair merged the same way as startedAt/ + // completedAt so a merged card never carries a stale exec pair (agent-run + // cards currently never carry exec timestamps, but keep the invariant). + if (fromBlock.tool.execStartedAt !== null) { + toBlock.tool.execStartedAt = toBlock.tool.execStartedAt === null + ? fromBlock.tool.execStartedAt + : Math.min(toBlock.tool.execStartedAt, fromBlock.tool.execStartedAt) + } + if (fromBlock.tool.execCompletedAt !== null) { + toBlock.tool.execCompletedAt = toBlock.tool.execCompletedAt === null + ? fromBlock.tool.execCompletedAt + : Math.max(toBlock.tool.execCompletedAt, fromBlock.tool.execCompletedAt) + } toBlock.durationMs = toBlock.durationMs ?? fromBlock.durationMs toBlock.usage = toBlock.usage ?? fromBlock.usage toBlock.model = toBlock.model ?? fromBlock.model @@ -852,12 +880,23 @@ export function reduceTimeline( name: c.name, input: c.input, description: c.description, - permission + permission, + agentTimestamp: msg.agentTimestamp }) if (block.tool.state === 'pending') { - block.tool = { ...block.tool, state: 'running', startedAt: msg.createdAt } + block.tool = { ...block.tool, state: 'running' } } + // Backfill both the hub-clock start and the Claude exec start + // regardless of state (not just the pending→running + // transition), so a tool_result reduced before its tool_use + // still lowers startedAt to the (earlier) tool_use receive + // time. Otherwise both hub ends equal the result time and + // toolDurationMs reads 0.0s. setEarliest* take the min; a + // null exec timestamp is a no-op, leaving exec start unset so + // toolDurationMs falls back to hub times on both sides. + setEarliestStartedAt(block, msg.createdAt) + setEarliestExecStartedAt(block, msg.agentTimestamp ?? null) if (isSubagentToolName(c.name) && !context.consumedGroupIds.has(msg.id)) { const sidechain = context.groups.get(msg.id) ?? null @@ -922,12 +961,23 @@ export function reduceTimeline( input: permissionEntry?.input ?? null, description: null, permission + // NOTE: no agentTimestamp seed here. execStartedAt must + // only ever originate from a tool_use entry; the tool_use + // path backfills it via setEarliestExecStartedAt. Seeding + // it from the result entry would, on a reorder with a + // timestamp-less tool_use, leave execStartedAt === + // execCompletedAt (the result stamp) → a bogus 0 duration + // instead of the correct hub-time fallback. }) block.tool = { ...block.tool, result: c.content, completedAt: msg.createdAt, + // Only a real Claude timestamp — never the hub receive + // time — so toolDurationMs never subtracts two clocks. + // Null here leaves the tool on the hub-time fallback. + execCompletedAt: msg.agentTimestamp ?? null, state: c.is_error ? 'error' : 'completed' } continue diff --git a/web/src/chat/reducerTools.ts b/web/src/chat/reducerTools.ts index 132017ed..d87009a8 100644 --- a/web/src/chat/reducerTools.ts +++ b/web/src/chat/reducerTools.ts @@ -66,6 +66,8 @@ export function ensureToolBlock( input: unknown description: string | null permission?: ToolPermission + /** Claude entry execution-machine timestamp for the tool_use, if known (see `ChatToolCall.execStartedAt`). */ + agentTimestamp?: number | null } ): ToolCallBlock { const existing = toolBlocksById.get(id) @@ -131,6 +133,11 @@ export function ensureToolBlock( createdAt: seed.createdAt, startedAt: initialState === 'running' ? seed.createdAt : null, completedAt: null, + // Exec start is only ever a real Claude entry timestamp (never the hub + // receive time). Null keeps the tool on the hub-time fallback in + // toolDurationMs; the tool_use path backfills the real value. + execStartedAt: initialState === 'running' ? (seed.agentTimestamp ?? null) : null, + execCompletedAt: null, description: seed.description, permission: seed.permission } diff --git a/web/src/chat/toolGroups.test.ts b/web/src/chat/toolGroups.test.ts index 4e151d8b..b3279193 100644 --- a/web/src/chat/toolGroups.test.ts +++ b/web/src/chat/toolGroups.test.ts @@ -22,6 +22,8 @@ function makeToolBlock( createdAt: 1, startedAt: 1, completedAt: 2, + execStartedAt: null, + execCompletedAt: null, description: null, result: null, permission: undefined, @@ -65,6 +67,8 @@ describe('isEligibleForToolGrouping', () => { createdAt: 1, startedAt: null, completedAt: null, + execStartedAt: null, + execCompletedAt: null, description: null, permission: { id: 'perm-1', @@ -84,6 +88,8 @@ describe('isEligibleForToolGrouping', () => { createdAt: 1, startedAt: 1, completedAt: 2, + execStartedAt: null, + execCompletedAt: null, description: null, permission: { id: 'approved-1', @@ -101,6 +107,8 @@ describe('isEligibleForToolGrouping', () => { createdAt: 1, startedAt: 1, completedAt: 2, + execStartedAt: null, + execCompletedAt: null, description: null, permission: { id: 'denied-1', @@ -121,6 +129,8 @@ describe('isEligibleForToolGrouping', () => { createdAt: 1, startedAt: 1, completedAt: 2, + execStartedAt: null, + execCompletedAt: null, description: null, permission: { id: 'codex-perm-1', @@ -202,6 +212,8 @@ describe('buildVisibleChatBlocks', () => { createdAt: 1, startedAt: 1, completedAt: 2, + execStartedAt: null, + execCompletedAt: null, description: null, result: 'Approved', permission: { @@ -276,6 +288,8 @@ describe('buildVisibleChatBlocks', () => { createdAt: 1, startedAt: 1, completedAt: 2, + execStartedAt: null, + execCompletedAt: null, description: null, result: 'Approved', permission: { diff --git a/web/src/chat/types.ts b/web/src/chat/types.ts index f42d0540..5dc934d7 100644 --- a/web/src/chat/types.ts +++ b/web/src/chat/types.ts @@ -129,6 +129,14 @@ export type NormalizedMessage = ({ originalText?: string invokedAt?: number | null model?: string | null + /** + * Execution-machine wall clock (epoch ms) parsed from the Claude entry's + * own `timestamp` field (see `parseAgentTimestampMs`), as opposed to + * `createdAt` which is when the hub received the message. Null when the + * source entry has no parseable timestamp (e.g. non-Claude agent + * flavors) — consumers should fall back to `createdAt` in that case. + */ + agentTimestamp?: number | null } export type ToolPermission = { @@ -152,6 +160,18 @@ export type ChatToolCall = { createdAt: number startedAt: number | null completedAt: number | null + /** + * Execution-machine timestamps (from `NormalizedMessage.agentTimestamp`) + * for the tool_use/tool_result entries, when available. Kept separate + * from `startedAt`/`completedAt` (rather than replacing them) because the + * running-state live timer (`ElapsedView`) reads `startedAt` directly — + * swapping that to the execution machine's clock would expose it to + * viewer/execution-machine clock skew. `toolDurationMs` prefers these + * fields for *completed* tool duration only; null when the source Claude + * entry had no parseable timestamp (e.g. non-Claude agent flavors). + */ + execStartedAt: number | null + execCompletedAt: number | null description: string | null result?: unknown permission?: ToolPermission diff --git a/web/src/components/ToolCard/ToolCard.tsx b/web/src/components/ToolCard/ToolCard.tsx index eb4bb1f1..f3a2eeb6 100644 --- a/web/src/components/ToolCard/ToolCard.tsx +++ b/web/src/components/ToolCard/ToolCard.tsx @@ -16,6 +16,8 @@ import { getToolPresentation } from '@/components/ToolCard/knownTools' import { getToolFullViewComponent, getToolViewComponent } from '@/components/ToolCard/views/_all' import { getToolResultViewComponent } from '@/components/ToolCard/views/_results' import { formatTaskChildLabel, TaskStateIcon } from '@/components/ToolCard/helpers' +import { toolDurationMs } from '@/components/ToolCard/toolDuration' +import { formatDuration } from '@/chat/presentation' import type { TerminalToolDisplayMode } from '@/hooks/useTerminalToolDisplayMode' import { usePointerFocusRing } from '@/hooks/usePointerFocusRing' import { getInputStringAny, truncate } from '@/lib/toolInputUtils' @@ -222,9 +224,16 @@ export function ToolDetailDialogContent(props: { const isQuestionToolWithAnswers = isQuestionTool && permission?.answers && Object.keys(permission.answers).length > 0 + const durationMs = toolDurationMs(props.block.tool) return (
+ {durationMs != null ? ( +
+ {t('tool.duration')} + {formatDuration(durationMs)} +
+ ) : null}
{isQuestionToolWithAnswers ? t('tool.questionsAnswers') : t('tool.input')} diff --git a/web/src/components/ToolCard/ToolGroupCard.test.tsx b/web/src/components/ToolCard/ToolGroupCard.test.tsx index 11d5c4cf..df3e66e6 100644 --- a/web/src/components/ToolCard/ToolGroupCard.test.tsx +++ b/web/src/components/ToolCard/ToolGroupCard.test.tsx @@ -22,6 +22,8 @@ function makeToolBlock(id: string, name: string, input: unknown = {}): ToolCallB createdAt: 1, startedAt: 1, completedAt: 2, + execStartedAt: null, + execCompletedAt: null, description: null, result: { content: 'done' }, permission: undefined, diff --git a/web/src/components/ToolCard/checklist.test.tsx b/web/src/components/ToolCard/checklist.test.tsx index 73898ba8..0a0a9d83 100644 --- a/web/src/components/ToolCard/checklist.test.tsx +++ b/web/src/components/ToolCard/checklist.test.tsx @@ -20,6 +20,8 @@ function makeUpdatePlanBlock(input: unknown, result?: unknown): ToolCallBlock { createdAt: 0, startedAt: 0, completedAt: 0, + execStartedAt: null, + execCompletedAt: null, description: null, result }, diff --git a/web/src/components/ToolCard/groupedPresentation.test.ts b/web/src/components/ToolCard/groupedPresentation.test.ts index c2572585..6301d07f 100644 --- a/web/src/components/ToolCard/groupedPresentation.test.ts +++ b/web/src/components/ToolCard/groupedPresentation.test.ts @@ -32,6 +32,8 @@ function makeTool(id: string, name: string, input: unknown = {}): ToolCallBlock createdAt: 1, startedAt: 1, completedAt: 2, + execStartedAt: null, + execCompletedAt: null, description: null, result: null, permission: undefined, diff --git a/web/src/components/ToolCard/toolDetailDuration.test.tsx b/web/src/components/ToolCard/toolDetailDuration.test.tsx new file mode 100644 index 00000000..37413097 --- /dev/null +++ b/web/src/components/ToolCard/toolDetailDuration.test.tsx @@ -0,0 +1,124 @@ +import { describe, expect, it } from 'vitest' +import { render, screen } from '@testing-library/react' +import type { ReactElement } from 'react' +import type { ChatToolCall, ToolCallBlock } from '@/chat/types' +import { ToolDetailDialogContent } from '@/components/ToolCard/ToolCard' +import { I18nProvider } from '@/lib/i18n-context' + +function renderWithI18n(ui: ReactElement) { + return render({ui}) +} + +function makeBlock(tool: Partial): ToolCallBlock { + return { + kind: 'tool-call', + id: 'tool-1', + localId: null, + createdAt: 0, + tool: { + id: 'tool-1', + name: 'Bash', + state: 'completed', + input: { command: 'ls' }, + createdAt: 0, + startedAt: 0, + completedAt: 0, + execStartedAt: null, + execCompletedAt: null, + description: null, + result: 'ok', + ...tool, + }, + children: [], + } +} + +describe('ToolDetailDialogContent — duration row', () => { + it('shows a Duration row for a completed tool', () => { + renderWithI18n() + expect(screen.getByText('Duration')).toBeTruthy() + expect(screen.getByText('2.5s')).toBeTruthy() + }) + + it('shows a Duration row for an error tool that completed', () => { + renderWithI18n() + expect(screen.getByText('Duration')).toBeTruthy() + expect(screen.getByText('0.8s')).toBeTruthy() + }) + + it('does not show a Duration row while running (no completedAt)', () => { + renderWithI18n() + expect(screen.queryByText('Duration')).toBeNull() + }) + + it('does not show a Duration row on clock skew (completedAt precedes startedAt)', () => { + renderWithI18n() + expect(screen.queryByText('Duration')).toBeNull() + }) + + it('does not show a Duration row while pending (no startedAt, no completedAt)', () => { + renderWithI18n() + expect(screen.queryByText('Duration')).toBeNull() + }) + + it('coexists with the Trace section summary on a completed Task tool call', () => { + // Task/CodexAgent tool calls render their own Trace section summary + // (children count/tokens/duration, self-reported by the tool result) in + // the same dialog. This guards against the two duration sources + // (hub wall-clock vs. tool-self-reported) silently clashing or crashing + // when both are present. + const child = makeBlock({ id: 'child-1', name: 'Read', state: 'completed' }) + const block: ToolCallBlock = { + kind: 'tool-call', + id: 'task-1', + localId: null, + createdAt: 0, + children: [child], + tool: { + id: 'task-1', + name: 'Task', + state: 'completed', + input: { subagent_type: 'Explore' }, + createdAt: 0, + startedAt: 1000, + completedAt: 3500, + execStartedAt: null, + execCompletedAt: null, + description: null, + result: { totalDurationMs: 2400, totalTokens: 1000, totalToolUseCount: 1 }, + }, + } + + renderWithI18n() + + expect(screen.getByText('Duration')).toBeTruthy() + expect(screen.getByText('2.5s')).toBeTruthy() + expect(screen.getByText('Trace')).toBeTruthy() + }) + + it('prefers the claude execution-machine timestamps over hub receive time when both are present', () => { + // Hub receipt shows an inflated 2.5s window (hub queue/transport + // overhead); the claude entries themselves show the true 2.0s. + renderWithI18n() + expect(screen.getByText('Duration')).toBeTruthy() + expect(screen.getByText('2.0s')).toBeTruthy() + }) + + it('falls back to the hub receive time when exec timestamps are absent (non-Claude agent, no regression)', () => { + renderWithI18n() + expect(screen.getByText('Duration')).toBeTruthy() + expect(screen.getByText('2.5s')).toBeTruthy() + }) +}) diff --git a/web/src/components/ToolCard/toolDuration.test.ts b/web/src/components/ToolCard/toolDuration.test.ts new file mode 100644 index 00000000..19c92918 --- /dev/null +++ b/web/src/components/ToolCard/toolDuration.test.ts @@ -0,0 +1,123 @@ +import { describe, expect, it } from 'vitest' +import type { ChatToolCall } from '@/chat/types' +import { toolDurationMs } from '@/components/ToolCard/toolDuration' + +function makeTool(overrides: Partial): ChatToolCall { + return { + id: 'tool-1', + name: 'Bash', + state: 'completed', + input: {}, + createdAt: 0, + startedAt: 0, + completedAt: 0, + execStartedAt: null, + execCompletedAt: null, + description: null, + ...overrides, + } +} + +describe('toolDurationMs', () => { + it('returns completedAt - startedAt for a completed tool', () => { + const tool = makeTool({ state: 'completed', startedAt: 100, completedAt: 2600 }) + expect(toolDurationMs(tool)).toBe(2500) + }) + + it('returns a duration for an error tool that has completedAt', () => { + const tool = makeTool({ state: 'error', startedAt: 100, completedAt: 900 }) + expect(toolDurationMs(tool)).toBe(800) + }) + + it('falls back to createdAt when startedAt is null', () => { + const tool = makeTool({ state: 'completed', startedAt: null, createdAt: 100, completedAt: 2600 }) + expect(toolDurationMs(tool)).toBe(2500) + }) + + it('returns null while running (completedAt is null)', () => { + const tool = makeTool({ state: 'running', startedAt: 100, completedAt: null }) + expect(toolDurationMs(tool)).toBeNull() + }) + + it('returns null while pending (no startedAt, no completedAt)', () => { + const tool = makeTool({ state: 'pending', startedAt: null, completedAt: null }) + expect(toolDurationMs(tool)).toBeNull() + }) + + it('returns null when completedAt precedes startedAt (clock skew, no negative)', () => { + const tool = makeTool({ state: 'completed', startedAt: 2600, completedAt: 100 }) + expect(toolDurationMs(tool)).toBeNull() + }) + + it('returns 0 for an instantaneous tool (completedAt equals startedAt)', () => { + const tool = makeTool({ state: 'completed', startedAt: 500, completedAt: 500 }) + expect(toolDurationMs(tool)).toBe(0) + }) + + describe('exec-timestamp (claude entry-side) preference', () => { + it('prefers execStartedAt/execCompletedAt over the hub-received startedAt/completedAt', () => { + // hub receipt shows an inflated 2.5s window, but the claude entries + // themselves (execStartedAt/execCompletedAt) show the true 2.0s. + const tool = makeTool({ + state: 'completed', + startedAt: 100, + completedAt: 2600, + execStartedAt: 200, + execCompletedAt: 2200, + }) + expect(toolDurationMs(tool)).toBe(2000) + }) + + it('falls back to startedAt/completedAt when exec fields are null (non-Claude agent, no regression)', () => { + const tool = makeTool({ + state: 'completed', + startedAt: 100, + completedAt: 2600, + execStartedAt: null, + execCompletedAt: null, + }) + expect(toolDurationMs(tool)).toBe(2500) + }) + + it('uses hub times on BOTH sides when only execStartedAt is present (no mixed-clock subtraction)', () => { + // Real Claude exec start but a hub-synthesized completion (e.g. a + // denied/timed-out tool). Mixing 2200 - 200 would fabricate 2000; + // both-or-neither falls back to the hub pair (2600 - 100 = 2500). + const tool = makeTool({ + state: 'completed', + startedAt: 100, + completedAt: 2600, + execStartedAt: 200, + execCompletedAt: null, + }) + expect(toolDurationMs(tool)).toBe(2500) + }) + + it('uses hub times on BOTH sides when only execCompletedAt is present', () => { + const tool = makeTool({ + state: 'completed', + startedAt: 100, + completedAt: 2600, + execStartedAt: null, + execCompletedAt: 2200, + }) + expect(toolDurationMs(tool)).toBe(2500) + }) + + it('returns null when execCompletedAt precedes execStartedAt (clock skew, no negative)', () => { + const tool = makeTool({ + state: 'completed', + startedAt: 100, + completedAt: 2600, + execStartedAt: 2200, + execCompletedAt: 200, + }) + expect(toolDurationMs(tool)).toBeNull() + }) + + it('returns null while running even if execStartedAt is set (no execCompletedAt yet)', () => { + const tool = makeTool({ state: 'running', startedAt: 100, execStartedAt: 200, completedAt: null, execCompletedAt: null }) + expect(toolDurationMs(tool)).toBeNull() + }) + }) +}) diff --git a/web/src/components/ToolCard/toolDuration.ts b/web/src/components/ToolCard/toolDuration.ts new file mode 100644 index 00000000..699630c1 --- /dev/null +++ b/web/src/components/ToolCard/toolDuration.ts @@ -0,0 +1,27 @@ +import type { ChatToolCall } from '@/chat/types' + +/** + * Wall-clock duration of a tool call in milliseconds, or null when it cannot be + * derived. Uses the Claude entry's own execution-machine timestamps + * (`execStartedAt`/`execCompletedAt`) — which reflect the true tool execution + * time without the hub receive/queue overhead — but only when *both* are + * present. This both-or-neither rule is deliberate: mixing one real Claude + * timestamp with one hub-received time subtracts two different clocks and + * silently yields a wrong duration (positive skew inflates it; only negative + * skew is caught by the guard below). When either exec timestamp is missing + * (e.g. a hub-synthesized tool_result for a denied/timed-out/cancelled tool, a + * malformed entry, or a non-Claude agent flavor), we fall back to the hub + * receive times on *both* sides so the subtraction stays clock-consistent. + * Returns null for pending/running tools (no completed end) and guards against + * clock skew where the end precedes the start. + */ +export function toolDurationMs(tool: ChatToolCall): number | null { + const useExec = tool.execStartedAt != null && tool.execCompletedAt != null + const end = useExec ? tool.execCompletedAt : tool.completedAt + if (end == null) return null + const start = useExec ? tool.execStartedAt : (tool.startedAt ?? tool.createdAt) + if (start == null) return null + const duration = end - start + if (duration < 0) return null + return duration +} diff --git a/web/src/components/ToolCard/trace.test.tsx b/web/src/components/ToolCard/trace.test.tsx index 8edf6820..a07bc86c 100644 --- a/web/src/components/ToolCard/trace.test.tsx +++ b/web/src/components/ToolCard/trace.test.tsx @@ -63,6 +63,8 @@ function makeChild( createdAt: 1000, startedAt: 1000, completedAt: 2000, + execStartedAt: null, + execCompletedAt: null, description: null, result: null, }, @@ -88,6 +90,8 @@ function makeTaskBlock( createdAt: 1000, startedAt: 1000, completedAt: 2000, + execStartedAt: null, + execCompletedAt: null, description: null, result, }, @@ -113,6 +117,8 @@ function makeCodexAgentBlock( createdAt: 1000, startedAt: 1000, completedAt: 2000, + execStartedAt: null, + execCompletedAt: null, description: null, result, }, @@ -138,6 +144,8 @@ function makeAgentBlock( createdAt: 1000, startedAt: 1000, completedAt: 2000, + execStartedAt: null, + execCompletedAt: null, description: null, result, }, diff --git a/web/src/components/ToolCard/views/_results.test.tsx b/web/src/components/ToolCard/views/_results.test.tsx index 37065349..f1add622 100644 --- a/web/src/components/ToolCard/views/_results.test.tsx +++ b/web/src/components/ToolCard/views/_results.test.tsx @@ -181,6 +181,8 @@ describe('dialog result formatting', () => { createdAt: 0, startedAt: null, completedAt: 0, + execStartedAt: null, + execCompletedAt: null, description: null } } @@ -238,6 +240,8 @@ describe('Codex agent result formatting', () => { createdAt: 0, startedAt: null, completedAt: 0, + execStartedAt: null, + execCompletedAt: null, description: null } } @@ -332,6 +336,8 @@ describe('Codex agent result formatting', () => { createdAt: 0, startedAt: 0, completedAt: null, + execStartedAt: null, + execCompletedAt: null, description: null } } @@ -365,6 +371,8 @@ describe('read file result formatting', () => { createdAt: 0, startedAt: null, completedAt: 0, + execStartedAt: null, + execCompletedAt: null, description: null } } diff --git a/web/src/lib/assistant-runtime.test.ts b/web/src/lib/assistant-runtime.test.ts index ef97f0bc..f30f065a 100644 --- a/web/src/lib/assistant-runtime.test.ts +++ b/web/src/lib/assistant-runtime.test.ts @@ -48,6 +48,8 @@ function toolCall(id: string, overrides: Partial = {}): ToolCallB createdAt: 0, startedAt: null, completedAt: null, + execStartedAt: null, + execCompletedAt: null, description: null }, children: [], diff --git a/web/src/lib/locales/en.ts b/web/src/lib/locales/en.ts index 6e24f108..3b7c30a0 100644 --- a/web/src/lib/locales/en.ts +++ b/web/src/lib/locales/en.ts @@ -380,6 +380,7 @@ export default { 'tool.trace': 'Trace', 'tool.trace.callsSuffix': 'calls', 'tool.result': 'Result', + 'tool.duration': 'Duration', 'tool.semanticTitle.readFile': 'Read file', 'tool.semanticTitle.runShell': 'Run shell', 'tool.semanticTitle.search': 'Search', diff --git a/web/src/lib/locales/zh-CN.ts b/web/src/lib/locales/zh-CN.ts index 0fe0ad31..ef1cb15f 100644 --- a/web/src/lib/locales/zh-CN.ts +++ b/web/src/lib/locales/zh-CN.ts @@ -384,6 +384,7 @@ export default { 'tool.trace': '追踪', 'tool.trace.callsSuffix': '次调用', 'tool.result': '结果', + 'tool.duration': '耗时', 'tool.semanticTitle.readFile': '读取文件', 'tool.semanticTitle.runShell': '运行命令', 'tool.semanticTitle.search': '搜索',