From e6864fbea740630fdc1517feebcd023262f6d96c Mon Sep 17 00:00:00 2001 From: leavelet Date: Wed, 10 Jun 2026 05:10:45 +0000 Subject: [PATCH] Demote HiCache/CacheCtrl per-op logs from info to debug The [HiCache-write]/[HiCache-load]/[HiCache-collective] and [CacheCtrl-write] per-operation logs fired at INFO on the scheduler thread during serving (every write-through, load-back, ack release, and rate-limited collective summary), eating into stream gaps. Demote all 29 to debug; one-time [HiCache-draft] init logs stay INFO and genuine failures stay WARNING (write_backup CP FAILED after deterministic retry). Also repair TestHiCacheEvictLoggingLevels, which asserted markers that no longer exist in this tree (stale list, failing on the pristine branch): pin the current hot-path markers as debug-only and extend the check to cache_controller. Co-Authored-By: Claude Fable 5 --- .../sglang/srt/managers/cache_controller.py | 20 +++++----- python/sglang/srt/mem_cache/hiradix_cache.py | 38 +++++++++---------- .../mem_cache/test_cp_hicache_metadata.py | 32 ++++++++++------ 3 files changed, 50 insertions(+), 40 deletions(-) diff --git a/python/sglang/srt/managers/cache_controller.py b/python/sglang/srt/managers/cache_controller.py index 5d366f610..c86510eb0 100644 --- a/python/sglang/srt/managers/cache_controller.py +++ b/python/sglang/srt/managers/cache_controller.py @@ -825,7 +825,7 @@ class HiCacheController: """ Back up KV caches from device memory to host memory. """ - logger.info( + logger.debug( "[CacheCtrl-write] write: node_id=%d len=%d cp=%s", node_id, len(device_indices), @@ -836,7 +836,7 @@ class HiCacheController: host_indices = self.mem_pool_host.alloc(len(device_indices)) if host_indices is None: - logger.info( + logger.debug( "[CacheCtrl-write] write non-CP FAILED (host full): node_id=%d len=%d", node_id, len(device_indices), @@ -850,7 +850,7 @@ class HiCacheController: CacheOperation(host_indices, device_indices, node_id, priority) ) self.start_writing() - logger.info( + logger.debug( "[CacheCtrl-write] write non-CP submitted: node_id=%d len=%d", node_id, len(device_indices), @@ -976,7 +976,7 @@ class HiCacheController: dtype=torch.int8, device="cpu" ) if owned_positions.numel() == 0: - logger.info( + logger.debug( "[CacheCtrl-write] reserve_write_cp zero-owned rank: node_id=%d logical_len=%d", node_id, logical_len, @@ -1008,7 +1008,7 @@ class HiCacheController: ) host_indices = host_alloc(len(physical_device_indices)) if host_indices is None: - logger.info( + logger.debug( "[CacheCtrl-write] reserve_write_cp FAILED (host full): node_id=%d logical_len=%d owned=%d", node_id, logical_len, @@ -1026,7 +1026,7 @@ class HiCacheController: draft_host_indices = draft_host_alloc(len(physical_device_indices)) if draft_host_indices is None: self.mem_pool_host.free(host_indices) - logger.info( + logger.debug( "[CacheCtrl-write] reserve_write_cp FAILED (draft host full): node_id=%d logical_len=%d owned=%d", node_id, logical_len, @@ -1082,7 +1082,7 @@ class HiCacheController: ) if len(reservation.physical_device_indices) == 0: self._append_completed_write_ack(reservation.node_id) - logger.info( + logger.debug( "[CacheCtrl-write] submit_write_cp_all_layer zero-owned ack: node_id=%d logical_len=%d", reservation.node_id, reservation.metadata.logical_len, @@ -1107,7 +1107,7 @@ class HiCacheController: ) ) self.start_writing() - logger.info( + logger.debug( "[CacheCtrl-write] submit_write_cp_all_layer submitted: node_id=%d logical_len=%d owned=%d physical=%d draft=%s", reservation.node_id, reservation.metadata.logical_len, @@ -1198,7 +1198,7 @@ class HiCacheController: self.ack_write_queue.append( HiCacheAck(state.start_event, state.finish_event, [reservation.node_id]) ) - logger.info( + logger.debug( "[CacheCtrl-write] submit_write_cp_layer final ack: node_id=%d logical_len=%d layers=%d draft=%s", reservation.node_id, reservation.metadata.logical_len, @@ -1394,7 +1394,7 @@ class HiCacheController: state = self._get_or_create_layer_write_state(reservation) if not catch_up_all_layers: - logger.info( + logger.debug( "[CacheCtrl-write] submit_write_cp_per_layer registered: node_id=%d logical_len=%d layers=%d draft=%s", reservation.node_id, reservation.metadata.logical_len, diff --git a/python/sglang/srt/mem_cache/hiradix_cache.py b/python/sglang/srt/mem_cache/hiradix_cache.py index f409ea415..f67ac56aa 100644 --- a/python/sglang/srt/mem_cache/hiradix_cache.py +++ b/python/sglang/srt/mem_cache/hiradix_cache.py @@ -692,7 +692,7 @@ class HiRadixCache(RadixCache): count = stats["count"] if count == 1 or count % 128 == 0 or elapsed_ms >= 10.0: - logger.info( + logger.debug( "[HiCache-collective] tag=%s count=%d total_ms=%.3f avg_ms=%.3f max_ms=%.3f last_ms=%.3f", tag, count, @@ -2252,7 +2252,7 @@ class HiRadixCache(RadixCache): locked=True, ) prepared.attached = True - logger.info( + logger.debug( "[HiCache-write] attached prepared CP backup: node_id=%d logical_len=%d owned_positions=%d pending_backups=%d", node.id, prepared.logical_len, @@ -2286,7 +2286,7 @@ class HiRadixCache(RadixCache): removed_ack = True if removed_ack: self.cache_controller.ack_write_queue = retained_acks - logger.info( + logger.debug( "[HiCache-write] rollback unattached prepared CP backup: node_id=%d logical_len=%d reason=%s", prepared.node_id, prepared.logical_len, @@ -2654,7 +2654,7 @@ class HiRadixCache(RadixCache): metadata=result.metadata, logical_len=len(kv_indices), ) - logger.info( + logger.debug( "[HiCache-write] prepared CP per-layer backup before forward: node_id=%d rid=%s logical_len=%d owned_positions=%d", node_id, getattr(req, "rid", ""), @@ -2748,7 +2748,7 @@ class HiRadixCache(RadixCache): return node.host_value def write_backup(self, node: TreeNode, write_back=False): - logger.info( + logger.debug( "[HiCache-write] write_backup triggered: node_id=%d len=%d cp=%s write_back=%s", node.id, len(node.value) if node.value is not None else 0, @@ -2790,7 +2790,7 @@ class HiRadixCache(RadixCache): self.ongoing_write_through.pop(node.id, None) self._rollback_pending_backup(node.id) raise - logger.info( + logger.debug( "[HiCache-write] write_backup CP SUBMITTED: node_id=%d logical_len=%d owned_positions=%d ongoing_writes=%d pending_backups=%d", node.id, len(node.value), @@ -2805,7 +2805,7 @@ class HiRadixCache(RadixCache): node_id=node.id, ) if host_indices is None: - logger.info( + logger.debug( "[HiCache-write] write_backup non-CP retry after host eviction: node_id=%d len=%d", node.id, len(node.value) if node.value is not None else 0, @@ -2826,14 +2826,14 @@ class HiRadixCache(RadixCache): # parents with non-evicted children), so path locking is # unnecessary and would over-reduce evictable_size_. self.inc_node_lock_ref(node) - logger.info( + logger.debug( "[HiCache-write] write_backup non-CP SUCCESS: node_id=%d len=%d ongoing_writes=%d", node.id, len(host_indices), len(self.ongoing_write_through), ) else: - logger.info( + logger.debug( "[HiCache-write] write_backup non-CP FAILED (host full): node_id=%d len=%d", node.id, len(node.value) if node.value is not None else 0, @@ -2866,7 +2866,7 @@ class HiRadixCache(RadixCache): if not self._node_backuped(node): if node.hit_count >= self.write_through_threshold: - logger.info( + logger.debug( "[HiCache-write] _inc_hit_count triggering write_through: node_id=%d hit_count=%d threshold=%d len=%d", node.id, node.hit_count, @@ -2971,7 +2971,7 @@ class HiRadixCache(RadixCache): self.write_backup_storage(backuped_node) finish_count -= 1 if released_nodes: - logger.info( + logger.debug( "[HiCache-write] writing_check released %d write locks: node_ids=%s remaining_ongoing=%d", len(released_nodes), released_nodes, @@ -3502,7 +3502,7 @@ class HiRadixCache(RadixCache): self.dec_lock_ref(ancester_node) raise host_hit_len = load_back_plan.host_hit_len - logger.info( + logger.debug( "[HiCache-load] load_back CP: node_id=%d nodes_to_load=%d " "host_hit_len=%d threshold=%d required_by_owner=%s " "available_by_owner=%s deficit_by_owner=%s " @@ -3521,7 +3521,7 @@ class HiRadixCache(RadixCache): ): # skip loading back if the total size is too small or exceeding the memory quota self.dec_lock_ref(ancester_node) - logger.info( + logger.debug( "[HiCache-load] load_back CP SKIP: host_hit_len=%d below threshold=%d or over quota", host_hit_len, self.load_back_threshold, @@ -3620,7 +3620,7 @@ class HiRadixCache(RadixCache): len(device_indices) ) - logger.info( + logger.debug( "[HiCache-load] load_back CP SUCCESS: node_id=%d loaded_tokens=%d physical_tokens=%d", last_hit_node.id, len(device_indices), @@ -3662,7 +3662,7 @@ class HiRadixCache(RadixCache): # load it all or not at all host_indices = torch.cat([n.host_value for n in nodes_to_load]) - logger.info( + logger.debug( "[HiCache-load] load_back non-CP: node_id=%d nodes_to_load=%d host_hit_len=%d threshold=%d", last_hit_node.id, len(nodes_to_load), @@ -3674,7 +3674,7 @@ class HiRadixCache(RadixCache): ): # skip loading back if the total size is too small or exceeding the memory quota self.dec_lock_ref(ancester_node) - logger.info( + logger.debug( "[HiCache-load] load_back non-CP SKIP: host_hit_len=%d below threshold=%d or over quota", len(host_indices), self.load_back_threshold, @@ -3685,7 +3685,7 @@ class HiRadixCache(RadixCache): host_indices=host_indices, node_id=last_hit_node.id ) if device_indices is None: - logger.info( + logger.debug( "[HiCache-load] load_back non-CP retry with eviction: node_id=%d tokens_needed=%d", last_hit_node.id, len(host_indices), @@ -3720,7 +3720,7 @@ class HiRadixCache(RadixCache): ) self.metrics_collector.increment_load_back_num_tokens(len(device_indices)) - logger.info( + logger.debug( "[HiCache-load] load_back non-CP SUCCESS: node_id=%d loaded_tokens=%d", last_hit_node.id, len(device_indices), @@ -3762,7 +3762,7 @@ class HiRadixCache(RadixCache): self.writing_check() ongoing_after = len(self.ongoing_write_through) if ongoing_before > 0: - logger.info( + logger.debug( "[HiCache-write] flush_write_through_acks: before=%d after=%d", ongoing_before, ongoing_after, 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 b0ed171ae..8677c0e4a 100644 --- a/test/registered/unit/mem_cache/test_cp_hicache_metadata.py +++ b/test/registered/unit/mem_cache/test_cp_hicache_metadata.py @@ -152,20 +152,30 @@ class TestHiCacheEvictLoggingLevels(CustomTestCase): self.assert_debug_marker(common_source, marker) for marker in ( - "[HiCache-load] owner-lane device eviction before CP load-back: ", - "[HiCache-evict] owner-lane evict found no contributing victims: ", - "[HiCache-evict] owner-lane evict victim no longer evictable: ", - "[HiCache-evict] owner-lane evict END: requested_tokens=%d ", - "[HiCache-evict] deterministic CP host eviction before write: ", - "[HiCache-write] write_backup CP retry after deterministic host eviction: ", - "[HiCache-evict] evict START:", - "[HiCache-evict] evict END:", - "[HiCache-evict] _evict_backuped:", - "[HiCache-evict] _evict_regular:", - "[HiCache-evict] _evict_host_for_physical_slots:", + "[HiCache-write] write_backup triggered: node_id=%d", + "[HiCache-write] write_backup CP SUBMITTED: node_id=%d", + "[HiCache-write] write_backup non-CP SUCCESS: node_id=%d", + "[HiCache-write] write_backup non-CP FAILED (host full): node_id=%d", + "[HiCache-write] _inc_hit_count triggering write_through: node_id=%d", + "[HiCache-write] writing_check released %d write locks:", + "[HiCache-load] load_back CP: node_id=%d", + "[HiCache-load] load_back CP SUCCESS: node_id=%d", + "[HiCache-load] load_back non-CP SUCCESS: node_id=%d", + "[HiCache-collective] tag=%s", ): self.assert_debug_marker(hiradix_source, marker) + import sglang.srt.managers.cache_controller as cache_controller_mod + + cache_controller_source = inspect.getsource(cache_controller_mod) + for marker in ( + "[CacheCtrl-write] write: node_id=%d", + "[CacheCtrl-write] write non-CP submitted: node_id=%d", + "[CacheCtrl-write] submit_write_cp_all_layer submitted: node_id=%d", + "[CacheCtrl-write] submit_write_cp_layer final ack: node_id=%d", + ): + self.assert_debug_marker(cache_controller_source, marker) + self.assertRegex( hiradix_source, r"logger\.warning\(\s*\n\s*\"\[HiCache-write\] write_backup CP FAILED after deterministic retry:",