[Bug] Extremely bad HiCache performance in containers

[jiangxiaosheng]

Checklist

• I searched related issues but found no solution.
• The bug persists in the latest version.
• Issues without environment info and a minimal reproducible demo are hard to resolve and may receive no feedback.
• If this is not a bug report but a general question, please start a discussion at https://github.com/sgl-project/sglang/discussions. Otherwise, it will be closed.
• Please use English. Otherwise, it will be closed.

Describe the bug

Enabling HiCache with file storage gives much slower performance.

Background:

I ran benchmark/hicache/bench_long_context.py with KV cache file storage offloading enabled. The directory has all requests already warmed up: the requests were served in earlier runs via the same benchmark suite and all of their KV caches are persisted in that directory. This means in any fresh run, every request will trigger a prefetching from storage to CPU mem pool.

The issue:

I noticed when HiCache + File storage is enabled, the benchmark results got much worse. I then instrumented relevant data path code and found that prefetching became the real bottleneck.

Code change for instrument:

diff --git a/python/sglang/srt/managers/cache_controller.py b/python/sglang/srt/managers/cache_controller.py
index e4f8d0b70..8f1454920 100644
--- a/python/sglang/srt/managers/cache_controller.py
+++ b/python/sglang/srt/managers/cache_controller.py
@@ -833,10 +833,19 @@ class HiCacheController:
 
     # todo: deprecate
     def _generic_page_get(self, operation, hash_values, host_indices, extra_info=None):
+        start_time = time.perf_counter()
         dummy_page_dst = [
             self.mem_pool_host.get_dummy_flat_data_page() for _ in hash_values
         ]
+        end_time = time.perf_counter()
+        alloc_time = end_time - start_time
+
+        start_time = time.perf_counter()
         page_data = self.storage_backend.batch_get(hash_values, dummy_page_dst)
+        end_time = time.perf_counter()
+        io_time = end_time - start_time
+
+        start_time = time.perf_counter()
         if page_data is None:
             return
         for i in range(len(hash_values)):
@@ -853,6 +862,12 @@ class HiCacheController:
             )
             if not operation.increment(self.page_size):
                 break  # Operation terminated by controller
+        end_time = time.perf_counter()
+        copy_time = end_time - start_time
+        logger.info(
+            f"Prefetch operation {operation.request_id} bytes: {len(hash_values) * self.page_size * self.mem_pool_host.size_per_token / 1e6:.2f}MB, "
+            f"alloc time: {alloc_time:.6f}s, io time: {io_time:.6f}s, copy time: {copy_time:.6f}s"
+        )

Server launch command:

SGLANG_LOG_MS=1 python3 -m sglang.launch_server  --model-path meta-llama/Llama-3.1-8B-Instruct --tp 1 --page-size 64 --context-length 65536 --chunked-prefill-size 6144 --mem-fraction-static 0.85  --enable-hierarchical-cache --hicache-ratio 4  --hicache-io-backend kernel --hicache-mem-layout page_first --hicache-storage-backend file --hicache-storage-prefetch-policy wait_complete

Runtime logs (partial):

