[Bug] sessionStats 的 TPS 口径缺陷：思考不以增量下发时，decodeMs 起点滑到可见文本/工具调用上，显示值虚高 3~5 倍

[intdwh]

[Bug] sessionStats 的 TPS 口径缺陷：思考不以增量下发时，decodeMs 起点滑到可见文本/工具调用上，显示值虚高 3~5 倍

摘要

底部统计条的 tok/s 取自 sessionStats 的 decodeTokens / decodeMs（decodeMs = 组装完成时间 − 首 token 时间，decodeTokens = 提供方上报的 outputTokens，含思考 token）。

当某个提供商的流不把思考内容作为增量（delta）下发，只在结束时整块给出时，decodeMs 的起点会退到第一段可见文本或第一个工具调用参数——而分子仍然包含全部思考 token。结果是同一份数据被放大 3~5 倍（以工具调用为主的步可达 30 倍）。根因不是提供商的实现有问题，而是 decodeMs 依赖了一个并非所有提供商都满足的可观测性前提。

环境

• DSH 0.2.0-rc.2（官方 Windows 桌面版，win-x64），Windows 11
• 提供商经 llm-pi-ai 挂载，api: openai-responses
• 会话日志：%USERPROFILE%\.dsh\sessions\<workspace>\session-<id>\session.v4.jsonl.zstd
• 涉及包：@deepseek-ai/dsh-session-stats、@deepseek-ai/dsh-llm、@deepseek-ai/dsh-client-ui-chat

复现

1. 配置一个走 api: openai-responses 的 OpenAI 兼容第三方网关，模型为推理模型（思考等级非 off）。
2. 正常对话若干轮，其中包含"只发起工具调用、不产出可见文本"的步。
3. 对比底部统计条显示的速度与端到端吞吐（ΣoutputTokens ÷ Σ整步耗时）。

期望：显示值约为端到端吞吐的 1.21.5 倍（与思考逐字下发的提供商同量级）。
实际：显示值为端到端的 **35 倍**。

该提供商的判定特征（无需看提供商实现即可确认）：assistant/message.stream 中 reasoning-chunks 记录数为 0，只有 chunk.block-start（blockType: "reasoning"）与结束时整块的 chunk.block-end。

根因（源码定位）

① 主机侧的折叠 —— @deepseek-ai/dsh-session-stats 的 sessionStatsProjectionDefinition.apply()，assistant/message 分支：

const firstToken = open.firstTokenTime ?? assistantStreamFirstTokenTime(event.data.stream) ?? null;
// ...
if (firstToken !== null) {
  next.ttftMs += Math.max(0, firstToken - open.startTime);
  next.ttftSteps += 1;
  const outputTokens = usageOutputTokens(event.data.usage);
  if (outputTokens !== null) {
    next.decodeMs += Math.max(0, event.time - firstToken);   // ← 分母起点
    next.decodeTokens += outputTokens;                      // ← 分子：含思考 token
  }
}

② "首 token"的判定 —— @deepseek-ai/dsh-llm 的 assistant-stream.ts：

function isTokenDelta(chunk) {
  switch (chunk.type) {
    case 'text-delta':
    case 'reasoning-delta': return chunk.text !== '';
    case 'tool-call-delta': return chunk.argumentsDelta !== '' || chunk.name !== undefined;
    default: return false;   // block-start / block-end / usage / finish 都不算
  }
}

export function assistantStreamFirstTokenTime(stream) {
  for (const record of stream) {
    const time = record.type === 'chunk'
      ? (isTokenDelta(record.chunk) ? record.time : undefined)
      : runFirstTokenTime(record);
    if (time !== undefined) return time;
  }
  return undefined;
}

即："首 token"只认承载 token 的增量片段。当思考整块下发时，流里不存在 reasoning-delta，block-start(reasoning) 又不被 isTokenDelta 接受，锚点于是滑到第一段 text-delta 或第一个 tool-call-delta——而后者往往出现在思考结束之后。

③ 客户端同口径镜像 —— @deepseek-ai/dsh-client-ui-chat 的 turn-metrics.ts → assistantStepReading()：

decodeMs: timing !== undefined && timing.firstTokenTime !== null
  ? Math.max(0, timing.completedTime - timing.firstTokenTime)
  : null

（该值在投影缺失时作为窗口折叠回退使用，与主机侧同一个锚点假设。）

数据

本机 47 个会话（46 个可用，21.6 MB 压缩日志）离线复算：按 finish.replayState.response.provider / api 分组，用与源码逐字等价的公式重放每个 step。

