DeepInfer 源码拆解（二十三）：运行时 Profiling 与统计日志——一次 decode step 如何被采样、聚合成吞吐与 MFU

从第二十二篇接上：为什么”看得见”是推理引擎的一等能力

前面二十二篇把 DeepInfer 的调度、KV 记账、并行拓扑、投机解码、结构化输出、CUDA Graph、权重装载、模型层和 InputMetadata 逐块拆开，看的都是”引擎怎么把计算跑起来”。这一篇换一个方向，看引擎怎么知道自己跑得怎么样：/profile 采集接口如何在不引入常驻开销的前提下抓取一段真实执行轨迹，StatsLogger 又如何把每个 step 的原始计数聚合成吞吐、MFU、投机接受率这些可读的指标。

这两个模块在代码量上都不大——profile_server.py 约三百行，stats_logger.py 约四百七十行——但它们把推理系统里几个容易被忽略的工程问题暴露得很清楚：采样动作如何跨线程交接、滑动窗口的分母该取到哪里、日志写盘为什么必须离开主循环，以及”只在 driver 卡上采”这种限制到底意味着什么。

先分清三条观测链路：trace、账本与标定曲线

DeepInfer 仓库里同时存在三套“看性能”的东西，它们服务的粒度完全不同，混在一起读很容易把它们当成重复实现。

第一套是 torch profiler 的 trace，入口是 ProfileManager（deepinfer/engine/profile_server.py）。它在真实的 engine step 上挂一小段采样，记录 CPU 侧函数调用、CUDA kernel、NCCL 通信与显存事件的精确时序，最后导出 Chrome trace。它回答的是“这一步的几毫秒到底花在哪些 kernel、哪次拷贝、哪次同步上”，粒度是微秒级。

第二套是 StatsLogger 的统计账本（deepinfer/engine/stats_logger.py）。它不记录单次调用的时间线，而是每个 step 往滑动窗口里追加几个整数或浮点数：批量 token 数、生成的 token 数、验证的草稿数、MoE 每卡负载、调度器估算的 FLOPs。每隔 100 个 step 做一次聚合，打印吞吐、MFU、缓存占用、接受率。它回答的是“过去一百步的整体状态是否健康”，粒度是 step 级。

第三套是启动期的 decode 性能曲线（ModelRunner.profile_decode_perf()）。它在 CUDA Graph 捕获完成后，对每个 batch size 重放若干次图，测出 (batch_size, 毫秒) 曲线，供 DSpark 的投机深度调度使用，也能落盘缓存。它回答的是“这个部署在这个 batch 档位上一步 decode 的基线成本是多少”，粒度是部署级、冷启动一次。

三条链路的分工可以用一句话记住：trace 找单点，账本看趋势，曲线定基线。这里的重点是前两条；曲线在前面的 CUDA Graph 篇和 MFU 篇已经拆过，本文只在需要对照时引用。

图源：DeepInfer 官方仓库 doc/images/architecture_overview.png。ProfileManager 与 StatsLogger 都挂在 LLMEngine 上，因此只存在于驱动进程；Prefill/Decode 拆开部署时，两侧各自拥有独立的观测链路。

/profile 的接口契约：一个 POST 如何把引擎冻住 20 步

profile_server.py 的模块 docstring 把接口行为写得很完整，先把它当成一份契约来读：

• 每个 engine 进程起一个 HTTP 服务，端口是 DEEPINFER_PROFILE_HTTP_PORT_BASE + driver_gpu_id，默认基址 6070；
• 只支持 POST /profile（代码里同时接受 GET，方便用浏览器或 curl 快速触发），参数是 output_dir 与 num_steps；
• 采满 num_steps 个 step 后把 trace 落盘，阻塞到文件写完才返回路径，所以没有单独的停止接口；
• 默认关闭，设置 DEEPINFER_PROFILE_HTTP_ENABLE=1 才启动；
• 只采 driver worker 这一张卡。torch profiler 是进程内的，context_parallel_size > 1 时 slave worker 在别的进程里，采不到。

参数上限也有明确约束：num_steps 默认 20，最大 50。代码注释给出的经验值是 trace 约 4.9 MB/step，步数越多，stop() 阻塞 engine 的时间越长——因为 profiler.stop() 必须在 engine 线程上同步执行。

一个最小的调用长这样：

