⏱️ feat: Expose Tool Preparation and Dispatch Timing - #577
Conversation
|
@codex review |
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. |
![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: b98de52969
ℹ️ 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".
| }; | ||
|
|
||
| void safeDispatchCustomEvent( | ||
| GraphEvents.ON_TOOL_CALLS_DISPATCHED, |
There was a problem hiding this comment.
When this ToolNode runs inside an attached or detached subagent, SubagentExecutor replaces the inherited callback chain with createForwarderCallback (src/tools/subagent/SubagentExecutor.ts:2753-2764), whose custom-event switch handles ON_TOOL_EXECUTE and run-step events but silently falls through for ON_TOOL_CALLS_DISPATCHED (:3444-3475). Consequently, host handlers never receive this handoff event for tools executed by child agents, so the newly exposed preparation/runtime split is unavailable precisely for multi-agent runs; add this event to the subagent forwarding path.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Child dispatch now forwards as a sanitized, scoped subagent timing update with no arguments; the forwarder regression passed. Fixed in 31f7ce3. Focused SDK tests: 274 passed; typecheck, tsdown, touched lint and import order passed.
| * it does not claim the host has begun its own work. Paired with the tool | ||
| * completion `completed_at`, the stamp measures SDK handoff-to-result time, | ||
| * not MCP or database execution time. The earliest `observed_at` tool-call |
There was a problem hiding this comment.
For a host that reports results only through the required resolve callback, this documented interval does not end when the SDK receives the result: dispatchPromise waits for both resultSettled and the entire ON_TOOL_EXECUTE handler to return, and only afterward does dispatchStepCompleted call Date.now(). The wrapper in safeDispatchCustomEvent can further delay request.resolve until Langfuse metadata tracing finishes. A handler that calls resolve(results) and then performs slow cleanup therefore inflates dispatched_at→completed_at even though the result was already received; capture the receipt timestamp in resolve (and propagate it to completion) rather than stamping after dispatch settlement.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Host results are stamped when resolve/onResult is called, before tracing and handler cleanup; the slow-cleanup regression passed. Fixed in 31f7ce3. Focused SDK tests: 274 passed; typecheck, tsdown, touched lint and import order passed.
| toolCallChunks: ToolCallChunk[]; | ||
| metadata?: Record<string, unknown>; | ||
| }): Promise<void> { | ||
| const observedAt = Date.now(); |
There was a problem hiding this comment.
On a coalesced model chunk containing both complete tool_calls and tool_call_chunks, this timestamp is captured too late: ChatModelStreamHandler.handle first awaits handleToolCalls and can then call startEagerToolExecutions (src/stream.ts:1835-1880) before it reaches handleToolCallChunks at :1928. Thus a slow run-step handler skews observed_at, and an eager call can even emit dispatched_at before the first fragment's observed_at, yielding a negative preparation duration. Capture the receipt time at handler entry and pass it through, or process/stamp the chunks before any complete-call dispatch.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
The model-chunk receipt timestamp is captured before awaited step dispatch and propagated to the delta even on coalesced eager calls; its regression passed. Fixed in 31f7ce3. Focused SDK tests: 274 passed; typecheck, tsdown, touched lint and import order passed.
|
Updated review head |
2 participants
Why
The current tool-step elapsed time can include minutes of model-generated arguments and post-dispatch tool work. Displaying it as tool runtime misattributes the wait.
What
on_run_step_delta.observed_atwhen an argument fragment first reaches the SDK, before any awaited step handling. Consumers can keep the first timestamp per call/index as the start of preparation.on_tool_calls_dispatchedevent immediately before direct, eager, or host tool dispatch. Only the timestamp and call identity travel, never the arguments. A denied/aborted tool does not emit a dispatch event.Verification
tsc --noEmit,tsdown, touched-file ESLint, import sort check, andgit diff --check: passed.Follow-up
LibreChat needs a companion consumer/UI change to present the new phases. This PR does not alter ClickHouse-specific metrics or claim database execution time.