SGLANG_LOG_MS=1 python3 -m sglang.launch_server  --model-path meta-llama/Llama-3.1-8B-Instruct --tp 1 --page-size 64 --context-length 65536 --chunked-prefill-size 6144 --mem-fraction-static 0.85  --enable-hierarchical-cache --hicache-ratio 4  --hicache-io-backend kernel --hicache-mem-layout page_first --hicache-storage-backend file --hicache-storage-prefetch-policy wait_complete |& tee log.txt
/mnt/code/sglang-latest/python/sglang/launch_server.py:51: UserWarning: 'python -m sglang.launch_server' is still supported, but 'sglang serve' is the recommended entrypoint.
  Example: sglang serve --model-path <model> [options]
  warnings.warn(
/mnt/code/sglang-latest/python/sglang/srt/entrypoints/http_server.py:175: FastAPIDeprecationWarning: ORJSONResponse is deprecated, FastAPI now serializes data directly to JSON bytes via Pydantic when a return type or response model is set, which is faster and doesn't need a custom response class. Read more in the FastAPI docs: https://fastapi.tiangolo.com/advanced/custom-response/#orjson-or-response-model and https://fastapi.tiangolo.com/tutorial/response-model/
  from sglang.srt.utils.json_response import (
[2026-04-01 20:41:54.358] server_args=ServerArgs(model_path='meta-llama/Llama-3.1-8B-Instruct', tokenizer_path='meta-llama/Llama-3.1-8B-Instruct', tokenizer_mode='auto', tokenizer_worker_num=1, skip_tokenizer_init=False, load_format='auto', model_loader_extra_config='{}', trust_remote_code=False, context_length=65536, is_embedding=False, enable_multimodal=None, revision=None, model_impl='auto', host='127.0.0.1', port=30000, fastapi_root_path='', grpc_mode=False, skip_server_warmup=False, warmups=None, nccl_port=None, checkpoint_engine_wait_weights_before_ready=False, ssl_keyfile=None, ssl_certfile=None, ssl_ca_certs=None, ssl_keyfile_password=None, enable_ssl_refresh=False, dtype='auto', quantization=None, quantization_param_path=None, kv_cache_dtype='auto', enable_fp32_lm_head=False, modelopt_quant=None, modelopt_checkpoint_restore_path=None, modelopt_checkpoint_save_path=None, modelopt_export_path=None, quantize_and_serve=False, rl_quant_profile=None, mem_fraction_static=0.85, max_running_requests=None, max_queued_requests=None, max_total_tokens=None, chunked_prefill_size=6144, enable_dynamic_chunking=False, max_prefill_tokens=16384, prefill_max_requests=None, schedule_policy='fcfs', enable_priority_scheduling=False, disable_priority_preemption=False, default_priority_value=None, abort_on_priority_when_disabled=False, schedule_low_priority_values_first=False, priority_scheduling_preemption_threshold=10, schedule_conservativeness=1.0, page_size=64, swa_full_tokens_ratio=0.8, disable_hybrid_swa_memory=False, radix_eviction_policy='lru', enable_prefill_delayer=False, prefill_delayer_max_delay_passes=30, prefill_delayer_token_usage_low_watermark=None, prefill_delayer_forward_passes_buckets=None, prefill_delayer_wait_seconds_buckets=None, device='cuda', tp_size=1, pp_size=1, pp_max_micro_batch_size=None, pp_async_batch_depth=0, stream_interval=1, incremental_streaming_output=False, enable_streaming_session=False, random_seed=516071476, constrained_json_whitespace_pattern=None, constrained_json_disable_any_whitespace=False, watchdog_timeout=300, soft_watchdog_timeout=None, dist_timeout=None, download_dir=None, model_checksum=None, base_gpu_id=0, gpu_id_step=1, sleep_on_idle=False, use_ray=False, custom_sigquit_handler=None, log_level='info', log_level_http=None, log_requests=False, log_requests_level=2, log_requests_format='text', log_requests_target=None, uvicorn_access_log_exclude_prefixes=[], crash_dump_folder=None, show_time_cost=False, enable_metrics=False, enable_metrics_for_all_schedulers=False, tokenizer_metrics_custom_labels_header='x-custom-labels', tokenizer_metrics_allowed_custom_labels=None, extra_metric_labels=None, bucket_time_to_first_token=None, bucket_inter_token_latency=None, bucket_e2e_request_latency=None, collect_tokens_histogram=False, prompt_tokens_buckets=None, generation_tokens_buckets=None, gc_warning_threshold_secs=0.0, decode_log_interval=40, enable_request_time_stats_logging=False, kv_events_config=None, enable_trace=False, otlp_traces_endpoint='localhost:4317', export_metrics_to_file=False, export_metrics_to_file_dir=None, api_key=None, admin_api_key=None, served_model_name='meta-llama/Llama-3.1-8B-Instruct', weight_version='default', chat_template=None, hf_chat_template_name=None, completion_template=None, file_storage_path='sglang_storage', enable_cache_report=False, reasoning_parser=None, tool_call_parser=None, tool_server=None, sampling_defaults='model', dp_size=1, load_balance_method='round_robin', attn_cp_size=1, moe_dp_size=1, dist_init_addr=None, nnodes=1, node_rank=0, json_model_override_args='{}', preferred_sampling_params=None, enable_lora=None, enable_lora_overlap_loading=None, max_lora_rank=None, lora_target_modules=None, lora_paths=None, max_loaded_loras=None, max_loras_per_batch=8, lora_eviction_policy='lru', lora_backend='csgmv', max_lora_chunk_size=16, attention_backend='flashinfer', decode_attention_backend=None, prefill_attention_backend=None, sampling_backend='flashinfer', grammar_backend='xgrammar', mm_attention_backend=None, fp8_gemm_runner_backend='auto', fp4_gemm_runner_backend='auto', nsa_prefill_backend=None, nsa_decode_backend=None, disable_flashinfer_autotune=False, mamba_backend='triton', speculative_algorithm=None, speculative_draft_model_path=None, speculative_draft_model_revision=None, speculative_draft_load_format=None, speculative_num_steps=None, speculative_eagle_topk=None, speculative_num_draft_tokens=None, speculative_accept_threshold_single=1.0, speculative_accept_threshold_acc=1.0, speculative_token_map=None, speculative_attention_mode='prefill', speculative_draft_attention_backend=None, speculative_moe_runner_backend='auto', speculative_moe_a2a_backend=None, speculative_draft_model_quantization=None, speculative_ngram_min_match_window_size=1, speculative_ngram_max_match_window_size=12, speculative_ngram_min_bfs_breadth=1, speculative_ngram_max_bfs_breadth=10, speculative_ngram_match_type='BFS', speculative_ngram_max_trie_depth=18, speculative_ngram_capacity=10000000, enable_multi_layer_eagle=False, ep_size=1, moe_a2a_backend='none', moe_runner_backend='auto', flashinfer_mxfp4_moe_precision='default', enable_flashinfer_allreduce_fusion=False, enable_aiter_allreduce_fusion=False, deepep_mode='auto', ep_num_redundant_experts=0, ep_dispatch_algorithm=None, init_expert_location='trivial', enable_eplb=False, eplb_algorithm='auto', eplb_rebalance_num_iterations=1000, eplb_rebalance_layers_per_chunk=None, eplb_min_rebalancing_utilization_threshold=1.0, expert_distribution_recorder_mode=None, expert_distribution_recorder_buffer_size=1000, enable_expert_distribution_metrics=False, deepep_config=None, moe_dense_tp_size=None, elastic_ep_backend=None, enable_elastic_expert_backup=False, mooncake_ib_device=None, max_mamba_cache_size=None, mamba_ssm_dtype=None, mamba_full_memory_ratio=0.9, mamba_scheduler_strategy='no_buffer', mamba_track_interval=256, linear_attn_backend='triton', linear_attn_decode_backend=None, linear_attn_prefill_backend=None, enable_hierarchical_cache=True, hicache_ratio=4.0, hicache_size=0, hicache_write_policy='write_through', hicache_io_backend='kernel', hicache_mem_layout='page_first', disable_hicache_numa_detect=False, hicache_storage_backend='file', hicache_storage_prefetch_policy='wait_complete', hicache_storage_backend_extra_config=None, enable_hisparse=False, hisparse_config=None, enable_lmcache=False, kt_weight_path=None, kt_method='AMXINT4', kt_cpuinfer=None, kt_threadpool_count=2, kt_num_gpu_experts=None, kt_max_deferred_experts_per_token=None, dllm_algorithm=None, dllm_algorithm_config=None, enable_double_sparsity=False, ds_channel_config_path=None, ds_heavy_channel_num=32, ds_heavy_token_num=256, ds_heavy_channel_type='qk', ds_sparse_decode_threshold=4096, cpu_offload_gb=0, offload_group_size=-1, offload_num_in_group=1, offload_prefetch_step=1, offload_mode='cpu', multi_item_scoring_delimiter=None, disable_radix_cache=False, cuda_graph_max_bs=32, cuda_graph_bs=[1, 2, 4, 8, 12, 16, 24, 32], disable_cuda_graph=False, disable_cuda_graph_padding=False, enable_profile_cuda_graph=False, enable_cudagraph_gc=False, enable_layerwise_nvtx_marker=False, enable_nccl_nvls=False, enable_symm_mem=False, disable_flashinfer_cutlass_moe_fp4_allgather=False, enable_tokenizer_batch_encode=False, disable_tokenizer_batch_decode=False, disable_outlines_disk_cache=False, disable_custom_all_reduce=False, enable_mscclpp=False, enable_torch_symm_mem=False, pre_warm_nccl=False, disable_overlap_schedule=False, enable_mixed_chunk=False, enable_dp_attention=False, enable_dp_lm_head=False, enable_two_batch_overlap=False, enable_single_batch_overlap=False, tbo_token_distribution_threshold=0.48, enable_torch_compile=False, disable_piecewise_cuda_graph=True, enforce_piecewise_cuda_graph=False, enable_torch_compile_debug_mode=False, torch_compile_max_bs=32, piecewise_cuda_graph_max_tokens=6144, piecewise_cuda_graph_tokens=[4, 8, 12, 16, 20, 24, 28, 32, 48, 64, 80, 96, 112, 128, 144, 160, 176, 192, 208, 224, 240, 256, 288, 320, 352, 384, 416, 448, 480, 512, 576, 640, 704, 768, 832, 896, 960, 1024, 1280, 1536, 1792, 2048, 2304, 2560, 2816, 3072, 3328, 3584, 3840, 4096, 4608, 5120, 5632, 6144], piecewise_cuda_graph_compiler='eager', torchao_config='', enable_nan_detection=False, enable_p2p_check=False, triton_attention_reduce_in_fp32=False, triton_attention_num_kv_splits=8, triton_attention_split_tile_size=None, num_continuous_decode_steps=1, delete_ckpt_after_loading=False, enable_memory_saver=False, enable_weights_cpu_backup=False, enable_draft_weights_cpu_backup=False, allow_auto_truncate=False, enable_custom_logit_processor=False, flashinfer_mla_disable_ragged=False, disable_shared_experts_fusion=False, disable_chunked_prefix_cache=False, disable_fast_image_processor=False, keep_mm_feature_on_device=False, enable_return_hidden_states=False, enable_return_routed_experts=False, scheduler_recv_interval=1, numa_node=None, enable_deterministic_inference=False, rl_on_policy_target=None, enable_attn_tp_input_scattered=False, enable_nsa_prefill_context_parallel=False, nsa_prefill_cp_mode='round-robin-split', enable_fused_qk_norm_rope=False, enable_precise_embedding_interpolation=False, enable_fused_moe_sum_all_reduce=False, enable_prefill_context_parallel=False, prefill_cp_mode='in-seq-split', enable_dynamic_batch_tokenizer=False, dynamic_batch_tokenizer_batch_size=32, dynamic_batch_tokenizer_batch_timeout=0.002, debug_tensor_dump_output_folder=None, debug_tensor_dump_layers=None, debug_tensor_dump_input_file=None, debug_tensor_dump_inject=False, disaggregation_mode='null', disaggregation_transfer_backend='mooncake', disaggregation_bootstrap_port=8998, disaggregation_ib_device=None, disaggregation_decode_enable_offload_kvcache=False, num_reserved_decode_tokens=512, disaggregation_decode_polling_interval=1, encoder_only=False, language_only=False, encoder_transfer_backend='zmq_to_scheduler', encoder_urls=[], enable_adaptive_dispatch_to_encoder=False, custom_weight_loader=[], weight_loader_disable_mmap=False, remote_instance_weight_loader_seed_instance_ip=None, remote_instance_weight_loader_seed_instance_service_port=None, remote_instance_weight_loader_send_weights_group_ports=None, remote_instance_weight_loader_backend='nccl', remote_instance_weight_loader_start_seed_via_transfer_engine=False, modelexpress_config=None, enable_pdmux=False, pdmux_config_path=None, sm_group_num=8, mm_max_concurrent_calls=32, mm_per_request_timeout=10.0, enable_broadcast_mm_inputs_process=False, enable_prefix_mm_cache=False, mm_enable_dp_encoder=False, mm_process_config={}, limit_mm_data_per_request=None, enable_mm_global_cache=False, decrypted_config_file=None, decrypted_draft_config_file=None, forward_hooks=None)
[2026-04-01 20:42:06.890] Init torch distributed begin.
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[2026-04-01 20:42:07.561] Init torch distributed ends. elapsed=0.67 s, mem usage=0.08 GB
2026-04-01 20:42:07.817 DEBUG Persistent cache disabled, using in-memory JIT cache
[2026-04-01 20:42:07.817] Persistent cache disabled, using in-memory JIT cache
2026-04-01 20:42:07.817 DEBUG Persistent cache disabled, using in-memory JIT cache
[2026-04-01 20:42:07.817] Persistent cache disabled, using in-memory JIT cache
2026-04-01 20:42:07.817 DEBUG Persistent cache disabled, using in-memory JIT cache
[2026-04-01 20:42:07.817] Persistent cache disabled, using in-memory JIT cache
2026-04-01 20:42:07.817 DEBUG Persistent cache disabled, using in-memory JIT cache
[2026-04-01 20:42:07.817] Persistent cache disabled, using in-memory JIT cache
2026-04-01 20:42:07.817 DEBUG Persistent cache disabled, using in-memory JIT cache
[2026-04-01 20:42:07.817] Persistent cache disabled, using in-memory JIT cache
[2026-04-01 20:42:08.425] Load weight begin. avail mem=38.88 GB
[2026-04-01 20:42:08.847] Found local HF snapshot for meta-llama/Llama-3.1-8B-Instruct at /mnt/.huggingface/hub/models--meta-llama--Llama-3.1-8B-Instruct/snapshots/0e9e39f249a16976918f6564b8830bc894c89659; skipping download.
Loading safetensors checkpoint shards: 100% Completed | 4/4 [00:01<00:00,  2.18it/s]
[2026-04-01 20:42:10.775] Load weight end. elapsed=2.36 s, type=LlamaForCausalLM, avail mem=23.86 GB, mem usage=15.02 GB.
[2026-04-01 20:42:10.776] Using KV cache dtype: torch.bfloat16
[2026-04-01 20:42:11.027] KV Cache is allocated. #tokens: 147648, K size: 9.02 GB, V size: 9.02 GB
[2026-04-01 20:42:11.027] Memory pool end. avail mem=5.24 GB
[2026-04-01 20:42:11.202] Capture cuda graph begin. This can take up to several minutes. avail mem=4.79 GB
[2026-04-01 20:42:11.202] Capture cuda graph bs [1, 2, 4, 8, 12, 16, 24, 32]
Capturing batches (bs=16 avail_mem=4.65 GB):  12%|█▎        | 1/8 [00:00<00:04,  1.66it/s][2026-04-01 20:42:12.240] Using default HuggingFace chat template with detected content format: string
Capturing batches (bs=1 avail_mem=4.49 GB): 100%|██████████| 8/8 [00:01<00:00,  6.55it/s]
[2026-04-01 20:42:13.051] Capture cuda graph end. Time elapsed: 1.85 s. mem usage=0.34 GB. avail mem=4.44 GB.
[2026-04-01 20:42:13.051] Disable piecewise CUDA graph because --disable-piecewise-cuda-graph is set
[2026-04-01 20:42:15.614] max_total_num_tokens=147648, chunked_prefill_size=6144, max_prefill_tokens=16384, max_running_requests=2048, context_len=65536, available_gpu_mem=4.44 GB
[2026-04-01 20:42:15.745] Allocating 77.42 GB host memory for hierarchical KV cache.
[2026-04-01 20:42:31.331] Creating storage backend 'file' (sglang.srt.mem_cache.hicache_storage.HiCacheFile)
[2026-04-01 20:42:31.332] Pin budget: 0 tokens (ratio=0.000)
[2026-04-01 20:42:33] INFO:     Started server process [3014241]
[2026-04-01 20:42:33] INFO:     Waiting for application startup.
[2026-04-01 20:42:33.086] Using default chat sampling params from model generation config: {'temperature': 0.6, 'top_p': 0.9}
[2026-04-01 20:42:33] INFO:     Application startup complete.
[2026-04-01 20:42:33] INFO:     Uvicorn running on http://127.0.0.1:30000 (Press CTRL+C to quit)
[2026-04-01 20:42:34] INFO:     127.0.0.1:33358 - "GET /model_info HTTP/1.1" 200 OK
[2026-04-01 20:42:34.365] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 0, token usage: 0.00, #running-req: 0, #queue-req: 0, cuda graph: False, input throughput (token/s): 0.00
[2026-04-01 20:42:34] INFO:     127.0.0.1:33366 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:34.458] The server is fired up and ready to roll!
[2026-04-01 20:42:48.419] Cache flushed successfully!
[2026-04-01 20:42:48] INFO:     127.0.0.1:38950 - "POST /flush_cache HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:38964 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:38972 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:38980 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:38990 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:38992 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39002 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39012 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39024 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39040 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39050 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39056 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39058 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39064 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39072 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39088 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39102 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39112 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39118 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39120 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39130 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39142 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:52] INFO:     127.0.0.1:39154 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:53] INFO:     127.0.0.1:39162 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:53] INFO:     127.0.0.1:39174 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:53.487] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.08, #running-req: 0, #queue-req: 23, cuda graph: False, input throughput (token/s): 3.35
[2026-04-01 20:42:53.605] Prefetch operation e3ae6bf823484b16aa2c49b46ba5082b bytes: 1073.74MB, alloc time: 0.780551s, io time: 0.157629s, copy time: 0.116396s
[2026-04-01 20:42:53.945] Prefetch operation e3ae6bf823484b16aa2c49b46ba5082b bytes: 1073.74MB, alloc time: 0.077736s, io time: 0.145542s, copy time: 0.116353s
[2026-04-01 20:42:53.978] Prefetch operation e3ae6bf823484b16aa2c49b46ba5082b bytes: 100.66MB, alloc time: 0.007268s, io time: 0.013561s, copy time: 0.011275s
[2026-04-01 20:42:53.998] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.12, #running-req: 0, #queue-req: 23, cuda graph: False, input throughput (token/s): 12013.14
[2026-04-01 20:42:54.342] Prefetch operation b79d7954f863452ea52abbb66e9e4ea4 bytes: 1073.74MB, alloc time: 0.078026s, io time: 0.167429s, copy time: 0.118728s
[2026-04-01 20:42:54.554] Prefill batch, #new-seq: 1, #new-token: 5504, #cached-token: 0, token usage: 0.24, #running-req: 0, #queue-req: 22, cuda graph: False, input throughput (token/s): 11062.28
[2026-04-01 20:42:54.597] Prefetch operation b79d7954f863452ea52abbb66e9e4ea4 bytes: 696.25MB, alloc time: 0.050719s, io time: 0.109984s, copy time: 0.093564s
[2026-04-01 20:42:54.798] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 17152, token usage: 0.28, #running-req: 1, #queue-req: 21, cuda graph: False, input throughput (token/s): 22515.77
[2026-04-01 20:42:55.024] Prefetch operation 4c2a012c336e434b8b2a149db6f512cd bytes: 1073.74MB, alloc time: 0.101920s, io time: 0.191916s, copy time: 0.132616s
[2026-04-01 20:42:55.053] Backup to storage completed op_id=18 tokens=6144 bytes=805.31MB time=0.253185s
[2026-04-01 20:42:55.177] Backup to storage completed op_id=19 tokens=6144 bytes=805.31MB time=0.123917s
[2026-04-01 20:42:55.216] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.41, #running-req: 2, #queue-req: 21, cuda graph: False, input throughput (token/s): 153.19
[2026-04-01 20:42:55.308] Backup to storage completed op_id=20 tokens=5440 bytes=713.03MB time=0.130731s
[2026-04-01 20:42:55.371] Prefetch operation 4c2a012c336e434b8b2a149db6f512cd bytes: 822.08MB, alloc time: 0.077454s, io time: 0.142641s, copy time: 0.126698s
[2026-04-01 20:42:55.707] Prefetch operation 341f4c449f5d4d2fbdf332206bec1bfa bytes: 1073.74MB, alloc time: 0.078806s, io time: 0.141121s, copy time: 0.116273s
[2026-04-01 20:42:55.740] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.45, #running-req: 2, #queue-req: 20, cuda graph: False, input throughput (token/s): 11723.33
[2026-04-01 20:42:56.056] Prefetch operation 341f4c449f5d4d2fbdf332206bec1bfa bytes: 1073.74MB, alloc time: 0.086140s, io time: 0.147171s, copy time: 0.115002s
[2026-04-01 20:42:56.178] Prefetch operation 341f4c449f5d4d2fbdf332206bec1bfa bytes: 385.88MB, alloc time: 0.028233s, io time: 0.051553s, copy time: 0.041820s
[2026-04-01 20:42:56.248] Prefill batch, #new-seq: 2, #new-token: 4992, #cached-token: 13504, token usage: 0.54, #running-req: 2, #queue-req: 19, cuda graph: False, input throughput (token/s): 12100.00
[2026-04-01 20:42:56.277] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 14464, token usage: 0.68, #running-req: 4, #queue-req: 18, cuda graph: False, input throughput (token/s): 170855.83
[2026-04-01 20:42:56.492] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 19328, token usage: 0.72, #running-req: 5, #queue-req: 17, cuda graph: False, input throughput (token/s): 298.08
[2026-04-01 20:42:56.639] Prefetch operation 4ba060e5517142418e149326e4cea312 bytes: 1073.74MB, alloc time: 0.091679s, io time: 0.215958s, copy time: 0.152896s
[2026-04-01 20:42:56.651] Backup to storage completed op_id=21 tokens=6144 bytes=805.31MB time=0.157252s
[2026-04-01 20:42:56.778] Backup to storage completed op_id=22 tokens=6144 bytes=805.31MB time=0.127022s
[2026-04-01 20:42:56.863] Backup to storage completed op_id=23 tokens=4864 bytes=637.53MB time=0.085206s
[2026-04-01 20:42:56.903] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.76, #running-req: 6, #queue-req: 17, cuda graph: False, input throughput (token/s): 155.51
[2026-04-01 20:42:57.054] Prefetch operation 4ba060e5517142418e149326e4cea312 bytes: 1073.74MB, alloc time: 0.105825s, io time: 0.193736s, copy time: 0.115341s
[2026-04-01 20:42:57.427] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.80, #running-req: 6, #queue-req: 17, cuda graph: False, input throughput (token/s): 11740.15
[2026-04-01 20:42:57.436] Prefetch operation 4ba060e5517142418e149326e4cea312 bytes: 1073.74MB, alloc time: 0.077737s, io time: 0.176431s, copy time: 0.127169s
[2026-04-01 20:42:57.585] Prefetch operation 4ba060e5517142418e149326e4cea312 bytes: 427.82MB, alloc time: 0.031127s, io time: 0.070958s, copy time: 0.046416s
[2026-04-01 20:42:57.918] Prefetch operation da99a52848994ab5975b55cd309c60bf bytes: 1073.74MB, alloc time: 0.077652s, io time: 0.139902s, copy time: 0.115296s
[2026-04-01 20:42:58.053] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.84, #running-req: 6, #queue-req: 17, cuda graph: False, input throughput (token/s): 9816.86
[2026-04-01 20:42:58.255] Prefetch operation da99a52848994ab5975b55cd309c60bf bytes: 1073.74MB, alloc time: 0.077480s, io time: 0.143807s, copy time: 0.115749s
[2026-04-01 20:42:58.569] Prefetch operation da99a52848994ab5975b55cd309c60bf bytes: 973.08MB, alloc time: 0.072309s, io time: 0.136564s, copy time: 0.104803s
[2026-04-01 20:42:58.774] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.84, #running-req: 6, #queue-req: 17, cuda graph: False, input throughput (token/s): 8517.61
[2026-04-01 20:42:58.803] Prefill batch, #new-seq: 1, #new-token: 256, #cached-token: 0, token usage: 0.84, #running-req: 6, #queue-req: 17, cuda graph: False, input throughput (token/s): 211196.74
[2026-04-01 20:42:59.002] Prefetch operation 4c174088402442c1970cec901a236744 bytes: 1073.74MB, alloc time: 0.077920s, io time: 0.156052s, copy time: 0.197906s
[2026-04-01 20:42:59] INFO:     127.0.0.1:39346 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:59] INFO:     127.0.0.1:39350 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:59.182] Backup to storage completed op_id=24 tokens=6144 bytes=805.31MB time=0.182840s
[2026-04-01 20:42:59.352] Backup to storage completed op_id=25 tokens=6144 bytes=805.31MB time=0.170045s
[2026-04-01 20:42:59.491] Prefill batch, #new-seq: 3, #new-token: 192, #cached-token: 79488, token usage: 0.84, #running-req: 5, #queue-req: 16, cuda graph: False, input throughput (token/s): 372.29
[2026-04-01 20:42:59] INFO:     127.0.0.1:39354 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:42:59.534] Backup to storage completed op_id=26 tokens=6144 bytes=805.31MB time=0.179961s
[2026-04-01 20:42:59.577] Prefetch operation 4c174088402442c1970cec901a236744 bytes: 1073.74MB, alloc time: 0.129348s, io time: 0.247343s, copy time: 0.198483s
[2026-04-01 20:42:59.657] Backup to storage completed op_id=27 tokens=6144 bytes=805.31MB time=0.122649s
[2026-04-01 20:42:59.661] Backup to storage completed op_id=28 tokens=192 bytes=25.17MB time=0.003663s
[2026-04-01 20:42:59.662] Backup to storage completed op_id=29 tokens=64 bytes=8.39MB time=0.001056s
[2026-04-01 20:42:59.696] Prefetch operation 4c174088402442c1970cec901a236744 bytes: 310.38MB, alloc time: 0.031455s, io time: 0.053005s, copy time: 0.033903s
[2026-04-01 20:42:59.941] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.92, #running-req: 7, #queue-req: 16, cuda graph: False, input throughput (token/s): 426.68
[2026-04-01 20:43:00.037] Prefetch operation 7f3bff4b580e43e29c0c3c0a0b07ee47 bytes: 1073.74MB, alloc time: 0.077391s, io time: 0.146064s, copy time: 0.117495s
[2026-04-01 20:43:00.405] Prefetch operation 7f3bff4b580e43e29c0c3c0a0b07ee47 bytes: 1073.74MB, alloc time: 0.077472s, io time: 0.167708s, copy time: 0.122444s
[2026-04-01 20:43:00.464] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.95, #running-req: 7, #queue-req: 16, cuda graph: False, input throughput (token/s): 11747.95
[2026-04-01 20:43:00.597] Prefetch operation 7f3bff4b580e43e29c0c3c0a0b07ee47 bytes: 553.65MB, alloc time: 0.040012s, io time: 0.091964s, copy time: 0.059473s
[2026-04-01 20:43:00.821] Prefill batch, #new-seq: 1, #new-token: 3648, #cached-token: 0, token usage: 0.95, #running-req: 7, #queue-req: 16, cuda graph: False, input throughput (token/s): 17175.67
[2026-04-01 20:43:00] INFO:     127.0.0.1:39370 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:43:00] INFO:     127.0.0.1:39372 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:43:01] INFO:     127.0.0.1:39382 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:43:01] INFO:     127.0.0.1:39394 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:43:01.090] Prefetch operation aa9ebccfd2994345a695c902e213ed33 bytes: 1073.74MB, alloc time: 0.077258s, io time: 0.173221s, copy time: 0.242273s
[2026-04-01 20:43:01.107] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 18752, token usage: 0.57, #running-req: 6, #queue-req: 17, cuda graph: False, input throughput (token/s): 12788.32
[2026-04-01 20:43:01.113] Backup to storage completed op_id=33 tokens=6144 bytes=805.31MB time=0.208834s
[2026-04-01 20:43:01.284] Backup to storage completed op_id=34 tokens=6144 bytes=805.31MB time=0.170627s
[2026-04-01 20:43:01.363] Backup to storage completed op_id=37 tokens=3584 bytes=469.76MB time=0.078713s
[2026-04-01 20:43:01.556] Prefetch operation aa9ebccfd2994345a695c902e213ed33 bytes: 1073.74MB, alloc time: 0.145057s, io time: 0.204927s, copy time: 0.115679s
[2026-04-01 20:43:01.599] Prefill batch, #new-seq: 2, #new-token: 6144, #cached-token: 20608, token usage: 0.79, #running-req: 5, #queue-req: 17, cuda graph: False, input throughput (token/s): 129.95
[2026-04-01 20:43:01.608] Prefetch operation aa9ebccfd2994345a695c902e213ed33 bytes: 142.61MB, alloc time: 0.010339s, io time: 0.023612s, copy time: 0.017935s
[2026-04-01 20:43:01.970] Prefetch operation 09141638a58b450cafa6599ad3fd1ae0 bytes: 1073.74MB, alloc time: 0.077460s, io time: 0.168349s, copy time: 0.115349s
[2026-04-01 20:43:02.119] Prefill batch, #new-seq: 1, #new-token: 6144, #cached-token: 0, token usage: 0.81, #running-req: 6, #queue-req: 17, cuda graph: False, input throughput (token/s): 11824.61
[2026-04-01 20:43:02.242] Prefetch operation 09141638a58b450cafa6599ad3fd1ae0 bytes: 746.59MB, alloc time: 0.053896s, io time: 0.119495s, copy time: 0.098428s
[2026-04-01 20:43:02.362] Prefill batch, #new-seq: 1, #new-token: 2304, #cached-token: 0, token usage: 0.93, #running-req: 6, #queue-req: 16, cuda graph: False, input throughput (token/s): 25291.54
[2026-04-01 20:43:02.365] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 17472, token usage: 0.93, #running-req: 7, #queue-req: 16, cuda graph: False, input throughput (token/s): 698067.56
[2026-04-01 20:43:02] INFO:     127.0.0.1:39398 - "POST /generate HTTP/1.1" 200 OK
[2026-04-01 20:43:02.595] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 13888, token usage: 0.81, #running-req: 7, #queue-req: 16, cuda graph: False, input throughput (token/s): 278.60
[2026-04-01 20:43:02.598] Backup to storage completed op_id=40 tokens=6080 bytes=796.92MB time=0.163963s
[2026-04-01 20:43:02.730] Backup to storage completed op_id=41 tokens=6144 bytes=805.31MB time=0.131709s
[2026-04-01 20:43:02.731] Prefetch operation bdedd2378a8f45a9a09a25a232004cc8 bytes: 1073.74MB, alloc time: 0.087483s, io time: 0.221271s, copy time: 0.179788s
[2026-04-01 20:43:02.778] Backup to storage completed op_id=42 tokens=2240 bytes=293.60MB time=0.048316s
[2026-04-01 20:43:02.780] Backup to storage completed op_id=44 tokens=64 bytes=8.39MB time=0.001524s
[2026-04-01 20:43:02.865] Backup to storage completed op_id=45 tokens=64 bytes=8.39MB time=0.001378s
[2026-04-01 20:43:02.927] Backup to storage completed op_id=46 tokens=64 bytes=8.39MB time=0.001347s
[2026-04-01 20:43:09.551] Prefetch operation bdedd2378a8f45a9a09a25a232004cc8 bytes: 1073.74MB, alloc time: 0.091322s, io time: 2.506906s, copy time: 4.221844s
[2026-04-01 20:43:11.000] Prefetch operation bdedd2378a8f45a9a09a25a232004cc8 bytes: 25.17MB, alloc time: 0.004273s, io time: 0.033019s, copy time: 0.608518s
[2026-04-01 20:43:11.152] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 16576, token usage: 0.11, #running-req: 0, #queue-req: 15, cuda graph: False, input throughput (token/s): 7.48
[2026-04-01 20:43:17.353] Prefetch operation 7d859df804e7440082968ec498da1d42 bytes: 1073.74MB, alloc time: 0.103801s, io time: 1.231125s, copy time: 5.000130s
[2026-04-01 20:43:35.357] Prefetch operation 7d859df804e7440082968ec498da1d42 bytes: 1073.74MB, alloc time: 3.938937s, io time: 6.054015s, copy time: 7.965754s
[2026-04-01 20:43:51.108] Prefetch operation 7d859df804e7440082968ec498da1d42 bytes: 973.08MB, alloc time: 3.807981s, io time: 6.141251s, copy time: 3.726887s
[2026-04-01 20:43:51.313] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 23808, token usage: 0.16, #running-req: 0, #queue-req: 14, cuda graph: False, input throughput (token/s): 1.59
[2026-04-01 20:43:51.343] Decode batch, #running-req: 1, #token: 23872, token usage: 0.16, cuda graph: True, gen throughput (token/s): 1.54, #queue-req: 14
[2026-04-01 20:43:51.498] Backup to storage completed op_id=47 tokens=64 bytes=8.39MB time=0.001545s
[2026-04-01 20:43:51.502] Prefetch operation 54e18f4ad74b4bb094ae198ae9999a2a bytes: 1073.74MB, alloc time: 0.101916s, io time: 0.153657s, copy time: 0.117879s
[2026-04-01 20:44:05.403] Prefetch operation 54e18f4ad74b4bb094ae198ae9999a2a bytes: 1073.74MB, alloc time: 2.872434s, io time: 6.950965s, copy time: 4.077062s
[2026-04-01 20:44:22.322] Prefetch operation 54e18f4ad74b4bb094ae198ae9999a2a bytes: 1073.74MB, alloc time: 2.269593s, io time: 8.472959s, copy time: 5.944756s
[2026-04-01 20:44:26.618] Prefetch operation 54e18f4ad74b4bb094ae198ae9999a2a bytes: 276.82MB, alloc time: 0.944929s, io time: 2.003663s, copy time: 1.279452s
[2026-04-01 20:44:26.829] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 26688, token usage: 0.18, #running-req: 0, #queue-req: 13, cuda graph: False, input throughput (token/s): 1.80
[2026-04-01 20:44:27.032] Prefetch operation 764cfc0211e247639fed38cabafef3af bytes: 1073.74MB, alloc time: 0.105632s, io time: 0.184017s, copy time: 0.116406s
[2026-04-01 20:44:27.257] Backup to storage completed op_id=48 tokens=64 bytes=8.39MB time=0.001856s
[2026-04-01 20:44:27.269] Decode batch, #running-req: 1, #token: 0, token usage: 0.00, cuda graph: True, gen throughput (token/s): 1.11, #queue-req: 13
[2026-04-01 20:44:32.028] Prefetch operation 764cfc0211e247639fed38cabafef3af bytes: 1073.74MB, alloc time: 0.078705s, io time: 0.247754s, copy time: 4.669737s
[2026-04-01 20:44:43.912] Prefetch operation 764cfc0211e247639fed38cabafef3af bytes: 1073.74MB, alloc time: 1.477154s, io time: 4.561513s, copy time: 5.518744s
[2026-04-01 20:44:58.005] Prefetch operation 764cfc0211e247639fed38cabafef3af bytes: 864.03MB, alloc time: 1.754171s, io time: 6.357325s, copy time: 5.577098s
[2026-04-01 20:44:58.341] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 31168, token usage: 0.21, #running-req: 0, #queue-req: 12, cuda graph: False, input throughput (token/s): 2.03
[2026-04-01 20:45:00.336] Prefetch operation 95aadf385b154bc59aa44d74cd4c8d51 bytes: 1073.74MB, alloc time: 0.101561s, io time: 0.154951s, copy time: 2.009634s
[2026-04-01 20:45:10.732] Prefetch operation 95aadf385b154bc59aa44d74cd4c8d51 bytes: 788.53MB, alloc time: 2.063660s, io time: 4.989487s, copy time: 3.337067s
[2026-04-01 20:45:10.876] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 14208, token usage: 0.10, #running-req: 0, #queue-req: 11, cuda graph: False, input throughput (token/s): 5.11
[2026-04-01 20:45:11.154] Prefetch operation 80bfd8228bc04ebb81fda909fc83bc50 bytes: 1073.74MB, alloc time: 0.104707s, io time: 0.171181s, copy time: 0.115279s
[2026-04-01 20:45:11.404] Decode batch, #running-req: 1, #token: 14336, token usage: 0.10, cuda graph: True, gen throughput (token/s): 0.91, #queue-req: 11
[2026-04-01 20:45:11.526] Prefetch operation 80bfd8228bc04ebb81fda909fc83bc50 bytes: 1073.74MB, alloc time: 0.077749s, io time: 0.177704s, copy time: 0.116016s
[2026-04-01 20:45:11.601] Prefetch operation 80bfd8228bc04ebb81fda909fc83bc50 bytes: 218.10MB, alloc time: 0.015824s, io time: 0.034896s, copy time: 0.023914s
[2026-04-01 20:45:11.737] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 18048, token usage: 0.22, #running-req: 1, #queue-req: 10, cuda graph: False, input throughput (token/s): 74.31
[2026-04-01 20:45:11.770] Backup to storage completed op_id=49 tokens=64 bytes=8.39MB time=0.001605s
[2026-04-01 20:45:14.832] Prefetch operation c3e32395556341bda1ff9ee9af9e8b34 bytes: 1073.74MB, alloc time: 0.107835s, io time: 0.144121s, copy time: 2.978616s
[2026-04-01 20:45:32.389] Prefetch operation c3e32395556341bda1ff9ee9af9e8b34 bytes: 1073.74MB, alloc time: 2.547209s, io time: 6.534915s, copy time: 6.986250s
[2026-04-01 20:45:49.309] Prefetch operation c3e32395556341bda1ff9ee9af9e8b34 bytes: 1073.74MB, alloc time: 1.410968s, io time: 8.802628s, copy time: 6.165010s
[2026-04-01 20:45:50.327] Prefetch operation c3e32395556341bda1ff9ee9af9e8b34 bytes: 16.78MB, alloc time: 0.048120s, io time: 0.462862s, copy time: 0.011820s
[2026-04-01 20:45:50.548] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 24704, token usage: 0.17, #running-req: 0, #queue-req: 9, cuda graph: False, input throughput (token/s): 1.65
[2026-04-01 20:45:50.719] Backup to storage completed op_id=50 tokens=64 bytes=8.39MB time=0.001658s
[2026-04-01 20:45:51.338] Prefetch operation f9d6fc0250f940efa35b59e5d4b28b04 bytes: 1073.74MB, alloc time: 0.134814s, io time: 0.168228s, copy time: 0.707836s
[2026-04-01 20:45:59.401] Prefetch operation f9d6fc0250f940efa35b59e5d4b28b04 bytes: 754.97MB, alloc time: 1.900066s, io time: 4.677348s, copy time: 1.379951s
[2026-04-01 20:45:59.535] Prefill batch, #new-seq: 1, #new-token: 64, #cached-token: 13952, token usage: 0.09, #running-req: 0, #queue-req: 8, cuda graph: False, input throughput (token/s): 7.12
[2026-04-01 20:45:59.549] Decode batch, #running-req: 1, #token: 14016, token usage: 0.09, cuda graph: True, gen throughput (token/s): 0.89, #queue-req: 8
[2026-04-01 20:45:59.724] Backup to storage completed op_id=51 tokens=64 bytes=8.39MB time=0.144641s
[2026-04-01 20:46:07.364] Prefetch operation cfff9b4cb85641c98a412c64e28965c7 bytes: 1073.74MB, alloc time: 0.100653s, io time: 3.435934s, copy time: 4.402099s
[2026-04-01 20:46:24.353] Prefetch operation cfff9b4cb85641c98a412c64e28965c7 bytes: 1073.74MB, alloc time: 4.146577s, io time: 6.824201s, copy time: 5.988296s
[2026-04-01 20:46:41.109] Prefetch operation cfff9b4cb85641c98a412c64e28965c7 bytes: 1040.19MB, alloc time: 2.014140s, io time: 6.028999s, copy time: 6.753087s

