request logger、trace 与 time stats#

这一节会把最常见的观测入口先统一起来，解释 request logger、trace 和时间字段分别站在哪一层、解决什么问题。

为什么这三样要放在一起看#

很多人会把 request logger、trace 和时间字段当成三组并列工具：

• logger 负责打印
• trace 负责看链路
• time stats 负责算延迟

但对 SGLang 来说，这三者更像同一条证据链的三个切面：

• request logger 提供请求首尾事实
• trace 提供阶段切片
• ReqTimeStats 提供统一时间语义

如果把它们分开理解，第四部分后面的很多调试动作都会重新变得零散。

request logger 真正留下了什么#

RequestLogger 在请求首尾两端留下结构化事实。典型的日志行如下：

INFO:     rid=7a3c21f8 | input=128 toks | output=64 toks | finish_reason=stop |
          TTFT=0.342s | E2E=2.187s | throughput=29.2 tok/s

这一行日志来自 python/sglang/srt/utils/request_logger.py，在请求结束时写入。它提供的不是 trace 级细节，而是：

• rid：请求的全局唯一标识，用于跨层对照；
• input / output token 数：最基础的输入输出规模；
• finish_reason：请求是正常结束（stop）、达到长度上限（length），还是中途中止（abort）；
• TTFT：time to first token，衡量首包延迟；
• E2E：请求从到达到最后一个 token 送出的全程耗时。

对排障来说，request logger 的价值不在于它有多详细，而在于它把首尾事实钉住了。在用 trace 或 metrics 深入之前，先确认这一行是否存在、finish_reason 是否符合预期，能排掉一大类"请求是不是根本没完成"这类问题。

ReqTimeStats 是所有时间证据的锚#

python/sglang/srt/observability/req_time_stats.py 里的 ReqTimeStats 把请求的完整时间线统一起来，其核心字段包括：

@dataclass
class ReqTimeStats:
    # 请求在 TokenizerManager 侧到达的时刻
    arrival_time: float
    # tokenization 完成、发送给 scheduler 的时刻
    tokenize_end_time: float
    # scheduler 开始 prefill 的时刻
    prefill_start_time: float
    # 第一个输出 token 写出的时刻（TTFT 终点）
    first_token_time: float
    # 最后一个 token 写出的时刻
    finish_time: float
    # response 送到客户端的时刻（streaming 下每 chunk 单独记录）
    response_sent_to_client_time: float

由这些字段可以直接推算出几个最常用的分段延迟：

这张表最重要的一点是：TTFT 不等于 prefill latency。TTFT 包含了 tokenization 时间和 queue wait time。如果只看 TTFT 高，不能直接推断"prefill 慢了"——必须先把 queue wait 分离出来。

trace 真正提供的是哪层信息#

RequestStage 枚举给出了请求在主链上的阶段切片：

class RequestStage(Enum):
    ARRIVED = "arrived"
    TOKENIZED = "tokenized"
    QUEUED = "queued"
    PREFILLING = "prefilling"
    DECODING = "decoding"
    FINISHED = "finished"
    ABORTED = "aborted"

trace 能让你看到一个请求在哪个阶段停留了多久，而不是只拿到一个总延迟数字。例如：

ARRIVED        t=0.000s
TOKENIZED      t=0.008s  (+0.008s  tokenization)
QUEUED         t=0.008s  (+0.000s  dispatch to scheduler)
PREFILLING     t=0.412s  (+0.404s  在 waiting queue 里等了 400ms)
DECODING       t=0.754s  (+0.342s  prefill 本身 = TTFT 终点)
FINISHED       t=2.187s  (+1.433s  decode 64 tokens)

从这条 trace 可以直接看出：这个请求的 TTFT 高主要是因为在 waiting queue 里等了 400ms，而 prefill 本身只有 342ms，decode 速度正常。如果没有 trace，只看 TTFT=0.754s，你会误判成 prefill 慢。

统一时间线：三层如何配合#

实际排障时，这三层通常按以下顺序使用：

1. 先看 request logger：确认请求的首尾事实是否成立。如果 finish_reason 是 abort，后面的分析方向完全不同。

2. 再看 trace / ReqTimeStats：用 RequestStage 把时间线切开，找出哪段时间最长。99% 的高延迟问题集中在以下三个位置：

   • queue wait 高 → 调度瓶颈，检查 num_waiting_reqs
   • prefill latency 高 → prompt 太长或 compute 不够
   • decode latency 高 → KV cache 压力或 batch 太大

3. 最后用 ReqTimeStats 字段对齐：当 trace 不够细时，用具体时间戳排除"是不是 tokenization 本身有异常"或"是不是 response send 出现了延迟"这类边缘问题。

调试时最容易踩的坑#

坑一：把 TTFT 和 prefill latency 混用
TTFT 是从客户端视角的等待时间，prefill latency 是 GPU 上跑 attention 的时间。两者相差的部分正好是 queue wait。如果 queue wait 大，即使把 prefill 优化到 0，TTFT 也不会有显著改善。

坑二：finish_time 不等于 response_sent_to_client_time
在 streaming 场景下，response 分多个 chunk 发送。finish_time 是最后一个 token 生成的时刻，response_sent_to_client_time 是它被写出的时刻。如果这两个时间差很大，问题在 I/O 层而不是 GPU 执行层。

坑三：时间戳没有被写进对象
ReqTimeStats 里的时间戳是逐步填入的，不是一次性写好的。如果某个阶段异常中断，对应的时间戳可能还是 0.0。排障时遇到时间字段为 0，先确认请求是不是在那个阶段之前就 abort 了。

小结#

这一节真正要建立的是一个判断：

• request logger、trace 和 ReqTimeStats 不是三套工具；
• 它们是同一条请求时间线的三个切面：首尾事实、阶段切片、统一时间语义。

只要这层先稳住，后面再读 metrics、profiling 和 crash dump 时，证据链就不会散。