qwen36_01/worklogs/decode_analysis_report_2026-07-14.md

# Decode 吞吐专项实验分析报告

日期：2026-07-14

## 一、结论摘要

本轮实验确认：当前服务的主要短板是 decode 阶段吞吐，而不是 prompt prefill、tool parser 或 reasoning parser。

核心证据：

- 短 prompt、单并发、256 token 输出时，Output TPS P10 只有 `8.3-8.7 tok/s`，明显低于官方目标 `>=20 tok/s`。
- 去掉 `--enable-auto-tool-choice`、`--tool-call-parser`、`--reasoning-parser` 后，decode TPS 没有提升，反而略低。
- 加并发后没有获得 batch 增益：并发 1 聚合约 `8.00 tok/s`，并发 2 聚合约 `7.23 tok/s`，并发 4 聚合约 `5.08 tok/s`。
- 并发 2 时硬件采样显示平均 GPU-Util 只有 `28.9%`，平均功耗约 `49.7W / 250W`，说明 GPU 没有被持续打满。

初步判断：瓶颈更像是 decode 路径中的调度、TP 同步、MoE kernel/专家路由、paged attention/kernel launch 开销，或 xFormers 后端限制，而不是 API parser 层。

## 二、实验环境

远端服务：

- 模型：`/root/public-storage/models/Qwen/Qwen3.6-35B-A3B`
- API：`vllm.entrypoints.openai.api_server`
- GPU：4 x Iluvatar BI-V100, 32GB
- 当前主要实验配置：
  - `-tp 4`
  - `--gpu-memory-utilization 0.95`
  - `--max-num-seqs 2`
  - `--max-num-batched-tokens 8192`
  - `--enable-chunked-prefill`
  - `--enable-prefix-caching`

本地脚本：

- `worklogs/decode_microbench.py`

远端脚本：

- `/root/work/decode_microbench.py`

本地原始结果：

- `worklogs/remote_results/2026-07-14-decode/`

## 三、实验结果

### 1. 纯短 prompt decode 基线

完整 parser 配置，短 prompt，单并发，3 请求，每请求 `max_tokens=256`。

结果文件：

- 远端：`/root/work/logs/decode_full_parser_short_c1_t256_r3.json`
- 本地：`worklogs/remote_results/2026-07-14-decode/decode_full_parser_short_c1_t256_r3.json`

指标：

| 指标 | 数值 |
|---|---:|
| 成功率 | 100% |
| TTFT P90 | 1.85s |
| Output TPS P10 | 8.74 tok/s |
| Output TPS P50 | 8.74 tok/s |
| 聚合 Output TPS | 8.34 tok/s |
| 总 completion tokens | 768 |
| reasoning tokens | 768 |

解释：

短 prompt 下 TTFT 已经较低，但 decode 速度仍只有约 `8.7 tok/s`。这说明长上下文不是唯一问题，短输出生成本身就偏慢。

### 2. Tool/parser 触发场景

完整 parser 配置，携带 29 个 tools，单并发，3 请求，每请求 `max_tokens=128`。

结果文件：

- 远端：`/root/work/logs/decode_full_parser_tool_c1_t128_r3.json`
- 本地：`worklogs/remote_results/2026-07-14-decode/decode_full_parser_tool_c1_t128_r3.json`

指标：

| 指标 | 数值 |
|---|---:|
| 成功率 | 100% |
| TTFT P90 | 4.98s |
| Output TPS P10 | 8.70 tok/s |
| Output TPS P50 | 8.70 tok/s |
| 聚合 Output TPS | 7.38 tok/s |
| prompt tokens | 6639 |
| cached tokens | 4416 |
| completion tokens | 384 |

单请求细节：

- 第 1 个请求：TTFT `5.97s`，cached tokens `0`
- 第 2/3 个请求：TTFT 约 `1.0s`，cached tokens `2208`

解释：

工具 schema 会明显影响首次 prefill/TTFT，但前缀缓存命中后 TTFT 恢复。Output TPS 仍约 `8.7 tok/s`，与纯短 prompt 基本一致，所以 tool parser 不是 decode TPS 主瓶颈。

### 3. Parser-off 对照

重启服务，去掉：

- `--enable-auto-tool-choice`
- `--tool-call-parser qwen3_coder`
- `--reasoning-parser qwen3`

其余参数保持一致。

短 prompt，单并发，3 请求，每请求 `max_tokens=256`。

