diff --git a/docs/advanced_features/nsa_prefill_cp_gsm8k_cachehit_temp_findings.md b/docs/advanced_features/nsa_prefill_cp_gsm8k_cachehit_temp_findings.md index f35531522..c1022be8e 100644 --- a/docs/advanced_features/nsa_prefill_cp_gsm8k_cachehit_temp_findings.md +++ b/docs/advanced_features/nsa_prefill_cp_gsm8k_cachehit_temp_findings.md @@ -399,3 +399,818 @@ PYTHONPATH=python python -m pytest -q \ - 通过 `GetK/GetS` 按 request page table 读取并反量化,对比原始 valid key rows。 结论:在单测覆盖的 GSM8K-like bs=5/tiny/FP8 形状中,persistent index cache 经 fused store → L2 backup/load → paged materialize → GetK/GetS 后仍可还原 valid rows。用户提出的“第二轮来自 L2 cache load 的错误”目前没有被 KV 或 index 的直接单测支持;下一步应把排查焦点上移到真实运行中的 radix/req_to_token/page_table 可见范围、chunked/full prompt cache-hit 后 valid length 与 page table 的组合、以及 prefill→decode transfer 元数据。 + +## 2026-06-07 O: 下一层 runtime 证伪点应放在 batch topk membership + +前面单测已经覆盖并通过:FP8 KV/index page_first_direct L2 roundtrip、persistent index fused-store、L2-loaded persistent index materialize、RAGGED topk offset、TAI batched index MQA prepare。当前还没有证据支持 raw L2 copy 或基本 persistent cache 布局损坏。 + +新的高优先级可证伪点是 `_get_topk_in_seq_cp_pair_batch()` 产出的 `topk_indices` 是否仍严格落在对应 request 的可见前缀内。这个检查能直接区分: + +- topk/index/range/offset/scatter 侧跨 request 或未来 token; +- MLA KV / prefill→decode transfer 侧错误。 + +计划:复用现有 `SGLANG_CP_SHARED_KV_BS_GT1_DEBUG`,在 batch topk scatter 后增加 fail-fast validator。对每个 compact span,允许 `-1`,其余值必须满足: + +```text +request_base <= topk < request_base + absolute_query_position + 1 +``` + +其中 `request_base=sum(seq_lens_cpu[:req_id])`。若违反,抛: + +```text +[CP_SHARED_KV_FAIL_FAST][index_topk] reason=batch_gt1_topk_membership +``` + +该 validator 是 debug-gated,预期只在 ETE 定位时打开;不会新增 collective,也不会改变正常 hot path。 + +### O 追加实现/验证结果 + +已实现 debug-gated runtime validator:`_validate_cp_shared_kv_batch_topk_membership()`。 + +接入点:`_get_topk_in_seq_cp_pair_batch()` compact topk scatter 后,且仅在 `SGLANG_CP_SHARED_KV_BS_GT1_DEBUG=1` 且非 CUDA graph capture 时运行。 + +验证:先在远端只同步测试,确认新测试因 helper 缺失失败;随后实现 helper 与接入后远端通过: + +```bash +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/layers/test_nsa_topk_transform.py -s +``` + +结果:`7 passed, 5 warnings in 7.29s`。 + +下一轮 ETE 如果仍然掉点但没有 `reason=batch_gt1_topk_membership`,就可以进一步降低 batch topk membership/cross-request/future-token 的优先级,把焦点移到 page table flatten 与 prefill→decode transfer metadata。 + +## 2026-06-07 P: Mooncake KV page-count 有 fail-fast,但 NSA state page-count 仍可能静默错配 + +继续审查 prefill→decode transfer runtime 发现:KV chunk 路径已经调用 `validate_transfer_page_count_or_raise()`,但 `maybe_send_extra()` 里的 `state_type in ["swa", "nsa"]` 分支仍只有旧逻辑:当 `prefill_state_indices` 少于 `dst_state_indices` 时只 warning,然后继续走 transfer。 + +对 CP shared-KV + NSA 来说,`state_indices` 是 index/state page 的 companion payload;如果 KV pages 数量正确但 state pages 错配,decode 侧仍可能拿到错误/缺失的 NSA index cache。这个路径与“第一轮主要 fresh current,第二轮更依赖 persisted/cached index/state”症状相容,需要 fail-fast 而不是 warning。 + +计划:复用已有 `validate_transfer_page_count_or_raise()`,在 CP shared-KV state transfer(调用方传入 `dst_state_indices`,即按 logical positions 选择后的目标 pages)时对 `prefill_state_indices` 和 `dst_state_indices` 做同样的 page-count fail-fast,path 标为 `mooncake_state`。非 CP shared-KV 暂不改变旧行为,避免扩大影响面。 + +### P 追加实现/验证结果 + +已在 `MooncakeKVManager.maybe_send_extra()` 的 `state_type in ["swa", "nsa"]` 分支补 CP shared-KV state page-count fail-fast:当调用方传入 `dst_state_indices`(即 CP shared-KV 已按 logical page positions 选择目标 state pages)时,`prefill_state_indices` 与 `dst_state_indices` 数量必须完全一致,否则抛: + +```text +[CP_SHARED_KV_FAIL_FAST][mooncake_transfer_page_count_mismatch] path=mooncake_state +``` + +TDD 验证:先同步新测试到远端,确认旧代码只 warning、不 raise;实现后远端通过: + +```bash +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/disaggregation/test_cp_shared_kv_transfer_mapping.py -s +``` + +结果:`10 passed, 3 warnings in 5.27s`。 + +这还不是 root-cause 结论,但它补掉了一个真实 silent-corruption 风险:KV page-count 正确时,NSA state/index companion pages 仍可能静默错配。 + +## 2026-06-07 Q: CP shared-KV NSA state buffer-count mismatch 也不应静默截断 + +继续审查 `maybe_send_extra()`:除 page-count mismatch 外,`src_state_data_ptrs` 与 `dst_state_ptrs` buffer 数量不一致时,当前逻辑只 warning,然后截断到 `min(src,dst)` 个 buffer 继续传输。 + +在 CP shared-KV + EAGLE/draft/shared NSA state 场景,这同样属于 silent corruption 风险:page 数量一致也不能保证 layer/state buffer 数量一致。若少传部分 state buffer,decode 侧可能继续运行但使用不完整的 NSA/draft companion state。 + +计划:仍只收窄到 CP shared-KV state transfer(`dst_state_indices is not None`),将 buffer-count mismatch 改为 fail-fast;非 CP shared-KV 旧路径暂不扩大影响。 + +### Q 追加实现/验证结果 + +已在 CP shared-KV state transfer 中把 state buffer-count mismatch 从 warning+truncate 改为 fail-fast: + +```text +[CP_SHARED_KV_FAIL_FAST][mooncake_state_buffer_count_mismatch] +``` + +TDD 验证:先同步新测试到远端,确认旧代码只 warning、不 raise;实现后远端通过组合测试: + +```bash +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/layers/test_nsa_topk_transform.py \ + test/registered/unit/disaggregation/test_cp_shared_kv_transfer_mapping.py -s +``` + +结果:`18 passed, 5 warnings in 7.21s`。 + +这进一步收窄了 decode 侧 silent corruption 风险:CP shared-KV 下 state pages 数量和 state buffer 数量都不允许静默截断。 + +## 2026-06-07 R: L1↔L2 路径当前测试缺口收敛到 controller 级批量 transfer + +继续按“不在生产热路径随意加 check”的约束阅读代码后,当前 L1→L2/L2→L1 真实路径是: + +- 写入/backup:`HiRadixCache.prepare_write_backups_for_reqs()` 为 bs>1 每个 request 单独 `reserve_write_cp()`,随后 `HiCacheController.submit_write_cp_per_layer(catch_up_all_layers=False)` 注册;真正 D2H 在 `on_layer_end()` 中通过 `_submit_write_cp_layer_states()` 把多个 reservation 的 `host_indices/physical_device_indices` concat 成一次 per-layer transfer。 +- 读取/load:`HiRadixCache.load_back()` 调 `HiCacheController.load_cp()`,按 metadata.page_owners 用 `alloc_pages_with_owners()` 复现 owner pattern,随后 `start_loading()` 通过 `CacheOperation.merge_ops()` 把多个 queued load op concat 成一次 per-layer H2D transfer。 +- 既有 CUDA 单测覆盖了 raw `NSATokenToKVPoolHost.backup_from_device_all_layer()` / `load_to_device_per_layer()`、L2-loaded MLA/index materialize、fused store 等;但缺少 controller 级“多个 CP HiCache node 的 per-layer grouped D2H + merged H2D”回归。 + +因此下一步单测不新增生产检查,而是构造 bs=5/GSM8K-like node reservations,走真实 `reserve_write_cp()` → grouped `on_layer_end()` backup → `load_cp()` × 多 node → merged `start_loading()`,验证 valid rows 与 index rows 在 L1→L2→L1 后仍按 request/node 顺序正确。 + +## 2026-06-07 S: controller-level L2 roundtrip test first run hit test-allocation artifact + +新增 controller 级 grouped bs=5 L1→L2→L1 单测后,远端首次运行在 host pool 初始化后的下一次 CUDA op 报: + +```text +torch.AcceleratorError: CUDA error: part or all of the requested memory range is already mapped +``` + +定位:这是测试环境里 `NSATokenToKVPoolHost(pin_memory=True)` 默认走 `cudaHostRegister`,同一 pytest 进程/循环中 CPU allocator 可能复用已注册地址导致的注册冲突;不是业务 L1/L2 数据不一致证据。既有测试已有模式:在这类 pin-memory host-pool 单测里临时把 `ALLOC_MEMORY_FUNCS["cuda"]` 切到 `alloc_with_pin_memory`,结束后恢复。 + +下一步只修正单测分配方式,不改生产路径。 + +## 2026-06-07 T: controller-level grouped bs=5 L1→L2→L1 path verified + +新增 controller 级单测并在远端通过: + +```bash +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/mem_cache/test_nsa_pool_host_unit.py::TestNSAHiCacheTransfer::test_cp_hicache_controller_grouped_bs5_l2_roundtrip_preserves_valid_rows -s +``` + +结果:`1 passed, 3 warnings in 8.10s`。 + +覆盖的真实控制路径: + +- `CPSharedPagedTokenToKVPoolAllocator.alloc_extend_compute_owner()` 生成真实 bs=5 out_cache_loc; +- `HiCacheController.reserve_write_cp()` 对每个 request 做 page padding、owner-lane physical mapping、host slot reservation; +- `submit_write_cp_per_layer(catch_up_all_layers=False)` 注册多个 node; +- `on_layer_end()` 把多个 reservation grouped 后 per-layer D2H 写入 host; +- 覆盖 L1; +- `load_cp()` 多 node 排队,`start_loading()` 通过 `CacheOperation.merge_ops()` 合并后 per-layer H2D load 回 L1; +- 校验每个 node 的 valid owned KV/index rows。 + +结论:在 GSM8K-like bs=5、FP8 packed KV、page_first_direct/direct、controller grouped backup/load 条件下,L1→L2→L1 数据 roundtrip 没有暴露损坏。因此当前掉点 root cause 继续从 radix/HiCache node 元数据、cache-hit consume 侧、或 prefill→decode transfer 语义排查;不继续往生产热路径加常态 check。 + +## 2026-06-07 U: 定位阶段不保留新增 runtime validator/fail-fast + +根据最新约束:“不能随便引入 check,这些冗余操作会导致正式推理时性能下降”。本轮未提交的 runtime validator / state fail-fast 已从本地和远端同步回退,当前只保留: + +- 临时排查文档; +- 不影响生产 hot path 的 L1↔L2 controller grouped CUDA 单测。 + +原则:后续继续用单测/benchmark 暴露问题;如果需要 runtime 证据,只能走已有 debug env 且明确限频,不加入默认路径。 + +## 2026-06-07 V: L2→L1 load_back exact-capacity path 仍触发同步 free-room eviction + +远端组合运行: + +```bash +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/mem_cache/test_nsa_pool_host_unit.py::TestNSAHiCacheTransfer::test_cp_hicache_controller_grouped_bs5_l2_roundtrip_preserves_valid_rows \ + test/registered/unit/mem_cache/test_cp_hicache_load_back_owner_lanes.py -q +``` + +结果:controller grouped L1↔L2 单测通过,但既有 CPU 单测失败: + +```text +TestCpHiCacheLoadBackOwnerLanes.test_load_back_does_not_synchronously_evict_for_l1_free_room_when_exact_capacity_fits +expected evicted_device_indices=[] +got [tensor([8, 9, 10, 11])] +``` + +含义:`HiRadixCache.load_back()` 在 owner-lane exact capacity 已满足、`deficit_by_owner=[0,...]` 时,仍然因为 `free_room_deficit_by_owner` 做同步 L1 eviction。这会把 L2→L1 load-back 的 scheduler/control path 变重,和当前“不能引入冗余热路径操作”的约束冲突。 + +修复方向:load-back 的 L1 free-room 信号应保持 advisory;exact capacity 已满足时不为了补 free-room 在 load_back 中同步 evict。真正容量不足仍走 exact deficit eviction。 + +### V 追加实现/验证结果 + +已做最小修复:删除 `HiRadixCache.load_back()` 中 exact owner-lane capacity 已满足时的同步 L1 free-room eviction,只保留 stage 记录为 advisory。容量不足时的 `deficit_by_owner` eviction 路径不变。 + +远端验证通过: + +```bash +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/mem_cache/test_nsa_pool_host_unit.py::TestNSAHiCacheTransfer::test_cp_hicache_controller_grouped_bs5_l2_roundtrip_preserves_valid_rows \ + test/registered/unit/mem_cache/test_cp_hicache_load_back_owner_lanes.py -q +``` + +结果:`12 passed, 3 warnings`。 + +结论:L1↔L2 数据 roundtrip 正确;L2→L1 control path 发现并修复了一个同步 eviction 过重问题。该修复是删除冗余热路径操作,不是新增 check。 + +## 2026-06-07 W: 增加默认关闭的 CP HiCache cache-hit 定位日志 + +当前 L1↔L2 controller grouped bs=5 roundtrip 单测通过,仍未解释 GSM8K 第二轮 cache hit 后掉点。为避免继续盲查,本轮只增加默认关闭、受 `SGLANG_CP_SHARED_KV_BS_GT1_DEBUG` 和 `SGLANG_CP_SHARED_KV_BS_GT1_DEBUG_LIMIT` 控制的限频日志,不加入默认 runtime check。 + +新增观测点: + +- `match_prefix_result`:每次 CP HiCache match 返回的 device 命中长度、host hit 长度、last_device_node、last_host_node、deferred node、rid(schedule_policy 已把 req 传给 MatchPrefixParams)。用于区分第二轮掉点是 L1 resident hit、L2 load_back hit,还是 pending-backup defer。 +- `match_floor_valid_tail`:valid-tail 被 page floor 的节点、原始 prefix、floor 后 prefix、host_len/padded_len/pending_write。用于确认 cache 以 page 为最小单位时是否仍暴露了 sub-page tail。 +- `init_load_back_start/loaded/unloaded` 和 `load_back_plan`:L2→L1 load_back 的 rid、节点链、owner-lane required/available/deficit/free-room。用于确认第二轮 hit 是否真的从 L2 加载,以及 exact/free-room 行为。 +- `prepare_write_backup`、`attach_prepared_backup`、`commit_pending_backup`:写入侧 node_id、logical_len、padded_len、host_indices、owned_positions、page owners。用于对齐“写入的 node 元数据”和“后续 match/load 消费的 node 元数据”。 + +启动方式示例: + +```bash +SGLANG_CP_SHARED_KV_BS_GT1_DEBUG=1 \ +SGLANG_CP_SHARED_KV_BS_GT1_DEBUG_LIMIT=256 \ +... +``` + +风险控制:日志全部默认关闭,限频;不做 tensor 内容校验,不引入 H2D/D2H 冗余检查,不改变 cache 行为。 + +### W 追加验证 + +远端已同步 `hiradix_cache.py`、`schedule_policy.py` 和本文档,并验证: + +```bash +python -m py_compile python/sglang/srt/mem_cache/hiradix_cache.py \ + python/sglang/srt/managers/schedule_policy.py + +SGLANG_CP_SHARED_KV_BS_GT1_DEBUG=1 \ +SGLANG_CP_SHARED_KV_BS_GT1_DEBUG_LIMIT=8 \ +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/mem_cache/test_nsa_pool_host_unit.py::TestNSAHiCacheTransfer::test_cp_hicache_controller_grouped_bs5_l2_roundtrip_preserves_valid_rows \ + test/registered/unit/mem_cache/test_cp_hicache_load_back_owner_lanes.py::TestCpHiCacheLoadBackOwnerLanes::test_load_back_does_not_synchronously_evict_for_l1_free_room_when_exact_capacity_fits -q +``` + +结果:`2 passed, 3 warnings`。debug env 打开时不会破坏对应 L1↔L2 / load_back 单测路径。 + +## 2026-06-07 X: GSM8K 两轮后仍掉点,当前日志暴露的问题 + +用户在同一进程上连续两轮完整 GSM8K: + +- 第一轮:Accuracy `0.955`,Invalid `0.001`,Latency `208.152s`,throughput `669.457 token/s`。 +- 第二轮:Accuracy `0.684`,Invalid `0.003`,Latency `216.646s`,throughput `658.218 token/s`。 + +远端最新日志:`/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_103959.log`。 + +### X1 debug env 实际未生效 + +日志中没有真正的 `[CP_SHARED_KV_BS_GT1_DEBUG][hicache]` 事件,只有如下 warning 重复出现: + +```text +Invalid value for SGLANG_CP_SHARED_KV_BS_GT1_TIMING_LIMIT: "-1SGLANG_CP_SHARED_KV_BS_GT1_DEBUG=1" is not a valid integer value +``` + +说明启动命令里 `SGLANG_CP_SHARED_KV_BS_GT1_TIMING_LIMIT=-1` 和 `SGLANG_CP_SHARED_KV_BS_GT1_DEBUG=1` 中间缺少空格/续行,导致 debug env 被拼进 timing limit;本轮无法用新增日志判断 match/load_back 细节。 + +正确写法需要类似: + +```bash +SGLANG_CP_SHARED_KV_BS_GT1_TIMING_LIMIT=-1 \ +SGLANG_CP_SHARED_KV_BS_GT1_DEBUG=1 \ +SGLANG_CP_SHARED_KV_BS_GT1_DEBUG_LIMIT=512 \ +... +``` + +### X2 普通日志未见显式 crash/fallback,但第二轮大量 cache hit + +普通日志无 `Traceback` / `RuntimeError` / `FALLBACK` / `FAIL_FAST`。按 CP0 的 `Prefill batch` 聚合: + +```text +minute cp0_batches cp0_newseq cp0_newtok cp0_cached cached_batches +2026-06-07 10:45 38 182 23744 115200 36 +2026-06-07 10:46 77 385 49216 245760 77 +2026-06-07 10:47 78 390 50112 248320 78 +2026-06-07 10:48 74 368 48576 234240 74 +2026-06-07 10:49 65 317 40832 241024 64 +2026-06-07 10:50 77 385 25024 269312 77 +2026-06-07 10:51 77 383 41088 269312 77 +2026-06-07 10:52 51 244 16128 169856 49 +``` + +第二轮缓存命中比例更高,符合“cache hit 后掉点”的现象。 + +### X3 可疑现象:短 extend 写入时只有 CP0 拥有 padded page + +日志中大量短 suffix: + +```text +node_id=6493 logical_len=8 CP0 owned_positions=64, CP1-7 owned_positions=0 +node_id=6494 logical_len=37 CP0 owned_positions=64, CP1-7 owned_positions=0 +node_id=6495 logical_len=21 CP0 owned_positions=64, CP1-7 owned_positions=0 +node_id=6496 logical_len=28 CP0 owned_positions=64, CP1-7 owned_positions=0 +``` + +这可能是合法的 page-minimum ownership,也可能说明 batch/page padding 后 owner 选择使用了 relative page id,导致短 suffix 的第一个 padded page 总是 owner 0,而不是按全局 page/sequence position 的 owner lane。需要回到 `build_in_seq_page_compute_owners()`、`alloc_extend_compute_owner()`、`reserve_write_cp()`、`get_cp_shared_kv_local_out_cache_loc()` 的 prefix/global-page 语义确认。 + +下一步:修正启动 debug env 后再跑一轮或小规模重复 GSM;同时从代码侧验证“短 suffix padded page 是否应总是 CP0 owner”。 + +## 2026-06-07 X: 最新 GSM8K 两轮日志复查(`20260607_103959`) + +用户再次连续跑全量 GSM8K,同一 prefill 进程: + +- 第 1 轮:`Accuracy=0.955`, `Invalid=0.001`, `Latency=208.152s`, `Output throughput=669.457 token/s` +- 第 2 轮:`Accuracy=0.684`, `Invalid=0.003`, `Latency=216.646s`, `Output throughput=658.218 token/s` + +远端日志:`g0034:/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_103959.log`。 + +复查事实: + +- `FALLBACK=0`, `FAIL_FAST=0`, `RuntimeError=0`。 +- `HiCache-load=0`, `load_back=0`, `CacheCtrl-load=0`;这份日志仍没有显式 L2->L1 load-back 证据。 +- `CP_SHARED_KV_BS_GT1_DEBUG` 没有真正生效。启动环境里出现拼接错误: + + ```text + Invalid value for SGLANG_CP_SHARED_KV_BS_GT1_TIMING_LIMIT: + "-1SGLANG_CP_SHARED_KV_BS_GT1_DEBUG=1" is not a valid integer value + ``` + + 因此日志里没有 `[CP_SHARED_KV_BS_GT1_DEBUG][hicache] match_prefix/load_back/...` 事件,不能用本轮日志判断真实 radix match/load_back 元数据。 + +- CP0 `Prefill batch` 按分钟统计显示两轮之间 cache-hit 确实上升: + + ```text + 10:45-10:48: cached/new 约 115200/23744 -> 248320/50112 + 10:49-10:52: cached/new 约 241024/40832 -> 269312/41088 -> 169856/16128 + ``` + +- 10:50 左右 timing 日志显示大量 tiny suffix batch:`split_tokens=89/126/163/175/...`,`compute_padding=True`,CP0 持有几乎全部 valid local rows,CP1 只有少量 tail row,符合当前 page-minimal valid-owner 设计。 +- 两轮结束后出现 detokenizer health failure 与 503 shutdown: + + ```text + 11:00:34 Health check failed. Server couldn't get a response from detokenizer for last 20 seconds. + 11:00:37 Shutdown: finished 0 streaming requests normally, aborted 2 requests with 503. + 11:00:37 serving_chat.py:818 AttributeError: 'int' object has no attribute 'name' + ``` + +判断: + +- 精度掉点仍然与第二轮更高 cache-hit 强相关。 +- 本轮日志不能证明 L2 load-back 参与;没有 `[HiCache-load]`。当前更像 L1/radix cache-hit consume 侧或 prefill->decode transfer/decoder consume 侧语义问题。 +- 新暴露的 detokenizer hang/503 shutdown 是独立稳定性问题,会污染尾部请求,但不能单独解释第二轮 `0.684` 的大幅掉点。 +- 下一轮若要靠 runtime 日志定位,必须修正 env 换行: + + ```bash + SGLANG_CP_SHARED_KV_BS_GT1_TIMING_LIMIT=-1 \ + SGLANG_CP_SHARED_KV_BS_GT1_DEBUG=1 \ + SGLANG_CP_SHARED_KV_BS_GT1_DEBUG_LIMIT=512 \ + ... + ``` + + +## 2026-06-07 Y: 重启后 debug 生效,掉点仍然集中在 L1 device suffix page hit + +远端最新日志:`g0034:/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_112229.log`,prefill PID `538216`。 + +启动环境已确认包含: + +```text +SGLANG_CP_SHARED_KV_BS_GT1_DEBUG=1 +SGLANG_CP_SHARED_KV_BS_GT1_DEBUG_LIMIT=-1 +SGLANG_CP_SHARED_KV_CURRENT_REUSE=1 +SGLANG_CP_SHARED_KV_FUSED_INDEX_MQA_PREPARE=1 +SGLANG_CP_SHARED_KV_FUSED_MLA_STORE=1 +SGLANG_CP_DRAFT_SHARED_KV=1 +SGLANG_DISAGGREGATION_ALL_CP_RANKS_TRANSFER=1 +``` + +### Y1 日志计数结论 + +```text +Traceback: 0 +RuntimeError: 0 +FAIL_FAST: 0 +FALLBACK: 0 +Health check failed: 0 +HiCache-load/load_back/CacheCtrl-load: 0 +match_prefix_result: 46464 +match_floor_valid_tail: 512 +send_kv_chunk: 21344 +prefill_result_handoff: 4480 +``` + +结论:本轮 debug 生效,且没有显式 fallback/crash;也没有 L2->L1 load_back 证据。GSM8K 第二轮掉点不能继续优先归因于 L2 load-back 数据损坏。 + +### Y2 两轮 GSM8K 的 CP0 prefill 形态 + +按 CP0 `Prefill batch` 聚合,第一轮约 `11:34-11:38`,第二轮约 `11:43-11:47`: + +```text +第一轮 11:34-11:38: newtok≈171392, cached≈843520 +第二轮 11:43-11:47: newtok≈86016, cached≈928896 +``` + +第二轮 new token 明显下降、cached token 上升,符合“cache hit 后精度下降”的现象。 + +### Y3 关键差异:第二轮大量命中 first-run 写入的 device suffix page + +过滤 CP0 且 `rid != None` 的 `match_prefix_result` 后: + +- 第一轮绝大多数真实请求只命中公共 prompt 的 `640` token device prefix;`last_device_host_len=640`。 +- 第二轮大量请求命中 `704/768/832` token device prefix;其中新增的 `64/128/192` token 来自第一轮写入的 suffix page node,`last_device_host_len=64/128/192`。 +- `host_hit_length` 始终为 `0`。 + +代表样例: + +```text +# 第一轮 +rid=09be43... key_len=697 device_tokens=640 last_device_node=8 last_device_host_len=640 + +# 第二轮 +rid=47c543... key_len=734 device_tokens=704 last_device_node=2650 last_device_host_len=64 +rid=5df882... key_len=779 device_tokens=768 last_device_node=2653 last_device_host_len=128 +``` + +### Y4 send_kv_chunk 与 transfer 侧没有暴露 page count mismatch + +第二轮 `send_kv_chunk` 的 `kv_page_count` 与 `state_page_count` 一致,且没有 mooncake transfer fail-fast/fallback。第二轮 extend 变得很短: + +```text +11:43 ext_min_avg_max=(1, 27.4, 65) +11:44 ext_min_avg_max=(2, 28.0, 65) +11:45 ext_min_avg_max=(2, 27.2, 65) +11:46 ext_min_avg_max=(2, 27.4, 65) +``` + +当前 root-cause 方向收窄为:第一轮写入并留在 L1 的 suffix page node,在第二轮作为 device cache prefix 被消费时语义错误。优先检查: + +1. radix/HiCache split 后 `node.value` 与 `cp_hicache` metadata 是否仍表示同一 token span; +2. page-floor 后 suffix node 的 `owned_positions` 是否相对 node-local 正确偏移; +3. cache-hit consume 时 `prefix_indices` / `req_to_token` 是否按全局 token 顺序拼接这些 suffix page; +4. first-run insert of `640 + short suffix` 到 second-run match `704/768` 的最小单测。 + +不要再重复优先排查 L2 load-back;本轮日志没有该路径参与证据。 + +## 2026-06-07 Z: root-cause direction refined to L1 persistent direct-write/read + +Latest debug-enabled run (`20260607_112229`) shows: + +- no `HiCache-load` / `load_back` / `CacheCtrl-load` events; +- no `FALLBACK` / `FAIL_FAST` / `RuntimeError`; +- second GSM8K run has far more device cache hits and short extends; +- second run consumes first-run suffix pages as L1 device prefix (`device_tokens=704/768/832`, `host_hit_length=0`). + +This makes L2 load-back unlikely for the accuracy drop. A stronger hypothesis is: + +1. first run computes prompt/current suffix correctly because attention/index paths use freshly produced current KV/index rows in partial-current compose; +2. first run also writes those rows into the persistent L1 CP shared-KV pool through direct-write/fused-store; +3. second run hits those persisted device pages and reads them as prefix; +4. if direct-write layout/offset/FP8 packing is wrong, first run can remain accurate while second run drops. + +Next inspection target: direct-write store/read roundtrip for `page_first_direct`, `fp8_e4m3`, batch/compute-padding, especially MLA KV fused store and NSA index K/scale store. Do not spend more cycles on L2 load-back for this run unless new logs show `HiCache-load`. + +## 2026-06-07 AA: cp_floor_exact false is internal refresh; transfer confirms second run sends fully cached prompts + +Latest log recheck for `20260607_112229`: + +- `cp_floor_exact=False` `match_prefix_result` events all have `rid=None`: + - `('False', rid_is_None=True, device_tokens_not_page_aligned)=20760` + - `('True', rid_is_None=False, device_tokens_page_aligned)=25336` +- Scheduler-visible request matches (`rid != None`) are page-aligned. The non-page results are from the post-insert/cache refresh path and are not direct scheduler planning inputs. +- First GSM8K run CP0 send shape: + - 1318/1319 requests transfer with `fill_len - extend_input_len = 640`. + - Average extend sent/computed ≈ 92 tokens. +- Second GSM8K run CP0 send shape: + - prefix distribution from `fill_len - extend_input_len`: `704:1154`, `768:82`, `640:81`, `832:2`. + - Average extend ≈ 27 tokens. +- `send_kv_chunk` runs after cache insertion refresh; its logged `prefix_len=len(req.prefix_indices)` often equals full `fill_len` in the second run, so decode is receiving page tables that can be entirely first-run cached prompt pages, not just freshly computed tail rows. + +Implication: the current strongest path is not L2 load-back and not scheduler non-page prefix planning. The second run transfers and consumes first-run persisted L1 prompt pages (question suffix pages) far more aggressively. Root-cause search should focus on persistent L1 writes/readback/transfer for bs>1 compute-padding FP8 CP shared KV: + +1. MLA KV fused persistent store -> cached prefix materialize / transfer. +2. NSA index fused persistent store -> cached prefix materialize / top-k. +3. Radix post-insert refresh replacing freshly computed tail with full cached prompt before transfer. + +Need a focused test that writes bs=5 compute-padded valid rows into persistent L1, then reads/materializes the same pages as a later cache-hit prefix. Existing tests cover index store+materialize and MLA store-vs-fallback, but do not yet prove FP8 MLA persistent pages survive the second-run cache-hit materialize/transfer shape. + +## 2026-06-07 AB: added MLA persistent-page cache-hit unit; collective materialize path passes + +Added `test_fp8_mla_persistent_pages_survive_bs5_cache_hit_materialize` to cover the missing MLA side of the second-run cache-hit shape: + +- bs=5, `prefix_lens=[640]*5`, `extend_lens=[95,81,140,66,86]`; +- writes valid rows through TAI fused MLA persistent store after compute-padding selection; +- materializes only full cached suffix pages as a later page-floored cache-hit prefix; +- simulates CP owner merge by summing per-rank dense buffers with IPC disabled. + +Remote CUDA result on `g0034` container: + +```text +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/mem_cache/test_cp_shared_kv_runtime.py::TestCpSharedKVRuntimeHelpers::test_fp8_mla_persistent_pages_survive_bs5_cache_hit_materialize +1 passed, 3 warnings in 8.76s +``` + +This weakens the hypothesis that the ordinary fused MLA store + local materialize + all-reduce path corrupts bs=5 FP8 persistent L1 pages. Remaining likely areas: + +1. runtime path difference not covered by the unit, especially TAI IPC materialize when a single prefix span is used; +2. decode/disaggregation transfer consuming cached prompt pages after `cache_finished_req` refreshes `req_to_token` to full cached prompt; +3. draft/target transfer parity for cached-prefix pages; +4. index runtime path still has a CUDA persistent-page test, but it disables IPC and may not cover the exact online materialized shared-buffer path with all environment flags. + +## 2026-06-07 AC: new process ready; raw-output based failure classification required + +New remote prefill log is `/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_131732.log`. + +Startup evidence: + +- server reached `The server is fired up and ready to roll!` at log line 4334; +- no startup `Traceback` / `RuntimeError` / `FAIL_FAST` / `FALLBACK` marker before readiness; +- fp8 KV cache still warns that no scaling factors were provided and scaling defaults to 1.0 on all ranks. This warning alone cannot explain the second-run-only accuracy drop because first-run fp8 accuracy was normal, but it remains part of the runtime context. + +Existing raw result file found: + +- `/mnt/beegfs/cjy/gsm8k_bench_sglang_full_raw_20260606_132651.jsonl`: 1319 rows, accuracy 0.955; its failures are ordinary wrong GSM8K reasoning/answers, not obvious repetitive gibberish. No matching second-run raw file was found yet, so cache-hit drop must be probed with new raw-result files. + +Next diagnostic: run two small GSM8K passes (50-200 questions) with `--raw-result-file`, then compare first vs second failures and prefill `match_prefix_result` / `prefill_result_handoff` / `send_kv_chunk` around that window. + +## 2026-06-07 AD: 200-question raw probe reproduces second-run drop and shows prompt/request contamination pattern + +Probe command shape: two sequential GSM8K passes with `--num-questions 200 --parallel 64 --raw-result-file`, on the new process/log `/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_131732.log`. + +Results: + +```text +pass1 raw=/mnt/beegfs/cjy/gsm8k_bs_gt1_probe_20260607_132646_pass1_raw.jsonl +Accuracy: 0.965, Invalid: 0.000 + +pass2 raw=/mnt/beegfs/cjy/gsm8k_bs_gt1_probe_20260607_132646_pass2_raw.jsonl +Accuracy: 0.700, Invalid: 0.000 +``` + +Raw transition summary over the same 200 prompt ids: + +```text +(True, True): 139 +(False, False): 6 +(True, False): 54 +(False, True): 1 +``` + +Failure classification: + +- pass1 failures: 7/7 normal wrong reasoning/answers; +- pass2 failures: 55 normal-looking wrong answers + 5 very-short outputs; +- pass2 newly bad ids: `[13, 14, 15, 18, 20, 25, 29, 31, 33, 35, 38, 39, 44, 45, 61, 62, 63, 64, 65, 75, 85, 89, 90, 93, 94, 100, 105, 108, 110, 115, 120, 124, 128, 129, 130, 134, 135, 143, 144, 154, 155, 159, 160, 164, 169, 170, 173, 175, 189, 190, 192, 193, 198, 199]`. + +Important qualitative signal: second-run failures are usually not random gibberish. Some outputs answer a different problem or echo a few-shot/example prompt fragment: + +- id=33 prompt asks Gretchen coins, output starts with the standard Janet-ducks GSM8K example and answers `18`; +- id=45 prompt asks Meredith blogging hours, output starts with `20\nKylie makes and sells scarves...` and answers `180`; +- id=62 prompt asks Marcy 30-year pension, output switches to a 25-year pension variant and answers `31250`; +- id=75 prompt asks average square footage, output answers a similar total-square-footage problem. + +Prompt-echo marker count: + +```text +pass1 total_echo=1, fail_echo=0 +pass2 total_echo=18, fail_echo=15 +``` + +This points away from pure fp8 numerical drift and toward request/prompt metadata contamination or offset/order mismatch under bs>1 cache-hit. The model is often coherent but conditioned on the wrong cached prompt slice / wrong hidden/topk / wrong transferred page table. + +Prefill log for the two-pass window: + +```text +Traceback=0 RuntimeError=0 FAIL_FAST=0 FALLBACK=0 HealthCheckFail=0 +HiCache-load=0 load_back=0 CacheCtrl-load=0 + +CP0 handoff bs distribution around probe: + mostly bs=5; no L2 load path. + +Second pass CP0 handoff prefix_top: + 640:176, 704:167, 768:16 +extend range: + min=2 avg≈56.9 max=165 +``` + +Conclusion update: root cause is likely in the bs>1 cache-hit online path where per-request cached prefix pages, output hidden/topk, and decode transfer metadata must stay aligned. Continue checking: + +1. `process_batch_result_disagg_prefill`: `batch.reqs`, `result.next_token_ids`, and `batch.spec_info.{hidden_states,topk}` order agreement; +2. `cache_unfinished_req` side effects before `send_kv_chunk` (it can refresh `req_to_token`/`prefix_indices` to a fuller cached prompt); +3. `send_kv_chunk` target/draft `page_indices/state_indices` consistency with the hidden/topk assigned to that same req; +4. any batch-level plan that reorders/splits valid rows without carrying request ids through to logits/sample/spec tensors. + +## 2026-06-07 AE: failing unit test isolates compute-padding all-gather rerange source-offset bug + +Added a targeted CPU unit test for this exact dataflow: + +- request 0 is a tiny extend that enables compute padding; +- request 1 follows it in the same bs>1 rank-major all-gather buffer; +- valid output must drop request-0 synthetic rows, but source offsets must still skip those synthetic rows. + +Remote failing evidence before fix: + +```text +test_batch_in_seq_all_gather_rerange_uses_compute_offsets_for_padded_source: FAILED +``` + +Root-cause candidate is now concrete: `_torch_batch_in_seq_all_gather_rerange()` used `request_split_lists` (valid rows) to compute source offsets inside the rank-major all-gather payload. Under compute padding, the source payload is laid out by `request_compute_split_lists`, while output must remain `request_split_lists`. This can make the second request read the first request's padded mirror rows or another request's rows after cache-hit/tiny-extend batching, matching the observed GSM8K prompt-fragment contamination. + +Required contract: + +- source rank offsets: compute split lists when `compute_padding_enabled`; +- output length/order: valid split lists; +- copy length per segment: valid segment length; +- no synthetic compute-padding row may appear in restored hidden/index/MLA rows. + +Fix applied: + +- `_torch_batch_in_seq_all_gather_rerange()` now separates `source_split_lists` from `output_split_lists`; +- source rank offsets and mirror offsets use `request_compute_split_lists` when compute padding is enabled; +- output allocation, output prefixes, and copy lengths still use valid `request_split_lists`; +- fail-fast validates that every compute segment covers the corresponding valid segment. + +Verification: + +```text +remote container: +PYTHONPATH=python python -m pytest -q test/registered/unit/layers/test_nsa_cp_utils.py -k batch_in_seq_all_gather_rerange +3 passed + +remote container: +PYTHONPATH=python python -m pytest -q test/registered/unit/layers/test_nsa_cp_utils.py +93 passed +``` + +ETE implication to verify after restart: if this was the second-run cache-hit accuracy root cause, a 200-question two-pass GSM8K probe should no longer show pass2 dropping to ~0.70 nor show prompt-fragment echo spikes. + +## 2026-06-07 AF: rerange 修复后第一次 ETE probe 被 decode/prefill fingerprint mismatch 阻断 + +修复 `_torch_batch_in_seq_all_gather_rerange()` 后,prefill 在 g0034 重新启动,日志 `/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_135544.log` 显示: + +- server ready; +- `Traceback=0`、`RuntimeError=0`、`FAIL_FAST=0`、`FALLBACK=0`、`Health check failed=0`; +- container 内 `/sgl-workspace/sglang-tai/python/.../nsa/utils.py` 已包含 `source_split_lists` 修复。 + +随后启动 200 条 GSM8K 两轮 probe,但 pass1 卡在 0/200。prefill 日志只看到 `/get_model_info` 和 health check,没有实际 `/v1/chat/completions` 请求进入 prefill。 + +检查 decode 日志 `/mnt/beegfs/cjy/log/decode{0,1}_20260607_1317*.log`,decode 在 14:04:20 退出,根因是 runtime fingerprint fail-fast: + +```text +Runtime source fingerprint mismatch between prefill and decode. +prefill_fingerprint=96939b022cf93b42c8e1231832cafd4e35528e268a79db3814236dc63a889d94 +decode_fingerprint=47b3db5225b34a3f22fded3af198d2eb1d79ef71c63f2bb01f344aabd5ed95fd +Restart both prefill and decode from the same source tree. +``` + +这不是新的数据正确性结论;它说明这轮 ETE 没有真正验证 rerange 修复。fingerprint guard 正确阻止了 prefill/decode 源码版本不一致下的 PD KV transfer。 + +当前状态: + +- g0034/g0035/g0036 host `/mnt/beegfs/cjy/sglang-dev` 中关键文件 sha256 一致; +- g0034/g0035/g0036 container `/sgl-workspace/sglang-tai` 中关键文件 sha256 也一致; +- decode 失败发生在旧 decode 进程与新 prefill 进程交互时;需要重启 decode,使其重新加载同一份源码 fingerprint,再重跑 50-200 条两轮 GSM8K probe。 + +被中止的 probe base: + +```text +/mnt/beegfs/cjy/gsm8k_bs_gt1_probe_after_rerange_fix_20260607_140414 +``` + +该 probe 未产生有效精度结果,不应用于判断 rerange 修复效果。 + +## 2026-06-07 AG: rerange 修复后仍复现 pass2 cache-hit 掉点 + +有效 probe base: + +```text +/mnt/beegfs/cjy/gsm8k_bs_gt1_probe_after_rerange_fix_20260607_142514 +``` + +结果: + +```text +pass1: Accuracy=0.955, Invalid=0.000, Latency=34.272s, Output throughput=613.860 token/s +pass2: Accuracy=0.720, Invalid=0.000, Latency=34.599s, Output throughput=627.594 token/s +``` + +因此 AE 的 `_torch_batch_in_seq_all_gather_rerange()` source/output split 修复是必要的,但不是完整 root cause。 + +pass1/pass2 raw 对比: + +```text +pass1: ok=191 bad=9 +pass2: ok=144 bad=56 +new regressions: 48 +regression ids first: [15, 18, 19, 29, 34, 35, 39, 44, 45, 50, 54, 58, 59, 64, 65, 75, 85, 90, 93, 94] +``` + +失败形态:pass2 多数输出是语义连贯但解错,且常表现为“读到相似但不完全相同的问题”: + +- id=15:原题增长率是 `2.5% / 1.2%`,pass2 输出按 `2% / 1%` 解; +- id=18:原题 `4 weeks`,pass2 输出按 `4 days` 解; +- id=19:原题要求 average speed=4mph 下 remaining speed,pass2 输出解成同速完成; +- id=34:原题 Aaron has `5 more than half`,pass2 输出误成 `half * 5`。 + +Prefill log 观察: + +```text +Traceback=0 RuntimeError=0 FAIL_FAST=0 FALLBACK=0 HealthCheckFail=0 +pass1 mostly: #new-token≈576-704, #cached-token=3200 +pass2 mostly: #new-token=320, #cached-token≈3456-3584 +``` + +这更像“缓存命中后,命中的部分 prompt KV 与当前请求 prompt 不完全一致”,而不是 decode 崩溃或 fp8 随机数值漂移。 + +新增关键线索:debug log 在 health check / tiny extend 路径上显示 compute padding 即使 bs=1 也会启用: + +```text +batch_plan bs=1 extend_lens=[1] valid_pages=[1] compute_pages=[8] padding_tokens=[511] +split_tensor:1d:compute input_tokens=8 expected_tokens=1 target_lens=[512] local_rows=64 static_padded=8 +``` + +这本身未直接证明 GSM8K 失败,但说明 current/prefix/tiny cache-hit 路径仍大量依赖 compute-padding contract。下一步不要继续盲改,需要沿 L1 cache-hit 使用的 KV 读取路径检查: + +1. radix/HiCache 命中是否会把非 page-aligned 的 logical prefix floor 到正确 page boundary,且不会返回跨请求 stale tail; +2. L1 cached prefix 的 `req_to_token_pool` / `out_cache_loc` 是否只包含真实 page slots,不包含 compute padding mirror rows; +3. direct write 时 valid rows 写入的 physical page slot 顺序,是否与后续 cache-hit page table 读取顺序一致; +4. index KV 与 MLA KV 是否都遵守同一 valid-page contract,尤其是 second-pass `new-token=320` 的 partial-current/cache-hit组合。 + +## 2026-06-07 AH: decode prebuilt out_cache_loc slices prefix instead of suffix + +Root-cause candidate found in `python/sglang/srt/disaggregation/decode_schedule_batch_mixin.py::prepare_for_prebuilt()`. + +Code facts: + +- `input_ids = fill_ids[len(prefix_indices):]` correctly makes decode prebuilt process only the suffix after cached prompt prefix. +- `seq_len - pre_len == req.extend_input_len` asserts the same suffix length contract. +- But `out_cache_loc` was built from: + + ```python + req_to_token_pool.req_to_token[req.req_pool_idx][: req.extend_input_len] + ``` + + which selects the first `extend_input_len` prompt locations, i.e. prefix page slots, not the suffix locations at `pre_len : pre_len + extend_input_len`. + +Observed failing unit test before fix: + +```text +TestDecodeQueueCompaction.test_prepare_for_prebuilt_uses_suffix_cache_locs_after_cache_hit +expected out_cache_loc=[2000,2001,2002] +actual out_cache_loc=[1000,1001,1002] +``` + +Why this matches GSM8K pass2 drop: + +- In pass1, many requests have low cache hit / larger prefill suffix, so the wrong prebuilt suffix mapping is less concentrated on short cache-hit tails. +- In pass2, `pre_len` is much larger and `extend_input_len` is often tiny; using `[:extend_input_len]` makes decode update/read the beginning of the prompt instead of the actual tail. +- Raw outputs looked like the model saw the first part of the question but missed final constraints (`per week`, `$3 fee + tip`, `4 weeks`, etc.), which is consistent with the tail KV being mapped to the wrong cache locs. + +Planned fix: slice decode prebuilt locs with `pre_len : pre_len + req.extend_input_len`, matching the existing input-id and assertion contract. This is not CP-specific; it is a general cache-hit prebuilt correctness bug that CP shared-KV bs>1 exposed by making second-pass cache hits much deeper/shorter. + +### AH 追加实现/验证结果 + +已按 TDD 做最小修复:`prepare_for_prebuilt()` 的 `out_cache_loc` 改为从 decode 端 `req_to_token_pool` 的 suffix 区间读取: + +```python +req_to_token_pool.req_to_token[req.req_pool_idx][pre_len : pre_len + req.extend_input_len] +``` + +同时 debug `out_chunk_start` 改为 `pre_len`,与 `expected_suffix_start` 保持一致。 + +验证: + +```bash +# RED: 同步测试到远端、旧代码失败 +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/disaggregation/test_decode_queue_compaction.py::TestDecodeQueueCompaction::test_prepare_for_prebuilt_uses_suffix_cache_locs_after_cache_hit -q +# expected [2000,2001,2002], actual [1000,1001,1002] + +# GREEN: 修复后 +PYTHONPATH=python python -m pytest -q \ + test/registered/unit/disaggregation/test_decode_queue_compaction.py \ + test/registered/unit/layers/test_nsa_cp_utils.py -q +# 108 passed +``` + +下一步 ETE 验证要求:需要重启 decode(该 bug 在 decode 进程路径),然后重复 200 条 GSM8K 两轮 probe。若 root cause 命中,第二轮准确率应不再从约 `0.95` 跌到约 `0.70`,并且 raw 输出里的 prompt-tail omission / prompt-fragment echo 应显著减少。 + +## 2026-06-07 AI: restart 后 200 条 probe 仍失败,问题仍在 L1 cache-hit page order + +用户重启后重新跑 200 条 GSM8K 两轮 probe: + +```bash +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 +``` + +结果目录:`/mnt/beegfs/cjy/gsm8k_retest_20260607_231950` + +结果: + +```text +pass1 Accuracy: 0.685 Invalid: 0.000 Latency: 35.842 s Output throughput: 614.422 token/s +pass2 Accuracy: 0.720 Invalid: 0.000 Latency: 34.502 s Output throughput: 609.073 token/s +``` + +说明 decode prebuilt suffix slicing 修复仍不足;当前进程内 cache 已经被命中/复用,第一轮也不是干净 cold baseline。 + +prefill log:`/mnt/beegfs/cjy/log/sglang_cp_hicache_20260607_145743.log` + +关键证据仍然是 `send_kv_chunk` 前 `req_to_token_pool` 的 page 顺序错误。示例: + +```text +event=send_kv_chunk rid=aaad28fd98184ef5bdd0b6e6a733c737 +start_idx=0 end_idx=721 page_size=64 +pages=head=[33,2,3,4,5,6,7,8] +state_pages=head=[33,2,3,4,5,6,7,8] +prefix_len=721 host_hit_length=0 extend_input_len=17 fill_len=721 origin_input_len=721 +``` + +同一批次多个 rid 都出现相同 pattern:`state_pages` 头部为新 suffix page(例如 33),后面才是公共 prefix page `[2,3,4,...]`。这不是 L2 load-back:`host_hit_length=0`,属于 L1/device hit 后的 page table 顺序问题。 + +当前排除项: + +1. `write_cache_indices()` 独立 CUDA/unit probe 已验证 prefix-first + suffix-after-prefix 的写入 contract 正确。 +2. `CPSharedPagedTokenToKVPoolAllocator.alloc_extend_compute_owner()` 简单 cache-hit suffix 分配 probe 已验证返回 suffix loc 是 request order。 +3. prefill/decode 日志没有新的 `FAIL_FAST` / `CP_SHARED_KV_FALLBACK` / `Traceback`。 + +下一步定位点不要再查上述两个 helper;应在真实 runtime 的以下边界记录 page-order: + +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 来源。 diff --git a/python/sglang/srt/managers/schedule_policy.py b/python/sglang/srt/managers/schedule_policy.py index ad2abae2f..82879899c 100644 --- a/python/sglang/srt/managers/schedule_policy.py +++ b/python/sglang/srt/managers/schedule_policy.py @@ -198,7 +198,8 @@ class SchedulePolicy: # NOTE: the prefix_indices must always be aligned with last_node match_result = self.tree_cache.match_prefix( MatchPrefixParams( - key=RadixKey(token_ids=prefix_ids, extra_key=extra_key) + key=RadixKey(token_ids=prefix_ids, extra_key=extra_key), + req=r, ) ) ( @@ -857,6 +858,7 @@ class PrefillAdder: last_host_node=req.last_host_node, host_hit_length=req.host_hit_length, mem_quota=self._get_load_back_mem_quota(real_input_tokens), + req=req, ) ) req.prefix_indices = torch.cat([req.prefix_indices, new_indices]) diff --git a/python/sglang/srt/mem_cache/hiradix_cache.py b/python/sglang/srt/mem_cache/hiradix_cache.py index 8184f3804..31f2b0a67 100644 --- a/python/sglang/srt/mem_cache/hiradix_cache.py +++ b/python/sglang/srt/mem_cache/hiradix_cache.py @@ -65,6 +65,33 @@ if TYPE_CHECKING: logger = logging.getLogger(__name__) +_CP_HICACHE_BS_GT1_DEBUG_COUNTS: Dict[str, int] = {} + + +def _cp_hicache_bs_gt1_debug( + key: str, + message: str, + *args, + limit: Optional[int] = None, +) -> None: + """Env-gated, rate-limited CP HiCache debug logging. + + Keep this local to mem_cache to avoid importing NSA attention helpers from + the radix cache path. It is intentionally default-off because these paths + run on scheduler/control hot paths. + """ + + if not envs.SGLANG_CP_SHARED_KV_BS_GT1_DEBUG.get(): + return + if limit is None: + limit = envs.SGLANG_CP_SHARED_KV_BS_GT1_DEBUG_LIMIT.get() + limit = int(limit) + count = _CP_HICACHE_BS_GT1_DEBUG_COUNTS.get(key, 0) + if limit > 0 and count >= limit: + return + _CP_HICACHE_BS_GT1_DEBUG_COUNTS[key] = count + 1 + logger.info("[CP_SHARED_KV_BS_GT1_DEBUG][hicache] event=%s " + message, key, *args) + def _estimate_hicache_size_per_token(kv_cache) -> int: dtype_size = kv_cache.store_dtype.itemsize @@ -1992,6 +2019,20 @@ class HiRadixCache(RadixCache): node.host_value = None if pending.locked: self.dec_node_lock_ref(node) + _cp_hicache_bs_gt1_debug( + "commit_pending_backup", + "node_id=%d key_len=%d host_len=%d padded_len=%s " + "owned_positions=%d host_indices=%d page_owner_pages=%d " + "remaining_pending=%d", + node.id, + len(node.key), + node.host_len, + getattr(pending.metadata, "padded_len", None), + pending.metadata.owned_positions.numel(), + pending.metadata.host_indices.numel(), + pending.metadata.page_owners.numel(), + len(self.pending_host_backups), + ) return node def _rollback_pending_backup(self, node_id: int) -> TreeNode: @@ -2156,6 +2197,21 @@ class HiRadixCache(RadixCache): locked=True, ) prepared.attached = True + _cp_hicache_bs_gt1_debug( + "attach_prepared_backup", + "node_id=%d key_len=%d value_len=%d logical_len=%d padded_len=%s " + "owned_positions=%d host_indices=%d page_owner_pages=%d " + "pending_backups=%d", + node.id, + len(node.key), + len(node.value), + prepared.logical_len, + getattr(prepared.metadata, "padded_len", None), + prepared.metadata.owned_positions.numel(), + prepared.metadata.host_indices.numel(), + prepared.metadata.page_owners.numel(), + len(self.pending_host_backups), + ) logger.info( "[HiCache-write] attached prepared CP backup: node_id=%d logical_len=%d owned_positions=%d pending_backups=%d", node.id, @@ -2280,6 +2336,7 @@ class HiRadixCache(RadixCache): request_len: int, *, floor_exact_key: bool = False, + debug_req_id: Optional[str] = None, ) -> int: """Floor exact CP valid-tail hits to the previous physical page. @@ -2306,7 +2363,29 @@ class HiRadixCache(RadixCache): or prefix_len % self.page_size == 0 ): return prefix_len - return floor_to_page_len(prefix_len, self.page_size) + floored_len = floor_to_page_len(prefix_len, self.page_size) + metadata = getattr(child, "cp_hicache", None) + _cp_hicache_bs_gt1_debug( + "match_floor_valid_tail", + "rid=%s node_id=%s prefix_len=%d floored_len=%d request_len=%d " + "child_key_len=%d page_size=%d evicted=%s host_len=%d " + "has_cp_hicache=%s padded_len=%s pending_write=%s floor_exact_key=%s", + debug_req_id, + getattr(child, "id", None), + prefix_len, + floored_len, + request_len, + len(child.key), + self.page_size, + child.evicted, + getattr(child, "host_len", 0), + metadata is not None, + getattr(metadata, "padded_len", None), + self._node_host_write_pending(child), + floor_exact_key, + limit=64, + ) + return floored_len def _cp_subtree_has_unprunable_state(self, node: TreeNode) -> bool: stack = [node] @@ -2558,6 +2637,25 @@ class HiRadixCache(RadixCache): metadata=result.metadata, logical_len=len(kv_indices), ) + _cp_hicache_bs_gt1_debug( + "prepare_write_backup", + "node_id=%d rid=%s logical_len=%d padded_len=%s " + "owned_positions=%d host_indices=%d draft_host_indices=%s " + "page_owner_pages=%d admission_checked=%s", + node_id, + getattr(req, "rid", ""), + len(kv_indices), + getattr(result.metadata, "padded_len", None), + result.metadata.owned_positions.numel(), + result.metadata.host_indices.numel(), + ( + None + if getattr(result.metadata, "draft_host_indices", None) is None + else result.metadata.draft_host_indices.numel() + ), + result.metadata.page_owners.numel(), + admission_checked, + ) logger.info( "[HiCache-write] prepared CP per-layer backup before forward: node_id=%d rid=%s logical_len=%d owned_positions=%d", node_id, @@ -3406,6 +3504,30 @@ class HiRadixCache(RadixCache): self.dec_lock_ref(ancester_node) raise host_hit_len = load_back_plan.host_hit_len + node_debug_summary = [ + ( + getattr(x, "id", None), + len(x.key) if getattr(x, "key", None) is not None else 0, + getattr(x, "host_len", 0), + getattr(getattr(x, "cp_hicache", None), "padded_len", None), + ) + for x in nodes_to_load + ] + _cp_hicache_bs_gt1_debug( + "load_back_plan", + "node_id=%d nodes=%s host_hit_len=%d threshold=%d " + "required_by_owner=%s available_by_owner=%s deficit_by_owner=%s " + "free_room_deficit_by_owner=%s", + last_hit_node.id, + node_debug_summary, + host_hit_len, + self.load_back_threshold, + load_back_plan.required_by_owner, + load_back_plan.available_by_owner, + load_back_plan.deficit_by_owner, + load_back_plan.free_room_deficit_by_owner, + limit=64, + ) logger.info( "[HiCache-load] load_back CP: node_id=%d nodes_to_load=%d " "host_hit_len=%d threshold=%d required_by_owner=%s " @@ -3638,16 +3760,46 @@ class HiRadixCache(RadixCache): ): last_node = params.last_host_node mem_quota = params.mem_quota + debug_req_id = getattr(getattr(params, "req", None), "rid", None) if last_node.evicted: + if self._uses_cp_hicache: + _cp_hicache_bs_gt1_debug( + "init_load_back_start", + "rid=%s last_host_node=%s host_hit_length=%d mem_quota=%s " + "node_host_len=%d", + debug_req_id, + getattr(last_node, "id", None), + int(params.host_hit_length), + mem_quota, + getattr(last_node, "host_len", 0), + ) loading_values = self.load_back(last_node, mem_quota) if loading_values is not None: logger.info( f"loading back {len(loading_values)} tokens for node {last_node.id}" ) + if self._uses_cp_hicache: + _cp_hicache_bs_gt1_debug( + "init_load_back_loaded", + "rid=%s loaded_tokens=%d loaded_node=%s host_hit_length=%d", + debug_req_id, + len(loading_values), + getattr(last_node, "id", None), + int(params.host_hit_length), + ) return loading_values, last_node while last_node.evicted: last_node = last_node.parent + if self._uses_cp_hicache: + _cp_hicache_bs_gt1_debug( + "init_load_back_unloaded", + "rid=%s fallback_device_node=%s host_hit_length=%d mem_quota=%s", + debug_req_id, + getattr(last_node, "id", None), + int(params.host_hit_length), + mem_quota, + ) return ( torch.empty((0,), dtype=torch.int64, device=self.device), @@ -3870,10 +4022,13 @@ class HiRadixCache(RadixCache): deferred_node = None try: + debug_req = getattr(params, "req", None) + debug_req_id = getattr(debug_req, "rid", None) value, last_node = self._match_prefix_helper( self.root_node, key, floor_exact_key=getattr(params, "cp_floor_exact", True), + debug_req_id=debug_req_id, ) except HiCachePendingBackupSplit as exc: value = [] @@ -3906,6 +4061,28 @@ class HiRadixCache(RadixCache): if not last_host_node.backuped: last_host_node = self.root_node + if self._uses_cp_hicache: + debug_req = getattr(params, "req", None) + _cp_hicache_bs_gt1_debug( + "match_prefix_result", + "rid=%s key_len=%d device_tokens=%d host_hit_length=%d " + "last_device_node=%s last_device_evicted=%s last_device_host_len=%d " + "last_host_node=%s last_host_evicted=%s last_host_host_len=%d " + "deferred_node=%s cp_floor_exact=%s", + getattr(debug_req, "rid", None), + len(key), + len(value), + host_hit_length, + getattr(last_node, "id", None), + getattr(last_node, "evicted", None), + getattr(last_node, "host_len", 0), + getattr(last_host_node, "id", None), + getattr(last_host_node, "evicted", None), + getattr(last_host_node, "host_len", 0), + getattr(deferred_node, "id", None), + getattr(params, "cp_floor_exact", True), + ) + return MatchResult( device_indices=value, last_device_node=last_node, @@ -4003,7 +4180,12 @@ class HiRadixCache(RadixCache): return matched_length def _match_prefix_helper( - self, node: TreeNode, key: RadixKey, *, floor_exact_key: bool = True + self, + node: TreeNode, + key: RadixKey, + *, + floor_exact_key: bool = True, + debug_req_id: Optional[str] = None, ): node.last_access_time = time.monotonic() child_key = self.get_child_key_fn(key) @@ -4021,6 +4203,7 @@ class HiRadixCache(RadixCache): raw_prefix_len, len(key), floor_exact_key=floor_exact_key, + debug_req_id=debug_req_id, ) stop_after_page_floor = prefix_len != raw_prefix_len prune_stale_tail_after_split = stop_after_page_floor diff --git a/python/sglang/srt/mem_cache/radix_cache.py b/python/sglang/srt/mem_cache/radix_cache.py index 35b6513ef..685233bfe 100644 --- a/python/sglang/srt/mem_cache/radix_cache.py +++ b/python/sglang/srt/mem_cache/radix_cache.py @@ -31,6 +31,8 @@ from typing import TYPE_CHECKING, Any, Iterator, List, Optional, Tuple, Union import torch +from sglang.srt.environ import envs + logger = logging.getLogger(__name__) from sglang.srt.disaggregation.kv_events import ( @@ -66,6 +68,41 @@ from sglang.srt.mem_cache.hicache_storage import get_hash_str, hash_str_to_int64 if TYPE_CHECKING: from sglang.srt.managers.schedule_batch import Req +_CP_SHARED_KV_RADIX_DEBUG_COUNTS: dict[str, int] = {} + + +def _cp_shared_kv_radix_debug( + key: str, + message: str, + *args, + limit: int | None = None, +) -> None: + if not envs.SGLANG_CP_SHARED_KV_BS_GT1_DEBUG.get(): + return + if limit is None: + limit = int(envs.SGLANG_CP_SHARED_KV_BS_GT1_DEBUG_LIMIT.get()) + count = _CP_SHARED_KV_RADIX_DEBUG_COUNTS.get(key, 0) + if limit > 0 and count >= limit: + return + _CP_SHARED_KV_RADIX_DEBUG_COUNTS[key] = count + 1 + logger.info("[CP_SHARED_KV_BS_GT1_DEBUG][radix] event=%s " + message, key, *args) + + +def _cp_shared_kv_page_head_for_debug( + locs: torch.Tensor | None, + *, + page_size: int, + max_items: int = 8, +) -> list[int] | None: + if locs is None: + return None + if page_size <= 0 or locs.numel() == 0: + return [] + pages = locs[::page_size] + if pages.numel() == 0: + return [] + return (pages[:max_items].detach().to("cpu", non_blocking=False) // page_size).tolist() + class RadixKey: def __init__( @@ -650,6 +687,24 @@ class RadixCache(BasePrefixCache): values = kv_indices[: len(keys)].to(dtype=torch.int64, copy=True) radix_key = RadixKey(keys, req.extra_key, is_bigram=self.is_eagle) prepared_cp_backup = getattr(req, "cp_hicache_prepared_backup", None) + if getattr(self, "_uses_cp_hicache", False): + _cp_shared_kv_radix_debug( + "unfinished_pre_insert", + "rid=%s chunked=%s key_len=%d kv_len=%d cache_protected_len=%d " + "req_pool_idx=%s value_pages=%s kv_pages=%s prefix_pages=%s", + getattr(req, "rid", None), + chunked, + len(keys), + int(kv_indices.numel()), + int(getattr(req, "cache_protected_len", 0) or 0), + getattr(req, "req_pool_idx", None), + _cp_shared_kv_page_head_for_debug(values, page_size=self.page_size), + _cp_shared_kv_page_head_for_debug(kv_indices, page_size=self.page_size), + _cp_shared_kv_page_head_for_debug( + getattr(req, "prefix_indices", None), page_size=self.page_size + ), + limit=160, + ) # Radix Cache takes one ref in memory pool result = self.insert( @@ -706,11 +761,46 @@ class RadixCache(BasePrefixCache): match_result.last_device_node, ) assert len(new_indices) == len(keys), f"{len(new_indices)=}, {len(keys)=}" + if getattr(self, "_uses_cp_hicache", False): + _cp_shared_kv_radix_debug( + "unfinished_post_match", + "rid=%s chunked=%s key_len=%d old_cache_protected_len=%d " + "new_indices_len=%d new_node=%s new_pages=%s kv_pages_before=%s", + getattr(req, "rid", None), + chunked, + len(keys), + int(getattr(req, "cache_protected_len", 0) or 0), + int(new_indices.numel()), + getattr(new_last_node, "id", None), + _cp_shared_kv_page_head_for_debug( + new_indices, page_size=self.page_size + ), + _cp_shared_kv_page_head_for_debug(kv_indices, page_size=self.page_size), + limit=160, + ) self.req_to_token_pool.write( (req.req_pool_idx, slice(req.cache_protected_len, len(new_indices))), new_indices[req.cache_protected_len :], ) + if getattr(self, "_uses_cp_hicache", False): + final_kv_indices = self.req_to_token_pool.req_to_token[ + req.req_pool_idx, : len(token_ids) + ] + _cp_shared_kv_radix_debug( + "unfinished_post_write", + "rid=%s chunked=%s key_len=%d cache_protected_len=%d " + "final_kv_len=%d final_pages=%s", + getattr(req, "rid", None), + chunked, + len(keys), + int(getattr(req, "cache_protected_len", 0) or 0), + int(final_kv_indices.numel()), + _cp_shared_kv_page_head_for_debug( + final_kv_indices, page_size=self.page_size + ), + limit=160, + ) # The cache_protected_len is not always equal to len(req.prefix_indices) # since for page_size > 1, the partial part is added to req.prefix_indices, but that part of kv indices is not added to the tree.