mirror of
https://github.com/cline/cline.git
synced 2026-09-11 05:47:07 +08:00
Compare commits
9
Commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
0f6be07a19 | ||
|
|
16d414eb60 | ||
|
|
5cdc8760ff | ||
|
|
05f2fc491d | ||
|
|
265e1707ab | ||
|
|
df9d3f814f | ||
|
|
792700d4a2 | ||
|
|
48181ce49e | ||
|
|
93a71dafbe |
@@ -0,0 +1,438 @@
|
||||
# Technique Plan: Assistant Presentation Scheduler
|
||||
|
||||
This document is the implementation plan for the **assistant presentation scheduler** technique identified in `docs/remote-workspace-latency-branch-analysis-report.md` as one of the highest-ROI improvements for remote-workspace responsiveness.
|
||||
|
||||
The central principle is:
|
||||
|
||||
> **The provider stream is not the UI clock.**
|
||||
|
||||
In other words, the model may emit chunks at machine cadence, but the user only needs the UI to update at a human-friendly cadence. Trying to present every chunk immediately is what turns remote-mode transport, persistence, and rendering overhead into visible jitter.
|
||||
|
||||
This plan explains how to introduce a scheduler that coalesces presentation work without compromising semantic immediacy at important boundaries like first token, tool transitions, errors, and final completion.
|
||||
|
||||
## How To Use This Plan
|
||||
|
||||
This plan should be implemented on its **own extraction branch**. Do not treat this document as a net-new design exercise.
|
||||
|
||||
The branch `eve_troubleshooting-remote-workspaces` already contains the **fully developed reference implementation** for this technique. That branch should be used constantly while executing this plan: inspect how it solves each subproblem, then extract the minimal coherent subset of that behavior into your branch with tests and clear review boundaries.
|
||||
|
||||
Be smart about this. The reference implementation has already paid the discovery cost. The goal now is to convert that integrated work into a smaller, comprehensible, reviewable, and verifiable technique PR. If something in the reference implementation looks surprising, understand it before simplifying it.
|
||||
|
||||
## Developer Operating Posture
|
||||
|
||||
This technique is not just “add a debounce.” It is a hot-path scheduling change in the core task-execution loop. Treat it with the care you would give any latency-sensitive distributed-systems control surface.
|
||||
|
||||
While implementing:
|
||||
|
||||
- keep one eye on the extracted branch and one on `eve_troubleshooting-remote-workspaces`,
|
||||
- preserve semantic immediacy even while coalescing ordinary chunk churn,
|
||||
- and continually ask whether the stream is being allowed to run at machine speed while the UI updates at human speed.
|
||||
|
||||
The cross-cutting wisdom from the analysis report applies directly here:
|
||||
|
||||
> **Stop treating every streamed chunk as a durable, full-state, immediately-presented event.**
|
||||
|
||||
For this technique, the emphasis is on the **immediately-presented** part.
|
||||
|
||||
## Document Type, Audience, and Quality Bar
|
||||
|
||||
This is an **extraction implementation plan** for a **Staff+ level distributed systems / infrastructure engineer**. It is not a request to invent a scheduler concept from scratch; it is a guide for extracting a production-worthy scheduler from the already-working reference implementation.
|
||||
|
||||
The quality bar is high:
|
||||
|
||||
- each step should be operationally clear,
|
||||
- each behavioral tradeoff should be explainable to reviewers,
|
||||
- and the extracted result should preserve semantic immediacy where it matters while reducing hot-path churn where it does not.
|
||||
|
||||
## Artifact Stack and Dependency Position
|
||||
|
||||
This document depends on the branch analysis report and should be used after reviewing:
|
||||
|
||||
1. `docs/remote-workspace-latency-branch-analysis-report.md` for the “why this is high ROI” framing.
|
||||
2. `eve_troubleshooting-remote-workspaces` for the actual known-good implementation details.
|
||||
3. This plan for the extraction sequence, tests, and safety boundaries.
|
||||
|
||||
That sequence matters because this technique is easiest to reason about when the business case, integrated implementation, and extraction steps are all visible at once.
|
||||
|
||||
## Minimal Coherent Extraction Boundary
|
||||
|
||||
The smallest coherent PR for this technique should usually include:
|
||||
|
||||
- the scheduler primitive,
|
||||
- task integration,
|
||||
- remote-aware cadence selection,
|
||||
- final-drain / disposal correctness,
|
||||
- and tests for cadence, preemption, overlap, and teardown.
|
||||
|
||||
What should **not** be split apart if avoidable:
|
||||
|
||||
- scheduler primitive from task integration,
|
||||
- immediate-priority semantics from cadence logic,
|
||||
- final-drain behavior from the scheduler extraction,
|
||||
- and the tests that prove overlap/teardown correctness.
|
||||
|
||||
## Common Failure Modes While Extracting
|
||||
|
||||
Watch for these failure modes explicitly:
|
||||
|
||||
- introducing a timer but leaving direct hot-path awaits in place,
|
||||
- over-coalescing semantic-boundary events that users expect to feel immediate,
|
||||
- forgetting final-drain behavior at stream completion,
|
||||
- teardown bugs that allow delayed flushes after task disposal,
|
||||
- and tuning cadence values without validating against the reference implementation.
|
||||
|
||||
---
|
||||
|
||||
## Why This Technique Matters
|
||||
|
||||
The streaming loop is one of the hottest paths in the whole system. If every chunk does all of the following synchronously:
|
||||
|
||||
- parse/update assistant content,
|
||||
- present to the UI,
|
||||
- possibly trigger follow-on state posting,
|
||||
- possibly interact with persistence or tool execution,
|
||||
|
||||
then the stream becomes paced by downstream work rather than by provider availability.
|
||||
|
||||
That problem gets worse in remote workspaces because UI presentation is no longer “just local work.” It often implies transport across host boundaries, local parsing, and frontend reconciliation.
|
||||
|
||||
The goal here is not to make the UI less live. The goal is to make it live at the **right cadence**.
|
||||
|
||||
---
|
||||
|
||||
## Success Criteria
|
||||
|
||||
- Normal text/reasoning/tool-progress chunk presentation is coalesced behind a scheduler.
|
||||
- The streaming loop no longer awaits presentation on every chunk.
|
||||
- Important semantic boundaries still flush immediately.
|
||||
- Remote workspaces use more conservative cadences than local workspaces.
|
||||
- Final drain behavior guarantees that no residual content is left unpresented.
|
||||
|
||||
---
|
||||
|
||||
## Files Most Likely to Change
|
||||
|
||||
- `src/core/task/TaskPresentationScheduler.ts`
|
||||
- `src/core/task/index.ts`
|
||||
- `src/core/task/latency.ts`
|
||||
- `src/core/task/__tests__/TaskPresentationScheduler.test.ts`
|
||||
- `src/core/task/__tests__/latency.test.ts`
|
||||
|
||||
---
|
||||
|
||||
## Step-by-Step Implementation Plan
|
||||
|
||||
## Step 1 — Define the presentation contract and priorities
|
||||
|
||||
### Goal
|
||||
|
||||
Establish which kinds of updates can be coalesced and which must feel immediate.
|
||||
|
||||
### Mental model
|
||||
|
||||
Not all updates are equal.
|
||||
|
||||
- A tenth text chunk arriving 20ms after the ninth is not urgent.
|
||||
- The first visible token is urgent.
|
||||
- A tool completion or approval transition is urgent.
|
||||
- Finalization is urgent.
|
||||
|
||||
The scheduler works only if priority rules are intentional and documented.
|
||||
|
||||
### Work
|
||||
|
||||
- [x] Define presentation priorities such as `immediate`, `normal`, and `low`.
|
||||
- [x] Document semantic boundaries that must flush immediately.
|
||||
- [x] Document which chunk types default to normal coalescing.
|
||||
|
||||
### Detailed code changes
|
||||
|
||||
- In `src/core/task/TaskPresentationScheduler.ts`:
|
||||
- [x] expose or preserve a `PresentationPriority` type.
|
||||
- In `src/core/task/index.ts`:
|
||||
- [x] document priority mapping logic near `getPresentationPriorityForChunk(...)`.
|
||||
- In comments/docstrings, explicitly call out immediate boundaries:
|
||||
- [x] first visible token,
|
||||
- [x] tool transitions,
|
||||
- [x] finalization,
|
||||
- [x] abort/error cleanup.
|
||||
|
||||
Use the reference implementation branch to understand where those boundaries were discovered empirically. Some of them exist because they matter for user perception; others exist because they matter for correctness or because delayed presentation would feel broken. Preserve that reasoning in the extraction.
|
||||
|
||||
### Tests
|
||||
|
||||
- [x] Unit test: priority merge rules behave as expected.
|
||||
|
||||
---
|
||||
|
||||
## Step 2 — Implement the scheduler primitive
|
||||
|
||||
### Goal
|
||||
|
||||
Build a reusable scheduler that coalesces repeated requests, avoids overlapping flushes, and supports immediate preemption.
|
||||
|
||||
### Mental model
|
||||
|
||||
Think of the scheduler as a small state machine:
|
||||
|
||||
- a flush may be pending,
|
||||
- a flush may be running,
|
||||
- more work may arrive while the flush is running,
|
||||
- the highest pending priority wins.
|
||||
|
||||
The implementation must be robust under bursty chunk arrival, not just simple timer-based debounce logic.
|
||||
|
||||
### Work
|
||||
|
||||
- [x] Implement `requestFlush(priority)`.
|
||||
- [x] Implement `flushNow()`.
|
||||
- [x] Track pending priority, active flush, and pending-while-flushing state.
|
||||
- [x] Add disposal semantics so no timers survive task teardown.
|
||||
|
||||
### Detailed code changes
|
||||
|
||||
- In `src/core/task/TaskPresentationScheduler.ts`:
|
||||
- [x] keep a `scheduledTimer`.
|
||||
- [x] keep `pendingPriority`.
|
||||
- [x] keep `flushInProgress`.
|
||||
- [x] keep `pendingWhileFlushing`.
|
||||
- [x] when `requestFlush(immediate)` arrives, cancel scheduled timer and run now.
|
||||
- [x] when work arrives during flush, mark pending and re-run once afterward.
|
||||
- [x] support `dispose()` to clear timer and suppress future work.
|
||||
|
||||
Be smart about state-machine edge cases. This scheduler sits on a bursty asynchronous path; the real implementation value is in correct behavior under overlap, priority escalation, and teardown, not just in the existence of a timer.
|
||||
|
||||
### Tests
|
||||
|
||||
- [x] Unit test: multiple requests inside the cadence window produce one flush.
|
||||
- [x] Unit test: immediate priority preempts pending normal work.
|
||||
- [x] Unit test: updates arriving during a flush produce exactly one follow-up flush.
|
||||
- [x] Unit test: dispose clears timers and suppresses future flushes.
|
||||
|
||||
---
|
||||
|
||||
## Step 3 — Integrate scheduler into `Task`
|
||||
|
||||
### Goal
|
||||
|
||||
Make the `Task` use the scheduler as the default path for presentation without breaking existing semantics.
|
||||
|
||||
### Mental model
|
||||
|
||||
`presentAssistantMessage()` should become the **drain implementation**, not the hot-path public API that every chunk directly awaits.
|
||||
|
||||
### Work
|
||||
|
||||
- [x] Add a scheduler field to `Task`.
|
||||
- [x] Add a scheduling wrapper such as `scheduleAssistantPresentation(...)`.
|
||||
- [x] Refactor direct callers to go through the wrapper except where explicit immediate drain is needed.
|
||||
|
||||
### Detailed code changes
|
||||
|
||||
- In `src/core/task/index.ts`:
|
||||
- [x] instantiate `TaskPresentationScheduler` in the constructor.
|
||||
- [x] wire `flush: async () => this.flushAssistantPresentation()`.
|
||||
- [x] add `scheduleAssistantPresentation(trigger, priority)`.
|
||||
- [x] keep `flushAssistantPresentation()` as the method that actually calls `presentAssistantMessage()`.
|
||||
|
||||
When extracting this step, mirror the reference implementation’s structure closely enough that future diffs remain comparable. The cleanest extraction is one where a reviewer can trivially line up the extracted version with the reference implementation and see the same conceptual architecture.
|
||||
|
||||
### Tests
|
||||
|
||||
- [x] Unit test: `scheduleAssistantPresentation(...)` increments request metrics correctly.
|
||||
- [x] Unit test: scheduling-disabled mode still drains immediately.
|
||||
|
||||
---
|
||||
|
||||
## Step 4 — Replace direct per-chunk presentation awaits in the streaming loop
|
||||
|
||||
### Goal
|
||||
|
||||
Remove the default `await presentAssistantMessage()` behavior from the chunk-ingestion hot path.
|
||||
|
||||
### Mental model
|
||||
|
||||
This is where the real latency win happens. If the chunk loop no longer blocks on presentation for normal chunk traffic, provider ingestion stays fast and the UI drains on its own cadence.
|
||||
|
||||
### Work
|
||||
|
||||
- [x] Update text chunk path to schedule presentation instead of awaiting it.
|
||||
- [x] Update reasoning chunk path to schedule presentation instead of awaiting it.
|
||||
- [x] Update tool-progress/native-tool-call related chunk path similarly.
|
||||
- [x] Preserve immediate scheduling for first-token and tool-related semantic transitions.
|
||||
|
||||
### Detailed code changes
|
||||
|
||||
- In `src/core/task/index.ts`, inside streaming chunk handling:
|
||||
- [x] text chunks should update assistant content and then call `scheduleAssistantPresentation("text", priority)`.
|
||||
- [x] reasoning chunks should call `scheduleAssistantPresentation("reasoning", priority)`.
|
||||
- [x] tool-call chunks should call `scheduleAssistantPresentation("tool", priority)`.
|
||||
- Ensure priority logic uses whether visible assistant content already exists.
|
||||
|
||||
This step is the actual latency win. Use the reference implementation to identify every place where the old flow awaited presentation inside streaming logic, then confirm whether that await was deliberately removed or preserved for a semantic boundary. Be explicit; do not guess.
|
||||
|
||||
### Tests
|
||||
|
||||
- [x] Integration-style test: many streaming chunks produce fewer presentation invocations than chunk count.
|
||||
- [x] Regression test: first visible token still appears promptly.
|
||||
- [x] Regression test: tool execution order is preserved under scheduled presentation.
|
||||
|
||||
---
|
||||
|
||||
## Step 5 — Add remote-aware cadence selection
|
||||
|
||||
### Goal
|
||||
|
||||
Use different default cadences for local and remote environments.
|
||||
|
||||
### Mental model
|
||||
|
||||
Remote workspaces need more coalescing because each UI flush is more expensive. The right question is not “what is the minimum possible delay?” but “what cadence is imperceptibly live while materially reducing churn?”
|
||||
|
||||
### Work
|
||||
|
||||
- [x] Centralize cadence lookup in `latency.ts`.
|
||||
- [x] Keep `immediate` priority at zero-delay.
|
||||
- [x] Use more conservative normal/low cadences in remote mode.
|
||||
- [x] Allow env-var overrides for tuning.
|
||||
|
||||
### Detailed code changes
|
||||
|
||||
- In `src/core/task/latency.ts`:
|
||||
- [x] add or preserve `getPresentationCadenceMs(isRemoteWorkspace, priority)`.
|
||||
- [x] keep override env vars for local and remote cadence values.
|
||||
- In `Task` constructor:
|
||||
- [x] pass cadence callback into scheduler so it adapts automatically once remote detection is known.
|
||||
|
||||
Do not tune cadence values from first principles unless necessary. Start from the values already proven in `eve_troubleshooting-remote-workspaces`, then adjust only if the extraction boundary demands it or validation shows a problem.
|
||||
|
||||
### Tests
|
||||
|
||||
- [x] Unit test: remote mode returns higher normal cadence than local mode.
|
||||
- [x] Unit test: env var override wins over default values.
|
||||
- [x] Unit test: immediate priority always returns zero.
|
||||
|
||||
---
|
||||
|
||||
## Step 6 — Preserve final-drain semantics
|
||||
|
||||
### Goal
|
||||
|
||||
Guarantee that all pending content is fully presented before request completion, abort, or disposal.
|
||||
|
||||
### Mental model
|
||||
|
||||
Schedulers are easy to add and easy to get subtly wrong at teardown. The user must never lose the last bit of visible content because it was still sitting in a pending timer when the request ended.
|
||||
|
||||
### Work
|
||||
|
||||
- [x] Force a final synchronous drain when the stream completes.
|
||||
- [x] Force final drain on abort/error cleanup where appropriate.
|
||||
- [x] Dispose scheduler cleanly during task teardown.
|
||||
|
||||
### Detailed code changes
|
||||
|
||||
- In `src/core/task/index.ts`:
|
||||
- [x] after the streaming loop has completed and partial blocks are finalized, call `await this.presentationScheduler.flushNow()`.
|
||||
- [x] in abort/finally paths, ensure no pending scheduled flush survives past task shutdown.
|
||||
- In `TaskPresentationScheduler`:
|
||||
- [x] make `dispose()` clear timers and suppress post-disposal flushes.
|
||||
|
||||
This is one of the places where smart engineering judgment matters most: the last 1% of scheduler teardown correctness often determines whether the feature is “production-grade” or “subtly flaky.” Compare end-of-stream and abort behavior carefully against the reference implementation.
|
||||
|
||||
### Tests
|
||||
|
||||
- [x] Unit test: final `flushNow()` drains pending coalesced work.
|
||||
- [x] Unit test: task disposal suppresses delayed pending flushes.
|
||||
- [x] Regression test: final text is visible before next request starts.
|
||||
|
||||
---
|
||||
|
||||
## Step 7 — Add instrumentation and verify chunk-to-visible behavior
|
||||
|
||||
### Goal
|
||||
|
||||
Measure the scheduler’s actual effect so cadence tuning is based on data.
|
||||
|
||||
### Mental model
|
||||
|
||||
Scheduling is always a tradeoff between update frequency and perceived responsiveness. The only good tuning process is to measure:
|
||||
|
||||
- how many flushes occur,
|
||||
- how long flushes take,
|
||||
- what the chunk-to-visible delay looks like.
|
||||
|
||||
### Work
|
||||
|
||||
- [x] Track presentation invocation count.
|
||||
- [x] Track total/average presentation duration.
|
||||
- [x] Track final chunk-to-webview delay distribution.
|
||||
- [x] Emit request-level telemetry summary.
|
||||
|
||||
### Detailed code changes
|
||||
|
||||
- In `src/core/task/index.ts`:
|
||||
- [x] accumulate presentation metrics in request-scoped latency metrics.
|
||||
- [x] record chunk-to-webview delay when state or partial-message updates occur.
|
||||
- In telemetry summary helpers:
|
||||
- [x] ensure presentation-related fields are included and comparable.
|
||||
|
||||
### Tests
|
||||
|
||||
- [x] Unit test: metrics aggregate correctly under multiple scheduler flushes.
|
||||
- [x] Unit test: instrumentation is failure-safe when telemetry is disabled/unavailable.
|
||||
|
||||
---
|
||||
|
||||
## Step 8 — Validate special high-churn scenarios such as large-file writes
|
||||
|
||||
### Goal
|
||||
|
||||
Ensure the scheduler meaningfully helps the scenarios users actually notice.
|
||||
|
||||
### Mental model
|
||||
|
||||
Large-file write scenarios often generate:
|
||||
|
||||
- lots of reasoning text,
|
||||
- tool descriptions/progress,
|
||||
- potential partial previews,
|
||||
- repeated task-state churn.
|
||||
|
||||
The scheduler should reduce the “chatty” feel without making the operation feel frozen.
|
||||
|
||||
That is why this technique materially helps large-file writes: the user does not need every incremental progress mutation painted at model-chunk cadence. They need the operation to feel continuously alive, not hyperactive.
|
||||
|
||||
### Work
|
||||
|
||||
- [x] Add validation scenario for long streamed response and/or large-file write workflow.
|
||||
- [x] Compare presentation flush count with scheduler enabled vs disabled.
|
||||
- [x] Confirm first-token latency remains acceptable.
|
||||
|
||||
### Tests
|
||||
|
||||
- [x] Validation harness scenario: scheduler-enabled mode produces fewer presentation flushes than chunk count.
|
||||
- [x] Comparison run: scheduler-disabled variant shows meaningfully higher presentation activity.
|
||||
|
||||
---
|
||||
|
||||
## Developer Checklist Summary
|
||||
|
||||
- [x] Define presentation priorities and semantic boundaries
|
||||
- [x] Implement the scheduler primitive
|
||||
- [x] Integrate scheduler into `Task`
|
||||
- [x] Replace direct per-chunk presentation awaits
|
||||
- [x] Add remote-aware cadence selection
|
||||
- [x] Preserve final-drain semantics
|
||||
- [x] Instrument and verify behavior
|
||||
- [x] Validate large-file / long-stream scenarios
|
||||
|
||||
---
|
||||
|
||||
## Final Mental Model Recap
|
||||
|
||||
- **Streams run at machine speed.**
|
||||
- **People read at human speed.**
|
||||
- **UI presentation should honor the latter without blocking the former.**
|
||||
|
||||
If developers hold that model throughout implementation, this technique will reliably reduce jitter and improve perceived responsiveness in remote workspaces.
|
||||
@@ -4,6 +4,11 @@ import { Logger } from "@/shared/services/Logger"
|
||||
import { getRequestRegistry, StreamingResponseHandler } from "../grpc-handler"
|
||||
import { Controller } from "../index"
|
||||
|
||||
export type PartialMessageEventStats = {
|
||||
payloadBytes: number
|
||||
broadcastDurationMs: number
|
||||
}
|
||||
|
||||
// Keep track of active partial message subscriptions (gRPC streams)
|
||||
const activePartialMessageSubscriptions = new Set<StreamingResponseHandler<ClineMessage>>()
|
||||
|
||||
@@ -54,7 +59,9 @@ export function registerPartialMessageCallback(callback: PartialMessageCallback)
|
||||
* Send a partial message event to all active subscribers
|
||||
* @param partialMessage The ClineMessage to send
|
||||
*/
|
||||
export async function sendPartialMessageEvent(partialMessage: ClineMessage): Promise<void> {
|
||||
export async function sendPartialMessageEvent(partialMessage: ClineMessage): Promise<PartialMessageEventStats> {
|
||||
const startedAt = performance.now()
|
||||
const payloadBytes = Buffer.byteLength(JSON.stringify(partialMessage), "utf8")
|
||||
// Send to gRPC stream subscribers
|
||||
const streamPromises = Array.from(activePartialMessageSubscriptions).map(async (responseStream) => {
|
||||
try {
|
||||
@@ -79,4 +86,9 @@ export async function sendPartialMessageEvent(partialMessage: ClineMessage): Pro
|
||||
}
|
||||
|
||||
await Promise.all(streamPromises)
|
||||
|
||||
return {
|
||||
payloadBytes,
|
||||
broadcastDurationMs: Math.max(0, performance.now() - startedAt),
|
||||
}
|
||||
}
|
||||
|
||||
@@ -0,0 +1,148 @@
|
||||
type PresentationPriority = "immediate" | "normal" | "low"
|
||||
|
||||
type TaskPresentationSchedulerOptions = {
|
||||
flush: () => Promise<void>
|
||||
getDelayMs: (priority: PresentationPriority) => number
|
||||
setTimeoutFn?: typeof setTimeout
|
||||
clearTimeoutFn?: typeof clearTimeout
|
||||
onFlushError?: (error: unknown) => void
|
||||
getNow?: () => number
|
||||
metrics?: {
|
||||
onFlushStarted?: (priority: PresentationPriority) => void
|
||||
onFlushCompleted?: (durationMs: number, priority: PresentationPriority) => void
|
||||
}
|
||||
}
|
||||
|
||||
export class TaskPresentationScheduler {
|
||||
private scheduledTimer: ReturnType<typeof setTimeout> | undefined
|
||||
private pendingPriority: PresentationPriority | undefined
|
||||
private flushInProgress = false
|
||||
private disposed = false
|
||||
private pendingWhileFlushing = false
|
||||
|
||||
private readonly flush: () => Promise<void>
|
||||
private readonly getDelayMs: (priority: PresentationPriority) => number
|
||||
private readonly setTimeoutFn: typeof setTimeout
|
||||
private readonly clearTimeoutFn: typeof clearTimeout
|
||||
private readonly onFlushError?: (error: unknown) => void
|
||||
private readonly getNow: () => number
|
||||
private readonly metrics?: TaskPresentationSchedulerOptions["metrics"]
|
||||
|
||||
constructor(options: TaskPresentationSchedulerOptions) {
|
||||
this.flush = options.flush
|
||||
this.getDelayMs = options.getDelayMs
|
||||
this.setTimeoutFn = options.setTimeoutFn ?? setTimeout
|
||||
this.clearTimeoutFn = options.clearTimeoutFn ?? clearTimeout
|
||||
this.onFlushError = options.onFlushError
|
||||
this.getNow = options.getNow ?? (() => performance.now())
|
||||
this.metrics = options.metrics
|
||||
}
|
||||
|
||||
requestFlush(priority: PresentationPriority = "normal"): void {
|
||||
if (this.disposed) {
|
||||
return
|
||||
}
|
||||
|
||||
this.pendingPriority = this.mergePriority(this.pendingPriority, priority)
|
||||
|
||||
if (this.flushInProgress) {
|
||||
this.pendingWhileFlushing = true
|
||||
return
|
||||
}
|
||||
|
||||
if (this.pendingPriority === "immediate") {
|
||||
if (this.scheduledTimer) {
|
||||
this.clearTimeoutFn(this.scheduledTimer)
|
||||
this.scheduledTimer = undefined
|
||||
}
|
||||
void this.runFlushCycle()
|
||||
return
|
||||
}
|
||||
|
||||
if (this.scheduledTimer) {
|
||||
return
|
||||
}
|
||||
|
||||
const nextPriority = this.pendingPriority ?? "normal"
|
||||
const delayMs = this.getDelayMs(nextPriority)
|
||||
this.scheduledTimer = this.setTimeoutFn(() => {
|
||||
this.scheduledTimer = undefined
|
||||
void this.runFlushCycle()
|
||||
}, delayMs)
|
||||
}
|
||||
|
||||
async flushNow(): Promise<void> {
|
||||
if (this.disposed) {
|
||||
return
|
||||
}
|
||||
|
||||
this.pendingPriority = this.mergePriority(this.pendingPriority, "immediate")
|
||||
if (this.scheduledTimer) {
|
||||
this.clearTimeoutFn(this.scheduledTimer)
|
||||
this.scheduledTimer = undefined
|
||||
}
|
||||
|
||||
await this.runFlushCycle()
|
||||
}
|
||||
|
||||
async dispose(): Promise<void> {
|
||||
this.disposed = true
|
||||
if (this.scheduledTimer) {
|
||||
this.clearTimeoutFn(this.scheduledTimer)
|
||||
this.scheduledTimer = undefined
|
||||
}
|
||||
this.pendingPriority = undefined
|
||||
this.pendingWhileFlushing = false
|
||||
}
|
||||
|
||||
private async runFlushCycle(): Promise<void> {
|
||||
if (this.disposed || this.flushInProgress || !this.pendingPriority) {
|
||||
return
|
||||
}
|
||||
|
||||
const priority = this.pendingPriority
|
||||
this.flushInProgress = true
|
||||
this.pendingPriority = undefined
|
||||
this.pendingWhileFlushing = false
|
||||
|
||||
const startedAt = this.getNow()
|
||||
this.metrics?.onFlushStarted?.(priority)
|
||||
try {
|
||||
await this.flush()
|
||||
} catch (error) {
|
||||
this.onFlushError?.(error)
|
||||
} finally {
|
||||
this.metrics?.onFlushCompleted?.(Math.max(0, this.getNow() - startedAt), priority)
|
||||
this.flushInProgress = false
|
||||
}
|
||||
|
||||
if (this.disposed) {
|
||||
return
|
||||
}
|
||||
|
||||
if (this.pendingPriority || this.pendingWhileFlushing) {
|
||||
const priorityToRun = this.pendingPriority
|
||||
if (priorityToRun === "immediate") {
|
||||
await this.runFlushCycle()
|
||||
} else {
|
||||
this.requestFlush(priorityToRun ?? "normal")
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
private mergePriority(current: PresentationPriority | undefined, next: PresentationPriority): PresentationPriority {
|
||||
if (!current) {
|
||||
return next
|
||||
}
|
||||
|
||||
const rank: Record<PresentationPriority, number> = {
|
||||
low: 0,
|
||||
normal: 1,
|
||||
immediate: 2,
|
||||
}
|
||||
|
||||
return rank[next] > rank[current] ? next : current
|
||||
}
|
||||
}
|
||||
|
||||
export type { PresentationPriority }
|
||||
@@ -7,6 +7,7 @@ export class TaskState {
|
||||
// Task-level timing
|
||||
taskStartTimeMs = Date.now()
|
||||
taskFirstTokenTimeMs?: number
|
||||
currentChunkReceivedAtMs?: number
|
||||
|
||||
// Streaming flags
|
||||
isStreaming = false
|
||||
|
||||
@@ -0,0 +1,337 @@
|
||||
import { strict as assert } from "assert"
|
||||
import { Task } from "../index"
|
||||
import { TaskPresentationScheduler } from "../TaskPresentationScheduler"
|
||||
|
||||
class FakeTimerController {
|
||||
private now = 0
|
||||
private nextId = 1
|
||||
private timers = new Map<number, { time: number; callback: () => void }>()
|
||||
|
||||
setTimeout = (callback: () => void, delay: number) => {
|
||||
const id = this.nextId++
|
||||
this.timers.set(id, { time: this.now + delay, callback })
|
||||
return id as unknown as ReturnType<typeof setTimeout>
|
||||
}
|
||||
|
||||
clearTimeout = (handle: ReturnType<typeof setTimeout>) => {
|
||||
this.timers.delete(handle as unknown as number)
|
||||
}
|
||||
|
||||
advance(ms: number) {
|
||||
this.now += ms
|
||||
let ran = true
|
||||
while (ran) {
|
||||
ran = false
|
||||
for (const [id, timer] of [...this.timers.entries()].sort((a, b) => a[1].time - b[1].time)) {
|
||||
if (timer.time <= this.now) {
|
||||
this.timers.delete(id)
|
||||
timer.callback()
|
||||
ran = true
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
getNow = () => this.now
|
||||
}
|
||||
|
||||
describe("Task.scheduleAssistantPresentation", () => {
|
||||
function createTaskDouble() {
|
||||
const task = Object.create(Task.prototype) as any
|
||||
|
||||
task.requestLatencyMetrics = {
|
||||
presentationInvocationCount: 0,
|
||||
presentationTrigger: undefined,
|
||||
}
|
||||
task.presentationSchedulingDisabled = false
|
||||
task.taskId = "task-test"
|
||||
|
||||
return task
|
||||
}
|
||||
|
||||
async function flushMicrotasks(iterations = 20) {
|
||||
for (let i = 0; i < iterations; i++) {
|
||||
await Promise.resolve()
|
||||
}
|
||||
}
|
||||
|
||||
function createPresentationTaskDouble() {
|
||||
const task = createTaskDouble()
|
||||
const events: string[] = []
|
||||
|
||||
task.taskState = {
|
||||
abort: false,
|
||||
presentAssistantMessageLocked: false,
|
||||
presentAssistantMessageHasPendingUpdates: false,
|
||||
currentStreamingContentIndex: 0,
|
||||
assistantMessageContent: [],
|
||||
didCompleteReadingStream: true,
|
||||
userMessageContentReady: false,
|
||||
didRejectTool: false,
|
||||
didAlreadyUseTool: false,
|
||||
} as any
|
||||
task.say = async (type: string, text?: string, _images?: unknown, _files?: unknown, _partial?: boolean) => {
|
||||
events.push(`${type}:${text ?? ""}`)
|
||||
return undefined
|
||||
}
|
||||
task.toolExecutor = {
|
||||
executeTool: async (block: { name: string }) => {
|
||||
events.push(`tool:${block.name}`)
|
||||
},
|
||||
} as any
|
||||
task.isParallelToolCallingEnabled = () => true
|
||||
task.initialCheckpointCommitPromise = undefined
|
||||
|
||||
return { task, events }
|
||||
}
|
||||
|
||||
it("increments request metrics and routes scheduled work through the scheduler", () => {
|
||||
const task = createTaskDouble()
|
||||
const requestedPriorities: string[] = []
|
||||
let flushedImmediately = 0
|
||||
|
||||
task.presentationScheduler = {
|
||||
requestFlush: (priority: string) => {
|
||||
requestedPriorities.push(priority)
|
||||
},
|
||||
}
|
||||
task.flushAssistantPresentation = async () => {
|
||||
flushedImmediately += 1
|
||||
}
|
||||
|
||||
task.scheduleAssistantPresentation("text", "normal")
|
||||
|
||||
assert.equal(task.requestLatencyMetrics.presentationInvocationCount, 1)
|
||||
assert.equal(task.requestLatencyMetrics.presentationTrigger, "text")
|
||||
assert.deepStrictEqual(requestedPriorities, ["normal"])
|
||||
assert.equal(flushedImmediately, 0)
|
||||
})
|
||||
|
||||
it("scheduling-disabled mode still drains immediately", async () => {
|
||||
const task = createTaskDouble()
|
||||
let scheduledFlushes = 0
|
||||
let flushedImmediately = 0
|
||||
|
||||
task.presentationSchedulingDisabled = true
|
||||
task.presentationScheduler = {
|
||||
requestFlush: () => {
|
||||
scheduledFlushes += 1
|
||||
},
|
||||
}
|
||||
task.flushAssistantPresentation = async () => {
|
||||
flushedImmediately += 1
|
||||
}
|
||||
|
||||
task.scheduleAssistantPresentation("tool", "immediate")
|
||||
await Promise.resolve()
|
||||
|
||||
assert.equal(task.requestLatencyMetrics.presentationInvocationCount, 1)
|
||||
assert.equal(task.requestLatencyMetrics.presentationTrigger, "tool")
|
||||
assert.equal(flushedImmediately, 1)
|
||||
assert.equal(scheduledFlushes, 0)
|
||||
})
|
||||
|
||||
it("coalesces many scheduled text updates into fewer flushes than request count", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
const task = createTaskDouble()
|
||||
let flushCount = 0
|
||||
|
||||
task.presentationScheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
flushCount += 1
|
||||
},
|
||||
getDelayMs: () => 50,
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
getNow: timer.getNow,
|
||||
})
|
||||
task.flushAssistantPresentation = async () => {
|
||||
flushCount += 1
|
||||
}
|
||||
|
||||
for (let i = 0; i < 5; i++) {
|
||||
task.scheduleAssistantPresentation("text", "normal")
|
||||
}
|
||||
|
||||
assert.equal(task.requestLatencyMetrics.presentationInvocationCount, 5)
|
||||
assert.equal(flushCount, 0)
|
||||
|
||||
timer.advance(50)
|
||||
await flushMicrotasks()
|
||||
|
||||
assert.equal(flushCount, 1)
|
||||
assert.ok(flushCount < task.requestLatencyMetrics.presentationInvocationCount)
|
||||
})
|
||||
|
||||
it("treats the first visible token and tool transitions as immediate-priority boundaries", () => {
|
||||
const task = createTaskDouble()
|
||||
|
||||
assert.equal(task.getPresentationPriorityForChunk({ chunkType: "text", hadVisibleAssistantContent: false }), "immediate")
|
||||
assert.equal(
|
||||
task.getPresentationPriorityForChunk({ chunkType: "tool_calls", hadVisibleAssistantContent: true }),
|
||||
"immediate",
|
||||
)
|
||||
assert.equal(task.getPresentationPriorityForChunk({ chunkType: "reasoning", hadVisibleAssistantContent: true }), "normal")
|
||||
})
|
||||
|
||||
it("flushes immediate-priority first-token presentations without waiting for cadence timers", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
const task = createTaskDouble()
|
||||
let flushCount = 0
|
||||
|
||||
task.presentationScheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
flushCount += 1
|
||||
},
|
||||
getDelayMs: (priority) => (priority === "immediate" ? 0 : 50),
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
getNow: timer.getNow,
|
||||
})
|
||||
task.flushAssistantPresentation = async () => {
|
||||
flushCount += 1
|
||||
}
|
||||
|
||||
task.scheduleAssistantPresentation("text", "immediate")
|
||||
await flushMicrotasks()
|
||||
|
||||
assert.equal(flushCount, 1)
|
||||
})
|
||||
|
||||
it("preserves text-before-tool execution order when draining presented content", async () => {
|
||||
const { task, events } = createPresentationTaskDouble()
|
||||
task.taskState.assistantMessageContent = [
|
||||
{ type: "text", content: "hello", partial: false },
|
||||
{ type: "tool_use", name: "read_file", partial: false, input: {} },
|
||||
]
|
||||
|
||||
await task.presentAssistantMessage()
|
||||
|
||||
assert.deepStrictEqual(events, ["text:hello", "tool:read_file"])
|
||||
assert.equal(task.taskState.userMessageContentReady, true)
|
||||
})
|
||||
|
||||
it("flushNow presents final text before the next request can proceed", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
const { task, events } = createPresentationTaskDouble()
|
||||
task.taskState.assistantMessageContent = [{ type: "text", content: "final answer", partial: false }]
|
||||
|
||||
task.presentationScheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
await task.presentAssistantMessage()
|
||||
},
|
||||
getDelayMs: () => 50,
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
getNow: timer.getNow,
|
||||
})
|
||||
|
||||
task.scheduleAssistantPresentation("text", "normal")
|
||||
assert.equal(task.taskState.userMessageContentReady, false)
|
||||
|
||||
await task.presentationScheduler.flushNow()
|
||||
|
||||
assert.deepStrictEqual(events, ["text:final answer"])
|
||||
assert.equal(task.taskState.userMessageContentReady, true)
|
||||
assert.equal(task.taskState.currentStreamingContentIndex, 1)
|
||||
})
|
||||
|
||||
it("shows meaningfully higher presentation activity when scheduling is disabled for the same burst workload", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
const scheduledTask = createTaskDouble()
|
||||
const immediateTask = createTaskDouble()
|
||||
let scheduledFlushCount = 0
|
||||
let immediateFlushCount = 0
|
||||
|
||||
scheduledTask.presentationScheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
scheduledFlushCount += 1
|
||||
},
|
||||
getDelayMs: () => 50,
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
getNow: timer.getNow,
|
||||
})
|
||||
scheduledTask.flushAssistantPresentation = async () => {
|
||||
scheduledFlushCount += 1
|
||||
}
|
||||
|
||||
immediateTask.presentationSchedulingDisabled = true
|
||||
immediateTask.presentationScheduler = {
|
||||
requestFlush: () => undefined,
|
||||
}
|
||||
immediateTask.flushAssistantPresentation = async () => {
|
||||
immediateFlushCount += 1
|
||||
}
|
||||
|
||||
for (let i = 0; i < 5; i++) {
|
||||
scheduledTask.scheduleAssistantPresentation("text", "normal")
|
||||
immediateTask.scheduleAssistantPresentation("text", "normal")
|
||||
}
|
||||
|
||||
await flushMicrotasks()
|
||||
timer.advance(50)
|
||||
await flushMicrotasks()
|
||||
|
||||
assert.equal(scheduledFlushCount, 1)
|
||||
assert.equal(immediateFlushCount, 5)
|
||||
assert.ok(immediateFlushCount > scheduledFlushCount)
|
||||
})
|
||||
|
||||
it("reduces presentation flushes for a long-stream / large-file-like mixed workload", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
const scheduledTask = createTaskDouble()
|
||||
const immediateTask = createTaskDouble()
|
||||
let scheduledFlushCount = 0
|
||||
let immediateFlushCount = 0
|
||||
|
||||
scheduledTask.presentationScheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
scheduledFlushCount += 1
|
||||
},
|
||||
getDelayMs: (priority) => (priority === "immediate" ? 0 : 50),
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
getNow: timer.getNow,
|
||||
})
|
||||
scheduledTask.flushAssistantPresentation = async () => {
|
||||
scheduledFlushCount += 1
|
||||
}
|
||||
|
||||
immediateTask.presentationSchedulingDisabled = true
|
||||
immediateTask.presentationScheduler = {
|
||||
requestFlush: () => undefined,
|
||||
}
|
||||
immediateTask.flushAssistantPresentation = async () => {
|
||||
immediateFlushCount += 1
|
||||
}
|
||||
|
||||
const workload: Array<["text" | "reasoning" | "tool", "immediate" | "normal"]> = [
|
||||
["text", "immediate"],
|
||||
["reasoning", "normal"],
|
||||
["reasoning", "normal"],
|
||||
["text", "normal"],
|
||||
["text", "normal"],
|
||||
["tool", "immediate"],
|
||||
["text", "normal"],
|
||||
["reasoning", "normal"],
|
||||
["text", "normal"],
|
||||
["tool", "immediate"],
|
||||
["text", "normal"],
|
||||
]
|
||||
|
||||
for (const [trigger, priority] of workload) {
|
||||
scheduledTask.scheduleAssistantPresentation(trigger, priority)
|
||||
immediateTask.scheduleAssistantPresentation(trigger, priority)
|
||||
await flushMicrotasks(5)
|
||||
}
|
||||
|
||||
timer.advance(50)
|
||||
await flushMicrotasks()
|
||||
|
||||
assert.ok(scheduledFlushCount < immediateFlushCount)
|
||||
assert.ok(scheduledFlushCount <= 6, `expected coalesced flushes, got ${scheduledFlushCount}`)
|
||||
assert.equal(immediateTask.requestLatencyMetrics.presentationInvocationCount, workload.length)
|
||||
assert.equal(scheduledTask.requestLatencyMetrics.presentationInvocationCount, workload.length)
|
||||
})
|
||||
})
|
||||
@@ -0,0 +1,192 @@
|
||||
import { strict as assert } from "assert"
|
||||
import { TaskPresentationScheduler } from "../TaskPresentationScheduler"
|
||||
|
||||
class FakeTimerController {
|
||||
private now = 0
|
||||
private nextId = 1
|
||||
private timers = new Map<number, { time: number; callback: () => void }>()
|
||||
|
||||
setTimeout = (callback: () => void, delay: number) => {
|
||||
const id = this.nextId++
|
||||
this.timers.set(id, { time: this.now + delay, callback })
|
||||
return id as unknown as ReturnType<typeof setTimeout>
|
||||
}
|
||||
|
||||
clearTimeout = (handle: ReturnType<typeof setTimeout>) => {
|
||||
this.timers.delete(handle as unknown as number)
|
||||
}
|
||||
|
||||
advance(ms: number) {
|
||||
this.now += ms
|
||||
let ran = true
|
||||
while (ran) {
|
||||
ran = false
|
||||
for (const [id, timer] of [...this.timers.entries()].sort((a, b) => a[1].time - b[1].time)) {
|
||||
if (timer.time <= this.now) {
|
||||
this.timers.delete(id)
|
||||
timer.callback()
|
||||
ran = true
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
describe("TaskPresentationScheduler", () => {
|
||||
it("coalesces multiple requests within the cadence window into one flush", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
let flushCount = 0
|
||||
const scheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
flushCount++
|
||||
},
|
||||
getDelayMs: () => 50,
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
})
|
||||
|
||||
scheduler.requestFlush("normal")
|
||||
scheduler.requestFlush("normal")
|
||||
scheduler.requestFlush("low")
|
||||
timer.advance(49)
|
||||
assert.equal(flushCount, 0)
|
||||
timer.advance(1)
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 1)
|
||||
})
|
||||
|
||||
it("immediate flush preempts scheduled normal work", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
let flushCount = 0
|
||||
const scheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
flushCount++
|
||||
},
|
||||
getDelayMs: () => 50,
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
})
|
||||
|
||||
scheduler.requestFlush("normal")
|
||||
await scheduler.flushNow()
|
||||
assert.equal(flushCount, 1)
|
||||
timer.advance(100)
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 1)
|
||||
})
|
||||
|
||||
it("runs one follow-up flush when new work arrives during an active flush", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
let flushCount = 0
|
||||
let resolveFlush: (() => void) | undefined
|
||||
const scheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
flushCount++
|
||||
await new Promise<void>((resolve) => {
|
||||
resolveFlush = resolve
|
||||
})
|
||||
},
|
||||
getDelayMs: () => 10,
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
})
|
||||
|
||||
scheduler.requestFlush("normal")
|
||||
timer.advance(10)
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 1)
|
||||
|
||||
scheduler.requestFlush("normal")
|
||||
resolveFlush?.()
|
||||
await Promise.resolve()
|
||||
await Promise.resolve()
|
||||
timer.advance(10)
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 2)
|
||||
})
|
||||
|
||||
it("disposes pending work", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
let flushCount = 0
|
||||
const scheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
flushCount++
|
||||
},
|
||||
getDelayMs: () => 50,
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
})
|
||||
|
||||
scheduler.requestFlush("normal")
|
||||
await scheduler.dispose()
|
||||
timer.advance(100)
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 0)
|
||||
})
|
||||
|
||||
it("does not schedule a follow-up flush after disposal during an active flush", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
let flushCount = 0
|
||||
let resolveFlush: (() => void) | undefined
|
||||
const scheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
flushCount++
|
||||
await new Promise<void>((resolve) => {
|
||||
resolveFlush = resolve
|
||||
})
|
||||
},
|
||||
getDelayMs: () => 10,
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
})
|
||||
|
||||
scheduler.requestFlush("normal")
|
||||
timer.advance(10)
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 1)
|
||||
|
||||
scheduler.requestFlush("normal")
|
||||
await scheduler.dispose()
|
||||
resolveFlush?.()
|
||||
await Promise.resolve()
|
||||
await Promise.resolve()
|
||||
timer.advance(20)
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 1)
|
||||
})
|
||||
|
||||
it("flushNow drains pending updates immediately after the current flush completes", async () => {
|
||||
const timer = new FakeTimerController()
|
||||
let flushCount = 0
|
||||
let resolveFlush: (() => void) | undefined
|
||||
const scheduler = new TaskPresentationScheduler({
|
||||
flush: async () => {
|
||||
flushCount++
|
||||
await new Promise<void>((resolve) => {
|
||||
resolveFlush = resolve
|
||||
})
|
||||
},
|
||||
getDelayMs: () => 25,
|
||||
setTimeoutFn: timer.setTimeout as typeof setTimeout,
|
||||
clearTimeoutFn: timer.clearTimeout as typeof clearTimeout,
|
||||
})
|
||||
|
||||
scheduler.requestFlush("normal")
|
||||
timer.advance(25)
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 1)
|
||||
|
||||
scheduler.requestFlush("normal")
|
||||
const drainPromise = scheduler.flushNow()
|
||||
resolveFlush?.()
|
||||
await Promise.resolve()
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 2)
|
||||
|
||||
resolveFlush?.()
|
||||
await drainPromise
|
||||
timer.advance(50)
|
||||
await Promise.resolve()
|
||||
assert.equal(flushCount, 2)
|
||||
})
|
||||
})
|
||||
@@ -0,0 +1,47 @@
|
||||
import { strict as assert } from "assert"
|
||||
import {
|
||||
getPresentationCadenceMs,
|
||||
isPresentationSchedulingDisabled,
|
||||
isRemoteWorkspaceEnvironment,
|
||||
summarizeChunkToWebviewDelays,
|
||||
} from "../latency"
|
||||
|
||||
describe("task latency helpers", () => {
|
||||
afterEach(() => {
|
||||
delete process.env.CLINE_PRESENTATION_CADENCE_MS
|
||||
delete process.env.CLINE_REMOTE_PRESENTATION_CADENCE_MS
|
||||
delete process.env.CLINE_DISABLE_PRESENTATION_SCHEDULER
|
||||
})
|
||||
|
||||
it("detects remote workspaces from remoteName, platform, and version metadata", () => {
|
||||
assert.equal(isRemoteWorkspaceEnvironment({ remoteName: "ssh-remote" }), true)
|
||||
assert.equal(isRemoteWorkspaceEnvironment({ platform: "VS Code Remote" }), true)
|
||||
assert.equal(isRemoteWorkspaceEnvironment({ version: "Remote Server 1.0" }), true)
|
||||
assert.equal(isRemoteWorkspaceEnvironment({ platform: "darwin", version: "1.0.0", remoteName: null }), false)
|
||||
})
|
||||
|
||||
it("uses remote-aware presentation cadences", () => {
|
||||
assert.equal(getPresentationCadenceMs(false, "immediate"), 0)
|
||||
assert.equal(getPresentationCadenceMs(false, "normal"), 40)
|
||||
assert.equal(getPresentationCadenceMs(true, "normal"), 90)
|
||||
assert.equal(getPresentationCadenceMs(true, "low"), 125)
|
||||
})
|
||||
|
||||
it("respects cadence overrides from environment variables", () => {
|
||||
process.env.CLINE_PRESENTATION_CADENCE_MS = "22"
|
||||
process.env.CLINE_REMOTE_PRESENTATION_CADENCE_MS = "77"
|
||||
|
||||
assert.equal(getPresentationCadenceMs(false, "normal"), 22)
|
||||
assert.equal(getPresentationCadenceMs(true, "normal"), 77)
|
||||
})
|
||||
|
||||
it("supports development flags for disabling presentation scheduling", () => {
|
||||
process.env.CLINE_DISABLE_PRESENTATION_SCHEDULER = "true"
|
||||
assert.equal(isPresentationSchedulingDisabled(), true)
|
||||
})
|
||||
|
||||
it("summarizes chunk-to-webview delays using median and p95", () => {
|
||||
assert.deepStrictEqual(summarizeChunkToWebviewDelays([]), { medianMs: 0, p95Ms: 0 })
|
||||
assert.deepStrictEqual(summarizeChunkToWebviewDelays([10, 20, 30, 40, 50]), { medianMs: 30, p95Ms: 50 })
|
||||
})
|
||||
})
|
||||
+132
-16
@@ -114,9 +114,17 @@ import { Controller } from "../controller"
|
||||
import { executeHook } from "../hooks/hook-executor"
|
||||
import { StateManager } from "../storage/StateManager"
|
||||
import { FocusChainManager } from "./focus-chain"
|
||||
import {
|
||||
getPresentationCadenceMs,
|
||||
isPresentationSchedulingDisabled,
|
||||
isRemoteWorkspaceEnvironment,
|
||||
summarizeChunkToWebviewDelays,
|
||||
type TaskLatencyTrigger,
|
||||
} from "./latency"
|
||||
import { MessageStateHandler } from "./message-state"
|
||||
import { StreamChunkCoordinator } from "./StreamChunkCoordinator"
|
||||
import { StreamResponseHandler } from "./StreamResponseHandler"
|
||||
import { type PresentationPriority, TaskPresentationScheduler } from "./TaskPresentationScheduler"
|
||||
import { TaskState } from "./TaskState"
|
||||
import { ToolExecutor } from "./ToolExecutor"
|
||||
import { detectAvailableCliTools, extractProviderDomainFromUrl, updateApiReqMsg } from "./utils"
|
||||
@@ -256,6 +264,10 @@ export class Task {
|
||||
|
||||
// Command executor for running shell commands (extracted from executeCommandTool)
|
||||
private commandExecutor!: CommandExecutor
|
||||
private isRemoteWorkspaceEnvironment = false
|
||||
private readonly presentationScheduler: TaskPresentationScheduler
|
||||
private readonly presentationSchedulingDisabled = isPresentationSchedulingDisabled()
|
||||
private requestLatencyMetrics = this.createRequestLatencyMetrics()
|
||||
|
||||
constructor(params: TaskParams) {
|
||||
const {
|
||||
@@ -283,6 +295,14 @@ export class Task {
|
||||
|
||||
this.taskInitializationStartTime = performance.now()
|
||||
this.taskState = new TaskState()
|
||||
void HostProvider.env
|
||||
.getHostVersion({})
|
||||
.then((hostVersion) => {
|
||||
this.isRemoteWorkspaceEnvironment = isRemoteWorkspaceEnvironment(hostVersion)
|
||||
})
|
||||
.catch((error) => {
|
||||
Logger.debug(`[Task ${taskId}] Failed to detect remote workspace state: ${error}`)
|
||||
})
|
||||
this.controller = controller
|
||||
this.mcpHub = mcpHub
|
||||
this.updateTaskHistory = updateTaskHistory
|
||||
@@ -531,6 +551,17 @@ export class Task {
|
||||
|
||||
this.commandExecutor = new CommandExecutor(commandExecutorConfig, commandExecutorCallbacks)
|
||||
|
||||
this.presentationScheduler = new TaskPresentationScheduler({
|
||||
flush: async () => this.flushAssistantPresentation(),
|
||||
getDelayMs: (priority) => getPresentationCadenceMs(this.isRemoteWorkspaceEnvironment, priority),
|
||||
onFlushError: (error) => Logger.debug(`[Task] Failed scheduled presentation flush: ${error}`),
|
||||
metrics: {
|
||||
onFlushCompleted: (durationMs, _priority) => {
|
||||
this.requestLatencyMetrics.presentationDurationMs += durationMs
|
||||
},
|
||||
},
|
||||
})
|
||||
|
||||
this.toolExecutor = new ToolExecutor(
|
||||
this.taskState,
|
||||
this.messageStateHandler,
|
||||
@@ -569,6 +600,80 @@ export class Task {
|
||||
)
|
||||
}
|
||||
|
||||
private createRequestLatencyMetrics() {
|
||||
return {
|
||||
presentationInvocationCount: 0,
|
||||
presentationDurationMs: 0,
|
||||
presentationTrigger: undefined as string | undefined,
|
||||
partialMessageCount: 0,
|
||||
partialMessagePayloadBytes: 0,
|
||||
partialMessageBroadcastDurationMs: 0,
|
||||
chunkToWebviewDelaysMs: [] as number[],
|
||||
}
|
||||
}
|
||||
|
||||
private notePartialMessageEvent(stats: { payloadBytes: number; broadcastDurationMs: number }) {
|
||||
this.requestLatencyMetrics.partialMessageCount += 1
|
||||
this.requestLatencyMetrics.partialMessagePayloadBytes += stats.payloadBytes
|
||||
this.requestLatencyMetrics.partialMessageBroadcastDurationMs += stats.broadcastDurationMs
|
||||
if (this.taskState.currentChunkReceivedAtMs) {
|
||||
this.requestLatencyMetrics.chunkToWebviewDelaysMs.push(
|
||||
Math.max(0, performance.now() - this.taskState.currentChunkReceivedAtMs),
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
private captureRequestLatencyMetrics() {
|
||||
const chunkDelays = summarizeChunkToWebviewDelays(this.requestLatencyMetrics.chunkToWebviewDelaysMs)
|
||||
telemetryService.captureTaskLatencyMetrics({
|
||||
ulid: this.ulid,
|
||||
requestIndex: this.taskState.apiRequestCount,
|
||||
isRemoteWorkspace: this.isRemoteWorkspaceEnvironment,
|
||||
presentationInvocationCount: this.requestLatencyMetrics.presentationInvocationCount,
|
||||
presentationDurationMs: this.requestLatencyMetrics.presentationDurationMs,
|
||||
presentationTrigger: this.requestLatencyMetrics.presentationTrigger,
|
||||
partialMessageCount: this.requestLatencyMetrics.partialMessageCount,
|
||||
partialMessagePayloadBytes: this.requestLatencyMetrics.partialMessagePayloadBytes,
|
||||
partialMessageBroadcastDurationMs: this.requestLatencyMetrics.partialMessageBroadcastDurationMs,
|
||||
chunkToWebviewMedianMs: chunkDelays.medianMs,
|
||||
chunkToWebviewP95Ms: chunkDelays.p95Ms,
|
||||
})
|
||||
}
|
||||
|
||||
private scheduleAssistantPresentation(trigger: TaskLatencyTrigger, priority: PresentationPriority = "normal") {
|
||||
this.requestLatencyMetrics.presentationInvocationCount += 1
|
||||
this.requestLatencyMetrics.presentationTrigger = trigger
|
||||
if (this.presentationSchedulingDisabled) {
|
||||
void this.flushAssistantPresentation().catch((error) =>
|
||||
Logger.debug(`[Task] Failed immediate presentation flush: ${error}`),
|
||||
)
|
||||
return
|
||||
}
|
||||
|
||||
// Immediate semantic boundaries: first visible token, tool transitions, finalization, and cleanup drains.
|
||||
Logger.debug(`[Task ${this.taskId}] schedule assistant presentation (${trigger}, ${priority})`)
|
||||
this.presentationScheduler.requestFlush(priority)
|
||||
}
|
||||
|
||||
private async flushAssistantPresentation() {
|
||||
await this.presentAssistantMessage()
|
||||
}
|
||||
|
||||
private getPresentationPriorityForChunk(args: {
|
||||
chunkType: "text" | "reasoning" | "tool_calls"
|
||||
hadVisibleAssistantContent: boolean
|
||||
}): PresentationPriority {
|
||||
if (!args.hadVisibleAssistantContent) {
|
||||
return "immediate"
|
||||
}
|
||||
|
||||
if (args.chunkType === "tool_calls") {
|
||||
return "immediate"
|
||||
}
|
||||
|
||||
return "normal"
|
||||
}
|
||||
|
||||
// Communicate with webview
|
||||
|
||||
// partial has three valid states true (partial message), false (completion of partial message), undefined (individual complete message)
|
||||
@@ -606,7 +711,7 @@ export class Task {
|
||||
// await this.saveClineMessagesAndUpdateHistory()
|
||||
// await this.postStateToWebview()
|
||||
const protoMessage = convertClineMessageToProto(lastMessage)
|
||||
await sendPartialMessageEvent(protoMessage)
|
||||
this.notePartialMessageEvent(await sendPartialMessageEvent(protoMessage))
|
||||
throw new Error("Current ask promise was ignored 1")
|
||||
}
|
||||
// this is a new partial message, so add it with partial state
|
||||
@@ -648,7 +753,7 @@ export class Task {
|
||||
})
|
||||
// await this.postStateToWebview()
|
||||
const protoMessage = convertClineMessageToProto(lastMessage)
|
||||
await sendPartialMessageEvent(protoMessage)
|
||||
this.notePartialMessageEvent(await sendPartialMessageEvent(protoMessage))
|
||||
} else {
|
||||
// this is a new partial=false message, so add it like normal
|
||||
this.taskState.askResponse = undefined
|
||||
@@ -787,7 +892,7 @@ export class Task {
|
||||
})
|
||||
|
||||
const protoMessage = convertClineMessageToProto(lastMessage)
|
||||
await sendPartialMessageEvent(protoMessage)
|
||||
this.notePartialMessageEvent(await sendPartialMessageEvent(protoMessage))
|
||||
return undefined
|
||||
}
|
||||
// this is a new partial message, so add it with partial state
|
||||
@@ -821,7 +926,7 @@ export class Task {
|
||||
|
||||
// await this.postStateToWebview()
|
||||
const protoMessage = convertClineMessageToProto(lastMessage)
|
||||
await sendPartialMessageEvent(protoMessage) // more performant than an entire postStateToWebview
|
||||
this.notePartialMessageEvent(await sendPartialMessageEvent(protoMessage)) // more performant than an entire postStateToWebview
|
||||
return undefined
|
||||
}
|
||||
// this is a new partial=false message, so add it like normal
|
||||
@@ -1583,6 +1688,7 @@ export class Task {
|
||||
if (this.FocusChainManager) {
|
||||
this.FocusChainManager.dispose()
|
||||
}
|
||||
await this.presentationScheduler.dispose()
|
||||
} finally {
|
||||
// Release task folder lock
|
||||
if (this.taskLockAcquired) {
|
||||
@@ -2730,7 +2836,7 @@ export class Task {
|
||||
})
|
||||
const completedReasoning = this.messageStateHandler.getClineMessages()[pendingReasoningIndex]
|
||||
if (completedReasoning) {
|
||||
await sendPartialMessageEvent(convertClineMessageToProto(completedReasoning))
|
||||
this.notePartialMessageEvent(await sendPartialMessageEvent(convertClineMessageToProto(completedReasoning)))
|
||||
}
|
||||
return true
|
||||
}
|
||||
@@ -2764,6 +2870,8 @@ export class Task {
|
||||
if (!chunk) {
|
||||
break
|
||||
}
|
||||
this.taskState.currentChunkReceivedAtMs = performance.now()
|
||||
const hadVisibleAssistantContent = assistantMessage.trim().length > 0
|
||||
if (!this.taskState.taskFirstTokenTimeMs) {
|
||||
this.taskState.taskFirstTokenTimeMs = Math.max(0, Date.now() - this.taskState.taskStartTimeMs)
|
||||
}
|
||||
@@ -2790,6 +2898,10 @@ export class Task {
|
||||
await this.say("reasoning", thinkingBlock.thinking, undefined, undefined, true)
|
||||
}
|
||||
}
|
||||
this.scheduleAssistantPresentation(
|
||||
"reasoning",
|
||||
this.getPresentationPriorityForChunk({ chunkType: "reasoning", hadVisibleAssistantContent }),
|
||||
)
|
||||
|
||||
break
|
||||
}
|
||||
@@ -2812,6 +2924,10 @@ export class Task {
|
||||
}
|
||||
|
||||
await this.processNativeToolCalls(assistantTextOnly, toolUseHandler.getPartialToolUsesAsContent())
|
||||
this.scheduleAssistantPresentation(
|
||||
"tool",
|
||||
this.getPresentationPriorityForChunk({ chunkType: "tool_calls", hadVisibleAssistantContent }),
|
||||
)
|
||||
break
|
||||
}
|
||||
case "text": {
|
||||
@@ -2839,16 +2955,14 @@ export class Task {
|
||||
if (this.taskState.assistantMessageContent.length > prevLength) {
|
||||
this.taskState.userMessageContentReady = false // new content we need to present, reset to false in case previous content set this to true
|
||||
}
|
||||
this.scheduleAssistantPresentation(
|
||||
"text",
|
||||
this.getPresentationPriorityForChunk({ chunkType: "text", hadVisibleAssistantContent }),
|
||||
)
|
||||
break
|
||||
}
|
||||
}
|
||||
|
||||
// Present content once per chunk. Calling this from multiple case branches can
|
||||
// race partial updates and duplicate text rows in the chat.
|
||||
await this.presentAssistantMessage().catch((error) =>
|
||||
Logger.debug("[Task] Failed to present message: " + error),
|
||||
)
|
||||
|
||||
if (this.taskState.abort) {
|
||||
this.api.abort?.()
|
||||
if (!this.taskState.abandoned) {
|
||||
@@ -3075,10 +3189,7 @@ export class Task {
|
||||
// in case there are native tool calls pending
|
||||
const partialToolBlocks = toolUseHandler.getPartialToolUsesAsContent()?.map((block) => ({ ...block, partial: false }))
|
||||
await this.processNativeToolCalls(assistantTextOnly, partialToolBlocks)
|
||||
|
||||
if (partialBlocks.length > 0) {
|
||||
await this.presentAssistantMessage() // if there is content to update then it will complete and update this.userMessageContentReady to true, which we pwaitfor before making the next request. all this is really doing is presenting the last partial message that we just set to complete
|
||||
}
|
||||
await this.presentationScheduler.flushNow() // finalization is immediate so no coalesced content remains pending
|
||||
|
||||
// now add to apiconversationhistory
|
||||
// need to save assistant responses to file before proceeding to tool use since user can exit at any moment and we wouldn't be able to save the assistant's response
|
||||
@@ -3205,8 +3316,13 @@ export class Task {
|
||||
return true
|
||||
}
|
||||
|
||||
this.captureRequestLatencyMetrics()
|
||||
this.requestLatencyMetrics = this.createRequestLatencyMetrics()
|
||||
this.taskState.currentChunkReceivedAtMs = undefined
|
||||
return didEndLoop // will always be false for now
|
||||
} catch (_error) {
|
||||
this.requestLatencyMetrics = this.createRequestLatencyMetrics()
|
||||
this.taskState.currentChunkReceivedAtMs = undefined
|
||||
// this should never happen since the only thing that can throw an error is the attemptApiRequest, which is wrapped in a try catch that sends an ask where if noButtonClicked, will clear current task and destroy this instance. However to avoid unhandled promise rejection, we will end this loop which will end execution of this instance (see startTask)
|
||||
return true // needs to be true so parent loop knows to end task
|
||||
}
|
||||
@@ -3369,7 +3485,7 @@ export class Task {
|
||||
lastMessage.partial = false
|
||||
await this.messageStateHandler.saveClineMessagesAndUpdateHistory()
|
||||
const protoMessage = convertClineMessageToProto(lastMessage)
|
||||
await sendPartialMessageEvent(protoMessage)
|
||||
this.notePartialMessageEvent(await sendPartialMessageEvent(protoMessage))
|
||||
}
|
||||
|
||||
this.taskState.assistantMessageContent = [...textBlocks, ...toolBlocks]
|
||||
|
||||
@@ -0,0 +1,75 @@
|
||||
import type { PresentationPriority } from "./TaskPresentationScheduler"
|
||||
|
||||
export type TaskLatencyTrigger = "text" | "reasoning" | "tool" | "finalization" | "other"
|
||||
|
||||
function readBooleanEnv(envVarName: string): boolean {
|
||||
const rawValue = process.env[envVarName]?.toLowerCase()
|
||||
return rawValue === "1" || rawValue === "true" || rawValue === "yes"
|
||||
}
|
||||
|
||||
function readCadenceOverride(envVarName: string): number | undefined {
|
||||
const rawValue = process.env[envVarName]
|
||||
if (!rawValue) {
|
||||
return undefined
|
||||
}
|
||||
|
||||
const parsed = Number.parseInt(rawValue, 10)
|
||||
if (!Number.isFinite(parsed) || parsed < 0) {
|
||||
return undefined
|
||||
}
|
||||
|
||||
return parsed
|
||||
}
|
||||
|
||||
function getCadenceOverride(args: { isRemoteWorkspace: boolean; localEnvVar: string; remoteEnvVar: string }): number | undefined {
|
||||
return args.isRemoteWorkspace ? readCadenceOverride(args.remoteEnvVar) : readCadenceOverride(args.localEnvVar)
|
||||
}
|
||||
|
||||
export function isRemoteWorkspaceEnvironment(host: { platform?: string; version?: string; remoteName?: string | null }): boolean {
|
||||
if (host.remoteName) {
|
||||
return true
|
||||
}
|
||||
|
||||
const platform = host.platform?.toLowerCase() ?? ""
|
||||
const version = host.version?.toLowerCase() ?? ""
|
||||
return platform.includes("remote") || version.includes("remote")
|
||||
}
|
||||
|
||||
export function isPresentationSchedulingDisabled(): boolean {
|
||||
return readBooleanEnv("CLINE_DISABLE_PRESENTATION_SCHEDULER")
|
||||
}
|
||||
|
||||
export function getPresentationCadenceMs(isRemoteWorkspace: boolean, priority: PresentationPriority): number {
|
||||
if (priority === "immediate") {
|
||||
return 0
|
||||
}
|
||||
|
||||
const override = getCadenceOverride({
|
||||
isRemoteWorkspace,
|
||||
localEnvVar: priority === "low" ? "CLINE_PRESENTATION_LOW_CADENCE_MS" : "CLINE_PRESENTATION_CADENCE_MS",
|
||||
remoteEnvVar: priority === "low" ? "CLINE_REMOTE_PRESENTATION_LOW_CADENCE_MS" : "CLINE_REMOTE_PRESENTATION_CADENCE_MS",
|
||||
})
|
||||
if (override !== undefined) {
|
||||
return override
|
||||
}
|
||||
|
||||
if (priority === "low") {
|
||||
return isRemoteWorkspace ? 125 : 50
|
||||
}
|
||||
|
||||
return isRemoteWorkspace ? 90 : 40
|
||||
}
|
||||
|
||||
export function summarizeChunkToWebviewDelays(delaysMs: number[]): { medianMs: number; p95Ms: number } {
|
||||
if (delaysMs.length === 0) {
|
||||
return { medianMs: 0, p95Ms: 0 }
|
||||
}
|
||||
|
||||
const sorted = [...delaysMs].sort((a, b) => a - b)
|
||||
const percentile = (ratio: number) => sorted[Math.min(sorted.length - 1, Math.max(0, Math.ceil(sorted.length * ratio) - 1))]
|
||||
|
||||
return {
|
||||
medianMs: percentile(0.5),
|
||||
p95Ms: percentile(0.95),
|
||||
}
|
||||
}
|
||||
@@ -164,6 +164,14 @@ export class TelemetryService {
|
||||
API: {
|
||||
TTFT_SECONDS: "cline.api.ttft.seconds",
|
||||
DURATION_SECONDS: "cline.api.duration.seconds",
|
||||
PRESENTATION_INVOCATIONS_PER_REQUEST: "cline.api.presentation.invocations.per_request",
|
||||
PRESENTATION_DURATION_SECONDS: "cline.api.presentation.duration.seconds",
|
||||
STATE_POSTS_PER_REQUEST: "cline.api.state_posts.per_request",
|
||||
STATE_SEND_DURATION_SECONDS: "cline.api.state_send.duration.seconds",
|
||||
PARTIAL_MESSAGES_PER_REQUEST: "cline.api.partial_messages.per_request",
|
||||
PARTIAL_MESSAGE_PAYLOAD_BYTES: "cline.api.partial_message_payload.bytes",
|
||||
PARTIAL_MESSAGE_BROADCAST_DURATION_SECONDS: "cline.api.partial_message_broadcast.duration.seconds",
|
||||
CHUNK_TO_WEBVIEW_SECONDS: "cline.api.chunk_to_webview.seconds",
|
||||
THROUGHPUT_TOKENS_PER_SECOND: "cline.api.throughput.tokens_per_second",
|
||||
},
|
||||
HOOKS: {
|
||||
@@ -292,6 +300,8 @@ export class TelemetryService {
|
||||
CLINE_WEB_TOOLS_TOGGLED: "task.cline_web_tools_toggled",
|
||||
// Tracks task initialization timing
|
||||
INITIALIZATION: "task.initialization",
|
||||
// Tracks request-scoped latency metrics for assistant presentation and UI delivery
|
||||
LATENCY_METRICS: "task.latency_metrics",
|
||||
// Terminal execution telemetry events
|
||||
TERMINAL_EXECUTION: "task.terminal_execution",
|
||||
TERMINAL_OUTPUT_FAILURE: "task.terminal_output_failure",
|
||||
@@ -1647,6 +1657,97 @@ export class TelemetryService {
|
||||
})
|
||||
}
|
||||
|
||||
public captureTaskLatencyMetrics(args: {
|
||||
ulid: string
|
||||
requestIndex: number
|
||||
isRemoteWorkspace: boolean
|
||||
presentationInvocationCount?: number
|
||||
presentationDurationMs?: number
|
||||
presentationTrigger?: string
|
||||
statePostCount?: number
|
||||
statePostSendDurationMs?: number
|
||||
partialMessageCount?: number
|
||||
partialMessagePayloadBytes?: number
|
||||
partialMessageBroadcastDurationMs?: number
|
||||
chunkToWebviewMedianMs?: number
|
||||
chunkToWebviewP95Ms?: number
|
||||
}): void {
|
||||
this.capture({
|
||||
event: TelemetryService.EVENTS.TASK.LATENCY_METRICS,
|
||||
properties: args,
|
||||
})
|
||||
|
||||
const attrs = {
|
||||
ulid: args.ulid,
|
||||
request_index: args.requestIndex,
|
||||
is_remote_workspace: args.isRemoteWorkspace,
|
||||
presentation_trigger: args.presentationTrigger,
|
||||
}
|
||||
|
||||
if (Number.isFinite(args.presentationDurationMs)) {
|
||||
this.recordHistogram(
|
||||
TelemetryService.METRICS.API.PRESENTATION_DURATION_SECONDS,
|
||||
(args.presentationDurationMs ?? 0) / 1000,
|
||||
attrs,
|
||||
)
|
||||
}
|
||||
|
||||
if (Number.isFinite(args.presentationInvocationCount)) {
|
||||
this.recordHistogram(
|
||||
TelemetryService.METRICS.API.PRESENTATION_INVOCATIONS_PER_REQUEST,
|
||||
args.presentationInvocationCount ?? 0,
|
||||
attrs,
|
||||
)
|
||||
}
|
||||
|
||||
if (Number.isFinite(args.statePostCount)) {
|
||||
this.recordHistogram(TelemetryService.METRICS.API.STATE_POSTS_PER_REQUEST, args.statePostCount ?? 0, attrs)
|
||||
}
|
||||
|
||||
if (Number.isFinite(args.statePostSendDurationMs) && (args.statePostSendDurationMs ?? 0) > 0) {
|
||||
this.recordHistogram(
|
||||
TelemetryService.METRICS.API.STATE_SEND_DURATION_SECONDS,
|
||||
(args.statePostSendDurationMs ?? 0) / 1000,
|
||||
attrs,
|
||||
)
|
||||
}
|
||||
|
||||
if (Number.isFinite(args.partialMessageCount)) {
|
||||
this.recordHistogram(TelemetryService.METRICS.API.PARTIAL_MESSAGES_PER_REQUEST, args.partialMessageCount ?? 0, attrs)
|
||||
}
|
||||
|
||||
if (Number.isFinite(args.partialMessagePayloadBytes) && (args.partialMessagePayloadBytes ?? 0) > 0) {
|
||||
this.recordHistogram(
|
||||
TelemetryService.METRICS.API.PARTIAL_MESSAGE_PAYLOAD_BYTES,
|
||||
args.partialMessagePayloadBytes ?? 0,
|
||||
attrs,
|
||||
)
|
||||
}
|
||||
|
||||
if (Number.isFinite(args.partialMessageBroadcastDurationMs) && (args.partialMessageBroadcastDurationMs ?? 0) > 0) {
|
||||
this.recordHistogram(
|
||||
TelemetryService.METRICS.API.PARTIAL_MESSAGE_BROADCAST_DURATION_SECONDS,
|
||||
(args.partialMessageBroadcastDurationMs ?? 0) / 1000,
|
||||
attrs,
|
||||
)
|
||||
}
|
||||
|
||||
if (Number.isFinite(args.chunkToWebviewMedianMs)) {
|
||||
this.recordHistogram(
|
||||
TelemetryService.METRICS.API.CHUNK_TO_WEBVIEW_SECONDS,
|
||||
(args.chunkToWebviewMedianMs ?? 0) / 1000,
|
||||
{ ...attrs, percentile: "p50" },
|
||||
)
|
||||
}
|
||||
|
||||
if (Number.isFinite(args.chunkToWebviewP95Ms)) {
|
||||
this.recordHistogram(TelemetryService.METRICS.API.CHUNK_TO_WEBVIEW_SECONDS, (args.chunkToWebviewP95Ms ?? 0) / 1000, {
|
||||
...attrs,
|
||||
percentile: "p95",
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* Records when the rules menu button is clicked to open the rules/workflows modal
|
||||
*/
|
||||
|
||||
@@ -64,6 +64,16 @@ class FakeProvider implements ITelemetryProvider {
|
||||
async dispose(): Promise<void> {}
|
||||
}
|
||||
|
||||
class ThrowingProvider extends FakeProvider {
|
||||
override recordHistogram(): void {
|
||||
throw new Error("histogram failed")
|
||||
}
|
||||
|
||||
override log(): void {
|
||||
throw new Error("log failed")
|
||||
}
|
||||
}
|
||||
|
||||
function createTelemetryService(provider: FakeProvider): TelemetryService {
|
||||
return new TelemetryService([provider], {
|
||||
extension_version: "test",
|
||||
@@ -332,6 +342,65 @@ describe("TelemetryService metrics", () => {
|
||||
assert.strictEqual(durationMetric?.attributes.scope, "task")
|
||||
})
|
||||
|
||||
it("captureTaskLatencyMetrics records presentation and chunk-to-webview histograms", () => {
|
||||
const provider = new FakeProvider()
|
||||
const service = createTelemetryService(provider)
|
||||
|
||||
service.captureTaskLatencyMetrics({
|
||||
ulid: "task-5",
|
||||
requestIndex: 2,
|
||||
isRemoteWorkspace: true,
|
||||
presentationInvocationCount: 4,
|
||||
presentationDurationMs: 120,
|
||||
presentationTrigger: "text",
|
||||
partialMessageCount: 3,
|
||||
partialMessagePayloadBytes: 2048,
|
||||
partialMessageBroadcastDurationMs: 45,
|
||||
chunkToWebviewMedianMs: 80,
|
||||
chunkToWebviewP95Ms: 150,
|
||||
})
|
||||
|
||||
const latencyEvent = provider.logs.find((entry) => entry.event === "task.latency_metrics")
|
||||
assert.ok(latencyEvent)
|
||||
assert.strictEqual(latencyEvent?.properties?.ulid, "task-5")
|
||||
assert.strictEqual(latencyEvent?.properties?.requestIndex, 2)
|
||||
|
||||
const presentationInvocations = provider.histograms.find(
|
||||
(entry) => entry.name === TelemetryService.METRICS.API.PRESENTATION_INVOCATIONS_PER_REQUEST,
|
||||
)
|
||||
assert.ok(presentationInvocations)
|
||||
assert.strictEqual(presentationInvocations?.value, 4)
|
||||
|
||||
const presentationDuration = provider.histograms.find(
|
||||
(entry) => entry.name === TelemetryService.METRICS.API.PRESENTATION_DURATION_SECONDS,
|
||||
)
|
||||
assert.ok(presentationDuration)
|
||||
assert.strictEqual(presentationDuration?.value, 0.12)
|
||||
|
||||
const chunkP95 = provider.histograms.find(
|
||||
(entry) =>
|
||||
entry.name === TelemetryService.METRICS.API.CHUNK_TO_WEBVIEW_SECONDS && entry.attributes.percentile === "p95",
|
||||
)
|
||||
assert.ok(chunkP95)
|
||||
assert.strictEqual(chunkP95?.value, 0.15)
|
||||
})
|
||||
|
||||
it("captureTaskLatencyMetrics is failure-safe when telemetry providers throw", () => {
|
||||
const provider = new ThrowingProvider()
|
||||
const service = createTelemetryService(provider)
|
||||
|
||||
assert.doesNotThrow(() => {
|
||||
service.captureTaskLatencyMetrics({
|
||||
ulid: "task-6",
|
||||
requestIndex: 1,
|
||||
isRemoteWorkspace: false,
|
||||
presentationInvocationCount: 2,
|
||||
presentationDurationMs: 25,
|
||||
chunkToWebviewMedianMs: 10,
|
||||
})
|
||||
})
|
||||
})
|
||||
|
||||
it("captureGrpcResponseSize records histogram with correct name, value, and attributes", () => {
|
||||
const provider = new FakeProvider()
|
||||
const service = createTelemetryService(provider)
|
||||
|
||||
@@ -0,0 +1,90 @@
|
||||
import { strict as assert } from "assert"
|
||||
import { compareTaskLatencySummaries, summarizeTaskLatencyEvents } from "../taskLatencySummary"
|
||||
|
||||
describe("taskLatencySummary", () => {
|
||||
it("summarizes averages and ranges across latency events", () => {
|
||||
const summary = summarizeTaskLatencyEvents([
|
||||
{
|
||||
ulid: "task-1",
|
||||
requestIndex: 1,
|
||||
presentationInvocationCount: 2,
|
||||
partialMessageCount: 4,
|
||||
statePostCount: 1,
|
||||
statePostSerializedBytes: 100,
|
||||
persistenceFlushCount: 1,
|
||||
chunkToWebviewMedianMs: 20,
|
||||
chunkToWebviewP95Ms: 35,
|
||||
taskInitializationDurationMs: 600,
|
||||
},
|
||||
{
|
||||
ulid: "task-1",
|
||||
requestIndex: 2,
|
||||
presentationInvocationCount: 4,
|
||||
partialMessageCount: 6,
|
||||
statePostCount: 3,
|
||||
statePostSerializedBytes: 300,
|
||||
persistenceFlushCount: 2,
|
||||
chunkToWebviewMedianMs: 30,
|
||||
chunkToWebviewP95Ms: 45,
|
||||
taskInitializationDurationMs: 900,
|
||||
},
|
||||
])
|
||||
|
||||
assert.equal(summary.eventCount, 2)
|
||||
assert.equal(summary.requestCount, 2)
|
||||
assert.deepStrictEqual(summary.metrics.presentationInvocationCount, { average: 3, min: 2, max: 4 })
|
||||
assert.deepStrictEqual(summary.metrics.statePostSerializedBytes, { average: 200, min: 100, max: 300 })
|
||||
assert.deepStrictEqual(summary.metrics.chunkToWebviewP95Ms, { average: 40, min: 35, max: 45 })
|
||||
assert.deepStrictEqual(summary.metrics.taskInitializationDurationMs, { average: 750, min: 600, max: 900 })
|
||||
})
|
||||
|
||||
it("returns zeroed summaries when events are empty or metrics are absent", () => {
|
||||
const summary = summarizeTaskLatencyEvents([{ ulid: "task-1", requestIndex: 1 }])
|
||||
assert.equal(summary.eventCount, 1)
|
||||
assert.equal(summary.requestCount, 1)
|
||||
assert.deepStrictEqual(summary.metrics.partialMessageCount, { average: 0, min: 0, max: 0 })
|
||||
|
||||
const empty = summarizeTaskLatencyEvents([])
|
||||
assert.equal(empty.eventCount, 0)
|
||||
assert.equal(empty.requestCount, 0)
|
||||
assert.deepStrictEqual(empty.metrics.statePostCount, { average: 0, min: 0, max: 0 })
|
||||
})
|
||||
|
||||
it("compares latency summaries for before/after analysis", () => {
|
||||
const baseline = summarizeTaskLatencyEvents([
|
||||
{ ulid: "task", requestIndex: 1, presentationInvocationCount: 5, statePostCount: 4 },
|
||||
])
|
||||
const candidate = summarizeTaskLatencyEvents([
|
||||
{ ulid: "task", requestIndex: 1, presentationInvocationCount: 3, statePostCount: 2 },
|
||||
])
|
||||
|
||||
const comparison = compareTaskLatencySummaries(baseline, candidate)
|
||||
assert.equal(comparison.baselineEvents, 1)
|
||||
assert.equal(comparison.candidateEvents, 1)
|
||||
assert.deepStrictEqual(comparison.metricDiffs.presentationInvocationCount, {
|
||||
averageDelta: -2,
|
||||
minDelta: -2,
|
||||
maxDelta: -2,
|
||||
})
|
||||
assert.deepStrictEqual(comparison.metricDiffs.statePostCount, {
|
||||
averageDelta: -2,
|
||||
minDelta: -2,
|
||||
maxDelta: -2,
|
||||
})
|
||||
})
|
||||
|
||||
it("normalizes task initialization events into latency summaries", () => {
|
||||
const summary = summarizeTaskLatencyEvents([
|
||||
{ event: "task.initialization", ulid: "task-1", taskId: "task-a", durationMs: 500 },
|
||||
{ event: "task.initialization", ulid: "task-2", taskId: "task-b", durationMs: 700 },
|
||||
])
|
||||
|
||||
assert.equal(summary.eventCount, 2)
|
||||
assert.equal(summary.requestCount, 0)
|
||||
assert.deepStrictEqual(summary.metrics.taskInitializationDurationMs, {
|
||||
average: 600,
|
||||
min: 500,
|
||||
max: 700,
|
||||
})
|
||||
})
|
||||
})
|
||||
@@ -0,0 +1,122 @@
|
||||
type TaskLatencyEvent = {
|
||||
presentationInvocationCount?: number
|
||||
partialMessageCount?: number
|
||||
statePostCount?: number
|
||||
statePostSerializedBytes?: number
|
||||
persistenceFlushCount?: number
|
||||
chunkToWebviewMedianMs?: number
|
||||
chunkToWebviewP95Ms?: number
|
||||
taskInitializationDurationMs?: number
|
||||
durationMs?: number
|
||||
requestIndex?: number
|
||||
ulid?: string
|
||||
taskId?: string
|
||||
event?: string
|
||||
[key: string]: unknown
|
||||
}
|
||||
|
||||
type NumericMetricKey =
|
||||
| "presentationInvocationCount"
|
||||
| "partialMessageCount"
|
||||
| "statePostCount"
|
||||
| "statePostSerializedBytes"
|
||||
| "persistenceFlushCount"
|
||||
| "chunkToWebviewMedianMs"
|
||||
| "chunkToWebviewP95Ms"
|
||||
| "taskInitializationDurationMs"
|
||||
|
||||
export type TaskLatencySummary = {
|
||||
eventCount: number
|
||||
requestCount: number
|
||||
metrics: Record<NumericMetricKey, { average: number; min: number; max: number }>
|
||||
}
|
||||
|
||||
export type TaskLatencySummaryComparison = {
|
||||
baselineEvents: number
|
||||
candidateEvents: number
|
||||
metricDiffs: Record<NumericMetricKey, { averageDelta: number; minDelta: number; maxDelta: number }>
|
||||
}
|
||||
|
||||
const METRIC_KEYS: NumericMetricKey[] = [
|
||||
"presentationInvocationCount",
|
||||
"partialMessageCount",
|
||||
"statePostCount",
|
||||
"statePostSerializedBytes",
|
||||
"persistenceFlushCount",
|
||||
"chunkToWebviewMedianMs",
|
||||
"chunkToWebviewP95Ms",
|
||||
"taskInitializationDurationMs",
|
||||
]
|
||||
|
||||
function normalizeEvent(event: TaskLatencyEvent): TaskLatencyEvent {
|
||||
if (Number.isFinite(event.taskInitializationDurationMs)) {
|
||||
return event
|
||||
}
|
||||
|
||||
if (event.event === "task.initialization" && Number.isFinite(event.durationMs)) {
|
||||
return {
|
||||
...event,
|
||||
taskInitializationDurationMs: event.durationMs as number,
|
||||
}
|
||||
}
|
||||
|
||||
return event
|
||||
}
|
||||
|
||||
function summarizeMetric(events: TaskLatencyEvent[], key: NumericMetricKey) {
|
||||
const values = events.map((event) => event[key]).filter((value): value is number => Number.isFinite(value))
|
||||
if (values.length === 0) {
|
||||
return { average: 0, min: 0, max: 0 }
|
||||
}
|
||||
|
||||
const total = values.reduce((sum, value) => sum + value, 0)
|
||||
return {
|
||||
average: total / values.length,
|
||||
min: Math.min(...values),
|
||||
max: Math.max(...values),
|
||||
}
|
||||
}
|
||||
|
||||
export function summarizeTaskLatencyEvents(events: TaskLatencyEvent[]): TaskLatencySummary {
|
||||
const normalizedEvents = events.map(normalizeEvent)
|
||||
const requestKeys = new Set(
|
||||
normalizedEvents
|
||||
.map((event) => {
|
||||
if (event.ulid && Number.isFinite(event.requestIndex)) {
|
||||
return `${event.ulid}:${event.requestIndex}`
|
||||
}
|
||||
return undefined
|
||||
})
|
||||
.filter((value): value is string => Boolean(value)),
|
||||
)
|
||||
|
||||
return {
|
||||
eventCount: normalizedEvents.length,
|
||||
requestCount: requestKeys.size,
|
||||
metrics: Object.fromEntries(
|
||||
METRIC_KEYS.map((key) => [key, summarizeMetric(normalizedEvents, key)]),
|
||||
) as TaskLatencySummary["metrics"],
|
||||
}
|
||||
}
|
||||
|
||||
export function compareTaskLatencySummaries(
|
||||
baseline: TaskLatencySummary,
|
||||
candidate: TaskLatencySummary,
|
||||
): TaskLatencySummaryComparison {
|
||||
return {
|
||||
baselineEvents: baseline.eventCount,
|
||||
candidateEvents: candidate.eventCount,
|
||||
metricDiffs: Object.fromEntries(
|
||||
METRIC_KEYS.map((key) => [
|
||||
key,
|
||||
{
|
||||
averageDelta: candidate.metrics[key].average - baseline.metrics[key].average,
|
||||
minDelta: candidate.metrics[key].min - baseline.metrics[key].min,
|
||||
maxDelta: candidate.metrics[key].max - baseline.metrics[key].max,
|
||||
},
|
||||
]),
|
||||
) as TaskLatencySummaryComparison["metricDiffs"],
|
||||
}
|
||||
}
|
||||
|
||||
export type { TaskLatencyEvent }
|
||||
Reference in New Issue
Block a user