1
curl -X POST http://<node-ip>:6070/profile \
2
  -H 'Content-Type: application/json' \
3
  -d '{"num_steps": 20, "output_dir": "/tmp/deepinfer-trace"}'

返回体包含 trace_file 字段，指向导出的 Chrome trace JSON。用 Perfetto 或 Chrome 的 chrome://tracing 打开，就能看到时间线。

1
ts = datetime.now().strftime("%Y%m%d-%H%M%S-%f")[:-3]
2
path = os.path.join(
3
    self._output_dir,
4
    f"profile-{self._ip}-gpu{self._gpu_id}-rank{self._global_rank}-{ts}.json",
5
)

线程模型：asyncio、engine 线程与单槽交接

ProfileManager 横跨三个执行上下文，这是它最容易读错的地方：

1. asyncio 线程：uvicorn 跑在一个 daemon 线程上的 event loop 里，负责解析请求、校验参数、等待 Future；
2. engine 线程：LLMEngine.step() 在开头调用 profile_manager.step()，负责取走请求、启停 profiler、推进倒计时；
3. IO 线程池：固定 1 个 worker，负责 export_chrome_trace() 这种几百毫秒到几秒的落盘操作。

三者之间只通过一个“单槽”交接，而不是队列：

1
# HTTP 侧
2
self._pending_req = req      # 先写槽位
3
self._req_ready.set()        # 再置 Event
4

5
# engine 侧
6
req, self._pending_req = self._pending_req, None
7
self._req_ready.clear()

两个语句的顺序有硬约束。如果先 set() 再写槽位，engine 可能在槽位还是 None 时就被唤醒；如果先 clear() 再读槽位，asyncio 侧可能在 clear 之后写入新请求，把还没读到的旧请求覆盖掉。代码注释把这两个顺序都标了出来。HTTP 侧只有一个 event loop 线程会写槽位，两句之间没有 await，所以不会被别的协程插进来。

槽位只负责“防止请求堆积”，不负责“同时只能有一个采集”。真正的互斥在 engine 侧：_handle_request() 发现 self._profiler is not None 时直接回 409。槽位被取走后立刻清空，因此第二个请求可以进来，但会被 engine 拒绝。这个分工让 HTTP 侧不需要知道 profiler 的状态。

请求对象上挂着一个 Future，它同时承担“回传结果”和“取消协议”两个职责：

1
@dataclass(frozen=True)
2
class _ProfileRequest:
3
    output_dir: str
4
    num_steps: int
5
    reply: Future[_Reply | _PendingTrace] = field(default_factory=Future)

客户端超时取消与 engine 侧 set_running_or_notify_cancel() 是原子二选一。engine 如果抢不到执行权，说明客户端已经走了，直接丢弃请求；如果抢到了，之后即使客户端超时，采集也会继续完成并落盘，只是结果没人接收。这个设计避免了“客户端超时后 engine 还在采，但下一次请求又启动了一个 profiler”的叠加。

等待分两段：

• _PICKUP_TIMEOUT_S = 30：等 engine 取走请求。engine 卡住、被挂起或还在加载模型时会超时。超时后如果 Future 能被取消，返回 503 并明确说明“请求不会生效”；
• _COMPLETION_TIMEOUT_S = 600：接手之后等采集与导出。trace 导出可能几十秒，给足十分钟。

如果第二次等待也超时，接口返回 503，并说明 trace 不会写出。这个语义比“无限等待”更适合自动化调用。

图源：本站根据 deepinfer/engine/profile_server.py 绘制。编号对应文中描述的顺序：先写槽位再置 Event，engine 在 step() 开头取走，采满后回传 _PendingTrace，最后由固定 1 个 worker 的线程池落盘。

怎么读一张 DeepInfer 的 trace

trace 本身是通用的 PyTorch/Kineto 格式，读法在站内 GPU 推理性能分析完全指南 里已经系统地讲过，这里只补 DeepInfer 特有的部分：它的 CPU 计时器会给每一段打上带前缀的名字。

deepinfer/timer.py 里的 CPUTimer.record() 用 torch.profiler.record_function(f"deepinfer:{name}") 包裹被测代码段：

1
@contextmanager
2
def record(self, name: str, enable: bool = True, record_name: str | None = None):
3
    if not enable:
4
        yield
5
        return
6
    t0 = time.perf_counter()
