用户感觉到的慢,通常是从客户端发出请求到看见第一段有效输出的这段时间,而不是接口返回的总耗时。建议先在这条时间线上确定一个切口:首段结果返回,也就是首个 token 或首个字节到达客户端的时刻;再往前补上客户端发出前、服务端收到两个时间点,端到端就被拆成网络往返、排队等待、生成输出三段。三段各有独立证据,也对应不同处理动作;不分段就只剩整体重写和盲目扩容两条路。
把一次真实调用打上 t0(客户端发出前)、t1(服务端收到)、t2(首段结果返回)、t3(全部结束)四个时间戳,用同一个 trace id 串起来,再重复取样观察抖动。Vivix 侧的接口路径、鉴权方式和请求体按实际接入填写,打点逻辑不变。分段结果只能定位耗时落在哪一段,不能替代容量规划;跨机器相减前要先确认两台机器的时钟偏差远小于被测段耗时,否则网络往返这一段算出来的数字不可用。
先在调用链上标出可以打断点的三个位置
三个位置的定义要写死在代码里,不能靠事后从访问日志反推:
- 客户端发出前(t0):放在请求体序列化完成、socket 写入之前。这一步之后再执行网络调用,t0 和 t1 的差值才包含 DNS、连接建立、TLS 握手和上行传输。如果放在 fetch 调用内部,连接复用和握手耗时会漏掉。
- 服务端收到(t1):放在框架的请求进入点,即能读到 header 和 body 之后、业务逻辑执行之前。同一个位置要再补一个 t1b:进入队列或等待并发名额结束、真正开始处理的时刻。t1 到 t1b 就是排队等待,t1b 之前的部分对客户端不可见,很容易被误算成网络慢。
- 首段结果返回(t2):服务端侧记为产出第一段内容并写入响应流的时刻,客户端侧记为读到第一个数据块的时刻。两个 t2 都要留,二者的差值是下行传输与缓冲带来的额外延迟,非流式接口则退化为收到完整响应头的时刻。
t3 是全部结束,用来算生成输出的总时长和吞吐,不参与快慢的初判。三段口径一旦固定,后续所有对比才有意义;中途改口径,前后数据不可比。
客户端与服务端同时打时间戳跑通一次调用
只在一侧打点无法判断慢在哪:客户端算出的网络往返里混着服务端排队,服务端算出的处理耗时里又不含下行传输。两边同时打并靠 trace id 关联,才有一次可比对的分段数据。下面是最小骨架,替换成你的实际运行时即可。
// client_probe.js —— 只做打点,不承担压测
// 执行位置:与真实用户网络环境接近的机器上
async function probeOnce(url, payload) {
const traceId = 'probe-' + Date.now() + '-' + Math.random().toString(16).slice(2, 8);
const mono = () => Number(process.hrtime.bigint()) / 1e6; // 单调时钟,毫秒
const t0m = mono(), t0w = new Date().toISOString();
const res = await fetch(url, {
method: 'POST',
headers: { 'content-type': 'application/json', 'x-trace-id': traceId },
body: JSON.stringify(payload)
});
const t1m = mono(); // 收到响应头
const reader = res.body.getReader();
const first = await reader.read();
const t2m = mono(); // 首个数据块
while (!(await reader.read()).done) {}
const t3m = mono(); // 全部结束
return { traceId, t0w, t0m, t1m, t2m, t3m,
net: t1m - t0m, gen: t2m - t1m, total: t3m - t0m };
}
# 服务端骨架:伪代码,按你的框架替换钩子
# 进入请求、能读到 header 时
ctx.trace_id = request.headers['x-trace-id']
ctx.t1 = now_wall() # 收到请求
ctx.t1_mono = now_mono() # 同机单调时钟
# 拿到并发名额、真正开始处理时
ctx.t1b = now_mono() # 排队结束
# 产出第一段内容、写入响应流时
ctx.t2 = now_mono()
write(chunk)
# 全部写完
ctx.t3 = now_mono()
log_json(ctx) # 一行一条,便于后续按 trace_id 聚合
时间戳格式建议双写:wall clock 用带毫秒的 ISO8601,只用于和日志对齐;真正相减用同机单调时钟的毫秒或微秒数,避免系统校时把差值算成负数。跨机器相减前先看时钟偏差,Linux 上可以用 chronyc tracking 查看 System time 偏移量,两台机器偏差远小于被测段耗时才可相减;否则网络往返只用客户端单侧的数据,服务端时间戳只用于判断内部排队。
同一段输入重复多次看抖动而不是只看均值
实时交互的典型特征是偶发慢:连接池打满、冷启动、下游偶发排队,这些在均值里被摊薄,在长尾里却直接影响体验。建议同一段输入重复 15 到 30 次,分散到不同时段各跑一轮,先看最大最小和中位数,再看均值。
取样记录一行一条,字段固定,方便后面直接统计:
| 字段 | 含义 | 记录方式 |
|---|---|---|
| run_id | 第几次取样 | 自增序号 |
| trace_id | 关联客户端与服务端 | 请求头透传 |
| t0 / t1 / t2 / t3 | 四个时间点 | 单调时钟毫秒 |
| net / queue / gen | 网络往返、排队等待、首段生成 | 由时间点相减得到 |
| out_len | 输出长度 | 字符数或 token 数 |
| note | 异常标记 | 重连、超时、非流式降级等 |
统计时对 net、queue、gen 三段分别算最小、最大、中位数(statistics.median 或 sort -n | awk 均可),并单独标出带 note 的样本。最大与中位数差距明显、且集中在少数几次,通常是排队或连接建立的问题;三段都稳定偏大,才是需要改架构的信号。样本量太少时不要下结论,先补到能看出分布的量级。
把分段结果和业务可接受阈值逐项对照
阈值要事先按业务约定写下来,再看实测是否越线。下表的阈值列留空,按你方已有的交互体验要求填写,不要事后按实测结果倒推阈值。
| 分段 | 计算口径 | 本次实测(中位数 / 最大) | 业务阈值 | 超出时的处理方向 |
|---|---|---|---|---|
| 网络往返 | t1 − t0 | 待填 | 待填 | 先查连接复用、TLS 握手是否每次重来、客户端与服务是否跨地域 |
| 排队等待 | t1b − t1 | 待填 | 待填 | 看并发上限、连接池大小、下游限流是否触发;区分稳定排队与突发排队 |
| 首段生成 | t2 − t1b | 待填 | 待填 | 确认是否开启流式输出、首段内容是否被前置逻辑阻塞、输入长度是否偏大 |
| 整体 | t2 − t0 | 待填 | 待填 | 仅用于对外承诺,不用于定位;越线时回到上面三行找那一段 |
对照的结论只有三种:单段越线就只改那一段,不要整体重写;多段同时越线且数值接近阈值上限,说明是容量或链路问题,先做限流和排队策略,再谈优化;全部在阈值内但用户仍反馈慢,多半是阈值定得比实际体验宽,回去复核首段结果的感知口径,而不是继续调服务端参数。任何改动后都用同一套打点和同一批输入重跑,对比的是分段中位数与最大值,而不是单次最好成绩。