Benchmark command and result:

$ python bench_long_context.py --dataset-path loogle_wiki_qa.json --num-clients 32
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 32/32 [06:08<00:00, 11.52s/it]
All requests completed
Performance metrics summary:
  Total requests: 32 at 24 requests per second
  Average Prompt Length: 19723.47 tokens
  Average Output Length: 12.50 tokens
  P90 Prompt Length: 27894 tokens
  P99 Prompt Length: 36567 tokens
  P90 Output Length: 24 tokens
  P99 Output Length: 55 tokens
  Average TTFT: 102.95
  P90 TTFT: 305.71
  P99 TTFT: 348.01
  Median TTFT: 18.57
  Max TTFT: 348.01
  Average ITL: 0.1250
  P90 ITL: 0.0902
  P99 ITL: 2.5856
  Median ITL: 0.0153
  Max ITL: 4.2801
  Average latency: 104.38
  P90 latency: 305.91
  P99 latency: 348.27
  Median latency: 18.61
  Max latency: 348.27
  Input token throughput: 1760.36 tokens per second
  Output token throughput: 1.12 tokens per second
  Request Throughput: 0.09 requests per second
  Cache Hit Rate: 0.855630

As we can see, the alloc/io/copy time fluctuates heavily during the run, and can go absurdly high (e.g. copying 1GB KV in host memory can take 10s). This essentially turn the workload to storage-bound under wait-complete policy, which explains the pool performance numbers.