结果文件：

- 远端：`/root/work/logs/decode_noparser_short_c1_t256_r3.json`
- 本地：`worklogs/remote_results/2026-07-14-decode/decode_noparser_short_c1_t256_r3.json`

指标：

| 指标 | 完整 parser | parser-off |
|---|---:|---:|
| 成功率 | 100% | 100% |
| TTFT P90 | 1.85s | 3.18s |
| Output TPS P10 | 8.74 | 8.30 |
| Output TPS P50 | 8.74 | 8.33 |
| 聚合 Output TPS | 8.34 | 7.87 |

解释：

关闭 parser 没有改善 decode。parser/reasoning/tool 相关启动项不是当前 decode 吞吐低的主因。

### 4. 并发曲线

parser-off 服务，短 prompt，每请求 `max_tokens=128`。

结果文件：

- `decode_noparser_short_c1_t128_r4.json`
- `decode_noparser_short_c2_t128_r4.json`
- `decode_noparser_short_c4_t128_r4.json`

指标：

| 并发 | 请求数 | 成功率 | TTFT P90 | Output TPS P10/请求 | 聚合 Output TPS |
|---:|---:|---:|---:|---:|---:|
| 1 | 4 | 100% | 0.79s | 8.30 | 8.00 |
| 2 | 4 | 100% | 0.92s | 3.68 | 7.23 |
| 4 | 4 | 100% | 51.60s | 2.57 | 5.08 |

解释：

并发提高后没有形成有效 batch 增益。并发 2 时单请求 TPS 近似减半，聚合 TPS 也略降；并发 4 时出现明显排队，TTFT P90 被拉到 `51.6s`。

这说明当前配置下 decode 并发能力很弱。由于服务参数 `--max-num-seqs=2`，并发 4 的后两个请求排队符合预期；但并发 2 聚合吞吐仍不提升，说明 decode 内部没有把双请求 batch 变成更高硬件利用率。

### 5. 硬件利用率采样

parser-off 服务，并发 2，4 请求，每请求 `max_tokens=128`，同时采样 `ixsmi`。

结果文件：

- 远端：`/root/work/logs/decode_noparser_short_c2_t128_r4_monitor.json`
- 远端：`/root/work/logs/ixsmi_noparser_short_c2_t128_r4_monitor.json`
- 本地同名文件位于：`worklogs/remote_results/2026-07-14-decode/`

指标：

| 指标 | 数值 |
|---|---:|
| 成功率 | 100% |
| TTFT P90 | 0.92s |
| Output TPS P10 | 3.79 tok/s |
| 聚合 Output TPS | 7.40 tok/s |
| ixsmi records | 52 |
| parsed GPU samples | 208 |
| 平均 GPU-Util | 28.91% |
| 最大 GPU-Util | 100% |
| 平均显存 | 30477 MiB |
| 最大显存 | 30555 MiB |
| 平均功耗 | 49.67 W |
| 最大功耗 | 51 W |

解释：

GPU 利用率和功耗都偏低。虽然瞬时 GPU-Util 能到 100%，但平均只有约 29%，功耗长期接近空载到轻载水平。这说明 decode 过程中存在大量空泡、同步等待或小 kernel 启动开销，GPU 算力没有被持续喂满。

## 四、瓶颈判断

当前最可能的瓶颈排序：

1. Decode 调度/后端限制
   - `--num-scheduler-steps 4` 曾尝试失败。
   - 报错：`Multi-Step + Chunked-Prefill not supported for attention backend: xformers`。
   - 当前服务日志显示使用 `XFormers backend`。

2. TP 通信或同步开销
   - 模型使用 `-tp 4`。
   - 短 decode 每步都可能涉及多卡同步。
   - 并发 2 聚合 TPS 不升反降，符合小 batch 多卡同步效率差的特征。

3. MoE decode kernel/专家路由效率
   - Qwen3.6-35B-A3B 是 MoE 模型。
   - decode batch 小时，专家路由和 fused MoE kernel 可能难以形成高利用率。

4. Paged attention / attention backend 每 token 开销
   - 当前 attention 后端为 xFormers。
   - multi-step decode 被 xFormers + chunked prefill 组合限制。

5. API/parser 层
   - 本轮实验基本排除其为主瓶颈。
   - tool/schema 影响首次 TTFT，但不显著影响 decode TPS。

## 五、下一步建议

