浏览代码

test(chat): 新增收尾耗时探针,量到等待全在 summary→result

用户反馈「正文结束后等 1~2 秒才看到参考资料」。新增 probe-answer-tail-timing.mjs:
增量读 SSE 并给每个事件打到达时刻,专测这段等待。

两次真实后端实测:
- 正文定稿 → result:3.07s / 10.09s(done 紧贴 result)
- result 载荷 390KB / 375KB
- 参考资料的数据(source 事件)在 answer_start 之前 0.4 秒就到齐了

即「等参考资料」等的是 done 事件,不是数据;而前端在 done 才 flushContent。
前端从 result 里只消费 company_info(给 DMS,不渲染)与 cipa(二维码)两个字段。

本轮只加探针与记录,未改行为。

Co-Authored-By: Claude Code <noreply@anthropic.com>
gongtianxiao 5 小时之前
父节点
当前提交
5e9de860d3
共有 2 个文件被更改,包括 137 次插入0 次删除
  1. 27 0
      harness/progress.md
  2. 110 0
      harness/tools/probe-answer-tail-timing.mjs

+ 27 - 0
harness/progress.md

@@ -3276,3 +3276,30 @@ DMS 主机(`121.43.55.7:10081`)是纯 API、根路径 404,没有登录页
 **下一步**:请用户复现一次「一小段重渲」,把控制台里下列关键字任一行发来 ——
 `[answer-stream]`(内容层改写)、`[record]`(重置/行改动/补偿)、`[TextContent][typewriter]`。
 哪一类出现,答案就在哪一层。
+
+### 续 10:量「收尾多等 1~2 秒」到底花在哪(用户问优化方案)
+
+**新工具** `harness/tools/probe-answer-tail-timing.mjs` —— **增量读 SSE**(不是攒完再解析),
+给每个事件打到达时刻,专测「正文定稿 → 参考资料出现」这段等待。
+
+**两次实测(真实后端,经 dev server 代理)**:
+
+| | 第一次 | 第二次 |
+|---|---|---|
+| 最后一片 `source`(参考资料的数据) | — | **49.09s** |
+| `answer_start`(正文开流) | — | 49.51s |
+| 最后一片 `answer_delta` | 35.36s | 53.15s |
+| `answer_end`(正文定稿) | 35.85s | 53.50s |
+| `summary` | 35.85s(+0.00s) | 53.51s(+0.00s) |
+| `result` | 38.92s(**+3.07s**) | 63.60s(**+10.09s**) |
+| `done` | 38.92s(+0.00s) | 63.60s(+0.00s) |
+| `result` 载荷 | 390,162 字符 | 375,024 字符 |
+
+**结论(有测量支撑)**:
+1. **等待全在 `summary → result` 这一段**(3.07s / 10.09s),`done` 紧贴 `result`。
+2. **参考资料的数据(`source`)在正文开流前 0.4 秒就到齐了**(49.09s vs 49.51s)——
+   第二次实测里「数据到齐」到「界面显示」差了 **14.5 秒**。**等的是事件,不是数据。**
+3. 前端在 `done` 才 `flushContent`,所以尾部(notices + 参考资料)被压到最后。
+4. 前端**从 `result` 里只消费两个字段**(代码证据:`api-chat-coordinator.ts` 的 `case 'result'`):
+   `company_info`(走 totalResponse 给 DMS 同步,**不在消息里渲染**)与 `cipa`(企业微信二维码,
+   渲染时必须排在参考资料**之前**)—— 除了 `cipa`,尾部其余部分在 `summary` 到达时就已就绪。

+ 110 - 0
harness/tools/probe-answer-tail-timing.mjs