组（provider / api）	会话	步数	Σ输出token	A 现值	B 修分母锚点后	C 端到端	A/C	B/C	思考逐字下发的步占比
Responses 通道（思考整块下发）	17	260	302,964	537.7	169.8	114.1	4.71×	1.49×	0%
Chat Completions（思考逐字）	1	37	59,669	174.5	154.3	105.2	1.66×	1.47×	59%
另一提供商（Chat Completions，思考逐字）	21	1,172	1,164,775	62.8	62.8	41.6	1.51×	1.51×	94%
DeepSeek 官方账号路由	10	1,323	1,502,246	257.7	225.9	185.4	1.39×	1.22×	69%

两个关键读法：

1. 在思考逐字下发的那一组，A 与 B 完全相同（62.8 = 62.8）——因为那里 block-start 不会早于首个思考 delta，Math.min 取不到它。也就是说下面建议的改动对已经正常的提供商是零影响。
2. 受影响的 Responses 组从 4.71× 虚高回落到与其余三组同一带（B/C 1.22~1.51×），指标从此跨提供商可比。

步级分布（单个受影响会话，173 步）：锚点落在可见文本的 103 步虚高 2.7×；落在工具调用的 70 步虚高 6.5×；最坏一步 30×（该步 1,705 输出 token，可见文本仅 57 字符，思考文本 6,419 字符）。

字符量对照（同一会话）：思考 588K 字符 vs 可见文本 76K vs 工具参数 190K——分子的大头是思考，而它恰恰不在分母覆盖的区间里。

建议的修法

（1）把 decodeMs 的起点改为"生成开始"，即首个 block-start 与首个 token delta 二者较早者

// @deepseek-ai/dsh-llm：新增一个与 assistantStreamFirstTokenTime 并列的读取器
export function assistantStreamFirstBlockStartTime(stream) {
  for (const record of stream) {
    if (record.type === 'chunk' && record.chunk.type === 'block-start') return record.time;
  }
  return undefined;
}

// @deepseek-ai/dsh-session-stats：assistant/message 分支
const blockStart = open.firstBlockStartTime ?? assistantStreamFirstBlockStartTime(event.data.stream);
const decodeStart = blockStart !== undefined && firstToken !== null
  ? Math.min(blockStart, firstToken)   // 只会比现状更早 ⇒ 数值只可能下降，不会引入新的虚高
  : firstToken;
next.decodeMs += Math.max(0, event.time - decodeStart);
// ttftMs 仍用 firstToken 计算，"首个 token 延迟"的语义不变

理由：分子是"全部输出 token"（思考＋可见文本＋工具参数），分母就应当覆盖这批 token 被产出的整个区间。block-start 是流中"模型开始产出"的最早可观测信号（实测出现在 step 起点后 2.1~3.6 s，而非 0 s，说明它标记的是开始产出而不是"流刚建立"）。在逐字下发思考的提供商上它不早于首个思考 delta，故改动零影响（见上表）。

（2）可选：客户端镜像同步

assistantStepReading() 使用同一个锚点（需要把 blockStartTime 一并写入 assistant 节点的 timing），使"无投影时"的窗口折叠回退与主机口径一致。

（3）可选：把两个含义拆成两个数字

统计弹窗目前只有一个速度值，它同时承担"解码速度"和"这一轮花了多久"两种含义。并列一个"端到端"速度（分母用 completedTime − stepStartTime）后，两个问题各有一个诚实的答案，不需要任何一方妥协。

（4）不建议：从分子里扣掉思考 token

那会让指标退化为"可见文本速度"；而且多数网关的 usage 并不上报可用的 reasoningTokens（本机 1,431 个 step 的用量记录里该字段一次都没出现过），无法普遍实现。

影响面

• 仅影响展示：sessionStats（底部统计条与统计弹窗）。不影响真实速度、计费、工具调用或缓存命中。
• 但它让指标跨提供商不可比：同一个会话内切换通道，同一指标相差 3~5 倍（实测 537.7 vs 174.5），足以让用户误判"这个模型快得离谱"。
• 触发条件与厂商无关：任何"思考只在 output_item.done / 整块给出"的通道都会命中，属于面向未来提供商的鲁棒性问题。

附：复现脚本

按 zstd 多帧逐帧解码 session.v4.jsonl.zstd，再按上述公式重放每个 step 即可复现（约 120 行）。如果需要，我可以在本讨论下贴出全文，或按仓库的测试框架把"思考整块下发的 step"改写成一个 sessionStats 的单测用例。

[argszero]

Verified first: your quotes are exact, and the rule you object to is a written rule

I checked every excerpt in your report against master at 1517a4dbca (the head as of this reply), and all four are verbatim:

• isTokenDelta — packages/llm/llm/src/assistant-stream.ts:250-260
• assistantStreamFirstTokenTime — same file, :333-341
• the fold — packages/session/session-stats/src/projection.ts:148 and :161
• the client mirror — packages/client/ui-chat/src/client/contract/turn-metrics.ts:39-40