7
    with torch.profiler.record_function(f"deepinfer:{record_name or name}"):
8
        yield
9
    elapsed = time.perf_counter() - t0
10
    self.add_time(name, elapsed)

因此在 trace 的 CPU 轨道上搜索 deepinfer:，就能把 DeepInfer 自己的阶段划分从几百个 Python 函数里筛出来。常见的标签分三类。

调度阶段（LLMEngine.step() 内）：

执行阶段（model_runner.py 内）：

后处理阶段（worker.py、llm_engine.py 内）：

launch_forward 的 record_name 用了动态字符串，所以在 trace 里可以看到 launch_forward_N64_B320 这样的标签。它把“这一步的批形状”直接写在时间线上，排查 CUDA Graph 档位是否命中时非常直观：如果标签名里的 N、B 与日志里打印的 num_seqs、num_batched_tokens 对不上，说明采样时刻与日志时刻之间的批组成已经变了。

读 trace 的三个典型用法：

1. 找 CPU 空泡。在 CPU 轨道上找 worker.post_process.sync，它左右两侧如果出现大段没有 kernel 提交的空白，就是等待采样完成的同步点。ZOS 的意义正是把这个同步点挪到下一拍的 forward 阴影里，见 异步调度与零开销调度 ZOS。
2. 核对图是否在重放。CUDA Graph 重放在 trace 里表现为一个大跨度的 kernel 序列，前面通常只有一个很短的 launch 段。如果每一步都有几百个零散的 kernel launch，说明图没有命中，需要检查形状桶与 DEEPINFER_ENFORCE_EAGER。
3. 看通信的占比。NCCL 的 all-reduce、all-to-all 会以 nccl* kernel 的形式出现在 GPU 轨道上。把它们的时间与 launch_forward 的时间相除，得到粗粒度的通信占比。

图源：PyTorch Profiler Recipe。DeepInfer 导出的 trace 是同一格式，只是 CPU 轨道上多了一层 deepinfer: 前缀的阶段划分。

采样期间性能会被轻微扰动：torch profiler 自身会插桩每个算子的 launch 与每个 memory 事件，CPU 侧开销明显增加，GPU 侧也有额外的事件记录。所以 trace 适合用来“定位结构”，不适合用来“测吞吐”。测吞吐请用 StatsLogger 的日志或官方 benchmark，二者的记账口径分别见下文与 LLM 推理 Benchmark 完全指南。

StatsLogger 的输入：一个 step 能提供哪些数

StatsLogger.log_step(StepStats) 是账本的入口。LLMEngine._process_model_outputs() 在 log_stats 为真时把这一步的数打包成一个 StepStats：

1
step_stats = StepStats(
2
    prompt_run=scheduler_outputs.prompt_run,
3
    num_seqs=len(scheduler_outputs.scheduled_seqs),
4
    num_batched_tokens=scheduler_outputs.num_batched_tokens,
5
    sum_seqlen_qxk=scheduler_outputs.sum_seqlen_qxk,
6
    max_seqlen_k=scheduler_outputs.max_seqlen_k,
7
    min_seqlen_k=scheduler_outputs.min_seqlen_k,
8
    attn_tflops=scheduler_outputs.attn_tflops,
9
    total_tflops=scheduler_outputs.total_tflops,
10
    first_token_latencies=first_token_latencies,
11
    num_cached_tokens_gpu=scheduler_outputs.num_cached_tokens_gpu,
12
    num_generated_tokens=output.num_generated_tokens,
13
    num_verified_tokens=output.num_verified_tokens,
14
    batch_confidence_error=output.batch_confidence_error,
15
    moe_load_balance_ratio=output.moe_load_balance_ratio,
16
)

字段来源可以分成三组：

• 调度器的预期账：num_batched_tokens、seqlen 统计量、attn_tflops / total_tflops。其中 FLOPs 是在 Scheduler::schedule() 里用 FlopsEstimator 顺手算的，是“预期做了多少计算”，详见 MFU 怎么算的。
• 采样的实测产出：num_generated_tokens 是一个列表，形状是 1 + nextn 项，分别记录每个草稿位置生成了几个 token；num_verified_tokens 同理记录每个位置验证了几个 token；batch_confidence_error 是置信度头的误差。
• 调度器账本的变化量：num_cached_tokens_gpu 是这一步被前缀缓存命中的 token 数，用来算 prefill 缓存命中率。