I initially suspected this might be due to file system's issue on managing lots of small files, but then I conducted a synthetic benchmark that reads many small files into memory like what SGLang does, and the effective bandwidth is way higher than what I see from SGLang's logs, so file system is not an issue here.

The real issue is likely due to GIL, as the scheduler's loop is contending with prefetch worker's loop. I then manually added a tiny sleep at the end of the schedule step:

diff --git a/python/sglang/srt/managers/scheduler_runtime_checker_mixin.py b/python/sglang/srt/managers/scheduler_runtime_checker_mixin.py
index 8d01f7792..4eb949401 100644
--- a/python/sglang/srt/managers/scheduler_runtime_checker_mixin.py
+++ b/python/sglang/srt/managers/scheduler_runtime_checker_mixin.py
@@ -375,6 +375,10 @@ class SchedulerRuntimeCheckerMixin:
             if self.hisparse_coordinator.has_ongoing_staging():
                 return
 
+        if self.enable_hicache_storage and len(self.waiting_queue) > 0:
+            time.sleep(0.001)
+            return
+
         self.check_memory()
         self.check_tree_cache()
         self.new_token_ratio = self.init_new_token_ratio

And rerun the benchmark:

$ python bench_long_context.py --dataset-path loogle_wiki_qa.json --num-clients 32       
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 32/32 [00:35<00:00,  1.09s/it]
All requests completed
Performance metrics summary:
  Total requests: 32 at 24 requests per second
  Average Prompt Length: 19723.47 tokens
  Average Output Length: 12.50 tokens
  P90 Prompt Length: 27894 tokens
  P99 Prompt Length: 36567 tokens
  P90 Output Length: 24 tokens
  P99 Output Length: 55 tokens
  Average TTFT: 10.08
  P90 TTFT: 15.49
  P99 TTFT: 17.18
  Median TTFT: 10.51
  Max TTFT: 17.18
  Average ITL: 0.1219
  P90 ITL: 0.0994
  P99 ITL: 2.3815
  Median ITL: 0.0152
  Max ITL: 4.1687
  Average latency: 11.48
  P90 latency: 15.53
  P99 latency: 17.35
  Median latency: 10.56
  Max latency: 17.35
  Input token throughput: 25238.20 tokens per second
  Output token throughput: 16.00 tokens per second
  Request Throughput: 1.28 requests per second
  Cache Hit Rate: 0.855630

