Selaa lähdekoodia

chore(tools): 量「回答慢」是前端还是后端——结论是后端

用户问回答时间为何很长。新增 probe-answer-latency.mjs:打真实后端记录每个 SSE 事件
的时间戳,并按 TextContent.vue 的真实参数模拟打字机展开时间,拆成两段。

实测(三个问题):
- 「你好」        后端 1.3s  | 767 字?无  | 打字机 0.5s
- 「高新技术企业优惠」后端 49.8s | 767 字 | 打字机 1.9s
- 「奶茶店扶持政策」 后端 65.0s | 896 字 | 打字机 2.1s

结论:**后端问题**。前端打字机只占 1.9~2.1 秒(约 3%)。
且后端**不是流式的**:正文(summary)在 48.4s 整段到达,在此之前界面没有任何正文,
只有心跳提示。事件时间线显示大头在 recommend 阶段(4.3s→30.8s,26.5 秒只有心跳)。

⚠️ 我第一版测量口径错了:只统计 answer 事件,而该后端把正文放在 summary 里,
一开始误判为"零输出";已改为 answer+summary(不含 result 快照)后重测。

建议(给后端):最有效的一步是改成流式;其次查 recommend 阶段为何 26 秒。

Co-Authored-By: Claude Code <noreply@anthropic.com>
gongtianxiao 2 päivää sitten
vanhempi
sitoutus
f1b166dc63
2 muutettua tiedostoa jossa 148 lisäystä ja 0 poistoa
  1. 44 0
      harness/progress.md
  2. 104 0
      harness/tools/probe-answer-latency.mjs

+ 44 - 0
harness/progress.md

@@ -2077,3 +2077,47 @@
   - ⚠️ `dist/` 未删(部署产物),要腾空间可自行删
 - **下一步最佳动作**:无(本轮为清理);上传功能的浏览器实测仍待做
 
+## Session 051
+
+- **日期**:2026-09-18
+- **本轮目标**:用户问「回答时间很长,是前端还是后端的问题」——**用测量回答,不猜**
+- **新增 `harness/tools/probe-answer-latency.mjs`**:打真实后端,记录每个 SSE 事件的时间戳,
+  并把前端打字机的展开时间按 `TextContent.vue` 的真实参数**模拟**出来,拆成两段
+
+### 实测结果(三个问题各一次)
+
+| 问题 | 后端耗时 | 回答字数 | 前端打字机 | 用户感知 |
+|---|---|---|---|---|
+| 「你好」 | **1.3s** | 81 | 0.5s | 1.7s |
+| 「高新技术企业能享受什么优惠」 | **49.8s** | 767 | 1.9s | 51.7s |
+| 「奶茶店有什么扶持政策」 | **65.0s** | 896 | 2.1s | 67.1s |
+
+- **结论:后端问题**。前端打字机只占 **1.9~2.1 秒(约 3%)**,后端占 49.8~65 秒
+- **后端不是流式的**(观感的第二大因素):`summary`(正文)在 48.4s **整段到达**,
+  在此之前界面上**没有任何正文**,只有「思考中」卡片 + 心跳提示"还在为您准备答复"
+- **时间花在哪**(事件时间线,以 33s 那次为例):
+  0~4.3s handoff→plan→retrieve;**4.3~30.8s 是 `recommend` 阶段(26.5 秒,期间只有 heartbeat)**;
+  30.8s 才出 source + summary
+- 简单问题(「你好」)1.3s → 说明**不是链路普遍慢**,是业务问题的检索/推荐环节慢
+
+### ⚠️ 过程中我自己的测量口径错了一次(已修正)
+
+第一版脚本只统计 `answer` 事件的字数,而这个后端**把正文放在 `summary` 里**
+(`result.response` 是同样的快照)→ 一开始得出「回答总字数 0」,误以为是"后端零输出"。
+已改为统计 `answer` + `summary`(**不含 result 快照**,因为适配层也只展示一次)后重测,
+上面的表是修正后的数据。
+
+### 前端这边的情况(结论:不是瓶颈)
+
+- 打字机已调到主流上沿(121 字符/秒起步 + 积压加速,实测平均 400+ 字符/秒)
+- 即便再调快,收益是**秒级**;而后端是**几十秒级** → 优先治后端
+
+- **运行过的验证**:三个问题各实测一次(原始事件时间戳为证);`validate-harness` 通过
+- **已记录证据**:本文件 Session 051;`harness/tools/probe-answer-latency.mjs`(可重跑)
+- **更新过的文件或工件**:`harness/tools/probe-answer-latency.mjs`(新增)、本文件
+- **已知风险或未解决问题**:
+  - ⚠️ 样本只有 3 次,且**每次问题不同**;若要更可靠,应固定问题重复多次取中位数
+  - ⚠️ 「后端为什么慢」超出的前端范围(`recommend` 阶段内部发生了什么,前端看不到)
+- **下一步最佳动作**:把这份数据给后端;**最有效的一步是让后端改成流式**(边生成边推
+  `answer`/`summary`),用户等待感会立刻不同;其次是查 `recommend` 阶段为何要 26 秒
+