first_token_latencies 的来源值得单独说一句。它不在 Python 侧计时，而是由 Scheduler::process_outputs() 在 C++ 里记录：

1
// csrc/engine/scheduler.hpp, process_outputs
2
if (seq.get_output_len() == 1) {
3
    first_token_latencies.push_back(ts - seq.request.arrival_time);
4
}

ts 是进入 process_outputs() 的时刻，arrival_time 是请求进入引擎的时刻。这个口径是从请求到达开始算到第一个 token 被采样出来，包含了排队、调度、prefill 与采样前同步的全部时间，比单纯测量 prefill 前向更接近用户感知的 TTFT。注释还特别说明：第一个 token 一定由 prompt run 产生，prompt 步不使用 nextn。

数组通过 pybind 零拷贝返回，借用一块进程级静态缓冲：

1
"""提交本 step 的模型输出，返回 (first_token_latencies float64[n], pushed_tokens_before_finish int32[n])。
2
两个数组零拷贝借用进程级静态缓冲，下一次 process_outputs 会覆写：须在此之前消费完，禁止跨 step 持有。"""

StatsLogger 只在 _collect() 里立即取 max 与 mean，没有把数组存进窗口。这不是偶然——如果窗口持有这块缓冲，下一次 process_outputs 会把它覆写成下一批的延迟，历史数据就被悄悄改掉了。

log_stats 本身是一个开关：LLMEngine 构造时 log_stats=not engine_args.disable_log_stats。离线 LLM 入口默认把它关掉（kwargs.setdefault("disable_log_stats", True)），服务部署默认打开。关闭时 log_stats_func 退化为一个空 lambda，连 StepStats 都不构造。

滑动窗口：同一组样本，三种分母

账本的核心是六个 Window，每个都只是 (时间戳, 载荷, step) 三元组的有序列表：

1
class Window:
2
    __slots__ = ("entries",)
3
    def append(self, now: float, payload: object, step: int) -> None:
4
        self.entries.append((now, payload, step))
5
    def trim(self, step: int, max_age: int) -> None:
6
        self.entries = [e for e in self.entries if step - e[2] <= max_age]

六个窗口的载荷分别是：prompt token 数、(生成 token 列表, 序列数, 批 token 数)、验证 token 数、置信度误差、(平均专家负载, 最大专家负载)、每步 TFLOPS。修剪以 step 为年龄，不是以时间为年龄：DEEPINFER_LOGGING_INTERVAL_STEP 默认 100，每次打日志时保留最近 100 步的样本。MoE 负载窗口用另一个更长的 DEEPINFER_MOE_LB_STAT_INTERVAL（默认 128），因为 MoE 每卡负载的统计本身按这个周期聚合。

在这个“步数定窗口大小”的基础上，两种聚合函数用了两种不同的时间分母：

1
@staticmethod
2
def _throughput(window: Window, now: float, key) -> tuple[float, int]:
3
    if len(window) <= 1:
4
        return 0.0, 0
5
    total = sum(key(p) for _, p, _ in window.entries[1:])
6
    # 口径：首条仅作窗口起点（值不计入），分母延伸到 now——含末样本之后的空窗，
7
    # 窗口停更时数值随时间衰减（对比 _mfu）
8
    return total / (now - window.entries[0][0]), total
9

10
def _mfu(self, now: float) -> float:
11
    entries = self._tflops.entries
12
    if len(entries) <= 1:
13
        return 0.0
14
    # 口径：首条仅作区间起点（值不计入），分母为首尾样本间隔、不延伸到 now
15
    tflops_per_s = (sum(v for _, v, _ in entries) - entries[0][1]) / (entries[-1][0] - entries[0][0])
16
    return tflops_per_s / self._parallel_config.model_parallel_size / self._tflops_limit

两者的共同点是“首条只做起点、不计入分子”，分子都把第一个样本的载荷减掉。区别只在分母的右端点：

• 吞吐的分母是 now - 首条时间戳。now 是本次聚合的时刻。如果窗口样本稀疏，最后一个样本到 now 之间有一段没有采样的时间，这段也被算进分母——平均速率因此被拉低。这是“此刻的平均速率”口径，反映的是最近一段时间内引擎真实在跑的速率，包括中途可能的停顿。
• MFU 的分母是 末条时间戳 - 首条时间戳。它只看样本覆盖的那段时间，不延伸到 now。

