diff --git a/docs/advanced_features/nsa_prefill_cp_page_aligned_cache_contract.md b/docs/advanced_features/nsa_prefill_cp_page_aligned_cache_contract.md index cafcdcee9..ecdd19550 100644 --- a/docs/advanced_features/nsa_prefill_cp_page_aligned_cache_contract.md +++ b/docs/advanced_features/nsa_prefill_cp_page_aligned_cache_contract.md @@ -2323,3 +2323,190 @@ Interpretation: - Do not use this process to judge C48. - If the earlier held-slot fix was active in this process, low accept length is not fully explained by missing EAGLE metadata lifetime alone; next investigation should compare a fresh C48 runtime and then inspect EAGLE state correctness/content, not just tensor presence. + +### C50. 2026-05-30 output_len=0 is confirmed by router/client; server-side checked points + +New user-provided fact: + +- `output_len=0` has been confirmed from router/client logs. Treat it as a + real external symptom even if the currently inspected SGLang server logs do + not print full response bodies. + +Server-side evidence checked so far: + +- The latest valid decode logs around the previous failure window contain a + burst of `Decode transfer failed ... Aborted by AbortReq` at + `2026-05-29 21:01:40`, and the paired prefill log contains matching + `Prefill bootstrap failed` / `Prefill transfer failed` aborts at + `2026-05-29 21:01:41`. +- A request aborted before any decoded token can produce a zero-length final + output at the scheduler boundary (`stream_output_generation()` reports + `completion_tokens=len(req.output_ids_through_stop)`). The OpenAI serving + layer should normally convert scheduler abort finish reasons to HTTP errors, + so a client-observed successful empty response still needs a request-id/rid + correlation or a server-side zero-output warning to determine whether the + empty result is `abort`, `length=0`, stop-trimming, or router/client handling. +- The newer prefill process PID `2763878` started at `2026-05-30 05:01:46 CST` + from the synced code, but at the time of this check it was still in startup / + weight-load/warmup logs (`sglang_cp_hicache_20260529_210146.log`). It cannot + yet validate whether C48/C49 fixed or changed the output-len symptom. + +Do-not-repeat: + +- Do not conclude “server did not output zero” only because the SGLang log does + not contain `completion_tokens=0`; those bodies are usually not logged. +- Do not treat router `Prefill server failed (CRITICAL)` as an independent + router bug when it aligns with prefill/decode KV-transfer aborts. + +Next useful evidence: + +- Add a low-frequency/anomaly-only server warning at the scheduler output + boundary for finished generation responses with `completion_tokens == 0`, + including `rid`, `finish_reason`, `max_new_tokens`, `origin_len`, cached + tokens, disaggregation mode, and bootstrap room. This should fire only on the + confirmed anomalous path and should be removed or gated after root cause is + found. + +### C51. 2026-05-30 split hypothesis for output_len=0 + +New user-provided hypothesis: + +- `output_len=0` may be caused by a split path. + +Checked points: + +- There are two distinct split mechanisms in the current failure surface: + 1. NSA in-seq CP split (`can_cp_split()` / `build_page_aligned_in_seq_split_list()`), + which affects forward compute distribution. + 2. Radix/HiCache tree split (`HiRadixCache._split_node()`), which affects + device/host cache residency and prefix matching. +- C24 already disables NSA in-seq CP split for cache-hit suffixes with fewer + physical suffix pages than CP lanes. This removes the known `extend_len=65` + mostly-zero-lane split path, but it does not address long suffixes or radix + structural splits. +- Current radix exact-valid-tail extension handling floors the matched prefix + to the previous page boundary. During insertion it then splits the old + valid-tail node and can leave two children under the same page-boundary parent + whose keys start at the same logical tail page, e.g. with `page_size=4`: + old child `(4, 5)` and new longer child `(4, 5, 6, 7)`. +- This overlapping-child shape is not yet proven to produce `output_len=0`, but + it is a real radix invariant risk: two children can represent overlapping + logical token ranges with independent device/host/draft HiCache state. Under + eviction/load-back or EAGLE target/draft mirror pressure, that can create + target/draft cache-state divergence or unnecessary transfer/abort pressure. +- The latest inspected runtime did not include the new `OUTPUT_ZERO_DEBUG` + scheduler boundary warning, so server-side classification of confirmed + client/router `output_len=0` is still pending a fresh process. Existing logs + still show the direct zero-output-compatible server symptom as large bursts of + prefill/decode `KVTransferError(...): Aborted by AbortReq` followed by decode + losing the prefill connection. + +Next checks: + +- Add a focused radix regression that demonstrates the overlapping-child shape + for exact valid-tail extension and then replace it with a page-granular policy + that sacrifices the old sub-page tail instead of keeping two overlapping + children. +- Keep the scheduler `OUTPUT_ZERO_DEBUG` anomaly warning until a fresh runtime + confirms whether client/router `output_len=0` corresponds to abort, + max_new_tokens=0/length finish, stop trimming, or another finish reason. + +### C52. 2026-05-30 exact valid-tail split currently preserves stale sub-page child + +Finding: + +- The existing focused unit test `test_cp_insert_extends_from_page_boundary_after_exact_valid_tail` + encodes the risky behavior from C51 as expected behavior: after an old valid-tail + CP node `(0..5)` is extended by a new request `(0..9)`, the radix tree keeps both + the stale old child `(4,5)` and the new longer child `(4,5,6,7,8,9)` under the + page-boundary parent `(0..3)`. +- This violates the page-granular cache contract we now want for CP HiCache: a + logical sub-page tail is not an independent cache-management unit once a request + extends beyond it. The old tail page should be sacrificed/freed, and the new + suffix should own that page from the boundary. + +Next implementation guardrail: + +- Add/adjust the regression first so the expected tree has only the new suffix + child after exact-valid-tail extension. Then implement a narrow CP-only prune + path for the stale tail child, with pending/in-flight backup split still fail-fast + or deferred instead of silently mutating an in-flight node. + +### C53. 2026-05-30 stale-tail pruning must cover backed partial-tail splits too + +Finding: + +- The exact-valid-tail extension case is only one instance of the same bug. + `test_cp_insert_floors_backed_tail_split_to_page_boundary` shows a backed CP + HiCache node `(0..5)` split by a shorter/new partial request `(0..4)`. The old + test also preserved the stale child `(4,5)` beside the new child `(4)`, creating + the same overlapping-page state. +- Therefore the prune condition cannot be limited to exact valid-tail extension. + Whenever CP split length is floored from inside a valid/padded tail page to the + previous page boundary, the stale tail subtree created by `_split_node()` must + be pruned unless it is protected or has an in-flight backup. + +Guardrail: + +- Probe-only paths may continue to floor without mutating. Mutating match/insert + paths must prune stale tails after page-floor split; protected/in-flight tails + must defer/fail rather than silently keeping overlapping children. + +### C54. 2026-05-30 stale CP tail pruning implemented and tested + +Implemented: + +- CP mutating radix match/insert paths now detect when a split length was floored + from inside a page to the previous page boundary. +- After `_split_node()` creates the page-boundary parent, the stale sub-page tail + subtree is pruned instead of being kept as an overlapping child. This applies + both to exact valid-tail extension and backed partial-tail split cases. +- The prune path first checks the stale subtree for lock refs, host refs, pending + backup, or ongoing write-through state. Such in-flight/protected tails defer + or fail via the existing pending-split path rather than silently mutating cache + state used by active work. +- Pruning frees device indices and CP host/draft metadata when the corresponding + cache-controller eviction hooks are available, then unlinks the stale subtree + and refreshes leaf state when the cache was fully initialized. + +Verification: + +- Remote py_compile passed for `python/sglang/srt/mem_cache/hiradix_cache.py` and + `python/sglang/srt/managers/scheduler_output_processor_mixin.py` in container + `/sgl-workspace/sglang-tai`. +- Remote targeted red tests first failed on the old overlapping-child behavior. +- Remote full focused suite passed after the fix: + `PYTHONPATH=python python -m pytest -q test/registered/unit/mem_cache/test_cp_hicache_metadata.py` + -> `97 passed, 5 warnings`. + +Remaining risk: + +- This removes one concrete split-induced overlapping-cache invariant violation, + but it does not yet prove the external `output_len=0` symptom is fixed. A fresh + ETE run still needs to check for `[OUTPUT_ZERO_DEBUG]`, decode accept length, + and router/client zero-output correlation. + +### C55. 2026-05-30 latest split-prune runtime: zero-output not seen in server logs, EAGLE accept still collapsed + +Runtime identity: + +- New prefill process on `g0034` PID `2796105` started at `2026-05-30 05:36:48 CST`, after the split-prune and `OUTPUT_ZERO_DEBUG` source sync (`05:33-05:34 CST`). +- Decode processes on `g0035`/`g0036` started at `05:36:52/05:36:55 CST` and see the same synced source mtimes. +- Latest logs inspected: + - prefill: `/mnt/beegfs/cjy/log/sglang_cp_hicache_20260529_213648.log` + - decode0: `/mnt/beegfs/cjy/log/decode0_20260529_213652.log` + - decode1: `/mnt/beegfs/cjy/log/decode1_20260529_213656.log` + +Checked result: + +- No `[OUTPUT_ZERO_DEBUG]` line was found in prefill/decode logs, and no server-side `completion_tokens: 0` / `output_len=0` text was found in these logs. This does not prove the router/client symptom is gone, but the scheduler boundary did not observe a finished generation with zero visible tokens in the inspected log window. +- No current prefill/decode `KVTransferError`, transfer abort burst, traceback, health-check failure, or scheduler exception was found in this log window. The only `out of memory` text was warmup max_m reduction, not runtime OOM. +- EAGLE accept remains bad in the inspected decode logs: + - decode0: `17649` accept-debug rows, average `avg_accept=0.073`, median `0.0`, `15650` zero rows, `17544` rows at `<=1.05`; last 200 rows average `0.135`. + - decode1: `17541` accept-debug rows, average `avg_accept=0.065`, median `0.0`, `15569` zero rows, `17495` rows at `<=1.05`; last 200 rows average `0.030`. +- Metadata presence is not missing in the samples: `has_pd_hidden=True`, `pd_hidden_shape=(6144,)`, `pd_topk_shape=(16,)`, no `has_pd_hidden=False` / `pd_topk_shape=None` lines. `spec_topk_shape=(0,1)` appears occasionally but is not the dominant count; most rows have `(1,1)` or `(2,1)`. + +Interpretation: + +- Split-prune removes a real overlapping-radix invariant violation, but it did not recover EAGLE accept length in this run. +- The current accept collapse is more likely in the semantic correctness/content of EAGLE prebuilt state or draft/target KV alignment than in missing metadata lifetime or gross transfer failure. Next debugging should compare the actual prebuilt top-k token/content and draft input state against a non-HiCache or non-CP baseline, not just tensor shape/presence. diff --git a/python/sglang/srt/managers/scheduler_output_processor_mixin.py b/python/sglang/srt/managers/scheduler_output_processor_mixin.py index 5ab6661f4..ec021482b 100644 --- a/python/sglang/srt/managers/scheduler_output_processor_mixin.py +++ b/python/sglang/srt/managers/scheduler_output_processor_mixin.py @@ -1140,6 +1140,28 @@ class SchedulerOutputProcessorMixin: # Exclude the tokens after stop condition output_ids_ = req.output_ids_through_stop + if req.finished() and len(output_ids_) == 0: + logger.warning( + "[OUTPUT_ZERO_DEBUG] finished generation with zero visible " + "tokens: rid=%s finish_reason=%s max_new_tokens=%s " + "origin_len=%s raw_output_len=%s finished_len=%s " + "send_token_offset=%s cached_tokens=%s disaggregation_mode=%s " + "bootstrap_room=%s", + getattr(req, "rid", None), + ( + req.finished_reason.to_json() + if req.finished_reason is not None + else None + ), + getattr(req.sampling_params, "max_new_tokens", None), + len(getattr(req, "origin_input_ids", []) or []), + len(getattr(req, "output_ids", []) or []), + getattr(req, "finished_len", None), + send_token_offset, + getattr(req, "cached_tokens", None), + getattr(self, "disaggregation_mode", None), + getattr(req, "bootstrap_room", None), + ) req.send_decode_id_offset = len(decode_ids) read_offsets.append(read_offset) diff --git a/python/sglang/srt/mem_cache/hiradix_cache.py b/python/sglang/srt/mem_cache/hiradix_cache.py index 53adf4313..d5f7898f4 100644 --- a/python/sglang/srt/mem_cache/hiradix_cache.py +++ b/python/sglang/srt/mem_cache/hiradix_cache.py @@ -2157,6 +2157,98 @@ class HiRadixCache(RadixCache): return prefix_len return floor_to_page_len(prefix_len, self.page_size) + def _cp_subtree_has_unprunable_state(self, node: TreeNode) -> bool: + stack = [node] + while stack: + current = stack.pop() + if ( + current.lock_ref > 0 + or current.host_ref_counter > 0 + or self._node_host_write_pending(current) + ): + return True + stack.extend(current.children.values()) + return False + + def _cp_prune_stale_tail_after_page_floor( + self, parent: TreeNode, stale_tail: TreeNode + ) -> None: + """Drop a sub-page CP tail after flooring an extending request to a page. + + CP HiCache owns KV at page granularity. If a cached key ends inside a + page and a later request extends past that valid tail, the old sub-page + child must not remain as an independent radix child beside the new + page-boundary suffix. Keeping both creates overlapping children for the + same physical page. We sacrifice the old tail page and let the new + request re-own that page from the boundary. + """ + + if not self._uses_cp_hicache: + return + if stale_tail.parent is not parent: + raise RuntimeError( + "CP HiCache stale-tail prune saw a detached split child: " + f"parent_id={getattr(parent, 'id', None)} " + f"tail_id={getattr(stale_tail, 'id', None)}" + ) + if self._cp_subtree_has_unprunable_state(stale_tail): + raise HiCachePendingBackupSplit(stale_tail) + self._cp_delete_stale_tail_subtree(stale_tail) + + def _cp_delete_stale_tail_subtree(self, node: TreeNode) -> None: + for child in list(node.children.values()): + self._cp_delete_stale_tail_subtree(child) + + parent = node.parent + if parent is None: + raise RuntimeError( + "CP HiCache stale-tail prune attempted to delete a root node" + ) + + device_resident_len = self._node_device_resident_len(node) + if hasattr(self, "evictable_leaves") and node in self.evictable_leaves: + self.evictable_leaves.remove(node) + if hasattr(self, "evictable_size_"): + self.evictable_size_ -= device_resident_len + if hasattr(self, "evictable_host_leaves") and node in self.evictable_host_leaves: + self.evictable_host_leaves.remove(node) + + if node.value is not None: + self._record_remove_event(node) + cache_controller = getattr(self, "cache_controller", None) + if cache_controller is not None and hasattr(cache_controller, "evict_device"): + cache_controller.evict_device(node.value) + elif cache_controller is not None and hasattr( + cache_controller, "mem_pool_device_allocator" + ): + cache_controller.mem_pool_device_allocator.free(node.value) + node.value = None + + if node.cp_hicache is not None: + cache_controller = getattr(self, "cache_controller", None) + if cache_controller is not None and hasattr(cache_controller, "evict_cp_host"): + cache_controller.evict_cp_host(node.cp_hicache) + node.cp_hicache = None + node.host_len = 0 + elif node.host_value is not None: + cache_controller = getattr(self, "cache_controller", None) + if cache_controller is not None and hasattr(cache_controller, "evict_host"): + cache_controller.evict_host(node.host_value) + node.host_value = None + node.host_len = 0 + + key = self.get_child_key_fn(node.key) + removed = parent.children.pop(key, None) + if removed is not node: + raise RuntimeError( + "CP HiCache stale-tail prune removed unexpected child: " + f"key={key} node_id={getattr(node, 'id', None)}" + ) + if hasattr(self, "evictable_leaves"): + self._update_leaf_status(parent) + if hasattr(self, "evictable_host_leaves"): + self._update_host_leaf_status(parent) + def prepare_write_backup_for_req(self, req) -> None: if self.disable or not self._uses_cp_hicache: return @@ -3552,10 +3644,12 @@ class HiRadixCache(RadixCache): # Refresh pin TTL on cache hit if self._is_pinned(child): child.pin_expiry = time.monotonic() + child.pin_ttl - prefix_len = self.key_match_fn(child.key, key) + raw_prefix_len = self.key_match_fn(child.key, key) prefix_len = self._cp_floor_exact_valid_tail_extension_len( - child, prefix_len, len(key) + child, raw_prefix_len, len(key) ) + stop_after_page_floor = prefix_len != raw_prefix_len + prune_stale_tail_after_split = stop_after_page_floor if prefix_len <= 0: break if prefix_len < len(child.key): @@ -3569,12 +3663,19 @@ class HiRadixCache(RadixCache): and self.page_size > 1 and prefix_len % self.page_size != 0 ): + unfloored_prefix_len = prefix_len prefix_len = self._cp_floor_backed_partial_split_len( child, prefix_len ) + prune_stale_tail_after_split = ( + prune_stale_tail_after_split + or prefix_len != unfloored_prefix_len + ) if prefix_len == 0: break new_node = self._split_node(child.key, child, prefix_len) + if prune_stale_tail_after_split: + self._cp_prune_stale_tail_after_page_floor(new_node, child) if not new_node.evicted: value.append(new_node.value) node = new_node @@ -3688,12 +3789,20 @@ class HiRadixCache(RadixCache): total_prefix_length += prefix_len else: # partial match, split the node + prune_stale_tail_after_split = stop_after_page_floor + unfloored_prefix_len = prefix_len prefix_len = self._cp_floor_backed_partial_split_len( node, prefix_len ) + prune_stale_tail_after_split = ( + prune_stale_tail_after_split + or prefix_len != unfloored_prefix_len + ) if prefix_len <= 0: break new_node = self._split_node(node.key, node, prefix_len) + if prune_stale_tail_after_split: + self._cp_prune_stale_tail_after_page_floor(new_node, node) # shared-prefix node should also reflect max priority new_node.priority = max(new_node.priority, priority) if new_node.evicted: diff --git a/test/registered/unit/mem_cache/test_cp_hicache_metadata.py b/test/registered/unit/mem_cache/test_cp_hicache_metadata.py index e7d992b08..e502f5f58 100644 --- a/test/registered/unit/mem_cache/test_cp_hicache_metadata.py +++ b/test/registered/unit/mem_cache/test_cp_hicache_metadata.py @@ -2646,11 +2646,7 @@ class TestHiRadixCacheCPLoadBack(CustomTestCase): self.assertEqual(result.last_host_node.host_len, 4) self.assertEqual(result.last_host_node.cp_hicache.logical_len, 4) self.assertEqual(result.last_host_node.cp_hicache.padded_len, 4) - child = result.last_host_node.children[(4, 5)] - self.assertEqual(child.key.token_ids, [4, 5]) - self.assertEqual(child.host_len, 2) - self.assertEqual(child.cp_hicache.logical_len, 2) - self.assertEqual(child.cp_hicache.padded_len, 4) + self.assertNotIn((4, 5), result.last_host_node.children) def test_cp_backed_tail_split_before_first_page_returns_root_match(self): cache = HiRadixCache.__new__(HiRadixCache) @@ -2790,6 +2786,8 @@ class TestHiRadixCacheCPLoadBack(CustomTestCase): cache.maybe_bigram_convert = lambda key: (key, None) cache._update_leaf_status = lambda node: None cache._update_host_leaf_status = lambda node: None + cache.enable_storage = False + cache.enable_kv_cache_events = False root = TreeNode() root.key = RadixKey([]) root.value = torch.empty((0,), dtype=torch.int64) @@ -2811,7 +2809,7 @@ class TestHiRadixCacheCPLoadBack(CustomTestCase): self.assertEqual(result.device_indices.tolist(), [0, 1, 2, 3]) self.assertEqual(result.host_hit_length, 0) self.assertEqual(result.last_device_node.key.token_ids, [0, 1, 2, 3]) - self.assertEqual(result.last_device_node.children[(4, 5)].key.token_ids, [4, 5]) + self.assertNotIn((4, 5), result.last_device_node.children) def test_cp_insert_floors_backed_tail_split_to_page_boundary(self): cache = HiRadixCache.__new__(HiRadixCache) @@ -2869,10 +2867,7 @@ class TestHiRadixCacheCPLoadBack(CustomTestCase): self.assertEqual(parent.key.token_ids, [0, 1, 2, 3]) self.assertEqual(parent.cp_hicache.logical_len, 4) self.assertEqual(parent.cp_hicache.padded_len, 4) - old_tail = parent.children[(4, 5)] - self.assertEqual(old_tail.key.token_ids, [4, 5]) - self.assertEqual(old_tail.cp_hicache.logical_len, 2) - self.assertEqual(old_tail.cp_hicache.padded_len, 4) + self.assertNotIn((4, 5), parent.children) new_tail = parent.children[(4,)] self.assertEqual(new_tail.key.token_ids, [4]) self.assertEqual(new_tail.value.tolist(), [4]) @@ -2937,7 +2932,7 @@ class TestHiRadixCacheCPLoadBack(CustomTestCase): self.assertEqual(result.prefix_len, 4) parent = root.children[(0, 1, 2, 3)] self.assertEqual(parent.key.token_ids, [0, 1, 2, 3]) - self.assertEqual(parent.children[(4, 5)].key.token_ids, [4, 5]) + self.assertNotIn((4, 5), parent.children) new_tail = parent.children[(4, 5, 6, 7)] self.assertEqual(new_tail.key.token_ids, [4, 5, 6, 7, 8, 9]) self.assertTrue(prepared.attached)