Add per-request latency observer churn summaries

This commit is contained in:
candieduniverse
2026-03-17 11:16:09 -07:00
parent a2ef36aca0
commit 080593b57c
6 changed files with 136 additions and 7 deletions
@@ -162,14 +162,14 @@ Why it matters:
Measure:
- [ ] number of full-state pushes per request
- [x] number of full-state pushes per request
- [x] total full-state payload bytes per request
- [ ] number of partial-message events per request
- [x] number of partial-message events per request
- [x] number of partial-message events per request
- [x] total partial-message payload bytes per request
- [ ] number of task UI deltas per request where supported
- [x] number of task UI deltas per request where supported
- [ ] persistence flush counts where supported
- [x] persistence flush counts where supported
Why it matters:
@@ -213,10 +213,10 @@ These should work on both `main` and `eve_troubleshooting-remote-workspaces` wit
These may only exist natively on `eve_troubleshooting-remote-workspaces` or may require additional light plumbing on `main`:
- [ ] chunk-to-webview timing
- [ ] full-state post counts / bytes
- [ ] partial-message event counts
- [ ] task UI delta counts
- [ ] persistence flush metrics
- [x] full-state post counts / bytes
- [x] partial-message event counts
- [x] task UI delta counts
- [x] persistence flush metrics
### Recommended implementation rule
@@ -3,16 +3,27 @@ import {
DEFAULT_LATENCY_OBSERVER_CAPABILITIES,
type LatencyObserverCapabilities,
type LatencyObserverLogEntry,
type LatencyObserverRequestCounterSummary,
type LatencyObserverSessionMetadata,
type LatencyObserverStateSnapshot,
type LatencySample,
} from "@/shared/LatencyObserver"
type ActiveRequest = {
taskId: string
requestId: string
startedAt: number
firstVisibleRecorded: boolean
firstFullStateRecorded: boolean
counterBaseline: Record<
| "fullStatePushes"
| "fullStateBytes"
| "partialMessageEvents"
| "partialMessageBytes"
| "taskUiDeltaEvents"
| "persistenceFlushes",
number
>
}
export class LatencyObserverService {
@@ -34,6 +45,7 @@ export class LatencyObserverService {
private readonly requestStartSamples: LatencySample[] = []
private readonly firstVisibleUpdateSamples: LatencySample[] = []
private readonly firstFullStateUpdateSamples: LatencySample[] = []
private readonly requestCounterSummaries: LatencyObserverRequestCounterSummary[] = []
private readonly logs: LatencyObserverLogEntry[] = []
private optionalCounters: Record<
| "fullStatePushes"
@@ -87,10 +99,12 @@ export class LatencyObserverService {
markRequestStart(taskId: string, requestId: string, startedAt = performance.now()): void {
this.activeRequests.set(taskId, {
taskId,
requestId,
startedAt,
firstVisibleRecorded: false,
firstFullStateRecorded: false,
counterBaseline: { ...this.optionalCounters },
})
this.requestStartSamples.push({
startedAt,
@@ -141,6 +155,22 @@ export class LatencyObserverService {
return
}
this.requestCounterSummaries.push({
requestId: activeRequest.requestId,
taskId: activeRequest.taskId,
startedAt: activeRequest.startedAt,
completedAt: performance.now(),
fullStatePushes: this.optionalCounters.fullStatePushes - activeRequest.counterBaseline.fullStatePushes,
fullStateBytes: this.optionalCounters.fullStateBytes - activeRequest.counterBaseline.fullStateBytes,
partialMessageEvents: this.optionalCounters.partialMessageEvents - activeRequest.counterBaseline.partialMessageEvents,
partialMessageBytes: this.optionalCounters.partialMessageBytes - activeRequest.counterBaseline.partialMessageBytes,
taskUiDeltaEvents: this.optionalCounters.taskUiDeltaEvents - activeRequest.counterBaseline.taskUiDeltaEvents,
persistenceFlushes: this.optionalCounters.persistenceFlushes - activeRequest.counterBaseline.persistenceFlushes,
})
if (this.requestCounterSummaries.length > 50) {
this.requestCounterSummaries.shift()
}
this.activeRequests.delete(taskId)
this.pushLog(`request completed`, taskId, activeRequest.requestId)
}
@@ -182,6 +212,7 @@ export class LatencyObserverService {
samples: [...this.firstFullStateUpdateSamples],
stats: createRollingLatencyStats(this.firstFullStateUpdateSamples),
},
requestCounterSummaries: [...this.requestCounterSummaries],
logs: [...this.logs],
optionalCounters: { ...this.optionalCounters },
}
@@ -205,6 +236,7 @@ export class LatencyObserverService {
this.requestStartSamples.length = 0
this.firstVisibleUpdateSamples.length = 0
this.firstFullStateUpdateSamples.length = 0
this.requestCounterSummaries.length = 0
this.logs.length = 0
this.optionalCounters = {
fullStatePushes: 0,
@@ -64,6 +64,34 @@ describe("LatencyObserverService", () => {
assert.equal(snapshot.optionalCounters?.partialMessageBytes, 128)
})
it("captures per-request richer counter summaries on completion", () => {
const service = new LatencyObserverService()
service.markRequestStart("task-4", "task-4:req-1", 50)
service.incrementCounter("fullStatePushes", 2)
service.incrementCounter("fullStateBytes", 300)
service.incrementCounter("partialMessageEvents", 3)
service.incrementCounter("partialMessageBytes", 120)
service.incrementCounter("taskUiDeltaEvents", 4)
service.incrementCounter("persistenceFlushes", 1)
service.completeRequest("task-4")
const snapshot = service.getSnapshot()
assert.equal(snapshot.requestCounterSummaries.length, 1)
assert.deepEqual(snapshot.requestCounterSummaries[0], {
requestId: "task-4:req-1",
taskId: "task-4",
startedAt: 50,
completedAt: snapshot.requestCounterSummaries[0].completedAt,
fullStatePushes: 2,
fullStateBytes: 300,
partialMessageEvents: 3,
partialMessageBytes: 120,
taskUiDeltaEvents: 4,
persistenceFlushes: 1,
})
})
it("uses capability support values in metric snapshots", () => {
const service = new LatencyObserverService()
@@ -102,6 +130,7 @@ describe("LatencyObserverService", () => {
assert.equal(snapshot.requestStart.stats.count, 0)
assert.equal(snapshot.firstVisibleUpdate.stats.count, 0)
assert.equal(snapshot.firstFullStateUpdate.stats.count, 0)
assert.equal(snapshot.requestCounterSummaries.length, 0)
assert.equal(snapshot.logs.length, 0)
assert.equal(snapshot.optionalCounters?.fullStatePushes, 0)
})
+14
View File
@@ -67,6 +67,19 @@ export interface LatencyObserverMetricSnapshot {
stats: RollingLatencyStats
}
export interface LatencyObserverRequestCounterSummary {
requestId: string
taskId?: string
startedAt: number
completedAt: number
fullStatePushes: number
fullStateBytes: number
partialMessageEvents: number
partialMessageBytes: number
taskUiDeltaEvents: number
persistenceFlushes: number
}
export interface LatencyObserverLogEntry {
ts: number
message: string
@@ -82,6 +95,7 @@ export interface LatencyObserverStateSnapshot {
requestStart: LatencyObserverMetricSnapshot
firstVisibleUpdate: LatencyObserverMetricSnapshot
firstFullStateUpdate: LatencyObserverMetricSnapshot
requestCounterSummaries: LatencyObserverRequestCounterSummary[]
logs: LatencyObserverLogEntry[]
optionalCounters?: LatencyObserverMetricSet["optionalCounters"]
}
@@ -38,6 +38,18 @@ type MockLatencyObserverState = {
firstVisibleUpdate: MockLatencyObserverState["transport"]
firstFullStateUpdate: MockLatencyObserverState["transport"]
logs: unknown[]
requestCounterSummaries: Array<{
requestId: string
taskId?: string
startedAt: number
completedAt: number
fullStatePushes: number
fullStateBytes: number
partialMessageEvents: number
partialMessageBytes: number
taskUiDeltaEvents: number
persistenceFlushes: number
}>
optionalCounters?: {
fullStatePushes: number
fullStateBytes: number
@@ -88,6 +100,20 @@ const extensionStateMock = vi.hoisted(() => ({
stats: { count: 1, minMs: 14, maxMs: 14, avgMs: 14, lastMs: 14, totalMs: 14 },
},
logs: [],
requestCounterSummaries: [
{
requestId: "task-1:req-1",
taskId: "task-1",
startedAt: 10,
completedAt: 24,
fullStatePushes: 2,
fullStateBytes: 512,
partialMessageEvents: 3,
partialMessageBytes: 256,
taskUiDeltaEvents: 4,
persistenceFlushes: 1,
},
],
optionalCounters: {
fullStatePushes: 3,
fullStateBytes: 1024,
@@ -156,6 +182,20 @@ describe("DebugSection", () => {
stats: { count: 1, minMs: 14, maxMs: 14, avgMs: 14, lastMs: 14, totalMs: 14 },
},
logs: [],
requestCounterSummaries: [
{
requestId: "task-1:req-1",
taskId: "task-1",
startedAt: 10,
completedAt: 24,
fullStatePushes: 2,
fullStateBytes: 512,
partialMessageEvents: 3,
partialMessageBytes: 256,
taskUiDeltaEvents: 4,
persistenceFlushes: 1,
},
],
optionalCounters: {
fullStatePushes: 3,
fullStateBytes: 1024,
@@ -201,6 +241,8 @@ describe("DebugSection", () => {
expect(screen.getByText(/State pushes: 3/)).toBeTruthy()
expect(screen.getByText(/State bytes: 1024/)).toBeTruthy()
expect(screen.getByText(/Partial bytes: 256/)).toBeTruthy()
expect(screen.getByText(/Req state pushes: 2/)).toBeTruthy()
expect(screen.getByText(/Req partial bytes: 256/)).toBeTruthy()
expect(screen.getByText(/Transport probe: Supported/)).toBeTruthy()
expect(screen.getByText(/First full-state avg: 14.00 ms/)).toBeTruthy()
expect(screen.getByText(/Task UI delta metrics: Unsupported on this branch/)).toBeTruthy()
@@ -60,6 +60,7 @@ const DebugSection = ({ onResetState, renderSectionHeader }: DebugSectionProps)
OBSERVATION_SCENARIOS.find((scenario) => scenario.id === selectedScenarioId) ?? OBSERVATION_SCENARIOS[0]
const transportSamples = latencyObserver?.transport.samples ?? []
const latestRequestSummary = latencyObserver?.requestCounterSummaries.at(-1)
const effectiveTransportSamples = useMemo(() => {
if (transportSamples.length > 0) {
return transportSamples
@@ -307,6 +308,17 @@ const DebugSection = ({ onResetState, renderSectionHeader }: DebugSectionProps)
<div>Partial bytes: {latencyObserver.optionalCounters?.partialMessageBytes ?? 0}</div>
<div>Task UI deltas: {latencyObserver.optionalCounters?.taskUiDeltaEvents ?? 0}</div>
<div>Persistence flushes: {latencyObserver.optionalCounters?.persistenceFlushes ?? 0}</div>
{latestRequestSummary && (
<>
<div className="font-medium text-foreground">Latest request churn</div>
<div>Req state pushes: {latestRequestSummary.fullStatePushes}</div>
<div>Req state bytes: {latestRequestSummary.fullStateBytes}</div>
<div>Req partial events: {latestRequestSummary.partialMessageEvents}</div>
<div>Req partial bytes: {latestRequestSummary.partialMessageBytes}</div>
<div>Req UI deltas: {latestRequestSummary.taskUiDeltaEvents}</div>
<div>Req persistence flushes: {latestRequestSummary.persistenceFlushes}</div>
</>
)}
<div className="max-h-24 overflow-auto rounded border border-[var(--vscode-panel-border)] p-2">
{latencyObserver.logs.length === 0
? "No observer events yet."