Compare commits

...
13 changed files with 1765 additions and 17 deletions
@@ -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 implementations 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 schedulers 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),
}
}
+148
View File
@@ -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 }
+1
View File
@@ -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)
})
})
+47
View File
@@ -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
View File
@@ -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]
+75
View File
@@ -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),
}
}
+101
View File
@@ -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 }