From 011931e281cacc126fc7645bce3e4e3ef0d7c08d Mon Sep 17 00:00:00 2001 From: Lia Date: Mon, 28 Sep 2026 16:19:44 +0000 Subject: [PATCH 1/8] =?UTF-8?q?=F0=9F=95=98=20feat:=20Distinguish=20Tool?= =?UTF-8?q?=20Preparation=20From=20Tool=20Call=20Time?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../agents/__tests__/callbacks.spec.js | 46 ++++++++ api/server/controllers/agents/callbacks.js | 11 ++ .../components/Chat/Messages/Content/Part.tsx | 4 + .../Chat/Messages/Content/ProgressText.tsx | 64 ++++++++--- .../Chat/Messages/Content/ToolCall.tsx | 29 ++++- .../Content/__tests__/ProgressText.test.tsx | 36 +++--- .../Content/__tests__/ToolCall.test.tsx | 15 +++ .../SSE/__tests__/useStepHandler.spec.ts | 45 ++++++++ client/src/hooks/SSE/useStepHandler.ts | 107 +++++++++++++++++- client/src/locales/en/translation.json | 5 + packages/api/src/agents/index.ts | 1 + packages/api/src/agents/toolTiming.spec.ts | 81 +++++++++++++ packages/api/src/agents/toolTiming.ts | 58 ++++++++++ packages/data-provider/src/index.ts | 1 + packages/data-provider/src/toolTiming.spec.ts | 31 +++++ packages/data-provider/src/toolTiming.ts | 29 +++++ packages/data-provider/src/types/agents.ts | 9 ++ packages/data-provider/src/types/content.ts | 8 ++ packages/data-provider/src/types/runs.ts | 2 + 19 files changed, 544 insertions(+), 38 deletions(-) create mode 100644 packages/api/src/agents/toolTiming.spec.ts create mode 100644 packages/api/src/agents/toolTiming.ts create mode 100644 packages/data-provider/src/toolTiming.spec.ts create mode 100644 packages/data-provider/src/toolTiming.ts diff --git a/api/server/controllers/agents/__tests__/callbacks.spec.js b/api/server/controllers/agents/__tests__/callbacks.spec.js index 318adaf8bc8..75be9ceda00 100644 --- a/api/server/controllers/agents/__tests__/callbacks.spec.js +++ b/api/server/controllers/agents/__tests__/callbacks.spec.js @@ -25,6 +25,7 @@ jest.mock('@librechat/api', () => ({ isCodeArtifactToolOutput: jest.requireActual('@librechat/api').isCodeArtifactToolOutput, isCodeSessionToolName: jest.requireActual('@librechat/api').isCodeSessionToolName, collectToolCallIds: jest.requireActual('@librechat/api').collectToolCallIds, + createToolTimingTracker: jest.requireActual('@librechat/api').createToolTimingTracker, })); jest.mock('@librechat/data-schemas', () => ({ @@ -1308,6 +1309,51 @@ describe('createToolEndCallback', () => { }); }); +describe('tool dispatch timing', () => { + it('forwards the SDK handoff and stores preparation and result intervals independently', async () => { + const { GraphEvents, createContentAggregator } = jest.requireActual('@librechat/agents'); + const { GenerationJobManager } = require('@librechat/api'); + const { getDefaultHandlers } = require('../callbacks'); + const { contentParts, stepMap, aggregateContent } = createContentAggregator(); + const handlers = getDefaultHandlers({ + res: { write: jest.fn() }, contentParts, stepMap, aggregateContent, + toolEndCallback: jest.fn(), collectedUsage: [], streamId: 'run', + }); + const step = { + id: 'step-1', index: 0, type: 'tool_calls', + stepDetails: { type: 'tool_calls', tool_calls: [{ id: 'call-1', name: 'query', args: '{}' }] }, + }; + await handlers[GraphEvents.ON_RUN_STEP].handle(GraphEvents.ON_RUN_STEP, step); + await handlers[GraphEvents.ON_RUN_STEP_DELTA].handle(GraphEvents.ON_RUN_STEP_DELTA, { + id: 'step-1', observed_at: 1_000, + delta: { type: 'tool_calls', tool_calls: [{ id: 'call-1', index: 0, args: '{' }] }, + }); + const dispatched = { dispatched_at: 248_000, toolCalls: [ + { id: 'call-1', name: 'query', stepId: 'step-1' }, + ] }; + await handlers[StepEvents.ON_TOOL_CALLS_DISPATCHED].handle( + StepEvents.ON_TOOL_CALLS_DISPATCHED, dispatched, + ); + await handlers[GraphEvents.ON_RUN_STEP_COMPLETED].handle(GraphEvents.ON_RUN_STEP_COMPLETED, { + result: { id: 'step-1', completed_at: 248_340, index: 0, + tool_call: { id: 'call-1', name: 'query', args: '{}', output: 'ok' }, + }, + }); + await handlers[GraphEvents.ON_RUN_STEP_CLOSED].handle(GraphEvents.ON_RUN_STEP_CLOSED, { + id: 'step-1', index: 0, type: 'tool_calls', status: 'completed', + created_at: 1_000, closed_at: 248_340, + }); + expect(GenerationJobManager.emitChunk).toHaveBeenCalledWith( + 'run', { event: StepEvents.ON_TOOL_CALLS_DISPATCHED, data: dispatched }, expect.anything(), + ); + expect(contentParts[0].tool_call).toMatchObject({ + runStepDurationMs: 247_340, + toolPreparationDurationMs: 247_000, + toolExecutionDurationMs: 340, + }); + }); +}); + describe('tool input validation marker', () => { it('marks the streamed result and persisted content part out of band', async () => { const { GraphEvents, createContentAggregator } = jest.requireActual('@librechat/agents'); diff --git a/api/server/controllers/agents/callbacks.js b/api/server/controllers/agents/callbacks.js index a42afb36257..b9b2b6e79e6 100644 --- a/api/server/controllers/agents/callbacks.js +++ b/api/server/controllers/agents/callbacks.js @@ -33,6 +33,7 @@ const { getToolInputValidationDetails, captureSubagentIdentity, collectToolCallIds, + createToolTimingTracker, } = require('@librechat/api'); const { processFileCitations } = require('~/server/services/Files/Citations'); const { processCodeOutput, runPreviewFinalize } = require('~/server/services/Files/Code/process'); @@ -513,7 +514,14 @@ function getDefaultHandlers({ } return emitForJob({ event: UsageEvents.ON_TOKEN_USAGE, data: payload }); }; + const toolTiming = createToolTimingTracker(); const handlers = { + [StepEvents.ON_TOOL_CALLS_DISPATCHED]: { + handle: async (event, data) => { + toolTiming.dispatched(data); + await emitForJob({ event, data }); + }, + }, [GraphEvents.CHAT_MODEL_END]: new ModelEndHandler( collectedUsage, collectedThoughtSignatures, @@ -594,6 +602,7 @@ function getDefaultHandlers({ const index = stepMap?.get(stepId)?.index; const part = typeof index === 'number' ? contentParts[index] : undefined; if (part?.type === ContentTypes.TOOL_CALL && part.tool_call) { + Object.assign(part.tool_call, toolTiming.take(part.tool_call.id, stepId)); part.tool_call.runStepStatus = data.status; /** * The raw derivable duration, left unset rather than zeroed when @@ -619,6 +628,7 @@ function getDefaultHandlers({ * @param {GraphRunnableConfig['configurable']} [metadata] The runnable metadata. */ handle: async (event, data, metadata) => { + toolTiming.observe(data); aggregateContent({ event, data }); if (data?.delta.type === StepTypes.TOOL_CALLS) { await emitForJob({ event, data }); @@ -655,6 +665,7 @@ function getDefaultHandlers({ agentId: metadata?.agent_id, }); } + toolTiming.completed(toolCallId, data?.result?.completed_at); aggregateContent({ event, data }); const stepId = data?.result?.id; const runStep = stepMap?.get(stepId); diff --git a/client/src/components/Chat/Messages/Content/Part.tsx b/client/src/components/Chat/Messages/Content/Part.tsx index 480f81b3406..775cc1efdb8 100644 --- a/client/src/components/Chat/Messages/Content/Part.tsx +++ b/client/src/components/Chat/Messages/Content/Part.tsx @@ -466,6 +466,10 @@ const Part = memo(function Part({ toolCall.backgroundTask?.cancelled === true ? 'cancelled' : toolCall.runStepStatus } runStepDurationMs={toolCall.runStepDurationMs} + toolPreparationStartedAt={toolCall.toolPreparationStartedAt} + toolDispatchedAt={toolCall.toolDispatchedAt} + toolPreparationDurationMs={toolCall.toolPreparationDurationMs} + toolExecutionDurationMs={toolCall.toolExecutionDurationMs} /> ); })(); diff --git a/client/src/components/Chat/Messages/Content/ProgressText.tsx b/client/src/components/Chat/Messages/Content/ProgressText.tsx index fba3dcc3ccc..af3d4e9c66a 100644 --- a/client/src/components/Chat/Messages/Content/ProgressText.tsx +++ b/client/src/components/Chat/Messages/Content/ProgressText.tsx @@ -8,6 +8,7 @@ import type { ToolCallPhase } from '~/utils/toolCallPhase'; import { cn, getRunStepDurationLabels } from '~/utils'; import CancelledIcon from './CancelledIcon'; import { useFailedReveal } from './reveal'; +import { ElapsedTimer } from '../Elapsed'; import { ROW_GLYPH_SLOT } from './rows'; import { useLocalize } from '~/hooks'; @@ -69,6 +70,9 @@ export default function ProgressText({ icon: iconProp, subtitle, durationMs, + toolPreparationDurationMs, + toolExecutionDurationMs, + phaseStartAt, hasInput = true, popover = false, isExpanded = false, @@ -89,8 +93,11 @@ export default function ProgressText({ authText?: string; icon?: React.ReactNode; subtitle?: string; - /** Wall-clock duration of the run step, from `PartMetadata.runStepDurationMs`. */ + /** Total run-step lifetime, not necessarily tool execution. */ durationMs?: number; + toolPreparationDurationMs?: number; + toolExecutionDurationMs?: number; + phaseStartAt?: number; hasInput?: boolean; popover?: boolean; isExpanded?: boolean; @@ -139,10 +146,36 @@ export default function ProgressText({ * failed card "how long it took" is not the fact the reader needs — that * slot already carries the cancelled icon or the failure suffix. */ - const duration = - phase === 'completed' && isReportableRunStepDuration(durationMs) - ? getRunStepDurationLabels(durationMs, i18n.language) - : undefined; + const measured = toolPreparationDurationMs != null || toolExecutionDurationMs != null; + const durationParts = + phase !== 'completed' + ? [] + : [ + ...(isReportableRunStepDuration(toolPreparationDurationMs) + ? [ + { + label: localize('com_ui_tool_preparation_time'), + duration: getRunStepDurationLabels(toolPreparationDurationMs, i18n.language), + }, + ] + : []), + ...(isReportableRunStepDuration(toolExecutionDurationMs) + ? [ + { + label: localize('com_ui_tool_call_time'), + duration: getRunStepDurationLabels(toolExecutionDurationMs, i18n.language), + }, + ] + : []), + ...(!measured && isReportableRunStepDuration(durationMs) + ? [ + { + label: localize('com_ui_tool_total_time'), + duration: getRunStepDurationLabels(durationMs, i18n.language), + }, + ] + : []), + ]; return ( @@ -194,22 +227,17 @@ export default function ProgressText({ {errorSuffix && ( · {errorSuffix} )} - {duration && ( - <> - {/* The compact form is the readable one on screen but a poor - thing to hear ("one point four s"), so it is hidden from - assistive technology and paired with a spoken equivalent. - Both live inside the button, so its accessible name carries - the duration — this is not an `aria-live` region and does not - re-announce. */} -