And the rule is documented as a rule, not as an accident: packages/session/session-stats/README.md:84 states "First-token latency records the first non-empty delta chunk and survives an in-step llm/retry", and :85 states "Decode time and tokens accrue only over steps carrying both a first token and a valid provider usage report". What your report actually establishes is that a documented rule has an undocumented precondition — that the stream delivers content as deltas. That framing is worth keeping, because it is the part the specification side has to absorb.

Your numerator premise also holds structurally, not just in your logs: TokenUsage.outputTokens is required (packages/llm/llm/src/types.ts:177) with an optional reasoningTokens (:188), and the token-meter normalizer rejects any report where reasoningTokens > outputTokens (packages/llm/token-meter/src/turn-usage.ts:88). Thinking is modelled as a subset of output here and nothing downstream subtracts it, so decodeTokens does carry the thinking tokens.

1. The anchor has a second setter — your patch location is still right, though not for the reason the snippet suggests

projection.ts:148 is the fallback. An earlier setter exists:

case 'assistant/attempt': {
  const open = state.openStep
  if (open === null || open.turn !== event.data.turn || open.step !== event.data.step) return state
  const first = assistantStreamFirstTokenTime(event.data.stream) ?? null
  if (open.firstTokenTime !== null || first === null) return state   // first wins
  return { ...state, openStep: { ...open, firstTokenTime: first } }
}

(projection.ts:138-144)

When does it fire? Only after a failed or aborted attempt. The loop appends assistant/attempt at packages/core/agent-loop/src/agent.ts:485-486 (aborted, no interrupted content), :491-492 (the stream threw) and :508-509 (finish.kind error or aborted). A successful step appends assistant/message with the same stream and no attempt event (agent.ts:537-539).

So on the normal path open.firstTokenTime is still null when the message arrives, the ?? at :148 runs, and the line you propose to change at :161 really is the live anchor. The patch is not misplaced.

The "first wins" rule at :142 is what makes it safe, and it constrains the open.firstBlockStartTime you introduce:

• Mirroring the new anchor into the attempt branch as well would mean that on a retried step the denominator becomes message.time − attempt-1 block-start, growing by (attempt-1 first token − attempt-1 block-start): the same class of inflation you are fixing, now applied to a step whose numerator (the usage on assistant/message) belongs to a later attempt. That asymmetry already exists — open.firstTokenTime deliberately survives the retry, per README :84 — and a block-start anchor made "first wins" too only widens it.
• The minimal version that leaves retry semantics untouched derives the new anchor from the message's own stream, so the fallback chain can only move earlier within one stream:

const tokenAnchor = open.firstTokenTime ?? assistantStreamFirstTokenTime(event.data.stream) ?? null
const blockStart = assistantStreamFirstBlockStartTime(event.data.stream)
const decodeStart = tokenAnchor !== null && blockStart !== undefined
  ? Math.min(blockStart, tokenAnchor)
  : tokenAnchor

then next.decodeMs += Math.max(0, event.time - decodeStart) while ttftMs/ttftSteps stay on tokenAnchor. On a retried step attempt 2's block-start is later than attempt 1's first token, so Math.min picks the token and those steps are unchanged; on a clean step it takes the earliest provable generation signal.

2. The same gap also drops steps — your two errors sit in one total, pointing opposite ways

Everything is gated on the anchor (projection.ts:156-164):

if (firstToken !== null) {
  next.ttftMs += ...; next.ttftSteps += 1
  const outputTokens = usageOutputTokens(event.data.usage)
  if (outputTokens !== null) { next.decodeMs += ...; next.decodeTokens += outputTokens }
}

A step whose stream carries no text-delta and no tool-call-delta — a provider batching thinking as one block, plus a step whose only output is a reasoning block (a max-tokens cut is the obvious route) — has firstToken === null. That step then contributes no decodeMs, no decodeTokens, no ttftMs and no ttftSteps: its provider-reported output tokens are absent from the numerator rather than mismatched against a short denominator.

Two consequences for your tables:

• Your A/C ratio attributes the whole numerator to inflated denominators, but part of the numerator is missing instead. Both errors live in the same total and the grouping cannot separate them.
• Your fix re-admits those steps, since a block-start gives them a first token. Corrected column B may therefore move for a second reason beyond re-anchoring; do not read the whole delta as the anchor's effect.

A cheap check on your own 47 sessions: count steps where the message carries a usage report while assistantStreamFirstTokenTime returns undefined but assistantStreamHasVisibleContent returns true. Both readers are in the same module (assistant-stream.ts:333 and :349) and that asymmetry — "token" means delta-only, "visible" means deltas or completed blocks — is exactly the gap.

