换模型后用户反馈“等得更久”，先不要在服务端大改配置。在客户端把一次调用拆成建连、首字节、生成三段，各打一个单调时钟时间戳，通常就能判断慢在自身网络、服务端排队，还是输出变长带来的主观错觉。这三种情况对应的动作完全不同，靠页面上的转圈时长或者体感是分不出来的。

建议的判断路径：请求发出前记录 t0，首个有效内容块到达记录 t1，流结束记录 t2。t1−t0 看建连与首包排队，t2−t1 看生成过程，t2−t0 是用户实际等待。若 t1−t0 偏大而 t2−t1 稳定，优先查客户端出口网络和服务侧排队；若单位输出耗时基本不变、总时长变长，多半是输出变长造成的错觉。单次结果不足以判断，需同一提示词重复多次取分位值。边界是客户端只能观测外部耗时，服务端内部排队要结合服务侧指标确认。

在请求前后打上单调时钟时间戳

计时要用单调时钟，不要用系统墙上时间做减法。系统时间会被 NTP 校正或人工修改，出现小幅回拨时，time.time()、Date.now() 这类值相减可能得到偏小甚至为负的耗时。Python 用 time.perf_counter()，Go 用 time.Now() 自带的单调读数配合 time.Since，Node 用 process.hrtime.bigint()，Java 用 System.nanoTime()，这些都不会被系统时钟跳变影响。

打点位置只有三个：调用发起前（t0）、首个内容块到达（t1）、流读取结束或连接关闭（t2）。日志字段建议统一命名并带上环境与参数，方便后续按模型版本筛选：

import time, uuid, logging

def call_once(prompt, opener, **kw):
    req_id = uuid.uuid4().hex[:12]
    t0 = time.perf_counter()          # 发起前
    t1 = None                          # 首个内容块到达
    chunks = []
    try:
        stream = opener(prompt, **kw)  # 替换为实际调用
        for ch in stream:
            if t1 is None and has_content(ch):
                t1 = time.perf_counter()
            chunks.append(ch)
        t2 = time.perf_counter()       # 结束
        logging.info(
            "req_id=%s model=%s stream=%s ttfb_ms=%.0f gen_ms=%.0f total_ms=%.0f",
            req_id, kw.get("model"), kw.get("stream"),
            ((t1 or t2) - t0) * 1000, (t2 - (t1 or t2)) * 1000, (t2 - t0) * 1000)
    except Exception as e:
        logging.warning("req_id=%s model=%s fail=%s elapsed_ms=%.0f",
                        req_id, kw.get("model"), type(e).__name__,
                        (time.perf_counter() - t0) * 1000)
        raise

字段命名建议固定为：req_id / model / stream / ttfb_ms / gen_ms / total_ms / prompt_chars / completion_chars / usage_completion_tokens / usage_estimated / retry_count / status。先固定字段再动手优化，否则后续比对没有基线。

把首字节时间和总耗时分开记录

只有 total_ms 无法区分“在排队等”和“在慢慢生成”。流式调用时，首个内容块的判定要按内容是否为空来判断，而不是按收到第一个数据包判断：有的实现先回一条只含角色信息的元数据帧，把它当成首字节会把 t1 记早，人为缩小排队时间。

def has_content(chunk):
    # 通用骨架：只认有实际文本增量的块，元数据帧不算首字节
    delta = getattr(chunk, "delta_text", None) or ""
    return len(delta.strip()) > 0

非流式调用拿不到首字节，只能做近似：记录建连与请求写出完成的时刻，用它和总耗时的差值粗略估计“服务端思考加生成”的时间，并在日志里标注 ttfb_estimated=true，不要把它当成精确值。另一种做法是临时发一个短输出请求（例如只要求回一个字）作为探针，用它的总耗时观察排队水位，探针请求要和业务请求分开统计。

统计输出长度与耗时的比值

用户说“变慢”，有时只是回答变长了。优先读返回体里的用量字段，把 completion_tokens 和 gen_ms 放在一起看，算单位输出的耗时；如果这个比值和换模型前大致相当，而总耗时上升，就该去查输出长度而不是查线路。

用量字段缺失时，按输出字符数估算：estimated_tokens = completion_chars / 1.7 这类比例只能当粗略参照，中英文混排差异很大，务必在日志里写 usage_estimated=true，并在报表里和真实用量分开。比较时用同一比值维度，不要拿“估算 token”和“真实 token”直接对齐。

同一提示词重复多次取分位值

单次调用的抖动很大，一次慢不能说明趋势。建议固定提示词、固定参数（模型、温度、最大输出长度），连续跑 5 到 10 次；次数取决于你能接受的观察成本，最少 5 次才有一点分布意义，需要更稳的判断就重复到当天不同时段各一组。

run | ttfb_ms | gen_ms | total_ms | completion_tokens | status
 1  |         |        |          |                   |
 2  |         |        |          |                   |
...
中位数 = 排序后取中间位；偶数条取中间两个的平均
最大值 = 排序后最后一条（不要用均值代替，均值会被长尾拉偏）

对照时看中位数判断常态，看最大值判断长尾。中位数正常但最大值明显拉长，多半是偶发排队或重试，而不是模型整体变慢。

对齐客户端超时与重试参数

重试会把慢请求变成“看起来正常”的请求，同时在日志里留下一次失败一次成功的两条记录。打点要放在重试循环外层，才能看到用户真实等待：

TIMEOUT = {"connect": 5, "read": 60}   # 通用骨架，按实际客户端替换
MAX_RETRY = 2

for attempt in range(MAX_RETRY + 1):
    t0 = time.perf_counter()
    try:
        resp = opener(prompt, timeout=TIMEOUT)
        logging.info("attempt=%d retry_count=%d ok_ms=%.0f",
                     attempt + 1, attempt, (time.perf_counter() - t0) * 1000)
        break
    except ReadTimeout:
        logging.warning("attempt=%d retry_count=%d timeout_ms=%.0f",
                        attempt + 1, attempt, (time.perf_counter() - t0) * 1000)
        if attempt == MAX_RETRY:
            raise

超时值要大于该场景下正常响应的中位耗时，否则大量请求会被误判超时再重试，反而把耗时叠上去。日志里必须带 attempt 和 retry_count，统计时先按 retry_count=0 筛一遍，看看真实一次成功的耗时分布，再决定是调超时、调重试次数，还是回到前面几节继续定位慢在哪一段。