建议下一步不要直接改大段 kernel，而是先做两个能明确指向代码修改方向的服务变体实验。

### 实验 A：decode-only multi-step 变体

目的：验证 multi-step scheduling 是否能明显提升 decode。

做法：

- 暂时关闭 `--enable-chunked-prefill`
- 加回 `--num-scheduler-steps 4`
- 保持 `max_num_seqs=2`
- 跑短 prompt decode 并发 1/2 曲线

判断：

- 如果 Output TPS 明显提升，说明 decode 调度是关键方向。
- 后续要研究如何让 multi-step 与长上下文 chunked prefill 共存，或按场景切换。

风险：

- 官方长上下文负载仍需要 chunked prefill，所以这不是最终配置，只是定位实验。

### 实验 B：attention backend 变体

目的：确认是否可以启用兼容 multi-step 的 attention backend。

做法：

- 尝试设置 `VLLM_ATTENTION_BACKEND=FLASH_ATTN`
- 或检查 CoreX/xFormers flash attention 能否被 vLLM selector 选中
- 如果能启动，再测试 multi-step + chunked prefill

判断：

- 如果 flash attention 能启动且 multi-step 可用，优先走 backend 配置/适配路线。
- 如果不能启动，需要看 `vllm/attention/selector.py`、`vllm/attention/backends/*` 和 CoreX xFormers 补丁。

### 实验 C：代码级 profiling

目的：把低 GPU 利用率归因到具体模块。

建议插桩位置：

- `vllm/worker/model_runner.py`
- `vllm/worker/multi_step_model_runner.py`
- `vllm/model_executor/models/qwen3_moe.py`
- `vllm/model_executor/layers/fused_moe/*`
- `attention.py`
- `paged_attn.py`

记录每步：

- model forward 耗时
- attention 耗时
- MoE/MLP 耗时
- sampler 耗时
- 每步前后同步耗时

### 实验 D：服务参数小网格

目的：确认当前 `max_num_seqs=2` 是否已经是最优。

建议组合：

| 参数 | 候选 |
|---|---|
| `max_num_seqs` | 1, 2, 4 |
| `max_num_batched_tokens` | 4096, 8192 |
| `chunked_prefill` | on/off |
| `num_scheduler_steps` | 1, 4 |

优先只在短 prompt decode 上跑，快速筛掉无效组合。

## 六、当前推荐行动

下一步优先跑：

1. `chunked_prefill=off + num_scheduler_steps=4`
2. 若能启动，跑 decode c1/c2/c4 曲线和 ixsmi 采样
3. 若 decode TPS 明显提升，再研究如何兼容官方长上下文 prefill
4. 若没有提升，进入 qwen3_moe / fused_moe / attention 的代码级 profiling

本轮最重要的事实是：GPU 平均利用率只有约 `29%`，所以先不要把问题简单归因为“卡算不动”。更像是当前 decode 执行路径没有把四张卡持续喂满。

## 七、调度方向验证实验：multi-step decode

追加日期：2026-07-14

### 目标

验证 `--num-scheduler-steps 4` 是否能作为 decode 吞吐提升方向。

由于上一轮实验显示并发升高没有带来 aggregate TPS 增益，且平均 GPU 利用率只有约 `29%`，multi-step scheduling 是最直接的调度侧候选优化：它理论上可以减少每 token 调度往返和 Python/worker 协调开销，让 decode 连续执行多个 step。

### 实验 1：关闭 chunked prefill，直接启用 multi-step

启动变体：

- `--num-scheduler-steps 4`
- 不加 `--enable-chunked-prefill`
- `--max-model-len 100000`
- `--max-num-batched-tokens 8192`
- 其它参数沿用完整 parser 服务配置

结果：

- 服务未启动。
- 远端日志：`/root/work/logs/server_exp_sched4_nochunk_fullparser.log`
- 本地归档：`worklogs/remote_results/2026-07-14-scheduler/server_exp_sched4_nochunk_fullparser.log`

失败原因：

```text
ValueError: max_num_batched_tokens (8192) is smaller than max_model_len (100000).
```

解释：

关闭 chunked prefill 后，vLLM 要求 `max_num_batched_tokens >= max_model_len`，否则实际最大可处理序列会被 `max_num_batched_tokens` 限制。这个配置不能用于官方长上下文，也无法进入 decode 压测。

### 实验 2：decode-only 诊断配置

为绕过实验 1 的限制，临时降低上下文长度，只用于短 prompt decode 诊断。