为什么同一个窗口要分两种分母？直觉来自两者的性质。吞吐是一个速率指标，用户关心“最近一百步里每秒吐出多少 token”，如果没有新样本，速率理应随时间衰减——引擎可能停了、可能在等 GPU、可能在处理一个超长的 prefill。MFU 是一个窗口汇总指标，关心“这一百步里 GPU 算力被利用了多大比例”，它应该是这段时间的平均值，不应该因为窗口停在旧时间点而“漂移”。在正常满批的持续负载下，两者几乎一致；差异只在窗口停更或采样稀疏时显现。

图源：本站根据 deepinfer/engine/stats_logger.py 中 Window、_throughput、_mfu 与 log_step 的窗口修剪逻辑绘制。

1
total_gpu = self._cache_config.num_gpu_blocks - 1
2
a.gpu_cache_usage = (total_gpu - eng.scheduler.get_num_free_gpu_blocks()) / total_gpu

1
a.num_pendings = eng.get_num_pendings()
2
a.num_runnings, _ = eng.scheduler.get_sum_prompt_len_running()
3
a.num_chunked, _ = eng.scheduler.get_sum_prompt_len_chunked()

1
std::pair<int, int> get_sum_prompt_len_running() {
2
    int sum = 0;
3
    int num_running = running.size();
4
    for (auto &seq : running) sum += seq->get_prompt_len();
5
    return {num_running, sum};
6
}
7

8
std::pair<int, int> get_sum_prompt_len_waiting() {
9
    int sum = 0;
10
    for (auto &seq : waiting) sum += seq->get_prompt_len();
11
    return {waiting.size() + prompted.size(), sum};
12
}
13

14
std::pair<int, int> get_sum_prompt_len_chunked() {
15
    int sum = 0;
16
    int count = 0;
17
    for (auto &seq : waiting) {
18
        if (seq->schedule.chunked_rest_len > 0) { sum += seq->get_prompt_len(); count++; }
19
    }
20
    return {count, sum};
21
}

指标怎么被算出来：吞吐、投机接受率、MoE 均衡与 MFU

聚合完成之后，_build_log_messages() 把结果拼成一行 [stats] 和若干行 [cpu]、[cuda]。先看 [stats] 行里每个字段的算法。

1
step_dur = eng.last_step_interval if (envs.DEEPINFER_ZERO_OVERHEAD_SCHEDULING and step > 0) else now - eng.step_start
2
a.cur_sps = 1 / step_dur
3
a.avg_sps = 0.0 if self._last_logging_time == 0 else (step - self._last_logging_step) / (now - self._last_logging_time)
4
a.cur_tps = sum(gen_tokens) / step_dur

1
if s.prompt_run:
2
    batch_pct = s.num_batched_tokens / self._model_config.max_num_batched_tokens
3
else:
4
    batch_pct = s.num_batched_tokens / (self._model_config.max_num_seqs * (1 + envs.DEEPINFER_USE_NEXTN_DECODE))

1
n = envs.DEEPINFER_USE_NEXTN_DECODE + 1
2
accepted = [0] * n
3
for _, (gen, _, _), _ in self._generation_tokens.entries:
4
    for i, v in enumerate(gen):
5
        accepted[i] += v
6
verified = [0] * n
7
for _, vt, _ in self._verified_tokens.entries:
8
    if vt is not None:
9
        for i, v in enumerate(vt):
10
            verified[i] += v

1
agg.nextn_rates = [accepted[i] / verified[i] if verified[i] > 0 else 0.0 for i in range(1, n)]
2
agg.nextn_rate = sum(accepted[1:]) / (agg.sum_total - agg.sum_batched + 1e-15)
3
agg.avg_vlen = sum(verified[1:]) / agg.sum_batched

1
def _moe_lb_ratio(self) -> float:
2
    if not self._moe_lb:
3
        return 1.0  # 无数据时默认完美均衡
4
    return self._moe_lb.sum(lambda p: p[1]) / max(1, self._moe_lb.sum(lambda p: p[0]))

1
a.avg_prompt_len, a.avg_completion_len, a.payload_len = self._finished_payload_stats()

