Preserve CP shared-KV cache-hit diagnostics
Warm-cache GSM8K failures needed request-to-log correlation across scheduler, prefill transfer, and Mooncake CP filtering. The added diagnostics are gated by existing CP shared-KV debug envs and include bounded token signatures plus transfer page summaries so future debugging can identify whether a failed request hit L1, L2, or transfer truncation paths.\n\nThe findings document records the ruled-out hypotheses and the RAGGED current-row contract failure, preventing repeated log archaeology after context compaction.\n\nConstraint: Production hot paths must not emit these logs unless SGLANG_CP_SHARED_KV_BS_GT1_DEBUG or existing CP shared-KV debug gates are enabled.\nRejected: Add a new debug env | reuse of existing bs>1 debug gate avoids more runtime switches.\nRejected: Store full token ids in logs | bounded signatures are enough for correlation without huge logs.\nConfidence: medium\nScope-risk: narrow\nDirective: Keep these diagnostics gated and bounded; do not convert them to unconditional INFO logs.\nTested: Remote container py_compile as part of the RAGGED fix validation.\nNot-tested: Long-running production log-volume impact with debug enabled.
This commit is contained in:
laoyao0822
@@ -1214,3 +1214,232 @@ prefix_len=721 host_hit_length=0 extend_input_len=17 fill_len=721 origin_input_l
|
||||
1. `alloc_for_extend()` / `write_cache_indices()` 后：记录每个 req 的 prefix pages、suffix/out pages、最终 `req_to_token[:seq_len]` pages。
|
||||
2. `cache_unfinished_req()` / `cache_finished_req()` 前后：记录插入 radix 的 `values` pages、match 后 `new_indices` pages、以及最终写回 `req_to_token` 的 pages。
|
||||
3. 如果 `alloc_for_extend()` 后顺序正确而 `send_kv_chunk()` 前错误，root cause 在 radix cache insertion / re-match / page-floor tail pruning；如果前者已经错误，则继续回溯 prefix_indices 来源。
|
||||
|
||||
## 2026-06-08 00:04 retest after reported restart
|
||||
|
||||
Command:
|
||||
|
||||
```bash
|
||||
cd /sgl-workspace/sglang
|
||||
python benchmark/gsm8k/bench_sglang.py \
|
||||
--host g0034 --port 17100 --backend srt \
|
||||
--data-path /mnt/beegfs/cjy/data/gsm8k_test.jsonl \
|
||||
--num-questions 200 --parallel 64 \
|
||||
--temperature 0.0 --top-p 1.0 --max-new-tokens 512 \
|
||||
--raw-result-file /mnt/beegfs/cjy/gsm8k_debug_retest_20260608_000457/pass1_raw.jsonl \
|
||||
--result-file /mnt/beegfs/cjy/gsm8k_debug_retest_20260608_000457/pass1_result.jsonl
|
||||
```
|
||||
|
||||
Result:
|
||||
|
||||
- Accuracy: 0.695
|
||||
- Invalid: 0.000
|
||||
- Latency: 35.829 s
|
||||
- Output throughput: 588.436 token/s
|
||||
|
||||
Notes:
|
||||
|
||||
- The prefill process observed before the retest was PID 627606, start time `Sun Jun 7 23:48:54 2026`, log `/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_154854.log`.
|
||||
- This means the retest was against an already warm cache from earlier GSM8K runs in the same prefill process, not a cold-cache first pass.
|
||||
- The result remains consistent with the cache-hit correctness regression: warm-cache GSM8K accuracy is around 0.69-0.72 while cold/first-pass accuracy is around 0.95-0.97.
|
||||
|
||||
## 2026-06-08 remote retest after syncing origin+cjy fixes
|
||||
|
||||
Remote code synced to g0034 `/mnt/beegfs/cjy/sglang-dev` and container path `/sgl-workspace/sglang-tai`.
|
||||
|
||||
Full GSM8K two-pass run directory:
|
||||
`/mnt/beegfs/cjy/gsm8k_retest_20260607_164904`
|
||||
|
||||
Results:
|
||||
- pass1: Accuracy 0.958, Invalid 0.000, Latency 214.254s, Output throughput 646.402 token/s.
|
||||
- pass2: Accuracy 0.690, Invalid 0.002, Latency 226.338s, Output throughput 624.138 token/s.
|
||||
|
||||
Conclusion: warm-cache/cache-hit correctness regression still reproduces after syncing per-layer transfer branch plus local fixes. For future iterations, do not start with full 1319-question runs. Run a 200-question GSM8K canary first for fast signal; only run full GSM8K after the 200-question warm-cache second pass stays near expected accuracy.
|
||||
|
||||
## 2026-06-08 AJ: 当前线上复现未开启 disagg per-layer transfer
|
||||
|
||||
用户确认当前线上版本没有开启 prefill→decode per-layer transfer。因此本轮 GSM8K warm-cache 掉点不应继续优先归因于 `CP_PER_LAYER_TRANSFER` 的异步/分组路径。
|
||||
|
||||
纠正：此前把 per-layer transfer block grouping 列为风险点只是代码层可能性；对当前线上日志/复现不成立。当前应回到 monolithic Mooncake transfer、radix/req_to_token page-order、NSA state/index companion transfer、以及 decode 端接收/consume 元数据路径。
|
||||
|
||||
已知日志事实仍保持：最新 debug 日志没有 `HiCache-load/load_back`，第二轮主要是 L1/device cache-hit 后 transfer/consume 更深 cached prefix；输出像“prompt/request 片段串了”，不是乱码。
|
||||
|
||||
## 2026-06-08 AK: 当前更强证据指向 radix/scheduler 过度 prefix hit，不是 per-layer transfer
|
||||
|
||||
纠正上一轮 page-order 解释：`send_kv_chunk pages=head=[25,2,3,...]` 不能单独证明 suffix-before-prefix。冷启动/无 cache 的 first pass 也会出现类似非单调 page id，这是 CP owner-lane allocator 的物理 page id 分配结果，数值顺序不等于 token 顺序。
|
||||
|
||||
新证据：用容器内 GLM-5.1 tokenizer 对 `/mnt/beegfs/cjy/gsm8k_retest_20260607_164904/pass1_raw.jsonl` 前 200 条 prompt 计算两两公共前缀：
|
||||
|
||||
```text
|
||||
prompt0 prefix cnt [(671, 198), (672, 1)] minmax 671 672
|
||||
pair floored common top [(640, 19900)]
|
||||
examples >=704 []
|
||||
```
|
||||
|
||||
也就是说，真实 GSM8K prompt 两两 page-floor 后只有 640 token 公共前缀，没有自然 704/768 公共前缀。
|
||||
|
||||
但 prefill 日志在 warm-cache pass 中出现：
|
||||
|
||||
```text
|
||||
match_prefix_result ... key_len=735 device_tokens=735 ... last_host_node=2645 last_host_host_len=64 cp_floor_exact=False
|
||||
batch_plan ... extend_lens=[32,18,3,13,23] prefix_lens=[704,704,704,768,704]
|
||||
```
|
||||
|
||||
这说明 runtime 里某些请求被暴露了 704/768 的 device prefix，而从真实 prompt token 序列看这些 prefix 不应该互相匹配。当前 root-cause 排查优先级应转向：
|
||||
|
||||
1. scheduler / waiting_queue radix match 是否用全 prompt 或临时树产生了过长 prefix；
|
||||
2. CP HiCache exact valid-tail floor 规则是否只在 `Req.adjust_max_prefix_ids()` 生效，而 `schedule_policy._compute_prefix_matches()` / in-batch prefix path 仍可能把非 page-aligned tail 当作命中；
|
||||
3. `cache_unfinished_req()` 内部 `match_prefix(cp_floor_exact=False)` 是当前请求自刷新用，不能让后续 scheduler-visible match 继承未 floor 的 valid-tail。
|
||||
|
||||
当前不再优先排查 disagg per-layer transfer；用户确认线上未开启该路径。
|
||||
|
||||
## 2026-06-08 AL: 排除 health check 后修正 AK 的过度 prefix-hit 判断
|
||||
|
||||
用户提醒：GSM8K 后面的请求很可能是 health check，不应纳入 cache-hit 掉点判断。后续日志分析只统计 benchmark 时间窗内的 `/v1/chat/completions` / scheduler prefill batch，不再用后续 health-check 长尾请求解释 GSM8K 精度下降。
|
||||
|
||||
同时修正 AK：pass2 是对同一批 GSM8K prompt 的重复请求，因此 `prefix_lens=704/768` 本身并不证明不同 prompt 之间发生过度匹配。用 tokenizer 计算得到的 `floor(prompt_len)` 也显示许多 GSM8K prompt 自身长度就是 704/768 页对齐前缀；warm-cache pass2 命中这些完整 prompt 页是预期行为。
|
||||
|
||||
因此当前更准确的判断是：
|
||||
|
||||
1. **不能再把 `704/768` prefix 命中单独作为 scheduler/radix overmatch 证据。** 只有当某个具体 request 的 `prefix_len` 超过其自身 `floor(prompt_len)`，或输出明显来自另一条 prompt 且能绑定到同一 request，才算 overmatch/串 cache 证据。
|
||||
2. **当前 warm-cache 掉点仍然成立**：full GSM8K pass1 约 `0.958`，pass2 约 `0.690`，且输出样例有 prompt 内容串用现象。
|
||||
3. **优先排查方向回到 cache-hit consume/transfer correctness**：L1 device cache hit 后的 CP shared KV page table、index/topk offset、MLA materialize/current reuse、monolithic Mooncake transfer/metadata consume。当前线上未开启 disagg per-layer transfer；health check 请求不作为证据。
|
||||
|
||||
下一步日志分析必须把 benchmark result/raw 文件与 prefill 日志时间窗绑定，必要时只跑 50/200 条 canary，并在 debug log 中输出 request/rid 与 prompt index 的可关联字段，否则很难把某条错误输出反推到具体 cache path。
|
||||
|
||||
## 2026-06-08 AM: 增加 GSM8K cache-hit 对齐用 debug log
|
||||
|
||||
新增 debug 只挂在既有 `SGLANG_CP_SHARED_KV_BS_GT1_DEBUG` / `SGLANG_CP_SHARED_KV_BS_GT1_DEBUG_LIMIT` 下，不新增开关，默认关闭。
|
||||
|
||||
目的：把 benchmark raw prompt 与 prefill/transfer 日志绑定起来，避免继续只能按时间和 request 顺序猜测。
|
||||
|
||||
新增字段/事件：
|
||||
|
||||
1. `scheduler_prefill_batch` 增加 `rids` 与 `origin_sigs`。
|
||||
- `origin_sig` 是 origin token ids 的稳定 hash + head/tail + len，可由 raw prompt 在同 tokenizer 下复算。
|
||||
2. `send_kv_chunk` 增加 `origin_sig` 与 `fill_sig`。
|
||||
- 用于确认 send 前请求身份、fill_ids 是否多了输出 token，以及同一 prompt pass1/pass2 是否绑定到预期 rid。
|
||||
3. Mooncake prefill sender 增加 `sender_filter`。
|
||||
- 记录 CP shared-KV 过滤前 logical request pages、过滤后 physical pages、logical page positions、state/indexer pages。
|
||||
4. Mooncake worker 增加 `transfer_worker_kv` / `transfer_worker_state`。
|
||||
- 记录实际发送到 decode dst pages 的映射，区分 KV 与 NSA state/indexer companion metadata。
|
||||
|
||||
这些日志用来验证：同一个 GSM8K prompt 在 pass2 cache-hit 时，prefill 端 page table、CP owner filter、decode dst page selection 是否一致；如果输出串 prompt，下一步应按 `origin_sig` 精确定位对应 rid/room，而不是再把 health check 或无关长尾请求纳入判断。
|
||||
|
||||
## 2026-06-08 AN: 200-question canary on new debug log
|
||||
|
||||
User started a new debug-log run and requested a 50-200 question GSM8K canary. I ran two 200-question passes against the existing prefill process/log:
|
||||
|
||||
- prefill PID: `666430`, started `Mon Jun 8 02:01:57 2026`
|
||||
- log: `/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_180157.log`
|
||||
- result dir: `/mnt/beegfs/cjy/gsm8k_debug_retest_20260607_183407`
|
||||
- time window: `2026-06-07 18:34:07` to `18:35:29`
|
||||
|
||||
Command shape:
|
||||
|
||||
```bash
|
||||
cd /sgl-workspace/sglang
|
||||
python benchmark/gsm8k/bench_sglang.py \
|
||||
--host g0034 --port 17100 --backend srt \
|
||||
--data-path /mnt/beegfs/cjy/data/gsm8k_test.jsonl \
|
||||
--num-questions 200 --parallel 64 \
|
||||
--temperature 0.0 --top-p 1.0 --max-new-tokens 512 \
|
||||
--raw-result-file /mnt/beegfs/cjy/gsm8k_debug_retest_20260607_183407/pass${PASS}_raw.jsonl \
|
||||
--result-file /mnt/beegfs/cjy/gsm8k_debug_retest_20260607_183407/pass${PASS}_result.jsonl
|
||||
```
|
||||
|
||||
Results:
|
||||
|
||||
- pass1: Accuracy `0.725`, Invalid `0.000`, Latency `35.364s`, Output throughput `601.398 token/s`.
|
||||
- pass2: Accuracy `0.710`, Invalid `0.000`, Latency `34.390s`, Output throughput `606.721 token/s`.
|
||||
|
||||
Important interpretation: this process/log was already warm before the canary, so pass1 is not a cold baseline. Both passes are warm-cache and both are already bad. This confirms the warm-cache correctness failure remains, but this particular canary does not measure cold→warm drop.
|
||||
|
||||
Bound scheduler/raw correlation through `origin_sigs`:
|
||||
|
||||
- 200 prompt IDs mapped to scheduler log entries.
|
||||
- Each prompt appeared exactly twice in the benchmark window.
|
||||
- CP0 scheduler batches: `bs=5` for 78 batches, `bs=4` for 2 batches, `bs=1` for 4 batches.
|
||||
- Prefix top counts: `704` x334, `640` x34, `768` x32, `0` x2.
|
||||
- Extend range: min `2`, max `65`, average `28.1` tokens.
|
||||
- `prefix_floor_bad=0`: no scheduler occurrence had `prefix_len > floor(prompt_len/page_size)*page_size`, and `extend_len == prompt_len - prefix_len` for all mapped prompts.
|
||||
- No `CP_SHARED_KV_FAIL_FAST`, `CP_SHARED_KV_FALLBACK`, `Traceback`, `RuntimeError`, or `Health check failed` in the benchmark window.
|
||||
|
||||
Accuracy by prompt tail length (`prompt_len % 64`) on this warm-cache process:
|
||||
|
||||
```text
|
||||
pass1:
|
||||
00-16: 63/70 = 0.900
|
||||
17-32: 49/62 = 0.790
|
||||
33-48: 16/34 = 0.471
|
||||
49-63: 17/34 = 0.500
|
||||
pass2:
|
||||
00-16: 61/70 = 0.871
|
||||
17-32: 47/62 = 0.758
|
||||
33-48: 15/34 = 0.441
|
||||
49-63: 19/34 = 0.559
|
||||
```
|
||||
|
||||
Current evidence-based direction:
|
||||
|
||||
1. Do not re-open the earlier `704/768 overmatch` hypothesis for this window: prompt-to-log matching shows no over-prefix relative to each prompt's own page floor.
|
||||
2. Do not prioritize L2 load-back for this window: there were no `HiCache-load/load_back` markers in the canary window, and every mapped request was already L1/device cache-hit plus short current suffix.
|
||||
3. The strongest current signal is tail-size correlation under warm L1 cache hit: failures rise sharply when the current suffix tail is larger. This points to cache-hit current-tail consume/compose, especially FP8/RAGGED MLA or index partial-current handling under compute padding, rather than radix overmatch or monolithic Mooncake transfer.
|
||||
4. Next code reading should focus on whether the FP8/RAGGED `nsa_backend` path materializes current tail tokens from persistent KV before they are actually stored, or otherwise omits the explicit partial-current compose used by the PAGED path.
|
||||
|
||||
## 2026-06-08 AO: RAGGED FP8 MLA cache-hit path can read current suffix through full materialize
|
||||
|
||||
New code-reading finding after the 200-question warm-cache canary:
|
||||
|
||||
- Current launch uses FP8 + `flashmla_sparse` RAGGED prefill path for CP shared KV.
|
||||
- `nsa_backend.forward_extend()` only enters the existing MLA current/partial-current compose block when `topk_transform_method == TopkTransformMethod.PAGED`.
|
||||
- The RAGGED branch later handles prefix sharing by calling `materialize_shared_token_kv_buffer(kv_cache, logical_locs=page_table_1_flattened, ...)` and then `dequantize_k_cache_paged(...)`.
|
||||
- For cache-hit requests, `page_table_1_flattened` includes both cached prefix tokens and the just-computed current suffix tokens. The current suffix was direct-written into each CP rank's persistent KV earlier in the layer.
|
||||
- If TAI IPC materialize is enabled, full materialize can read current suffix pages directly from peer ranks without an inter-rank ordering point proving those peer direct-write kernels have completed. The old collective materialize path incidentally provided such ordering; IPC gather removes it.
|
||||
|
||||
This matches the observed shape: cold/current-only first-pass can be correct, but warm L1 cache-hit requests with short current suffixes lose accuracy, and failure rate correlates with current tail size. It also explains why no L2 load-back markers or radix over-prefix evidence appeared in the canary window.
|
||||
|
||||
Planned test/fix direction:
|
||||
|
||||
1. Add a regression/source-contract test showing the RAGGED CP shared-KV prefix-hit path must use page-slot partial-current compose, not full materialize of prefix+current through IPC.
|
||||
2. Update RAGGED path to materialize prefix slots and fill/reduce current slots via `materialize_prefix_and_reuse_current_kv_page_slots`, mirroring the PAGED partial-current contract, then dequantize the resulting dense page-slot buffer.
|
||||
3. Keep the test narrow; if this does not recover GSM8K warm-cache accuracy, add bounded RAGGED materialize debug under existing `SGLANG_CP_SHARED_KV_BS_GT1_DEBUG`.
|
||||
|
||||
## 2026-06-08 AP: RAGGED fix exposed wrong current-row selector assumption
|
||||
|
||||
Remote 200-question canary after the first RAGGED partial-current fix killed prefill before accuracy could be measured.
|
||||
|
||||
Observed prefill exception in `/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_192001.log`:
|
||||
|
||||
```text
|
||||
RuntimeError: [CP_SHARED_KV_FAIL_FAST][cache_write_valid_selector_shape]
|
||||
CP shared-KV cache write tensor must contain local compute rows before valid-row selection.
|
||||
local_rows=473 expected_compute_rows=320 valid_rows=13
|
||||
```
|
||||
|
||||
and on another rank:
|
||||
|
||||
```text
|
||||
local_rows=473 expected_compute_rows=320 valid_rows=140
|
||||
```
|
||||
|
||||
Call stack:
|
||||
|
||||
```text
|
||||
nsa_backend.forward_extend -> RAGGED cache-hit compose ->
|
||||
select_cp_local_valid_rows_for_cache_write(forward_batch, k/k_rope)
|
||||
```
|
||||
|
||||
Interpretation:
|
||||
|
||||
- `select_cp_local_valid_rows_for_cache_write()` is only valid for tensors whose first dimension is the CP-local compute-padded row count (`expected_compute_rows`).
|
||||
- In the `flashmla_sparse` RAGGED attention branch, `k/k_rope` can have a different row contract (`local_rows=473` in the crash), so blindly reusing the cache-write selector there is wrong.
|
||||
- The actual direct KV write path in `forward_mla._maybe_write_cp_shared_local_mla_kv()` has already performed the compute-padding valid-row selection before writing to persistent KV. The RAGGED attention compose path only needs a current-row source for attention materialization; it must select rows based on the actual tensor contract, not assume cache-write local compute rows.
|
||||
|
||||
Next fix direction:
|
||||
|
||||
1. Factor a helper for RAGGED/PAGED current-row source selection that accepts either:
|
||||
- already local valid rows (`rows == local_out_cache_loc.numel()`), or
|
||||
- CP-local compute-padded rows (`rows == expected_compute_rows`), using `select_cp_local_valid_rows_for_cache_write()`, or
|
||||
- global valid current rows (`rows == current_extend_kv_rows_for_reuse(...)`), using `cp_split_and_rebuild_data()`.
|
||||
2. Add a unit/source-contract test covering the `rows == local_out_cache_loc.numel()` fast path before production code change.
|
||||
|
||||
Reference in New Issue
Block a user