Skip to content

Commit 442ec37

Browse files
committed
🤖 fix: propagate backend startTime to fix negative TTFT on replay
When the frontend reconnected to an active stream (via replayStream()), timestamps were mismatched: - Frontend set startTime = Date.now() when receiving stream-start - Backend sent delta timestamps from when they were originally created - Result: firstTokenTime < startTime = negative TTFT Fixed by adding startTime to StreamStartEvent schema and propagating the backend's original stream start time to the frontend. This also fixes inflated tool execution time during replay, which was caused by pendingToolStarts containing historical timestamps while getActiveStreamTimingStats() calculated duration using Date.now(). Change-Id: I67813d7127913c1aa19894a81c7b330953383be4 Signed-off-by: Thomas Kosiewski <[email protected]>
1 parent a3fab78 commit 442ec37

File tree

11 files changed

+32
-2
lines changed

11 files changed

+32
-2
lines changed

src/browser/stores/WorkspaceStore.test.ts

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -328,6 +328,7 @@ describe("WorkspaceStore", () => {
328328
messageId: "msg1",
329329
model: "claude-opus-4",
330330
workspaceId: "test-workspace",
331+
startTime: Date.now(),
331332
};
332333
await new Promise<void>((resolve) => {
333334
setTimeout(resolve, 10);
@@ -433,6 +434,7 @@ describe("WorkspaceStore", () => {
433434
messageId: "msg1",
434435
model: "claude-sonnet-4",
435436
workspaceId: "test-workspace",
437+
startTime: Date.now(),
436438
};
437439
await new Promise<void>((resolve) => {
438440
setTimeout(resolve, 10);
@@ -476,6 +478,7 @@ describe("WorkspaceStore", () => {
476478
messageId: "msg1",
477479
model: "claude-sonnet-4",
478480
workspaceId: "test-workspace",
481+
startTime: Date.now(),
479482
};
480483
await new Promise<void>((resolve) => {
481484
setTimeout(resolve, 10);

src/browser/stories/mockFactory.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -605,6 +605,7 @@ export function createStreamingChatHandler(opts: {
605605
messageId: opts.streamingMessageId,
606606
model: opts.model,
607607
historySequence: opts.historySequence,
608+
startTime: Date.now(),
608609
});
609610

610611
// Send text delta if provided

src/browser/utils/messages/ChatEventProcessor.test.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ describe("ChatEventProcessor - Reasoning Delta", () => {
1313
messageId,
1414
model: "gpt-4",
1515
historySequence: 1,
16+
startTime: Date.now(),
1617
});
1718

1819
// Send reasoning deltas
@@ -69,6 +70,7 @@ describe("ChatEventProcessor - Reasoning Delta", () => {
6970
messageId,
7071
model: "gpt-4",
7172
historySequence: 1,
73+
startTime: Date.now(),
7274
});
7375

7476
// Reasoning 1

src/browser/utils/messages/StreamingMessageAggregator.status.test.ts

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -113,6 +113,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
113113
messageId,
114114
model: "test-model",
115115
historySequence: 1,
116+
startTime: Date.now(),
116117
});
117118

118119
// Add a status_set tool call
@@ -155,6 +156,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
155156
messageId,
156157
model: "test-model",
157158
historySequence: 1,
159+
startTime: Date.now(),
158160
});
159161

160162
// First status_set
@@ -218,6 +220,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
218220
messageId,
219221
model: "test-model",
220222
historySequence: 1,
223+
startTime: Date.now(),
221224
});
222225

223226
// Set status
@@ -269,6 +272,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
269272
messageId,
270273
model: "test-model",
271274
historySequence: 1,
275+
startTime: Date.now(),
272276
});
273277

274278
// Add a status_set tool call
@@ -308,6 +312,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
308312
messageId: "msg1",
309313
model: "test-model",
310314
historySequence: 1,
315+
startTime: Date.now(),
311316
});
312317

313318
aggregator.handleToolCallStart({
@@ -370,6 +375,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
370375
messageId,
371376
model: "test-model",
372377
historySequence: 1,
378+
startTime: Date.now(),
373379
});
374380

375381
// Add a status_set tool call with invalid emoji
@@ -429,6 +435,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
429435
messageId,
430436
model: "test-model",
431437
historySequence: 1,
438+
startTime: Date.now(),
432439
});
433440

