Skip to content

Commit bf38798

Browse files
committed
feat(agent-core-v2): attribute event-loop-busy decode time to the client
1 parent 9c1f7b8 commit bf38798

13 files changed

Lines changed: 38 additions & 2 deletions

File tree

apps/pythinker-code/src/utils/usage/debug-timing.ts

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@ export interface StepTimingInput {
2424
*/
2525
readonly llmServerDecodeMs?: number;
2626
readonly llmClientConsumeMs?: number;
27+
readonly llmClientBlockedMs?: number;
2728
readonly usage?: DebugTokenUsage;
2829
}
2930

@@ -119,7 +120,9 @@ function formatDecodeSplit(input: StepTimingInput): string {
119120
const server = input.llmServerDecodeMs;
120121
const client = input.llmClientConsumeMs;
121122
if (server === undefined || client === undefined) return '';
122-
return `; server ${formatDuration(server)} + client ${formatDuration(client)}`;
123+
const blocked = input.llmClientBlockedMs;
124+
const blockedPart = blocked === undefined ? '' : ` (busy ${formatDuration(blocked)})`;
125+
return `; server ${formatDuration(server)}${blockedPart} + client ${formatDuration(client)}`;
123126
}
124127

125128
function formatDuration(ms: number): string {

apps/pythinker-code/test/utils/usage/debug-timing.test.ts

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,20 @@ describe('formatStepDebugTiming', () => {
2727
expect(result).toBe('[Debug] TTFT: 800ms | TPS: 40.0 tok/s (200 tokens in 5.0s)');
2828
});
2929

30+
it('appends the blocked share to the decode split when present', () => {
31+
const result = formatStepDebugTiming({
32+
llmFirstTokenLatencyMs: 800,
33+
llmStreamDurationMs: 6000,
34+
llmServerDecodeMs: 6000,
35+
llmClientConsumeMs: 25,
36+
llmClientBlockedMs: 4875,
37+
usage: { output: 216 },
38+
});
39+
expect(result).toBe(
40+
'[Debug] TTFT: 800ms | TPS: 36.0 tok/s (216 tokens in 6.0s; server 6.0s (busy 4.9s) + client 25ms)',
41+
);
42+
});
43+
3044
it('formats input tokens and cache read/write counts', () => {
3145
const result = formatStepDebugTiming({
3246
llmFirstTokenLatencyMs: 800,

apps/vis/web/src/components/analysis/TimelineTab.tsx

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -307,9 +307,10 @@ function StepRow({ step, turnDurationMs }: { step: StepNode; turnDurationMs?: nu
307307
{step.llmServerDecodeMs !== undefined && step.llmClientConsumeMs !== undefined ? (
308308
<span
309309
className="text-fg-3 tabular"
310-
title="decode window split (server awaiting parts + client processing parts)"
310+
title="decode window split (server awaiting parts + client processing parts; busy = event loop busy with other work)"
311311
>
312312
decode {step.llmServerDecodeMs}+{step.llmClientConsumeMs}ms
313+
{step.llmClientBlockedMs !== undefined ? ` (busy ${step.llmClientBlockedMs}ms)` : ''}
313314
</span>
314315
) : null}
315316
{step.contextTokens !== undefined ? (

apps/vis/web/src/components/wire/parts.tsx

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -397,6 +397,11 @@ export function LoopEventDetail({ event }: { event: LoopRecordedEvent }) {
397397
<span className="text-fg-1">{event.llmClientConsumeMs} ms</span>
398398
</FieldRow>
399399
) : null}
400+
{event.llmClientBlockedMs !== undefined ? (
401+
<FieldRow label="streamDuration/blocked">
402+
<span className="text-fg-1">{event.llmClientBlockedMs} ms</span>
403+
</FieldRow>
404+
) : null}
400405
</div>
401406
{usage !== undefined ? (
402407
<div>

apps/vis/web/src/lib/analysis.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -60,6 +60,7 @@ export interface StepNode {
6060
/** Decode split: server time awaiting parts vs. client time processing them. */
6161
llmServerDecodeMs?: number;
6262
llmClientConsumeMs?: number;
63+
llmClientBlockedMs?: number;
6364
content: ContentSummary;
6465
toolCalls: ToolCallNode[];
6566
}
@@ -375,6 +376,7 @@ export function analyzeWire(entries: readonly WireEntry[]): Analysis {
375376
step.llmServerFirstTokenMs = ev.llmServerFirstTokenMs;
376377
step.llmServerDecodeMs = ev.llmServerDecodeMs;
377378
step.llmClientConsumeMs = ev.llmClientConsumeMs;
379+
step.llmClientBlockedMs = ev.llmClientBlockedMs;
378380
if (step.beginTime !== undefined && t !== undefined) step.durationMs = t - step.beginTime;
379381
// Steps don't carry a generic 'error' finish reason (errors are
380382
// thrown, not recorded). 'filtered' means the provider blocked the

packages/agent-core-v2/src/agent/contextMemory/loopEventFold.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,7 @@ export type LoopRecordedEvent =
3030
readonly llmServerFirstTokenMs?: number;
3131
readonly llmServerDecodeMs?: number;
3232
readonly llmClientConsumeMs?: number;
33+
readonly llmClientBlockedMs?: number;
3334
readonly messageId?: string;
3435
readonly providerFinishReason?: FinishReason;
3536
readonly rawFinishReason?: string;

packages/agent-core-v2/src/agent/llmRequester/llmRequesterService.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -815,6 +815,7 @@ export class AgentLLMRequesterService implements IAgentLLMRequesterService {
815815
}
816816
if (timing.serverDecodeMs !== undefined) payload['serverDecodeMs'] = timing.serverDecodeMs;
817817
if (timing.clientConsumeMs !== undefined) payload['clientConsumeMs'] = timing.clientConsumeMs;
818+
if (timing.clientBlockedMs !== undefined) payload['clientBlockedMs'] = timing.clientBlockedMs;
818819
this.log.info('llm response', payload);
819820
}
820821

packages/agent-core-v2/src/agent/loop/loopService.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1041,6 +1041,7 @@ export class AgentLoopService extends Disposable implements IAgentLoopService {
10411041
llmServerFirstTokenMs: timing?.serverFirstTokenMs,
10421042
llmServerDecodeMs: timing?.serverDecodeMs,
10431043
llmClientConsumeMs: timing?.clientConsumeMs,
1044+
llmClientBlockedMs: timing?.clientBlockedMs,
10441045
messageId: response.providerMessageId,
10451046
providerFinishReason: response.providerFinishReason,
10461047
rawFinishReason: response.rawFinishReason,
@@ -1102,6 +1103,7 @@ export class AgentLoopService extends Disposable implements IAgentLoopService {
11021103
llmServerFirstTokenMs: response.timing?.serverFirstTokenMs,
11031104
llmServerDecodeMs: response.timing?.serverDecodeMs,
11041105
llmClientConsumeMs: response.timing?.clientConsumeMs,
1106+
llmClientBlockedMs: response.timing?.clientBlockedMs,
11051107
providerFinishReason: response.providerFinishReason,
11061108
rawFinishReason: response.rawFinishReason,
11071109
}),

packages/agent-core-v2/src/agent/loop/turnEvents.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -123,6 +123,7 @@ export interface TurnStepCompletedPayload {
123123
readonly llmServerFirstTokenMs?: number;
124124
readonly llmServerDecodeMs?: number;
125125
readonly llmClientConsumeMs?: number;
126+
readonly llmClientBlockedMs?: number;
126127
readonly providerFinishReason?: FinishReason;
127128
readonly rawFinishReason?: string;
128129
}

packages/agent-core-v2/src/kosong/contract/provider.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -62,6 +62,7 @@ export interface ToolCallIdPolicy {
6262
export interface StreamDecodeStats {
6363
readonly serverDecodeMs: number;
6464
readonly clientConsumeMs: number;
65+
readonly clientBlockedMs?: number;
6566
}
6667

6768
export interface VideoUploadInput {

0 commit comments

Comments
 (0)