@@ -0,0 +1,110 @@
+/**
+ * 量「正文结束 → 参考资料出现」这段**收尾等待**到底花在哪。
+ *
+ * 背景:正文是逐片流式上屏的,但参考资料(`<ref_links>`)要等 `done` 才由 `flushContent`
+ * 追加。用户反馈正文结束后还要等 1~2 秒才看到参考资料 —— 这个脚本就是量这段。
+ *
+ * 它**增量读 SSE**(不是 `await res.text()` 攒完再解析),所以能拿到每个事件真正的到达时刻。
+ *
+ * 怎么跑(需要 dev server 起着走同源代理):
+ *   node harness/tools/probe-answer-tail-timing.mjs "青浦区高新技术企业有什么扶持政策"
+ *   # 可选:CHAT_BASE=https://localhost:8083/chat-api 覆盖地址
+ *
+ * 只读:不改任何数据。
+ */
+
+process.env.NODE_TLS_REJECT_UNAUTHORIZED = '0';
+
+const chatBase = (process.env.CHAT_BASE || 'https://localhost:8083/chat-api').replace(/\/+$/, '');
+const question = process.argv[2] || '青浦区高新技术企业有什么扶持政策';
+
+const startedAt = Date.now();
+const res = await fetch(`${chatBase}/api/chat`, {
+  method: 'POST',
+  headers: { 'Content-Type': 'application/json' },
+  body: JSON.stringify({ thread_id: `probe-tail-${Date.now()}`, question }),
+});
+if (!res.ok) {
+  console.error(`HTTP ${res.status}`);
+  process.exit(1);
+}
+console.log(`问题:${question}\n地址:${chatBase}/api/chat\n`);
+
+const reader = res.body.getReader();
+const decoder = new TextDecoder();
+let buffer = '';
+const events = []; // { name, at, size }
+
+const handleEvent = (block) => {
+  const m = block.match(/^event: (\S+)\r?\ndata: ([\s\S]*)$/);
+  if (!m) return;
+  events.push({ name: m[1], at: Date.now() - startedAt, size: m[2].length });
+};
+
+while (true) {
+  const { value, done } = await reader.read();
+  if (done) break;
+  buffer += decoder.decode(value, { stream: true });
+  let idx;
+  while ((idx = buffer.search(/\r?\n\r?\n/)) !== -1) {
+    const nl = buffer.match(/\r?\n\r?\n/)[0].length;
+    handleEvent(buffer.slice(0, idx));
+    buffer = buffer.slice(idx + nl);
+  }
+}
+if (buffer.trim()) handleEvent(buffer);
+const totalMs = Date.now() - startedAt;
+
+/* ---------------- 统计 ---------------- */
+const first = (name) => events.find((e) => e.name === name);
+const last = (name) => [...events].reverse().find((e) => e.name === name);
+const count = (name) => events.filter((e) => e.name === name).length;
+
+const deltaLast = last('answer_delta');
+const answerEnd = first('answer_end');
+const summary = first('summary');
+const result = first('result');
+const done = first('done');
+const refLinksInPayload = events.some(
+  (e) => e.name === 'summary' || e.name === 'result'
+);
+
+console.log('【事件计数】', JSON.stringify(
+  events.reduce((acc, e) => ((acc[e.name] = (acc[e.name] || 0) + 1), acc), {})
+));
+
+console.log('\n【收尾时间线】(相对请求发出;括号内为距上一步的间隔)');
+const steps = [
+  ['最后一片 source(参考资料的数据)', last('source')],
+  ['最后一片 item(卡片数据)', last('item')],
+  ['answer_start(正文开流)', first('answer_start')],
+  ['最后一片 answer_delta', deltaLast],
+  ['answer_end(正文定稿)', answerEnd],
+  ['summary', summary],
+  ['result', result],
+  ['done', done],
+].filter(([, e]) => e);
+let prev = null;
+for (const [label, e] of steps) {
+  const gap = prev === null ? '' : `  (+${((e.at - prev.at) / 1000).toFixed(2)}s)`;
+  console.log(`  ${String(e.at / 1000).padStart(6)}s  ${label}${gap}`);
+  prev = e;
+}
+console.log(`  ${String(totalMs / 1000).padStart(6)}s  流结束(EOF)`);
+
+console.log('\n【结论】');
+const waitAfterBody = answerEnd ? (totalMs - answerEnd.at) / 1000 : null;
+console.log(`  正文定稿 → 流结束:${waitAfterBody === null ? '(无 answer_end)' : waitAfterBody.toFixed(2) + 's'}`);
+if (!done) {
+  console.log('  ⚠️ 没有 done 事件 —— 前端会在 EOF 才 flush(把参考资料推到最后时刻),');
+  console.log('     而且会走「断流」分支报 disconnected。这是**最大的等待来源**。');
+}
+if (answerEnd && summary) {
+  console.log(`  answer_end → summary:${((summary.at - answerEnd.at) / 1000).toFixed(2)}s`);
+}
+if (summary && result) {
+  console.log(`  summary → result:${((result.at - summary.at) / 1000).toFixed(2)}s(result 是完整快照,通常最大)`);
+  console.log(`     result 载荷大小:${result.size} 字符`);
+}
+console.log('  参考资料由 source 事件决定,而 source 在 answer_start 之前就发完了 ——');
+console.log('  也就是说「等参考资料」等的是 done,不是等数据。');