+ 104 - 0
harness/tools/probe-answer-latency.mjs

@@ -0,0 +1,104 @@
+/**
+ * 量「一个问题从发送到看完」的时间,拆成【后端耗时】与【前端打字机延迟】两段。
+ *
+ * 为什么要量:用户反馈"回答时间很长"。前端有打字机(后端一次返回整段时,打字机是
+ * **纯额外延迟**),所以"慢"可能来自两头,必须分开量才知道该治哪个。
+ *
+ * 用法:node harness/tools/probe-answer-latency.mjs "你的问题" [chatApiBase]
+ */
+
+const question = process.argv[2] || '我想在青浦开一家奶茶店,有什么相关扶持政策吗';
+const base = (process.argv[3] || 'http://192.168.2.23:8000').replace(/\/+$/, '');
+const url = base.endsWith('/api/chat') ? base : `${base}/api/chat`;
+
+// ── 前端打字机参数(与 src/components/Chat/TextContent.vue 保持一致)──
+const TICK_MS = 33;
+const BASE_CHARS_PER_TICK = 4;
+const BURST = [
+  { pendingLength: 32, batchSize: 8 },
+  { pendingLength: 96, batchSize: 12 },
+  { pendingLength: 256, batchSize: 16 },
+  { pendingLength: 512, batchSize: 20 },
+  { pendingLength: 1024, batchSize: 24 },
+];
+
+/** 模拟前端的打字机循环,返回展开这段内容需要多少毫秒 */
+const simulateTypewriter = (totalChars) => {
+  let pending = totalChars;
+  let ms = 0;
+  while (pending > 0) {
+    let batch = BASE_CHARS_PER_TICK;
+    for (const t of BURST) if (pending > t.pendingLength) batch = t.batchSize;
+    pending -= batch;
+    ms += TICK_MS;
+  }
+  return ms;
+};
+
+const t0 = Date.now();
+let tFirstEvent = null;
+let tFirstAnswer = null;
+let tDone = null;
+let eventCount = 0;
+let answerChars = 0;
+const payloads = [];
+
+const response = await fetch(url, {
+  method: 'POST',
+  headers: { 'Content-Type': 'application/json', Accept: 'text/event-stream' },
+  body: JSON.stringify({ thread_id: `latency_${Date.now()}`, question }),
+});
+
+const reader = response.body.getReader();
+const decoder = new TextDecoder();
+let buffer = '';
+let currentEvent = '';
+
+while (true) {
+  const { done, value } = await reader.read();
+  if (done) break;
+  buffer += decoder.decode(value, { stream: true });
+  const lines = buffer.split('\n');
+  buffer = lines.pop() || '';
+  for (const raw of lines) {
+    const line = raw.replace(/\r$/, '');
+    if (line.startsWith('event:')) {
+      currentEvent = line.slice(6).trim();
+      eventCount++;
+      if (tFirstEvent === null) tFirstEvent = Date.now();
+    } else if (line.startsWith('data:')) {
+      const p = line.slice(5).trim();
+      try {
+        const j = JSON.parse(p);
+        const d = j?.data ?? j;
+        // 正文可能走 answer,也可能走 summary(该后端两种都用过);
+        // result.response 是快照,**不重复计数**(适配层也只展示一次)
+        if ((currentEvent === 'answer' || currentEvent === 'summary') && d?.text) {
+          if (tFirstAnswer === null) tFirstAnswer = Date.now();
+          answerChars += String(d.text).length;
+        }
+        if (currentEvent === 'done') tDone = Date.now();
+        if (['progress', 'answer', 'item', 'source', 'summary'].includes(currentEvent)) {
+          payloads.push(`${currentEvent}@${Date.now() - t0}ms`);
+        }
+      } catch { /* 分片 */ }
+    }
+  }
+}
+if (tDone === null) tDone = Date.now();
+
+const typeMs = simulateTypewriter(answerChars);
+const backendMs = tDone - t0;
+const fmt = (ms) => (ms / 1000).toFixed(1) + 's';
+
+console.log(`\n问题:${question}\n`);
+console.log('【后端】');
+console.log('  首事件到达      :', fmt(tFirstEvent - t0));
+console.log('  首段 answer 到达:', tFirstAnswer ? fmt(tFirstAnswer - t0) : '(没有 answer 事件)');
+console.log('  done 到达       :', fmt(backendMs), ' ← **后端总耗时**');
+console.log('  事件数          :', eventCount);
+console.log('  回答总字数      :', answerChars);
+console.log('\n【前端打字机】(后端一次返回整段,这段是**纯额外延迟**)');
+console.log('  展开', answerChars, '字需要:', fmt(typeMs), `(${Math.round(answerChars / (typeMs / 1000))} 字符/秒 平均)`);
+console.log('\n【用户感知总计】', fmt(backendMs + typeMs), `= 后端 ${fmt(backendMs)} + 打字机 ${fmt(typeMs)}`);
+console.log('\n事件时间线(前 12 个):', payloads.slice(0, 12).join('  '));