This time the alloc/io/copy time becomes very reliable (e.g. 0.1s copy time for 1GB KV tensor, vs. 10s in before).

I saw vLLM has this tiny sleep and in their comment explicitly says it can effectively mitigates GIL contention: https://github.com/vllm-project/vllm/blob/main/vllm/v1/engine/core.py#L1193

My question

I would like to get this potential bug acknowledged and fixed properly, as without that the whole HiCache feature becomes unusable in my testbed. I also don't know why this bug did not show up on other people's side. The command I used was very similar to the HiCache blog's: https://www.lmsys.org/blog/2025-09-10-sglang-hicache/ -- but it did not appear to be a problem?

The above is on the read side (i.e. prefetching). The write side (i.e. backup to storage with write-through) also has its issues: weird and slow write bandwidth pins KV data in host mem pool and enforces recompute for any incoming requests despite their KV cache hit. And this is not solved by adding sleep(0.001). I will probably report this in another GitHub issue.

Reproduction

Commands:

For server: SGLANG_LOG_MS=1 python3 -m sglang.launch_server --model-path meta-llama/Llama-3.1-8B-Instruct --tp 1 --page-size 64 --context-length 65536 --chunked-prefill-size 6144 --mem-fraction-static 0.85 --enable-hierarchical-cache --hicache-ratio 4 --hicache-io-backend kernel --hicache-mem-layout page_first --hicache-storage-backend file --hicache-storage-prefetch-policy wait_complete