启动变体：

- `--max-model-len 4096`
- `--max-seq-len-to-capture 4096`
- `--max-num-batched-tokens 8192`
- `--num-scheduler-steps 4`
- 不加 `--enable-chunked-prefill`
- attention backend 仍为自动选择

结果：

- 服务未启动。
- 远端日志：`/root/work/logs/server_exp_sched4_nochunk_len4096_fullparser.log`
- 本地归档：`worklogs/remote_results/2026-07-14-scheduler/server_exp_sched4_nochunk_len4096_fullparser.log`

关键日志：

```text
Using XFormers backend.
ValueError: Multi-Step not supported for attention backend: xformers.
Set VLLM_ATTENTION_BACKEND to a value from ['flash-attn', 'rocm-flash-attn', 'flashinfer'].
```

解释：

这说明当前环境不是“chunked prefill 与 multi-step 的组合不支持”这么简单，而是 `xformers` attention backend 本身不支持 multi-step worker。只要 attention backend 仍然落到 xFormers，multi-step 调度就无法启用。

### 实验 3：强制 FlashInfer backend

启动变体：

- 环境变量：`VLLM_ATTENTION_BACKEND=FLASHINFER`
- `--max-model-len 4096`
- `--num-scheduler-steps 4`
- 不加 `--enable-chunked-prefill`
- 其它参数同实验 2

结果：

- 服务未启动。
- 远端日志：`/root/work/logs/server_exp_sched4_nochunk_len4096_flashinfer.log`
- 本地归档：`worklogs/remote_results/2026-07-14-scheduler/server_exp_sched4_nochunk_len4096_flashinfer.log`

关键日志：

```text
TypeError: 'NoneType' object is not callable
...
self._decode_wrapper = BatchDecodeWithPagedKVCacheWrapper(...)
```

解释：

`vllm/attention/backends/flashinfer.py` 会导入：

- `flashinfer.BatchDecodeWithPagedKVCacheWrapper`
- `flashinfer.decode.CUDAGraphBatchDecodeWithPagedKVCacheWrapper`
- `flashinfer.prefill.BatchPrefillWithPagedKVCacheWrapper`
- `ixformer.contrib.vllm_flash_attn.flash_attn_varlen_func`

当前环境中至少有关键 FlashInfer wrapper 没导入成功，导致 wrapper 为 `None`，在 profiling 阶段调用时报错。

### 实验结论

本轮没有进入 c1/c2/c4 decode 曲线压测，因为 multi-step 服务在启动阶段就失败。

结论不是“调度一定无效”，而是：

1. 当前 xFormers backend 下，multi-step 调度不可用。
2. 当前 FlashInfer backend 依赖不完整或与 CoreX 环境不兼容，不能直接替代 xFormers。
3. 自动 FlashAttention 也不可用；此前日志已显示 `vllm_flash_attn` 包缺失，因此自动回落到 xFormers。

因此，调度优化如果要继续推进，前置任务是 attention backend 适配：

- 路线 A：补齐/修复 CoreX 环境里的 FlashAttention 或 FlashInfer backend。
- 路线 B：改造 xFormers backend 或 MultiStepModelRunner，使其支持当前 xFormers 路径。
- 路线 C：绕过 multi-step，直接 profile xFormers decode、paged attention、MoE 与 TP 通信开销。

### 对下一步方向的影响

短期内，继续调 `--num-scheduler-steps` 没意义；它被 backend 卡住了。

下一步建议改为两条线并行：

1. **backend 可用性线**
   - 检查 `flashinfer` 和 `ixformer.contrib.vllm_flash_attn` 在服务器上的实际导入错误。
   - 确认官方镜像/包中是否本应包含 `vllm_flash_attn`。
   - 如果能补齐依赖，再重跑 multi-step decode 曲线。

2. **代码 profiling 线**
   - 直接在当前可用 xFormers 路径插桩。
   - 重点记录每 token decode 中 attention、MoE、sampler、TP 同步的耗时。
   - 当前平均 GPU 利用率低，profiling 比继续盲调参数更有价值。

## 2026-07-14：解除强制 eager / custom all-reduce 禁用验证

### 修改内容

本轮先处理 `vllm/engine/arg_utils.py` 中两个会掩盖真实性能路径的硬编码：

```python
enforce_eager=True
disable_custom_all_reduce=True
```

改为尊重 CLI / dataclass 参数：

