chenchenghao/sglang
1
0
Fork 0
Code Issues Pull Requests Actions 11 Packages Projects Releases Wiki Activity

Demote HiCache/CacheCtrl per-op logs from info to debug

Browse Source 
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 <noreply@anthropic.com>
This commit is contained in:
孙远航
2026-06-10 05:10:45 +00:00
parent d221212565
commit e6864fbea7
3 changed files with 50 additions and 40 deletions
Download Patch File Download Diff File Expand all files Collapse all files

20
python/sglang/srt/managers/cache_controller.py
View File

@@ -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,

38
python/sglang/srt/mem_cache/hiradix_cache.py
View File

@@ -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", "<unknown>"),
@@ -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,

32
test/registered/unit/mem_cache/test_cp_hicache_metadata.py
View File

@@ -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:",