434441
// Add a successful status_set tool call
@@ -672,6 +679,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
672679
messageId,
673680
model: "test-model",
674681
historySequence: 1,
682+
startTime: Date.now(),
675683
});
676684

677685
// Status_set with long message (would be truncated by backend)
@@ -717,6 +725,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
717725
messageId,
718726
model: "test-model",
719727
historySequence: 1,
728+
startTime: Date.now(),
720729
});
721730

722731
// Add a status_set tool call with URL
@@ -761,6 +770,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
761770
messageId,
762771
model: "test-model",
763772
historySequence: 1,
773+
startTime: Date.now(),
764774
});
765775

766776
// First status with URL
@@ -855,6 +865,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
855865
messageId: messageId1,
856866
model: "test-model",
857867
historySequence: 1,
868+
startTime: Date.now(),
858869
});
859870

860871
// Set status with URL in first stream
@@ -902,6 +913,7 @@ describe("StreamingMessageAggregator - Agent Status", () => {
902913
messageId: messageId2,
903914
model: "test-model",
904915
historySequence: 2,
916+
startTime: Date.now(),
905917
});
906918

907919
// Set new status WITHOUT URL - should use the last URL ever seen

src/browser/utils/messages/StreamingMessageAggregator.test.ts

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -149,6 +149,7 @@ describe("StreamingMessageAggregator", () => {
149149
messageId: "msg1",
150150
historySequence: 1,
151151
model: "claude-3-5-sonnet-20241022",
152+
startTime: Date.now(),
152153
});
153154

154155
// Simulate todo_write tool call
@@ -208,6 +209,7 @@ describe("StreamingMessageAggregator", () => {
208209
messageId: "msg1",
209210
historySequence: 1,
210211
model: "claude-3-5-sonnet-20241022",
212+
startTime: Date.now(),
211213
});
212214

213215
// Simulate todo_write
@@ -343,6 +345,7 @@ describe("StreamingMessageAggregator", () => {
343345
messageId: "msg1",
344346
historySequence: 1,
345347
model: "claude-3-5-sonnet-20241022",
348+
startTime: Date.now(),
346349
});
347350

348351
aggregator.handleToolCallStart({

src/browser/utils/messages/StreamingMessageAggregator.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -860,7 +860,7 @@ export class StreamingMessageAggregator {
860860
const isCompacting = lastUserMsg?.metadata?.muxMetadata?.type === "compaction-request";
861861

862862
const context: StreamingContext = {
863-
startTime: Date.now(),
863+
startTime: data.startTime,
864864
isComplete: false,
865865
isCompacting,
866866
model: data.model,

src/common/orpc/schemas/stream.ts

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,9 @@ export const StreamStartEventSchema = z.object({
4040
historySequence: z.number().meta({
4141
description: "Backend assigns global message ordering",
4242
}),
43+
startTime: z.number().meta({
44+
description: "Backend timestamp when stream started (Date.now())",
45+
}),
4346
});
4447

4548
export const StreamDeltaEventSchema = z.object({

src/node/services/agentSession.disposeRace.test.ts

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -105,7 +105,8 @@ describe("AgentSession disposal race conditions", () => {
105105
workspaceId: "ws",
106106
messageId: "m1",
107107
model: "anthropic:claude-sonnet-4-5",
108-
timestamp: Date.now(),
108+
historySequence: 1,
109+
startTime: Date.now(),
109110
})
110111
).not.toThrow();
111112
});

src/node/services/aiService.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1282,6 +1282,7 @@ export class AIService extends EventEmitter {
12821282
messageId: assistantMessageId,
12831283
model: modelString,
12841284
historySequence,
1285+
startTime: Date.now(),
12851286
};
12861287
this.emit("stream-start", streamStartEvent);
12871288

@@ -1317,6 +1318,7 @@ export class AIService extends EventEmitter {
13171318
messageId: assistantMessageId,
13181319
model: modelString,
13191320
historySequence,
1321+
startTime: Date.now(),
13201322
};
13211323
this.emit("stream-start", streamStartEvent);
13221324

src/node/services/mock/mockScenarioPlayer.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -272,6 +272,7 @@ export class MockScenarioPlayer {
272272
messageId,
273273
model: event.model,
274274
historySequence,
275+
startTime: Date.now(),
275276
};
276277
this.deps.aiService.emit("stream-start", payload);
277278
break;

0 commit comments

Comments
 (0)