```python
enforce_eager=self.enforce_eager
disable_custom_all_reduce=self.disable_custom_all_reduce
```

同时更新 `qwen3_6_scripts/patch_xformers_sdpa_seq.py`，让后续重新执行 patchops 时也会保留该行为。服务器实际运行路径已确认：

```text
PYTHONPATH=/usr/local/corex/lib/python3/dist-packages:/usr/local/corex/lib64/python3/dist-packages
```

因此运行时同时 patch 了：

- `/usr/local/corex/lib/python3/dist-packages/vllm/engine/arg_utils.py`
- `/usr/local/corex/lib64/python3/dist-packages/vllm/engine/arg_utils.py`

远端运行时备份：

- `arg_utils.py.bak_20260714_eager_allreduce`

### 实验 1：CUDA Graph + custom all-reduce 同时开启

启动命令不再带 `--enforce-eager`，也不带 `--disable-custom-all-reduce`。

日志确认配置已生效：

```text
disable_custom_all_reduce=False
enforce_eager=False
use_async_output_proc=True
```

结果：服务未能完成启动，长时间卡在 CUDA Graph capture 阶段。

关键日志：

```text
Capturing the model for CUDA graphs.
[W CUDAGraph.cpp:145] Warning: Waiting for pending NCCL work to finish before starting graph capture.
```

判断：当前 Iluvatar BI-V100 + CoreX + xFormers + TP=4 路径下，CUDA Graph capture 不可直接启用。它没有快速报错，而是卡在 graph capture / NCCL pending work 阶段，风险比普通参数不兼容更高。短期不建议继续沿 CUDA Graph 方向盲试。

本地归档：

- `worklogs/remote_results/2026-07-14-eager-allreduce/server_exp_graph_allreduce_seq2_b8192.log`

### 实验 2：仅开启 custom all-reduce，继续 eager

启动命令保留 `--enforce-eager`，但不再带 `--disable-custom-all-reduce`。

日志确认：

```text
enforce_eager=True
disable_custom_all_reduce=False
```

服务可以正常启动并通过 `/health`。

decode microbench 结果：

| 配置 | 成功率 | TTFT P90 | Output TPS P10/req | Aggregate Output TPS | 对比旧结果 |
| --- | ---: | ---: | ---: | ---: | --- |
| short c1, 256 tok, custom AR on | 100% | 3.47s | 8.47 | 7.94 | 旧 full-parser c1 为 P10 8.74 / aggregate 8.34，略降 |
| short c2, 128 tok, custom AR on | 100% | 1.46s | 4.22 | 8.07 | 旧 parser-off c2 aggregate 7.23，略升但口径不完全相同 |

本地归档：

- `worklogs/remote_results/2026-07-14-eager-allreduce/decode_eager_custom_ar_short_c1_t256_r3.json`
- `worklogs/remote_results/2026-07-14-eager-allreduce/decode_eager_custom_ar_short_c2_t128_r4.json`
- `worklogs/remote_results/2026-07-14-eager-allreduce/server_exp_eager_custom_ar_seq2_b8192_retry.log`

### 结论

1. 之前的硬编码确实屏蔽了真实配置，本轮已经解除，并确认修改落在实际运行的 CoreX site-packages 路径里。
2. CUDA Graph 当前不兼容或存在严重启动卡死问题，不适合作为短期主优化方向。
3. custom all-reduce 可以启动和推理，但收益有限：c2 聚合吞吐有小幅提升，c1 无提升。
4. 当前 decode 吞吐仍在 8 tok/s 左右，距离 Output TPS P10 >= 20 仍有明显差距，瓶颈不只是 all-reduce 开关。

### 下一步 profiling 方向

优先进入代码级 profiling，而不是继续调 CLI 开关：

1. 在 `ModelRunner.execute_model` 统计模型 forward、logits、sample 的阶段耗时。
2. 在 Qwen MoE 层统计 attention、MoE expert、MoE gate、TP all-reduce 的耗时占比。
3. 在 fused MoE 路径统计 topk、expert kernel、activation、sum 的耗时。
4. 用 `ENGINEX_PROFILE_DECODE=1` 这类环境变量控制插桩，只在短压测时开启，避免污染正式结果。

初步判断：custom all-reduce 不是第一大瓶颈；更可能的主战场是 xFormers decode attention、MoE 小 batch kernel、以及 TP 下大量小 kernel / 同步造成的低 GPU 利用率。