🕘 feat: Distinguish Tool Preparation From Tool Call Time - #16455
lia-by-librechat[bot] wants to merge 8 commits into
Conversation
|
Review head |
|
Updated review head |
|
Review head |
|
Updated review head |
|
Self-review head Release blocker: this PR still locks @librechat/agents 3.9.7. The new phases cannot work in a release until agents#577 is merged, published, and LibreChat's dependency and lockfile are updated. The PR description now explicitly limits separate phases to generic tool cards and describes approval wait and fallback semantics. A maintainer may initiate the exact-head review from this handoff. |
|
@codex review |
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 38badd02ad
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| [StepEvents.ON_TOOL_CALLS_DISPATCHED]: { | ||
| handle: async (event, data) => { | ||
| toolTiming.dispatched(data); | ||
| await emitForJob({ event, data }); | ||
| }, |
There was a problem hiding this comment.
A clean install of this commit still uses @librechat/agents 3.9.7 (packages/api/package.json and package-lock.json), which does not emit on_tool_calls_dispatched, observed_at, or the new completion timestamp. Consequently this handler is never invoked and the preparation/call timing feature silently falls back to the old total-elapsed display. Update both the dependency range and lockfile to a release containing the required SDK signals.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Confirmed release blocker, not resolved. SDK PR #577 is still open and the latest published agents release is 3.9.7. This PR must not merge as a delivered timing feature until the SDK change is merged/published and the LibreChat dependency and lockfile are updated. No unpublished or Git-branch SDK dependency is being introduced. Review fix: a502a22. The blocked release dependency is explicitly noted above.
There was a problem hiding this comment.
Resolved by df59e10. Agents SDK #577 is merged and its changes are published as @librechat/agents 3.9.8. This PR now requires ^3.9.8 in packages/api/package.json and locks 3.9.8 in package-lock.json; the npm tarball integrity matches the lock. The production API resolves that published SDK and its on_tool_calls_dispatched event. Focused tests against 3.9.8 passed: 286 client, 25 API tracker/replay, 42 server callbacks, and 3 data-provider. Data-provider, API, and client typechecks, builds, and affected static checks passed. CI is running on this exact head.
| finishedText={getFinishedText()} | ||
| subtitle={subtitle} | ||
| durationMs={runStepDurationMs} | ||
| toolPreparationDurationMs={toolPreparationDurationMs} |
There was a problem hiding this comment.
toolDispatchedAt and toolPreparationStartedAt are server-authored SSE timestamps, but ElapsedTimer subtracts the supplied value from the browser's Date.now() (Elapsed.tsx:8-9). Whenever the browser clock differs from the server clock, the live phase timer can remain at zero or show an arbitrarily inflated duration even though the server-side interval calculation is valid. Store a client receipt timestamp for the live timer, while retaining the server timestamps for completed-duration subtraction.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Fixed in the new head. The live timer now starts on the browser clock when a server phase stamp arrives; a skewed-clock regression verifies it restarts at zero on dispatch. Review fix: a502a22. The blocked release dependency is explicitly noted above.
| } else if (stepEvent.event === StepEvents.ON_TOOL_CALLS_DISPATCHED) { | ||
| const { dispatched_at: at, toolCalls } = stepEvent.data; |
There was a problem hiding this comment.
This live-event branch is the only path that stamps toolDispatchedAt onto an in-progress client card, but GenerationJobManager.trackEvent does not retain on_tool_calls_dispatched in resumeState.replayEvents, and the backend tracker only writes durations when the step closes. If a resumable client reconnects after handoff but before the result, its restored aggregatedContent therefore loses the Calling state and phase timer until completion. Persist/replay this event or stamp the dispatch timestamp into the resumable aggregate.
AGENTS.md reference: AGENTS.md:L49-L52
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Fixed in the new head. The generation manager persists compact first-fragment and dispatch markers per call and replays them after the restored content snapshot. Replay manager and client SSE regressions pass. Review fix: a502a22. The blocked release dependency is explicitly noted above.
| firstByStep.delete(stepId); | ||
| firstCallByStep.delete(stepId); | ||
| callIdsByStep.delete(stepId); |
There was a problem hiding this comment.
When multiple dispatched calls share a stepId and complete out of order, calling take for one sibling unconditionally deletes all step-level ownership and start state. If the first call was seen only as an ID-less index-0 fragment and a different sibling closes first, the later take for the actual first call can no longer recover its preparation start, so its persisted preparation duration is omitted. Remove only the consumed call and clear these step maps after every dispatched sibling has been taken.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Fixed in the new head. The step-owned tracker retains unresolved sibling timestamps until each dispatched call is consumed. A faster-sibling-first regression verifies attribution. Review fix: a502a22. The blocked release dependency is explicitly noted above.
| const firstByCall = new Map<string, number>(); | ||
| const firstByStep = new Map<string, number>(); | ||
| const firstCallByStep = new Map<string, string>(); | ||
| const callIdsByStep = new Map<string, Set<string>>(); | ||
| const dispatchedByCall = new Map<string, number>(); |
There was a problem hiding this comment.
These maps key timing exclusively by provider call ID even though one tracker spans the whole response and LibreChat explicitly supports provider IDs repeating across agent and step ownership. If parallel agents emit the same ID concurrently, their starts, dispatches, and completions are merged or overwritten, and closing either call deletes the other's state, producing incorrect or missing persisted durations. Key the records by at least (stepId, callId) and pass the result step ID into completed.
AGENTS.md reference: AGENTS.md:L44-L47
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Fixed in the new head. API records are scoped by step ID and client maps use step-and-call composite keys. Reused-ID regressions cover concurrent steps. Review fix: a502a22. The blocked release dependency is explicitly noted above.
| } | ||
| return emitForJob({ event: UsageEvents.ON_TOKEN_USAGE, data: payload }); | ||
| }; | ||
| const toolTiming = createToolTimingTracker(); |
There was a problem hiding this comment.
The timing tracker is created inside getDefaultHandlers, but an approval resume reconstructs the client through initializeClient and therefore creates a fresh handler set. The first-fragment timestamp captured before the pause is neither persisted in aggregated content nor restored into this new tracker, so after approval the dispatch and completion can produce only tool execution time; the preparation interval that is supposed to include approval waiting is permanently lost on the saved card. Persist the pre-dispatch stamps in resumable state or seed the rebuilt tracker from the paused run.
AGENTS.md reference: AGENTS.md:L49-L52
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Fixed in the new head. The approval resume passes its already-loaded replay snapshot into the new handler; a rebuilt-handler test proves that pre-pause preparation survives approval. Review fix: a502a22. The blocked release dependency is explicitly noted above.
Codex Review SummaryThis comment shows the latest Codex review activity on this pull request.
ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings. |
|
Review head |
|
Review head |
|
@codex review the latest head |
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: df59e10aa7
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| const toolTiming = createToolTimingTracker(toolTimingReplayEvents); | ||
| const handlers = { | ||
| [StepEvents.ON_TOOL_CALLS_DISPATCHED]: { | ||
| handle: async (event, data) => { | ||
| toolTiming.dispatched(data); |
There was a problem hiding this comment.
This new tracker lifecycle, event-handler branch, and later persistence mutation place backend behavior directly in api/server/controllers/agents/callbacks.js. Repository guidance explicitly requires new branches and service calls under /api to be implemented in packages/api, leaving the CJS layer only to wire or re-export the TypeScript implementation; move the timing lifecycle adapter into that package and invoke it from here.
AGENTS.md reference: AGENTS.md:L77-L81
Useful? React with 👍 / 👎.
| [StepEvents.ON_TOOL_CALLS_DISPATCHED]: { | ||
| handle: async (event, data) => { | ||
| toolTiming.dispatched(data); | ||
| await emitForJob({ event, data }); |
There was a problem hiding this comment.
When this handler is instantiated with eventChildActivity for an event-task child agent, emitForJob calls publishEventChildActivity, but eventActivityPhases has no mapping for ON_TOOL_CALLS_DISPATCHED, so this newly handled dispatch event is silently omitted from the child stream. The subagent reducer therefore never gets the dispatch boundary needed to transition its tool cards to Calling or calculate split timing, despite SubagentUpdatePhase now advertising tool_calls_dispatched; add the child phase mapping and fold it into the child tool metadata.
Useful? React with 👍 / 👎.
| 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)); |
There was a problem hiding this comment.
When a reconnect or HITL resume lands on a replica without the live contentParts reference, RedisJobStore.getContentParts reconstructs the message from durable chunks, but its on_run_step_closed overlay restores only runStepStatus and runStepDurationMs, not the timing assigned here. The compact replay markers also contain no completion timestamp, and a completed step receives no later closure on which the client could recompute it, so completed cards from before a cross-replica resume fall back to Total elapsed and may subsequently be saved without their split timing; extend durable reconstruction or the closure payload to restore both intervals.
AGENTS.md reference: AGENTS.md:L49-L52
Useful? React with 👍 / 👎.
This branch has not been deployed
2 participants
Problem
A long model-generated tool argument can make a tool row look like it ran for minutes, even when the tool itself was fast. The existing run-step lifetime is real but does not measure the host tool call.
Change
The preparation interval can include approval or other pre-dispatch waiting, not only model generation. The Tool call interval is SDK handoff-to-result wall time, not the MCP round trip or ClickHouse execution time. Specialized bash/code/file/memory cards do not yet show the split; their existing step lifetime is labelled Total elapsed.
SDK release
Agents SDK #577 is merged and published in
@librechat/agents3.9.8. This PR upgradespackages/apito^3.9.8and locks the published tarball. Its npm integrity matches the installed tarball; focused tests and all three changed TypeScript workspaces were checked against the published package, not a source checkout. Previous messages still show the Total elapsed fallback. No publication or deployment is part of this PR.Verification
tsc --noEmitpassed in packages/data-provider, packages/api and client with the published package. Data-provider and API builds passed. Affected ESLint, Prettier, import-order, package-lock validation and circular-dependency checks passed.