3. Option (3) is smaller than you think, and it has a trap

An end-to-end model time already ships. llmMs is step/start → assistant/message (projection.ts:153; the client window fold computes the same field at StatsPills.tsx:71), and the stats dialog already renders it as "LLM time" (StatsPills.tsx:252). The denominator you want is in the fold and on screen today; what is missing is a speed label derived from it, not a new figure.

The trap: the two totals do not cover the same steps. llmMs adds every assistant node that has timing (StatsPills.tsx:71), while decode adds only nodes carrying both a first token and a usage report (:79-80). decodeTokens / llmMs is therefore not a per-step rate — the honest end-to-end figure must sum numerator and denominator over the same step set, which is a further reason to compute it where the step is the fold unit rather than in the pill.

4. Option (4): your conclusion is right, your stated reason is not

reasoningTokens is already wired end to end: typed on TokenUsage (llm/llm/src/types.ts:188), summed by the headless JSON stream (packages/bundle/headless/src/json-stream.ts:215), carried on the client node (packages/client/ui-chat/src/client/contract/chat-nodes.ts:88) and rendered whenever present (packages/client/ui-chat/src/client/chat/TurnUsagePanel.tsx:98-100). Your 0/1,431 is a statement about your gateways, not about the harness: the field is optional by design and appears only when a provider reports it.

So "cannot be implemented universally" reads better as "cannot be implemented uniformly" — subtracting would work where reported and be undefined elsewhere, which is precisely the cross-provider comparability you are trying to restore. That is a stronger reason to refuse the change than unavailability, and it is the same reason your first fix is the right one.

5. The fix has three sites, not two — and the third is a second tok/s surface

The rule is implemented three times, independently:

layer	token rule	first-token capture	consumer
host	llm/src/assistant-stream.ts:250	:333	session-stats/src/projection.ts:148 → pill and dialog
ui-chat	conversation-nodes/event-projection.ts:167	conversation-nodes/assistant.ts:150, :158-159	turn-metrics.ts:39-40 → window-fold fallback (StatsPills.tsx:53)
ui-trajectory	trajectory-event-projection.ts:145	trajectory-assistant-definition.ts:187-188	TrajectoryTable.tsx:365-370 throughput()

The third is not a mirror of the second: TrajectoryTable.tsx:365-370 computes outputTokens / ((completedTime − firstTokenTime) / 1000) from its own fold and renders it as {value} tok/s (locales.ts:67) in the step timing panel. Your item (2) covers the ui-chat side; the trajectory panel keeps the old anchor unless it is changed too. The clients do not import dsh-llm for this rule — each carries its own isTokenDelta — so editing the host reader fixes the host and nothing else.

The correction belongs in those three folds. The display is a different matter, and better than I first assumed when writing this section: the activity pill is one dock entry registered by id — packages/client/ui-chat/src/client/apply.ts:322-327 registers the conversation.composer.dock cells activity and usage, with the source comment "One dock entry per pill, so a plugin replaces or adds a single pill by id". So a client plugin can ship its own activity cell and recompute the anchor itself from the durable assistant streams, which still carry the block-start records: option (3) is shippable without waiting for upstream. What such a plugin cannot do is change the values the other surfaces read — the window-fold fallback and the trajectory timing panel.

6. One thing I cannot verify from this tree, and the measurement that would settle it

In llm-pi-ai the block-start you want to anchor on is emitted from pi-ai's own event: case 'thinking_start': yield { type: 'block-start', index: event.contentIndex, blockType: 'reasoning' } (packages/llm/llm-pi-ai/src/stream.ts:166). Whether that instant is when reasoning began or when the adapter learned the reasoning item exists is decided inside pi-ai, not in this repository — so I cannot confirm from the harness that block-start is the right anchor rather than merely a better one. Your data shows better (4.71× → 1.49×); "right" hinges on one measurement you can take on the affected channel without reading pi-ai:

Compare the block-start { blockType: 'reasoning' } record's timestamp with its matching block-end { block: reasoning }. If the gap is roughly the thinking duration, the anchor is a true start; if the gap is ≈ 0, the block-start was synthesised when the completed item arrived, and the improvement comes from a different effect than the one the report describes.

Worth stating in the fix's own terms too: block-start is not guaranteed to exist. packages/llm/llm/src/assembler.ts:34 documents tolerance of "delta-only protocols (no block-start/end)", so on such a protocol the new reader returns undefined and the number stays exactly as today's. Your ?? firstToken fallback handles that correctly — it just means the change is "anchor at the earliest signal the stream can prove", not "always correct", and the corrected figure remains arrival-window based, i.e. still dependent on what the provider chooses to stream.