Jesse_ChenandClaude Opus 5.5
86ff9a40d1
- BUG_HISTORY BUG-1047 (investigating), PROGRESS with timing estimates, A/B evidence, diagnostics guide, test diffs and env gaps. - CHANGELOG (Skill version not bumped), docs/testing checklist + headless screenshots, tasks README row -> 待验收, BLOCKED entry. - pre-work ledger: ERR-110 (byte-identical engine perf changes still trip the frozen-scoring integrity gate), ERR-111 (Shadbala fingerprint depends on PYTHONHASHSEED). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_017eEAG8HD3mm8gsKXgk8uU8
119 lines
16 KiB
Markdown
119 lines
16 KiB
Markdown
# PROGRESS · 生时校正每轮等待过长：埋点 + 分类超时 + 发出后立即反馈（2026-09-26）
|
||
|
||
- 任务书：`TASK-rectification-latency-20260926.md`
|
||
- 执行：Claude 子代理（直接执行模式，产品授权），分支 `codex/rectification-latency-20260926`，worktree `.worktrees/rectification-latency-20260926`
|
||
- 基线：开工 `origin/staging` `f1d16405`（已含 BUG-1045/1046，任务书要求的串行前置已满足）；提交前变基到 `fe76d547`（仅 `docs/BUG_HISTORY.md` / `docs/tasks/README.md` 两处文档差异）。本单未推送。
|
||
- BUG：BUG-1047（开工时最大号 BUG-1046，核对无冲突），状态 investigating（未部署、真实模型耗时未复核）。
|
||
- 开工预检（AGENTS §9）：`python3 scripts/pre_work_check.py --remote-timeout 8 --command-timeout 45` exit 0，远端 verified、适配器与碎片扫描、5 个 focused 目标全过；新发现 ERR-110 / ERR-111 已写入 `docs/research/pre_work_error_ledger.md`。
|
||
|
||
## 结论
|
||
|
||
| 决策 | 结果 |
|
||
|---|---|
|
||
| D1 收尾两步不动 | 未改 Agent 步数、set-focus、最终正文、Skill 文本与各步 thinking |
|
||
| D2 分类加 10 s 超时 | 已做。每次尝试 10 s，超时走既有重试 → `classifier_unavailable`；模型与思考不变 |
|
||
| D3 发出后立即反馈 | 已做。客户端发送同一帧显示第一句；服务端先建流、首行 `turn.progress`；四句阶段进度；不落库 |
|
||
| D4 补埋点 | 已做。每步起止、推理 token、分类耗时（成功也记）、每次引擎调用耗时 |
|
||
| D5 ① refresh 探针只算一遍 | **未提交**（见「偏离」1）：字面做法改变输出；输出一致的替代方案 A/B 逐字节一致，但触碰冻结评分身份 |
|
||
| D5 ② 第二次 `persistNextInterviewIfIdle` 跳过 | 已做（只在第一次命中「下一题已 active」时跳过，可证明等价） |
|
||
| D5 ③ `/v5/versions` 进程内缓存 | 已做（30 s，只存完整身份） |
|
||
|
||
## 做了什么
|
||
|
||
| 项 | 实现 | 位置 |
|
||
|---|---|---|
|
||
| T1 / D4 埋点 | `RectificationRunDiagnostic` 新增 `steps[]`（每步 `startMs`/`endMs`/token/公开工具名，相对 attempt 起点）、`inputTokens`/`outputTokens`/`reasoningTokens`（各步供应商用量之和，未报告为 null）、`stepCount` 改为真实模型步数（原为"用过几种工具"，另留 `distinctToolCount`）、`toolCallCount`（含重复）、`attemptNumber`/`attemptStartMs`/`attemptElapsedMs`、`classifier`、`engineCalls[]`。分类每次都打 `RectificationClassifierDiagnostic`（成功也打）；确定性回复轮打 `RectificationTurnDiagnostic`。引擎耗时由 `turn-instrumentation.ts` 的 AsyncLocalStorage 回合作用域收集，只记路径、毫秒、结果档（ok/busy/http_error/timeout/bad_payload） | `v9/run-diagnostic.ts`、`v9/agent-run.ts`、`v9/turn-instrumentation.ts`、`v9/engine-client.ts`、`route.ts` |
|
||
| T2 / D2 分类超时 | `classifyWithinTimeout`：每次尝试独立 `AbortController` + 10 s 计时，`Promise.race` 保证供应商不理会 signal 也会结束；超时计入 `timedOutAttempts`。仍是 `for (attempt < 2)`、仍是会话模型、未加任何 thinking/providerOptions | `v9/turn-intent-classifier.ts` |
|
||
| T2 / D3 分类移入流内 | message 分支：原 IIFE 改为 `computeImmediateResponse`，`action === "message"` 时不在开流前执行；`new ReadableStream` 在 `instrumentation.run()` 内构建，`start()` 第一件事 `advance("received")`，再跑预检（分类 + 确定性回复）与无焦点分类。预检返回的 200 回复先过同一个 `awaitTurnExitBeforeResponse(finalizeSuccessfulTurnExit)` 再逐行推给流；非 2xx 变成 `turn.rejected`（原状态码、code、文案）。点选题、开场、只读续轮的请求/响应形态不变 | `route.ts` |
|
||
| T3 / D3 阶段进度句 | 服务端：`record-evidence-batch` 等写入工具开始 → recording；`/v5/score` / `/v5/block_scan` 引擎调用开始或 compare 工具 → rescoring；写入工具完成、set-focus / 出口门 / Agent 收尾空闲调用 → preparing_question；只前进，重试 attempt 重置后重推 received。`turn.progress` / `turn.rejected` 进公开白名单。客户端：发送即「收到，正在对照你的档案…」；`turn.progress` 换句并改写正在进行的工具步骤；工具开始 / 完成 / `activity.changed` 不再用工具名或「正在分析…」顶替阶段句；结算时 live 行与 activity 一并清掉。时间线适配器把四句识别为进度句 | `v9/stream-mapping.ts`、`v9/turn-progress.ts`、`rectification-agentic-chat.tsx`、`rectification-activity-labels.ts`、`rectification-timeline-adapter.ts`、`rectification-surface-state.ts` |
|
||
| VOICE / DESIGN | VOICE 新节「生时校正打字回答的阶段进度句」+ 好/坏对照一行；DESIGN 新节 + 状态表 `typed-pending` 行 + §9 一句 | `frontend/docs/VOICE.md`、`frontend/DESIGN.md` |
|
||
| T4 / D5 | `/v5/versions` 记忆：`WeakMap<fetch 实现, Map<引擎地址, {identity, expiresAt}>>`，TTL 30 s，只存 algorithm+policy 两项齐全的身份，失败与残缺不存，返回副本。第二次空闲调用：`persistNextInterviewIfIdle` 在「焦点已 active」出口返回 `focusActive: true`；Agent 收尾调用命中它时 `interviewSettled = true`，路由出口 `finalizeSuccessfulTurnExit({ interviewSettled })` 直接进入 `ensureNonTerminalTurnExit` | `v9/engine-client.ts`、`v9/answer-choice.ts`、`v9/agent-run.ts`、`v9/turn-exit.ts` |
|
||
| T5 记录 | BUG-1047、CHANGELOG、真机清单、状态板、BLOCKED、错误台账 ERR-110/111 | `docs/` |
|
||
|
||
## 偏离与说明
|
||
|
||
1. **D5 ① 未提交。** refresh 分支两遍探针用的候选集不同：第一遍是 refresh 列（出 `discriminating_event_probes`），第二遍是全网格（出 `candidate_contrast_opportunities`），按网格截然不同的代表盘各算各的（实测两遍 `_score_year` 键零重合，950 vs 13345 次）。合成一遍必然改变第二项输出，违反"逐位不变"。热点其实在每个探针格子里重建 Vimshottari 时间线与 Narayana 大运表（`_score_year` 调 `_active_*` 时不传表）。输出一致的替代方案是复用候选静态上下文里已按同样输入算好的两张表（Vimshottari 只在候选日期等于 `birth_date` 且月亮经度相同时复用，跨午夜候选照旧重建）。同机 A/B（`PYTHONHASHSEED=0`，基线 = `origin/staging` scripts 原样导出，新 = 补丁后，逐字节 `cmp`）：
|
||
|
||
| 场景（1990-01-01 北京公开烟测盘 + 6 条虚构事件） | 基线最快 s | 新最快 s | 输出 |
|
||
|---|---:|---:|---|
|
||
| 05:00–06:00（61 候选）默认 | 1.332 | 1.263 | 逐字节一致 |
|
||
| 同上 + refresh 10 列 | 2.329 | 1.837 | 逐字节一致 |
|
||
| 05:10–05:30（21 候选）默认 | 0.366 | 0.334 | 逐字节一致 |
|
||
| 同上 + refresh 4 列 | 0.764 | 0.624 | 逐字节一致 |
|
||
| 61 候选 3 条事件 | 1.063 | 1.044 | 逐字节一致 |
|
||
| 23:40–00:20 跨午夜 | 0.808 | 0.801 | 逐字节一致 |
|
||
| 跨午夜 + refresh 5 列 | 2.332 | 1.883 | 逐字节一致 |
|
||
|
||
另写了同进程 A/B pytest（两臂各跑一次 `score_candidates`、整份输出规范化 JSON 相等；突变校验：把复用的大运表改坏后输出确实变化，说明测试敏感）。**但** `event_probes.py` 在冻结评分身份 `PRODUCTION_FILES` 里，快速门的 `test_rectification_validation_integrity_gate.py` 4 条随即失败（按文件字节哈希核对 sealed holdout / reported offset 冻结记录）。重新冻结是研究协议动作，不在本单授权内，所以补丁未提交：`scratchpad/lat2/d5-python-static-tables.patch`（含测试），A/B 脚本 `scratchpad/lat2/ab.sh` + `bench.py`。建议另开单：合入补丁 + 按协议重新冻结记录。
|
||
2. **stepCount 语义修正**：原字段实为 `toolsUsed.size`，本单改为真实模型步数，旧含义留在 `distinctToolCount`。`mapModelFinishToErrorCode` 的输入仍用 `toolsUsed.size`（业务判断不动）。
|
||
3. **「正在分析」时间线标题仍在**：时间线折叠标题 live 时写「正在分析」（与普通对话共用的 `ConsultationRunTimeline` 摘要），本单没动；变化的是下面那一行 live 步骤（截图可见）。
|
||
4. **开场轮也会带 `turn.progress preparing_question`**：Agent 收尾空闲调用处统一上报；开场 live 行在收尾时显示「正在准备下一个问题…」，语义属实，未单独屏蔽。
|
||
5. **阶段信号来源**：除工具事件外，「正在重新对照盘面…」也由引擎打分调用本身触发（`record-evidence-batch` 在工具内部重算，没有独立工具事件）；不新增模型调用。
|
||
6. **跳过第二次空闲调用的条件收窄**：只在第一次落在「焦点已 active」出口时跳过。其它出口（新写焦点、交付收尾、穷尽门）第二次调用可能读到第一次的写入而走不同分支，无法证明等价，保持原样。
|
||
7. **路由拒绝的形态**：开流前的鉴权、绑定、终态、声明时段拦截仍是原 HTTP 状态码；只有原先发生在分类/确定性回复里的拒绝改走 `turn.rejected`，客户端复用同一个 `rejectTurn`（撤回打字标记、402 / 401 / 资料不完整分支与原来一致）。
|
||
|
||
## 各段耗时估计（改前 / 改后）
|
||
|
||
| 段 | 改前 | 改后 | 依据 |
|
||
|---|---|---|---|
|
||
| 发送 → 屏幕上第一句确定性文字 | 立刻出现通用「正在处理…」，之后长时间不变 | 13–17 ms 出「收到，正在对照你的档案…」 | 无头 Chrome 实测（rAF 轮询可见文本） |
|
||
| 发送 → 服务端第一个字节 | 分类结束后（分类开思考，典型数秒，无上限） | 鉴权 + Case/会话读取后立即（路由测试 8 ms，替身环境） | `rectification-latency-route-20260926.test.ts` |
|
||
| 意图分类 | 每次无上限，最多 2 次；discriminator 分支再分类 1 次 | 每次 ≤ 10 s，最坏 20 s 后走既有兜底 | 单元测试（模拟计时器） |
|
||
| Agent 四步 | 不变（D1） | 不变，现可逐步看到起止与推理 token | 部署后看 `steps[]` |
|
||
| 引擎重算 | 20 候选 0.4–0.5 s / 61 候选 2.3–2.5 s / refresh 5.8–6.1 s（任务书实测） | 本分支不变（D5 ① 未提交）；替代方案 refresh 约 −21% | 上表 A/B |
|
||
| `/v5/versions` | 每轮按调用点 4–7 次 GET | 每进程每 30 s 1 次 | 单元测试 |
|
||
| 出口第二次空闲调用 | 1 次档案读 + 版本读 + 幂等链接写 | Agent 轮常见路径跳过 | 单元测试（写集合不变、调用数减少） |
|
||
|
||
单轮总时长仍由模型步数决定（D1 不动），本单主要改善的是"开流前空等"和"无反馈"；真实分布待部署后用新埋点复核。
|
||
|
||
## A/B 与等价证据（前端 D5）
|
||
|
||
- `/v5/versions`：TTL 内两次读取只发 1 次请求、返回副本；TTL 过后重读；残缺身份与异常不记忆；换 fetch 实现互不串用（`rectification-latency-20260926.test.ts` D5 三条）。
|
||
- 第二次空闲调用：同一 fixture 连调两次 `persistNextInterviewIfIdle`，第二次返回值与第一次深相等，唯一写操作是同参数的幂等链接；出口 `interviewSettled: true / false` 两臂（都先做 Agent 的那次调用）写操作集合相同、调用数更少。
|
||
|
||
## 新埋点字段与部署后怎么看
|
||
|
||
在 staging 主机上：
|
||
|
||
```bash
|
||
docker compose --env-file .env.staging -f deploy/docker-compose.server.yml logs --since 30m web \
|
||
| grep -E 'RectificationRunDiagnostic|RectificationTurnDiagnostic|RectificationClassifierDiagnostic|rectification_classifier_unavailable'
|
||
```
|
||
|
||
- `RectificationTurnDiagnostic`（每个 message 轮一行）：`path`（`deterministic` 确定性回复 / `agent`）、`status`、`totalMs`（路由收到请求到流结束）、`streamMs`（流内耗时）、`classifier`（`outcome`/`attempts`/`timedOutAttempts`/`elapsedMs`）、`engineCalls[]`（`path`/`ms`/`outcome`）。
|
||
- `RectificationRunDiagnostic`（每次 Agent attempt 一行）：`attemptNumber`、`attemptStartMs`、`attemptElapsedMs`、`elapsedMs`（整轮）、`stepCount`、`steps[]`（每步 `startMs`→`endMs`、`reasoningTokens`、`tools`）、`inputTokens`/`outputTokens`/`reasoningTokens` 合计、`toolCallCount`/`distinctToolCount`、`classifier`、`engineCalls[]`（本 attempt 内）、`finishReason`、`expectedWrite`。
|
||
- 读法：`totalMs − attemptElapsedMs 之和` ≈ 分类 + 预检 + 出口门；某步 `endMs − startMs` 大而 `reasoningTokens` 高 = 思考耗时；`engineCalls` 里 `/api/rectification/v5/score` 的 `ms` 就是重算耗时；`classifier.timedOutAttempts > 0` 说明 10 s 上限触发过。
|
||
- 这些行不含用户原文、出生资料或模型文本（测试断言）。
|
||
|
||
## 改动的既有断言
|
||
|
||
| 文件 | 原值 | 新值 | 原因 |
|
||
|---|---|---|---|
|
||
| `frontend/tests/rectification-surface-state.test.ts`「live-row labels follow the action that started the turn」 | `rectificationInitialLiveLabel("message") === "正在处理…"` | `=== "收到，正在对照你的档案…"` | D3：打字回答发出即显示第一句阶段进度，替代一直不变的「正在处理…」（断言内已写三栏注释） |
|
||
|
||
其余既有断言未改。三条会被字面源码合同卡住的写法，按原文保留（例如 `if (response.status === 402)`、`rememberLiveActivity(RECTIFICATION_ANALYZING_LIVE_LABEL, null)`、计费块缩进），没有去改测试。
|
||
|
||
## 验证
|
||
|
||
| 项 | 结果 |
|
||
|---|---|
|
||
| `tsc --noEmit` | 0 错 |
|
||
| `npm run lint` | 0 error；126 warnings，与基线 126 逐条一致（按文件+规则比对） |
|
||
| 新测试 | `rectification-latency-20260926.test.ts` 17/17；`.test.tsx` 2/2；`rectification-latency-route-20260926.test.ts` 2/2（Node 22.14；Node 20 为 `mock.module` 环境缺口） |
|
||
| 全量 `npm test`（Node 20.19.2） | 4002 条：3912 通过 / 63 失败 / 27 跳过。基线 `test14.log` 3981 / 61 失败；失败名单差异只有本单 2 条路由测试（`mock.module`，Node 20 既有缺口，Node 22 通过）；基线测试名无一消失 |
|
||
| 全量 `npm test`（Node 22.14.0，本机 `/exec-daemon/node`） | 4002 条：3951 通过 / 24 失败 / 27 跳过。同机 Node 22 基线（`origin/staging` 独立 worktree）3981 / 24 失败；24 条全是 Docker/DB 套件，名单逐条一致，新增失败 0，消失测试名 0 |
|
||
| `npm run build -- --webpack` | 通过；`┌ ○ /` Static；构建产生的 `frontend/frontend/` 已删除 |
|
||
| 首屏 gzip | `rootMainFiles` 4 个文件 130933 B → 130933 B（0%） |
|
||
| Python 快速门 pytest 集合（门禁同款 69 个文件，本机 python3.13） | 948 通过 / 1 跳过 / 0 失败，与基线一致（本分支最终不含 Python 改动；带 D5 ① 补丁时为 4 条验证完整性门禁失败，见偏离 1） |
|
||
| 浏览器（`next start` + Chrome 151 无头；CDP 拦截 `/api/*` 返回虚构账户/会话/Case，`/api/rectification/agent` 改道到本地延迟 NDJSON 服务） | 1280 与 390 宽：回车后 17 / 13 ms 显示「收到，正在对照你的档案…」；3.03 / 5.03 / 7.03 s 分别换成「正在记下这件事…」「正在重新对照盘面…」「正在准备下一个问题…」（与服务端事件同步）；全程未见「正在处理… / 正在分析…」live 行；结算后无进度句，下一题卡可点。截图 `docs/testing/rectification-latency-20260926/`（`1280-1-sent`、`1280-2-recording`、`1280-3-rescoring`、`1280-4-preparing`、`1280-5-settled`、`390-1-sent`） |
|
||
|
||
## 环境缺口
|
||
|
||
- 无模型凭据、无受控登录账号：真实模型下各段耗时、10 s 上限是否触发，按 `docs/testing/rectification-latency-20260926.md` 部署后复核（BLOCKED.md 已记）。
|
||
- 无 Docker：`npm run test:db` 未跑（本单不动表）。
|
||
- Node 20 下新路由测试 2 条失败属既有 `mock.module` 缺口；Node 22 已全量跑过。
|
||
|
||
## 观察项（未修）
|
||
|
||
- ERR-111：同一请求跨进程 `candidate_feature_snapshot` 的 Shadbala / static 指纹与 `feature_hash` 随 `PYTHONHASHSEED` 变化；A/B 因此固定哈希种子。
|