For benchmark client: python bench_long_context.py --dataset-path loogle_wiki_qa.json --num-clients 32

Before running the benchmark apply this patch:

diff --git a/benchmark/hicache/bench_long_context.py b/benchmark/hicache/bench_long_context.py
index dfcecbbc3..dca865f82 100644
--- a/benchmark/hicache/bench_long_context.py
+++ b/benchmark/hicache/bench_long_context.py
@@ -10,6 +10,7 @@ from bench_multiturn import (
     log_to_jsonl_file,
     parse_args,
 )
+from sglang.test.kits.cache_hit_kit import async_request_sglang_generate
 from tqdm.asyncio import tqdm
 
 from sglang.benchmark.utils import get_tokenizer
@@ -20,6 +21,7 @@ class ContextWorkloadGenerator(WorkloadGenerator):
         # Construct the base URL for requests
         self.baseurl = f"http://{args.host}:{args.port}/"
         self.url = self.baseurl + "generate"
+        self.request_func = async_request_sglang_generate
 
         self.tokenizer = get_tokenizer(args.model_path)
         self.distribution = args.distribution
@@ -48,7 +50,7 @@ class ContextWorkloadGenerator(WorkloadGenerator):
                 ]
             )
             init_requests.append((i, gen_payload(input_ids, output_len)))