1
total_calc = sum(calc for calc, _ in self._prefill_cached_tokens)
2
gpu_pct = sum(gpu for _, gpu in self._prefill_cached_tokens) / max(1, total_calc)

日志行怎么读：从 [stats] 到 [cpu] / [cuda]

一次日志由一段 [stats] 和两段计时器汇总组成。先看触发频率：

1
def _should_log(self, s: StepStats) -> tuple[bool, int]:
2
    step = self._engine.generate_step
3
    interval = envs.DEEPINFER_LOGGING_INTERVAL_STEP
4
    if interval <= 0:
5
        return False, interval
6
    if self._engine_type == EngineType.PROMPT:
7
        interval = max(1, interval // 5)
8
    should_log = step == 0 or step - self._last_logging_step >= interval
9
    return should_log, interval

默认每 100 步打一次，step == 0 时立刻打一次。PROMPT 引擎的间隔除以 5（默认 20 步），因为 prefill 引擎的步数少、单步成本高，按同样的步数间隔会等太久才看到第一条日志。interval <= 0 表示关闭日志，但窗口修剪仍然进行，只是不打印。

[stats] 行的字段大致按这个顺序拼接：

1
RANK 0, GPU 0, step 1200, [stats] (is_prompt False | cur_SPS 2.431 | avg_SPS 2.402 |
2
cur_TPS 311.2 | prompt_TPS 1820.4 | completion_TPS 298.7 | avg_nextn_accept_rate 62.35% |
3
nextn_accept_rate [78.10%, 65.40%, 52.20%, 41.90%, 33.10%] | verified_tokens 18422 |
4
accepted_tokens 11488 | avg_verified_len 5.63 | avg_confidence_error 0.0412 | moe_lb 1.087 |
5
running 128 | pending 3 | chunked 0 | num_batched_tokens 768[100.00%] |
6
KV_cache_usage 73.41% | state_cache_usage 12.50% | prefill/decode 0.00%/99.80% |
7
prefill_caching_rate (GPU 0.00%) | TTFT (max 812.4 ms, mean 143.7 ms) |
8
avg_length (input 1834.2, output 612.8) | finished 4211 | preempted 0 | aborted 2 |
9
sum_seqlen_qxk 18422 | max_seqlen_k 20311 | min_seqlen_k 1801 |
10
attn_TFLOPs 42.1 | MFU 0.318)

这些数字只是示意，用来说明字段之间的关系，不是任何实测曲线。逐组读：

吞吐组。cur_SPS 与 avg_SPS 是步率，cur_TPS 是这一步的 token 率，prompt_TPS 与 completion_TPS 是窗口平均的 prefill/生成 token 率。cur_TPS 高但 completion_TPS 低，说明窗口里混入了大量 prefill 步：当前步很快，但过去一百步的平均被长 prompt 拉低。

投机组。avg_nextn_accept_rate 是整体接受率，后面方括号是按位置的接受率。verified_tokens 与 accepted_tokens 是窗口累计数，avg_verified_len 是平均每条序列验证了几个草稿。avg_confidence_error 越小，置信度头越可信。

负载与缓存组。running、pending、chunked 是当前队列长度；num_batched_tokens 后面的百分比是批利用率；KV_cache_usage 与 state_cache_usage 是当前占用；prefill/decode 是窗口内 CPU 计时器里 engine_step:prefill 与 engine_step:decode 的占比，不是 GPU 时间占比；prefill_caching_rate 是前缀命中率。

延迟与形状组。TTFT 是窗口内新首 token 的 max/mean；avg_length 是完成请求的平均输入/输出长度；sum_seqlen_qxk 与 max_seqlen_k、min_seqlen_k 是当前步的 q×k 总量与 k 长度范围，用来判断注意力的形状分布。它们与 attn_TFLOPs 一起，是调度器估算账的原始输入。

MFU 是窗口平均，不是当前步。看到 MFU 异常时，先确认窗口里 prefill 与 decode 的比例，再看 attn_TFLOPs 与 sum_seqlen_qxk 是否与当前步的实际形状一致。

1
RANK 0, GPU 0, step 1200, [cpu] (schedule cur2.1ms/mean1.8ms/max9.4ms/100calls/18.3% |
2
schedule:cpp cur1.2ms/mean1.0ms/max6.1ms/100calls/10.2% | ... )

1
def _log_worker(q: queue.SimpleQueue[list[str] | None]) -> None:
2
    need_sleep = True
3
    for msgs in iter(q.get, None):
4
        try:
5
            if need_sleep:
6
                time.sleep((dist.get_rank() % 8) * 0.005)
7
            for m in msgs:
8
                logger.info(m)
9
            need_sleep = q.empty()
10
        except Exception:
11
            traceback.print_exc()

第三个日志通道：NCCL 通信器显存

StatsLogger 还挂了一个独立的 NCCLMemoryStatsLogger。它不是窗口统计，而是每隔一段时间采样一次 driver 进程里所有 NCCL communicator 的显存占用：

1
_FIRST_SAMPLE_STEP = 10
2
_GiB = 1 << 30
3

4
for group in c10d._world.pg_map:
5
    if dist.get_backend(group) != "nccl":
6
        continue
7
    backend = group._get_backend(torch.device("cuda"))
8
    if backend._comm_ptr() == 0:
9
        continue
10
    total = backend.memory_stats()["total"]
11
    ...

采样频率由 DEEPINFER_NCCL_MEMORY_SAMPLE_INTERVAL_STEPS 控制，默认 1000 步；前 10 步不采，避免启动期的 communicator 还没建完。采样结果只有在发生变化时才打印：

1
RANK 0, GPU 0, step 3000, [nccl_memory] (total=1.842 GiB | communicator_count=7 |
2
groups=[... (0.312 GiB); ...])

每个 communicator 的标签会带上它在 PG_dict 里的别名；多套 tag 的部署里，同名 group 会加上 tag 前缀区分。memory_stats()["total"] 是 NCCL 为该 communicator 分配的显存总量，包含 buffers 与算法所需的临时空间。

这个指标解决的是一个很具体的问题：EP/CP/DP 组越建越多，NCCL 的显存开销会悄悄吃掉 KV 池的预算。启动时的 profile_run() 只能量到当时的通信器；如果运行中动态建组（弹性 EP、故障恢复、重新分组），显存会在运行期增长，而普通日志看不到。NCCL 显存日志在变化时才打印，既能看到增长，又不会每 1000 步刷一行相同的数字。弹性 EP 的建组与重排见 弹性 EP 与故障恢复，DeepInfer 侧的并行拓扑见 DP Attention 与 Wide-EP。

采样本身也会失败：某些 NCCL 版本或后端不提供 memory_stats()，或者 communicator 正在销毁。step() 捕获异常并只打印一次 stats_unavailable=...，同样的错误字符串不会重复刷屏。这个“错误去重”与“变化才打印”是同一个思路：日志的价值在于变化，重复的稳定状态只会淹没信号。

三种观测方式的分工与选取

一个实际的排查顺序是：

1. 先看日志里 avg_SPS、completion_TPS 是否相对基线下降，KV_cache_usage 是否长期接近 100%、pending 与 preempted 是否上升——这些是调度与容量层面的问题；
2. 如果吞吐正常但尾延迟变差，看 [cuda] 行里哪个 kernel 的 max 明显高于 mean，再用 trace 定位这个 kernel 前后的同步点；
3. 如果 MFU 掉但吞吐没掉，先看 attn_TFLOPs 与 sum_seqlen_qxk：可能是模型结构变更后 FlopsEstimator 的系数没有更新，而不是硬件利用率真的下降；
4. 如果 avg_nextn_accept_rate 与按位置接受率同时下滑，说明置信度头或草稿头与目标模型的分布漂移，投机解码在赔本；
5. 如果 [nccl_memory] 在某一步之后 total 跳升，检查是否发生了动态建组或 EP 重排列。

与其他框架的观测体系对照

vLLM 的观测走的是另一条路线：事件驱动的迭代统计 + Prometheus 指标。引擎每个 iteration 结束时更新一组计数器，用户通过 /metrics 端点拉取，再由 Prometheus/Grafana 做持久化与告警。它的指标命名面向运维，例如 vllm:spec_decode_num_draft_tokens、vllm:spec_decode_num_accepted_tokens、vllm:spec_decode_draft_acceptance_rate、vllm:spec_decode_efficiency。注意它的接受率也是“接受数 / 草稿数”的全局比值，与 DeepInfer 的 avg_nextn_accept_rate 同义，但 vLLM 额外区分了 emitted tokens 与 efficiency，用来判断投机是否真的省了时间而不只是提高了每步 token 数。vLLM 官方文档里还有一段关于 autoscaling 的讨论：哪些指标适合作为扩缩容信号，本身是一个尚未定论的问题。

DeepInfer 的选择更“嵌入式”：

• 没有 HTTP 指标端点，统计以结构化日志行输出，由外部日志系统采集。这与它在 DeepSeek 内部服务的部署方式有关，日志体系已经在使用；
• 指标更贴近模型结构：nextn_accept_rate 按草稿位置分开，moe_lb 直接对应 EPLB 的收益来源，MFU 用 FlopsEstimator 的 FP8 等效口径，这些都是为 V4.1-Flash 这类模型定制的；
• profiling 通过 engine 内的 HTTP 接口，而不是启动时的命令行参数，可以在服务运行中随时抓一段 trace，采完即停，不需要重启。

SGLang 的观测则更依赖外部组件：它把调度与 KV 池的状态暴露为指标，并在 profiler 集成上提供独立的入口。TensorRT-LLM 自带较强的 profiling 工具链，覆盖构建期与运行期。三者放在一起看，可以得出一个共同结论：推理框架的观测能力不是“加个日志”，而是根据部署形态选择采集面、聚合粒度与暴露方式。批量离线推理更看重单次 trace，在线服务更看重周期聚合与外部可采集性。

DeepInfer 的 StatsLogger 是典型的“在线服务优先”设计：周期聚合、滑动窗口、按 rank 错峰写日志、错误去重，每一项都是为了在几十到几百个 rank 的集群里不拖慢主循环。

工程边界与容易踩的坑

1
try:
2
    log_stats_func()
3
except Exception as e:
4
    traceback.print_exc()
5
    logger.error("打印统计信息失败：%s", e)

小结

DeepInfer 的观测体系可以概括成一句话：采样走 HTTP、聚合走窗口、解释走日志。

ProfileManager 用三个执行上下文（asyncio、engine、IO 线程池）和一个单槽，把“随时抓一段 trace”做成了一个不影响 engine 启动、不阻塞 HTTP、不跨线程 stop profiler 的接口。它的限制也同样明确：只采 driver 卡、采满即停、阻塞式返回、trace 体积与步数成正比。理解这些限制，才能判断一张 trace 能回答什么问题、不能回答什么问题。

StatsLogger 用六个滑动窗口和两种时间分母，把逐 step 的计数变成吞吐、MFU、接受率、缓存占用与队列状态。它的关键设计不在于字段多，而在于口径统一：首条样本只做起点、吞吐延伸到 now、MFU 止于末条样本、decode 批利用率按 query token 上限归一、MoE 负载按最大/平均定义。口径一旦明确，日志里的数字才可以跨时间、跨部署比较。

/profile 与 StatsLogger 的关系，是显微镜与仪表盘的关系。显微镜用来定位一次具体的停顿，仪表盘用来判断服务是否偏离基线。两者都不替代 benchmark：benchmark 控制变量、重复测量，回答“这个部署能跑多快”；观测回答“现在为什么跑成这样”。把三者放在一起，才是完整的推理性能工程。

参考资料

1. DeepInfer 官方仓库
2. DeepInfer profile_server.py：运行时 profiling 的 HTTP 接口
3. DeepInfer stats_logger.py：滑动窗口、吞吐/MFU 口径与日志构建
4. DeepInfer timer.py：CPU/CUDA 计时器与 deepinfer: trace 标注
5. DeepInfer llm_engine.py：step 入口、ProfileManager 构造与 StepStats 打包
6. DeepInfer model_runner.py：profile_decode_perf() 与图重放测量
7. DeepInfer decode_perf_cache.py：decode 性能曲线的哈希键、TTL 与原子写盘
8. DeepInfer nccl_memory.py：NCCL communicator 显存采样与变化检测
9. DeepInfer environ.py：profiling、日志与缓存相关环境变量
10. PyTorch Profiler 文档
11. PyTorch Profiler Recipe：trace 的采集与 Chrome trace 查看
12. PyTorch Kineto：profiler 的底层事件采集库
13. Perfetto UI：Chrome trace 的可视化工具
14. vLLM Production Metrics：指标命名、投机解码指标与自动扩缩容讨论
15. SGLang 官方文档
16. TensorRT-LLM 官方文档