-        self.ready_queue = ReadyQueue(init_requests=init_requests)
+        self.ready_queue = ReadyQueue(init_requests=init_requests, policy="fifo")
 
         self.response_queue = queue.Queue()
         self.pbar = tqdm(total=num_requests)
@@ -92,7 +94,7 @@ if __name__ == "__main__":
     args.max_parallel = 24
     flush_cache_url = f"http://{args.host}:{args.port}/flush_cache"
 

Notes

As I mentioned above, make sure to run the benchmark multiple times so that all requests' KV caches are warmed up in file storage and each later run can trigger file reads on each new request.

Environment

Python: 3.12.12 (main, Feb 12 2026, 00:42:14) [Clang 21.1.4 ]
CUDA available: True
GPU 0,1,2,3: NVIDIA A100-SXM4-40GB
GPU 0,1,2,3 Compute Capability: 8.0
CUDA_HOME: /usr/local/cuda
NVCC: Cuda compilation tools, release 12.8, V12.8.61
CUDA Driver Version: 535.216.03
PyTorch: 2.9.1+cu128
sglang: 0.5.10rc0
sglang-kernel: 0.4.0
flashinfer_python: 0.6.6
flashinfer_cubin: 0.6.6
flashinfer_jit_cache: Module Not Found
triton: 3.5.1
transformers: 5.3.0
torchao: 0.9.0
numpy: 2.4.4
aiohttp: 3.13.5
fastapi: 0.135.3
huggingface_hub: 1.8.0
interegular: 0.3.3
modelscope: 1.35.3
orjson: 3.11.8
outlines: 0.1.11
packaging: 26.0
psutil: 7.2.2
pydantic: 2.12.5
python-multipart: 0.0.22
pyzmq: 27.1.0
uvicorn: 0.42.0
uvloop: 0.22.1
vllm: Module Not Found
xgrammar: 0.1.32
openai: 2.6.1
tiktoken: 0.12.0
anthropic: 0.87.0
litellm: Module Not Found
torchcodec: 0.9.1
NVIDIA Topology: 
        GPU0    GPU1    GPU2    GPU3    NIC0    NIC1    NIC2    NIC3    NIC4    NIC5    NIC6    NIC7    NIC8    NIC9    CPU Affinity    NUMA Affinity   GPU NUMA ID
GPU0     X      NV12    NV12    NV12    SYS     SYS     SYS     SYS     PXB     PXB     SYS     SYS     SYS     SYS     112-127,240-255 7               N/A
GPU1    NV12     X      NV12    NV12    SYS     SYS     SYS     SYS     PXB     PXB     SYS     SYS     SYS     SYS     112-127,240-255 7               N/A
GPU2    NV12    NV12     X      NV12    SYS     SYS     SYS     SYS     SYS     SYS     PXB     PXB     SYS     SYS     80-95,208-223   5               N/A
GPU3    NV12    NV12    NV12     X      SYS     SYS     SYS     SYS     SYS     SYS     PXB     PXB     SYS     SYS     80-95,208-223   5               N/A
NIC0    SYS     SYS     SYS     SYS      X      PXB     SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS
NIC1    SYS     SYS     SYS     SYS     PXB      X      SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS
NIC2    SYS     SYS     SYS     SYS     SYS     SYS      X      PXB     SYS     SYS     SYS     SYS     SYS     SYS
NIC3    SYS     SYS     SYS     SYS     SYS     SYS     PXB      X      SYS     SYS     SYS     SYS     SYS     SYS
NIC4    PXB     PXB     SYS     SYS     SYS     SYS     SYS     SYS      X      PXB     SYS     SYS     SYS     SYS
NIC5    PXB     PXB     SYS     SYS     SYS     SYS     SYS     SYS     PXB      X      SYS     SYS     SYS     SYS
NIC6    SYS     SYS     PXB     PXB     SYS     SYS     SYS     SYS     SYS     SYS      X      PXB     SYS     SYS
NIC7    SYS     SYS     PXB     PXB     SYS     SYS     SYS     SYS     SYS     SYS     PXB      X      SYS     SYS
NIC8    SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS      X      PIX
NIC9    SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS     SYS     PIX      X 

Legend:

  X    = Self
  SYS  = Connection traversing PCIe as well as the SMP interconnect between NUMA nodes (e.g., QPI/UPI)
  NODE = Connection traversing PCIe as well as the interconnect between PCIe Host Bridges within a NUMA node
  PHB  = Connection traversing PCIe as well as a PCIe Host Bridge (typically the CPU)
  PXB  = Connection traversing multiple PCIe bridges (without traversing the PCIe Host Bridge)
  PIX  = Connection traversing at most a single PCIe bridge
  NV#  = Connection traversing a bonded set of # NVLinks

NIC Legend:

  NIC0: mlx5_0
  NIC1: mlx5_1
  NIC2: mlx5_2
  NIC3: mlx5_3
  NIC4: mlx5_4
  NIC5: mlx5_5
  NIC6: mlx5_6
  NIC7: mlx5_7
  NIC8: mlx5_8
  NIC9: mlx5_9


ulimit soft: 1048576

This is running in a k8s pod.

[hzh0425]

You should use the 3fs / Mooncake backend to deliver higher storage performance.

[jiangxiaosheng]

Using 3fs/mooncake backend makes sense. I think the hidden GIL issue is only exposed by the file backend as it's fully sequential, reading each file for each page at a time with tensor.allocate() + open() + readinto() + tensor.copy(). That can cause extensive GIL contention, while the 3fs/mooncake zero-copy paths are well optimized by parallelism and io_uring.

I don't know the right move for SGLang on this issue. Apparently file backend is not usable even for testing without the tiny sleep trick. Maybe add a warning somewhere is helpful for those who want to play with storage offloading.

[BenWongCityuCS]

I encountered the same Pin budget: 0 tokens (ratio=0.000) issue and severe performance degradation in Docker containers. Here is my debugging process:

Environment:

• Docker with --privileged flag and --ulimit memlock=-1
• 8x H20 GPUs (141GB each)
• Host memory: 2TB (with vm.max_map_count increased to 2097152)
• Model: Kimi-K2.5 (with EAGLE3 speculative decoding)
• SGLang version: 0.5.10 (latest)

Symptoms:

1. Pin budget: 0 tokens (ratio=0.000) despite --hicache-ratio 2.0
2. Extremely slow generation speed (~0.2 tokens/s)
3. HiCache host memory allocation succeeds (Allocating 105.60 GB host memory), but pin budget remains zero
4. server_args shows correct hicache_ratio=2.0, but runtime shows ratio=0.000

Attempts made:

1. Tried pure ratio mode: Used --hicache-ratio 2.0 without --hicache-size to avoid parameter override → Still Pin budget: 0
2. Increased system limits: Modified host vm.max_map_count from 65530 to 2097152 → No effect, still Pin budget: 0
3. Verified resources: GPU memory available (~16GB free), system memory充足 (2TB), no OOM errors

Key Observation:
The Pin budget: 0 appears to be a container-specific initialization bug where the ratio parameter is not correctly passed to the internal HiCache controller, or the pinned memory allocation fails silently in Docker environment despite system limits being increased.

Connection to this issue:
The severe performance degradation (0.2 token/s) matches the GIL contention problem described here, but the Pin budget: 0 indicates an additional initialization failure specific to container environments.

Request:
Could the maintainers look into why HiCache initialization fails in Docker containers with Pin budget: 0 even when system resources are sufficient and max_map_count is properly configured?

docker run --rm -it
--name sglang-kimi-k2.5
--gpus '"device=0,1,2,3,4,5,6,7"'
--ipc=host
--net=host
--ulimit memlock=-1
--ulimit stack=67108864
--shm-size=64g
-p 8000:8000
-v /ssd1:/model_files:ro
-v /dev/null:/dev/null
-e SGLANG_ENABLE_SPEC_V2=1
-e NCCL_DEBUG=WARN
-e PYTHONUNBUFFERED=1
-e CUDA_DEVICE_ORDER=PCI_BUS_ID
--privileged
lmsysorg/sglang:latest
python -m sglang.launch_server
--model-path /model_files/Kimi-K2.5
--tp 8
--ep-size 8
--kv-cache-dtype fp8_e4m3
--mem-fraction-static 0.88
--max-running-requests 25
--max-prefill-tokens 16384
--chunked-prefill-size 8192
--speculative-algorithm EAGLE3
--speculative-draft-model-path /model_files/Kimi-K2.5-Eagle3
--speculative-num-steps 3
--speculative-eagle-topk 1
--speculative-num-draft-tokens 4
--enable-hierarchical-cache
--hicache-mem-layout layer_first
--hicache-ratio 2.0
--hicache-write-policy write_through_selective
--page-size 64
--mm-enable-dp-encoder
--mm-max-concurrent-calls 32
--host 0.0.0.0
--port 8000
--trust-remote-code
--reasoning-parser kimi_k2
--tool-call-parser kimi_k2

[github-actions]

This issue has been automatically closed due to inactivity. Please feel free to reopen it if needed.