2026-05-14T15:58:10.331764+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:10.332522+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:10.332696+08:00   INFO infer: main.rs:402 DeepSeek V4 serving distributed env: ranks=8 gpu_layers=43 model=/root/DeepSeek-V4-Flash
2026-05-14T15:58:10.342760+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:10.342775+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:10.342814+08:00   INFO infer: main.rs:1022 === Infer Server - DeepSeek-V4 (GPU) ===
2026-05-14T15:58:10.449419+08:00   INFO infer::runtime_topology: runtime_topology.rs:132 Runtime topology: numa_nodes=2 gpus=8 nics=8 fallback_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179
2026-05-14T15:58:10.449444+08:00   INFO infer::runtime_topology: runtime_topology.rs:140 Runtime topology NUMA node 0: cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89
2026-05-14T15:58:10.449452+08:00   INFO infer::runtime_topology: runtime_topology.rs:140 Runtime topology NUMA node 1: cpus=90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179
2026-05-14T15:58:10.449466+08:00   INFO infer::runtime_topology: runtime_topology.rs:147 Runtime topology GPU 0: pci=65:02.0 numa=Some(0) local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89 nearest_nics=eth0,eth1,eth2,eth5
2026-05-14T15:58:10.449491+08:00   INFO infer::runtime_topology: runtime_topology.rs:147 Runtime topology GPU 1: pci=65:03.0 numa=Some(0) local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89 nearest_nics=eth0,eth1,eth2,eth5
2026-05-14T15:58:10.449499+08:00   INFO infer::runtime_topology: runtime_topology.rs:147 Runtime topology GPU 2: pci=67:02.0 numa=Some(0) local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89 nearest_nics=eth0,eth1,eth2,eth5
2026-05-14T15:58:10.449508+08:00   INFO infer::runtime_topology: runtime_topology.rs:147 Runtime topology GPU 3: pci=67:03.0 numa=Some(0) local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89 nearest_nics=eth0,eth1,eth2,eth5
2026-05-14T15:58:10.449515+08:00   INFO infer::runtime_topology: runtime_topology.rs:147 Runtime topology GPU 4: pci=69:02.0 numa=Some(1) local_cpus=90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179 nearest_nics=eth3,eth4
2026-05-14T15:58:10.449522+08:00   INFO infer::runtime_topology: runtime_topology.rs:147 Runtime topology GPU 5: pci=69:03.0 numa=Some(1) local_cpus=90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179 nearest_nics=eth3,eth4
2026-05-14T15:58:10.449528+08:00   INFO infer::runtime_topology: runtime_topology.rs:147 Runtime topology GPU 6: pci=6b:02.0 numa=Some(1) local_cpus=90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179 nearest_nics=eth3,eth4
2026-05-14T15:58:10.449537+08:00   INFO infer::runtime_topology: runtime_topology.rs:147 Runtime topology GPU 7: pci=6b:03.0 numa=Some(1) local_cpus=90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179 nearest_nics=eth3,eth4
2026-05-14T15:58:10.449545+08:00   INFO infer::runtime_topology: runtime_topology.rs:161 Runtime topology NIC eth0: pci=00:02.0 numa=Some(0) local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89
2026-05-14T15:58:10.449553+08:00   INFO infer::runtime_topology: runtime_topology.rs:161 Runtime topology NIC eth1: pci=65:01.0 numa=Some(0) local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89
2026-05-14T15:58:10.449559+08:00   INFO infer::runtime_topology: runtime_topology.rs:161 Runtime topology NIC eth2: pci=67:01.0 numa=Some(0) local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89
2026-05-14T15:58:10.449566+08:00   INFO infer::runtime_topology: runtime_topology.rs:161 Runtime topology NIC eth3: pci=69:01.0 numa=Some(1) local_cpus=90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179
2026-05-14T15:58:10.449574+08:00   INFO infer::runtime_topology: runtime_topology.rs:161 Runtime topology NIC eth4: pci=6b:01.0 numa=Some(1) local_cpus=90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179
2026-05-14T15:58:10.449581+08:00   INFO infer::runtime_topology: runtime_topology.rs:161 Runtime topology NIC eth5: pci=00:03.0 numa=Some(0) local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89
2026-05-14T15:58:10.449593+08:00   INFO infer::runtime_topology: runtime_topology.rs:161 Runtime topology NIC eth6: pci=00:04.0 numa=None local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179
2026-05-14T15:58:10.449604+08:00   INFO infer::runtime_topology: runtime_topology.rs:161 Runtime topology NIC eth7: pci=00:05.0 numa=None local_cpus=0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49,50,51,52,53,54,55,56,57,58,59,60,61,62,63,64,65,66,67,68,69,70,71,72,73,74,75,76,77,78,79,80,81,82,83,84,85,86,87,88,89,90,91,92,93,94,95,96,97,98,99,100,101,102,103,104,105,106,107,108,109,110,111,112,113,114,115,116,117,118,119,120,121,122,123,124,125,126,127,128,129,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,151,152,153,154,155,156,157,158,159,160,161,162,163,164,165,166,167,168,169,170,171,172,173,174,175,176,177,178,179
2026-05-14T15:58:10.449619+08:00   INFO infer: main.rs:1033 Configured 8 CUDA scheduler workers; per-worker bootstrap will bind CPU affinity before initializing CUDA
2026-05-14T15:58:10.449624+08:00   INFO infer: main.rs:809 Final runtime worker placement: worker=0 cuda_ordinal=0 gpu=0 numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5 affinity_applied=false reason=multi-worker bootstrap applies affinity per worker before CUDA context
2026-05-14T15:58:10.449629+08:00   INFO infer: main.rs:809 Final runtime worker placement: worker=1 cuda_ordinal=1 gpu=1 numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5 affinity_applied=false reason=multi-worker bootstrap applies affinity per worker before CUDA context
2026-05-14T15:58:10.449631+08:00   INFO infer: main.rs:809 Final runtime worker placement: worker=2 cuda_ordinal=2 gpu=2 numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5 affinity_applied=false reason=multi-worker bootstrap applies affinity per worker before CUDA context
2026-05-14T15:58:10.449632+08:00   INFO infer: main.rs:809 Final runtime worker placement: worker=3 cuda_ordinal=3 gpu=3 numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5 affinity_applied=false reason=multi-worker bootstrap applies affinity per worker before CUDA context
2026-05-14T15:58:10.449633+08:00   INFO infer: main.rs:809 Final runtime worker placement: worker=4 cuda_ordinal=4 gpu=4 numa=Some(1) cpus=90 nics=eth3,eth4 affinity_applied=false reason=multi-worker bootstrap applies affinity per worker before CUDA context
2026-05-14T15:58:10.449635+08:00   INFO infer: main.rs:809 Final runtime worker placement: worker=5 cuda_ordinal=5 gpu=5 numa=Some(1) cpus=90 nics=eth3,eth4 affinity_applied=false reason=multi-worker bootstrap applies affinity per worker before CUDA context
2026-05-14T15:58:10.449636+08:00   INFO infer: main.rs:809 Final runtime worker placement: worker=6 cuda_ordinal=6 gpu=6 numa=Some(1) cpus=90 nics=eth3,eth4 affinity_applied=false reason=multi-worker bootstrap applies affinity per worker before CUDA context
2026-05-14T15:58:10.449638+08:00   INFO infer: main.rs:809 Final runtime worker placement: worker=7 cuda_ordinal=7 gpu=7 numa=Some(1) cpus=90 nics=eth3,eth4 affinity_applied=false reason=multi-worker bootstrap applies affinity per worker before CUDA context
2026-05-14T15:58:10.455339+08:00   INFO infer: main.rs:1062 Skipping process-wide early GPU memory snapshot for 8 CUDA workers; each worker snapshots after NUMA binding before model load
2026-05-14T15:58:10.455352+08:00   INFO infer: main.rs:1069 Loading model...
2026-05-14T15:58:10.455576+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:336 CUDA bootstrap worker placement: worker=0 gpu=0 cuda_ordinal=Some(0) numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5 affinity_applied=true reason=applied
2026-05-14T15:58:10.455675+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:336 CUDA bootstrap worker placement: worker=1 gpu=1 cuda_ordinal=Some(1) numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5 affinity_applied=true reason=applied
2026-05-14T15:58:10.455737+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:336 CUDA bootstrap worker placement: worker=2 gpu=2 cuda_ordinal=Some(2) numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5 affinity_applied=true reason=applied
2026-05-14T15:58:10.455747+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:336 CUDA bootstrap worker placement: worker=3 gpu=3 cuda_ordinal=Some(3) numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5 affinity_applied=true reason=applied
2026-05-14T15:58:10.455859+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:336 CUDA bootstrap worker placement: worker=4 gpu=4 cuda_ordinal=Some(4) numa=Some(1) cpus=90 nics=eth3,eth4 affinity_applied=true reason=applied
2026-05-14T15:58:10.455930+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:336 CUDA bootstrap worker placement: worker=5 gpu=5 cuda_ordinal=Some(5) numa=Some(1) cpus=90 nics=eth3,eth4 affinity_applied=true reason=applied
2026-05-14T15:58:10.455946+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:336 CUDA bootstrap worker placement: worker=6 gpu=6 cuda_ordinal=Some(6) numa=Some(1) cpus=90 nics=eth3,eth4 affinity_applied=true reason=applied
2026-05-14T15:58:10.455969+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:336 CUDA bootstrap worker placement: worker=7 gpu=7 cuda_ordinal=Some(7) numa=Some(1) cpus=90 nics=eth3,eth4 affinity_applied=true reason=applied
2026-05-14T15:58:11.130343+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:374 GPU memory @ pre_model_load: free=101.68 GB / total=102.25 GB (delta vs post_cuda_ctx = +0 MB bytes — AOT cubins + lazy_static loaders)
2026-05-14T15:58:11.130379+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.130445+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.144963+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:374 GPU memory @ pre_model_load: free=101.68 GB / total=102.25 GB (delta vs post_cuda_ctx = +0 MB bytes — AOT cubins + lazy_static loaders)
2026-05-14T15:58:11.144995+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.145054+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.160482+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:374 GPU memory @ pre_model_load: free=101.68 GB / total=102.25 GB (delta vs post_cuda_ctx = +0 MB bytes — AOT cubins + lazy_static loaders)
2026-05-14T15:58:11.160506+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.160559+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.176195+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:374 GPU memory @ pre_model_load: free=101.68 GB / total=102.25 GB (delta vs post_cuda_ctx = +0 MB bytes — AOT cubins + lazy_static loaders)
2026-05-14T15:58:11.176235+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.176292+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.192264+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:374 GPU memory @ pre_model_load: free=101.68 GB / total=102.25 GB (delta vs post_cuda_ctx = +0 MB bytes — AOT cubins + lazy_static loaders)
2026-05-14T15:58:11.192297+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.192345+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.209808+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:374 GPU memory @ pre_model_load: free=101.68 GB / total=102.25 GB (delta vs post_cuda_ctx = +0 MB bytes — AOT cubins + lazy_static loaders)
2026-05-14T15:58:11.209830+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.209894+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.228381+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:374 GPU memory @ pre_model_load: free=101.68 GB / total=102.25 GB (delta vs post_cuda_ctx = +0 MB bytes — AOT cubins + lazy_static loaders)
2026-05-14T15:58:11.228411+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.228489+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.248939+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:374 GPU memory @ pre_model_load: free=101.68 GB / total=102.25 GB (delta vs post_cuda_ctx = +0 MB bytes — AOT cubins + lazy_static loaders)
2026-05-14T15:58:11.248964+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:11.249033+08:00   INFO infer::hf_hub: hf_hub.rs:49 Using local model path: /root/DeepSeek-V4-Flash
2026-05-14T15:58:14.491114+08:00   INFO infer::weight_loader: weight_loader.rs:77 Memory-mapped 46 shard(s) (159617.1 MB) in 0ms
2026-05-14T15:58:14.492943+08:00   INFO infer::weight_loader: weight_loader.rs:77 Memory-mapped 46 shard(s) (159617.1 MB) in 1ms
2026-05-14T15:58:14.493329+08:00   INFO infer::weight_loader: weight_loader.rs:77 Memory-mapped 46 shard(s) (159617.1 MB) in 1ms
2026-05-14T15:58:14.493340+08:00   INFO infer::weight_loader: weight_loader.rs:77 Memory-mapped 46 shard(s) (159617.1 MB) in 1ms
2026-05-14T15:58:14.493474+08:00   INFO infer::weight_loader: weight_loader.rs:77 Memory-mapped 46 shard(s) (159617.1 MB) in 1ms
2026-05-14T15:58:14.493627+08:00   INFO infer::weight_loader: weight_loader.rs:77 Memory-mapped 46 shard(s) (159617.1 MB) in 0ms
2026-05-14T15:58:14.494248+08:00   INFO infer::weight_loader: weight_loader.rs:77 Memory-mapped 46 shard(s) (159617.1 MB) in 0ms
2026-05-14T15:58:14.495195+08:00   INFO infer::weight_loader: weight_loader.rs:77 Memory-mapped 46 shard(s) (159617.1 MB) in 0ms
2026-05-14T15:58:27.358839+08:00   INFO infer::model::deepseek::weights: weights.rs:1915 DeepSeek V4 loaded GPU-resident layer weights: layers=43 local_experts_per_layer=32 tp_rank=2/8 ep_rank=2/8
2026-05-14T15:58:27.358870+08:00   INFO infer::model::deepseek::weights: weights.rs:313 DeepSeek V4 Phase 2A.1 CUDA top-level logits smoke loaded: sliding_window_layers=2 csa_layers=21 hca_layers=20 vocab_size=129280 hidden_size=4096 tp_rank=2/8 ep_rank=2/8 experts_per_rank=32 real_reference=false
2026-05-14T15:58:27.737194+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:388 GPU memory @ post_model_load: free=77.88 GB / total=102.25 GB
2026-05-14T15:58:27.737852+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:519 Scheduling envelope (resolved | SGLang-equiv): max_num_batched_tokens=16384 | 16384, chunked_prefill_size=16384 | 16384, max_prefill_tokens=16384 | 16384, mem_fraction_static=0.10 | 0.85, max_slots=1 | (n/a — SGLang has no fixed cap)
2026-05-14T15:58:27.737865+08:00   INFO infer::scheduler::cuda::core: core.rs:1010 KV cache: using explicit --max-seq-len=900000
2026-05-14T15:58:27.737945+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:132 Initialized state slot 1/1
2026-05-14T15:58:27.737958+08:00   WARN infer::scheduler::cuda::core::construction: construction.rs:197 TokenKVPool budget raised from 0.000 GB to 0.302 GB to honor explicit max_seq_len=900000 across 1 slot(s)
2026-05-14T15:58:27.737965+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:214 TokenKVPool budget: 0.3 GB (contiguous=0.0 GB, est_workspace=0.0 GB, fraction=10%)
2026-05-14T15:58:27.737969+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:333 TokenKVPool: 900000 max tokens (56250 pages @ page_size=16), 0.3 GB for 20 layers (1 kv_heads x 4 head_dim, kv_dim=4, format=FP8E4M3)
2026-05-14T15:58:27.739832+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:421 TokenKVPool FP8E4M3: data=7.2MB/layer scales=7.2MB/layer working=14.4MB
2026-05-14T15:58:27.755377+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:245 Scheduler ready: model=DeepSeek-V4-Flash, slots=1, seed=42, max_seq_len=900000, max_waiting=256, chunked_prefill_size=16384, max_num_batched_tokens=16384, max_prefill_tokens=16384, prefill_max_requests=none, schedule_policy=fcfs, admission_policy=queue-bound, cold_headroom=default, prefix_cache=on, short_prompt_bypass_tokens=256, stream_interval=1, host_pool=67.1MB, t1_min_prompt_tokens=4096
2026-05-14T15:58:27.755522+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:290 Scheduler worker placement: worker=2 gpu=2 numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5
2026-05-14T15:58:27.778897+08:00   INFO infer::scheduler::cuda::core::emit_worker: emit_worker.rs:77 CUDA detokenizer worker ready: worker=2 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:27.816393+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:562 CUDA scheduler worker ready: worker=2 gpu=2 cuda_ordinal=Some(2) numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:27.816421+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:46 Graph capture disabled (eager decode, e.g. LoRA); running eager warmup + cublasLt autotune for 1 batch sizes (max 1)...
2026-05-14T15:58:27.863237+08:00   INFO infer::model::deepseek::weights: weights.rs:1915 DeepSeek V4 loaded GPU-resident layer weights: layers=43 local_experts_per_layer=32 tp_rank=0/8 ep_rank=0/8
2026-05-14T15:58:27.863246+08:00   INFO infer::model::deepseek::weights: weights.rs:1915 DeepSeek V4 loaded GPU-resident layer weights: layers=43 local_experts_per_layer=32 tp_rank=1/8 ep_rank=1/8
2026-05-14T15:58:27.863266+08:00   INFO infer::model::deepseek::weights: weights.rs:313 DeepSeek V4 Phase 2A.1 CUDA top-level logits smoke loaded: sliding_window_layers=2 csa_layers=21 hca_layers=20 vocab_size=129280 hidden_size=4096 tp_rank=0/8 ep_rank=0/8 experts_per_rank=32 real_reference=false
2026-05-14T15:58:27.863251+08:00   INFO infer::model::deepseek::weights: weights.rs:1915 DeepSeek V4 loaded GPU-resident layer weights: layers=43 local_experts_per_layer=32 tp_rank=3/8 ep_rank=3/8
2026-05-14T15:58:27.863274+08:00   INFO infer::model::deepseek::weights: weights.rs:313 DeepSeek V4 Phase 2A.1 CUDA top-level logits smoke loaded: sliding_window_layers=2 csa_layers=21 hca_layers=20 vocab_size=129280 hidden_size=4096 tp_rank=1/8 ep_rank=1/8 experts_per_rank=32 real_reference=false
2026-05-14T15:58:27.863281+08:00   INFO infer::model::deepseek::weights: weights.rs:313 DeepSeek V4 Phase 2A.1 CUDA top-level logits smoke loaded: sliding_window_layers=2 csa_layers=21 hca_layers=20 vocab_size=129280 hidden_size=4096 tp_rank=3/8 ep_rank=3/8 experts_per_rank=32 real_reference=false
2026-05-14T15:58:28.895064+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:388 GPU memory @ post_model_load: free=77.88 GB / total=102.25 GB
2026-05-14T15:58:28.895723+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:519 Scheduling envelope (resolved | SGLang-equiv): max_num_batched_tokens=16384 | 16384, chunked_prefill_size=16384 | 16384, max_prefill_tokens=16384 | 16384, mem_fraction_static=0.10 | 0.85, max_slots=1 | (n/a — SGLang has no fixed cap)
2026-05-14T15:58:28.895736+08:00   INFO infer::scheduler::cuda::core: core.rs:1010 KV cache: using explicit --max-seq-len=900000
2026-05-14T15:58:28.895812+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:132 Initialized state slot 1/1
2026-05-14T15:58:28.895825+08:00   WARN infer::scheduler::cuda::core::construction: construction.rs:197 TokenKVPool budget raised from 0.000 GB to 0.302 GB to honor explicit max_seq_len=900000 across 1 slot(s)
2026-05-14T15:58:28.895832+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:214 TokenKVPool budget: 0.3 GB (contiguous=0.0 GB, est_workspace=0.0 GB, fraction=10%)
2026-05-14T15:58:28.895837+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:333 TokenKVPool: 900000 max tokens (56250 pages @ page_size=16), 0.3 GB for 20 layers (1 kv_heads x 4 head_dim, kv_dim=4, format=FP8E4M3)
2026-05-14T15:58:28.897138+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:421 TokenKVPool FP8E4M3: data=7.2MB/layer scales=7.2MB/layer working=14.4MB
2026-05-14T15:58:28.968028+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:245 Scheduler ready: model=DeepSeek-V4-Flash, slots=1, seed=42, max_seq_len=900000, max_waiting=256, chunked_prefill_size=16384, max_num_batched_tokens=16384, max_prefill_tokens=16384, prefill_max_requests=none, schedule_policy=fcfs, admission_policy=queue-bound, cold_headroom=default, prefix_cache=on, short_prompt_bypass_tokens=256, stream_interval=1, host_pool=67.1MB, t1_min_prompt_tokens=4096
2026-05-14T15:58:28.968479+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:290 Scheduler worker placement: worker=3 gpu=3 numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5
2026-05-14T15:58:28.968379+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:388 GPU memory @ post_model_load: free=77.88 GB / total=102.25 GB
2026-05-14T15:58:28.969011+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:519 Scheduling envelope (resolved | SGLang-equiv): max_num_batched_tokens=16384 | 16384, chunked_prefill_size=16384 | 16384, max_prefill_tokens=16384 | 16384, mem_fraction_static=0.10 | 0.85, max_slots=1 | (n/a — SGLang has no fixed cap)
2026-05-14T15:58:28.969023+08:00   INFO infer::scheduler::cuda::core: core.rs:1010 KV cache: using explicit --max-seq-len=900000
2026-05-14T15:58:28.968497+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:388 GPU memory @ post_model_load: free=77.88 GB / total=102.25 GB
2026-05-14T15:58:28.969095+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:132 Initialized state slot 1/1
2026-05-14T15:58:28.969116+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:519 Scheduling envelope (resolved | SGLang-equiv): max_num_batched_tokens=16384 | 16384, chunked_prefill_size=16384 | 16384, max_prefill_tokens=16384 | 16384, mem_fraction_static=0.10 | 0.85, max_slots=1 | (n/a — SGLang has no fixed cap)
2026-05-14T15:58:28.969125+08:00   INFO infer::scheduler::cuda::core: core.rs:1010 KV cache: using explicit --max-seq-len=900000
2026-05-14T15:58:28.969123+08:00   WARN infer::scheduler::cuda::core::construction: construction.rs:197 TokenKVPool budget raised from 0.000 GB to 0.302 GB to honor explicit max_seq_len=900000 across 1 slot(s)
2026-05-14T15:58:28.969130+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:214 TokenKVPool budget: 0.3 GB (contiguous=0.0 GB, est_workspace=0.0 GB, fraction=10%)
2026-05-14T15:58:28.969136+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:333 TokenKVPool: 900000 max tokens (56250 pages @ page_size=16), 0.3 GB for 20 layers (1 kv_heads x 4 head_dim, kv_dim=4, format=FP8E4M3)
2026-05-14T15:58:28.969186+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:132 Initialized state slot 1/1
2026-05-14T15:58:28.969216+08:00   WARN infer::scheduler::cuda::core::construction: construction.rs:197 TokenKVPool budget raised from 0.000 GB to 0.302 GB to honor explicit max_seq_len=900000 across 1 slot(s)
2026-05-14T15:58:28.969236+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:214 TokenKVPool budget: 0.3 GB (contiguous=0.0 GB, est_workspace=0.0 GB, fraction=10%)
2026-05-14T15:58:28.969240+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:333 TokenKVPool: 900000 max tokens (56250 pages @ page_size=16), 0.3 GB for 20 layers (1 kv_heads x 4 head_dim, kv_dim=4, format=FP8E4M3)
2026-05-14T15:58:28.970714+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:421 TokenKVPool FP8E4M3: data=7.2MB/layer scales=7.2MB/layer working=14.4MB
2026-05-14T15:58:28.970775+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:421 TokenKVPool FP8E4M3: data=7.2MB/layer scales=7.2MB/layer working=14.4MB
2026-05-14T15:58:28.994102+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:245 Scheduler ready: model=DeepSeek-V4-Flash, slots=1, seed=42, max_seq_len=900000, max_waiting=256, chunked_prefill_size=16384, max_num_batched_tokens=16384, max_prefill_tokens=16384, prefill_max_requests=none, schedule_policy=fcfs, admission_policy=queue-bound, cold_headroom=default, prefix_cache=on, short_prompt_bypass_tokens=256, stream_interval=1, host_pool=67.1MB, t1_min_prompt_tokens=4096
2026-05-14T15:58:28.994212+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:290 Scheduler worker placement: worker=0 gpu=0 numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5
2026-05-14T15:58:28.996761+08:00   INFO infer::scheduler::cuda::core::emit_worker: emit_worker.rs:77 CUDA detokenizer worker ready: worker=3 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:29.000024+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:245 Scheduler ready: model=DeepSeek-V4-Flash, slots=1, seed=42, max_seq_len=900000, max_waiting=256, chunked_prefill_size=16384, max_num_batched_tokens=16384, max_prefill_tokens=16384, prefill_max_requests=none, schedule_policy=fcfs, admission_policy=queue-bound, cold_headroom=default, prefix_cache=on, short_prompt_bypass_tokens=256, stream_interval=1, host_pool=67.1MB, t1_min_prompt_tokens=4096
2026-05-14T15:58:29.000103+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:290 Scheduler worker placement: worker=1 gpu=1 numa=Some(0) cpus=90 nics=eth0,eth1,eth2,eth5
2026-05-14T15:58:29.015232+08:00   INFO infer::scheduler::cuda::core::emit_worker: emit_worker.rs:77 CUDA detokenizer worker ready: worker=0 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:29.025602+08:00   INFO infer::scheduler::cuda::core::emit_worker: emit_worker.rs:77 CUDA detokenizer worker ready: worker=1 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:29.033980+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:562 CUDA scheduler worker ready: worker=3 gpu=3 cuda_ordinal=Some(3) numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:29.034005+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:46 Graph capture disabled (eager decode, e.g. LoRA); running eager warmup + cublasLt autotune for 1 batch sizes (max 1)...
2026-05-14T15:58:29.052955+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:562 CUDA scheduler worker ready: worker=0 gpu=0 cuda_ordinal=Some(0) numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:29.053008+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:46 Graph capture disabled (eager decode, e.g. LoRA); running eager warmup + cublasLt autotune for 1 batch sizes (max 1)...
2026-05-14T15:58:29.053009+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:562 CUDA scheduler worker ready: worker=1 gpu=1 cuda_ordinal=Some(1) numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:29.053026+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:46 Graph capture disabled (eager decode, e.g. LoRA); running eager warmup + cublasLt autotune for 1 batch sizes (max 1)...
2026-05-14T15:58:29.175095+08:00   INFO infer::model::deepseek::weights: weights.rs:1915 DeepSeek V4 loaded GPU-resident layer weights: layers=43 local_experts_per_layer=32 tp_rank=4/8 ep_rank=4/8
2026-05-14T15:58:29.175127+08:00   INFO infer::model::deepseek::weights: weights.rs:313 DeepSeek V4 Phase 2A.1 CUDA top-level logits smoke loaded: sliding_window_layers=2 csa_layers=21 hca_layers=20 vocab_size=129280 hidden_size=4096 tp_rank=4/8 ep_rank=4/8 experts_per_rank=32 real_reference=false
2026-05-14T15:58:29.176770+08:00   INFO infer::model::deepseek::weights: weights.rs:1915 DeepSeek V4 loaded GPU-resident layer weights: layers=43 local_experts_per_layer=32 tp_rank=7/8 ep_rank=7/8
2026-05-14T15:58:29.176789+08:00   INFO infer::model::deepseek::weights: weights.rs:313 DeepSeek V4 Phase 2A.1 CUDA top-level logits smoke loaded: sliding_window_layers=2 csa_layers=21 hca_layers=20 vocab_size=129280 hidden_size=4096 tp_rank=7/8 ep_rank=7/8 experts_per_rank=32 real_reference=false
2026-05-14T15:58:29.917588+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:388 GPU memory @ post_model_load: free=77.88 GB / total=102.25 GB
2026-05-14T15:58:29.918546+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:519 Scheduling envelope (resolved | SGLang-equiv): max_num_batched_tokens=16384 | 16384, chunked_prefill_size=16384 | 16384, max_prefill_tokens=16384 | 16384, mem_fraction_static=0.10 | 0.85, max_slots=1 | (n/a — SGLang has no fixed cap)
2026-05-14T15:58:29.918561+08:00   INFO infer::scheduler::cuda::core: core.rs:1010 KV cache: using explicit --max-seq-len=900000
2026-05-14T15:58:29.918639+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:132 Initialized state slot 1/1
2026-05-14T15:58:29.918654+08:00   WARN infer::scheduler::cuda::core::construction: construction.rs:197 TokenKVPool budget raised from 0.000 GB to 0.302 GB to honor explicit max_seq_len=900000 across 1 slot(s)
2026-05-14T15:58:29.918660+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:214 TokenKVPool budget: 0.3 GB (contiguous=0.0 GB, est_workspace=0.0 GB, fraction=10%)
2026-05-14T15:58:29.918665+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:333 TokenKVPool: 900000 max tokens (56250 pages @ page_size=16), 0.3 GB for 20 layers (1 kv_heads x 4 head_dim, kv_dim=4, format=FP8E4M3)
2026-05-14T15:58:29.959781+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:421 TokenKVPool FP8E4M3: data=7.2MB/layer scales=7.2MB/layer working=14.4MB
2026-05-14T15:58:29.965242+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:388 GPU memory @ post_model_load: free=77.88 GB / total=102.25 GB
2026-05-14T15:58:29.966278+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:519 Scheduling envelope (resolved | SGLang-equiv): max_num_batched_tokens=16384 | 16384, chunked_prefill_size=16384 | 16384, max_prefill_tokens=16384 | 16384, mem_fraction_static=0.10 | 0.85, max_slots=1 | (n/a — SGLang has no fixed cap)
2026-05-14T15:58:29.966290+08:00   INFO infer::scheduler::cuda::core: core.rs:1010 KV cache: using explicit --max-seq-len=900000
2026-05-14T15:58:29.966341+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:132 Initialized state slot 1/1
2026-05-14T15:58:29.966355+08:00   WARN infer::scheduler::cuda::core::construction: construction.rs:197 TokenKVPool budget raised from 0.000 GB to 0.302 GB to honor explicit max_seq_len=900000 across 1 slot(s)
2026-05-14T15:58:29.966361+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:214 TokenKVPool budget: 0.3 GB (contiguous=0.0 GB, est_workspace=0.0 GB, fraction=10%)
2026-05-14T15:58:29.966364+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:333 TokenKVPool: 900000 max tokens (56250 pages @ page_size=16), 0.3 GB for 20 layers (1 kv_heads x 4 head_dim, kv_dim=4, format=FP8E4M3)
2026-05-14T15:58:29.967542+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:421 TokenKVPool FP8E4M3: data=7.2MB/layer scales=7.2MB/layer working=14.4MB
2026-05-14T15:58:29.993368+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:245 Scheduler ready: model=DeepSeek-V4-Flash, slots=1, seed=42, max_seq_len=900000, max_waiting=256, chunked_prefill_size=16384, max_num_batched_tokens=16384, max_prefill_tokens=16384, prefill_max_requests=none, schedule_policy=fcfs, admission_policy=queue-bound, cold_headroom=default, prefix_cache=on, short_prompt_bypass_tokens=256, stream_interval=1, host_pool=67.1MB, t1_min_prompt_tokens=4096
2026-05-14T15:58:29.993471+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:290 Scheduler worker placement: worker=4 gpu=4 numa=Some(1) cpus=90 nics=eth3,eth4
2026-05-14T15:58:29.999058+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:245 Scheduler ready: model=DeepSeek-V4-Flash, slots=1, seed=42, max_seq_len=900000, max_waiting=256, chunked_prefill_size=16384, max_num_batched_tokens=16384, max_prefill_tokens=16384, prefill_max_requests=none, schedule_policy=fcfs, admission_policy=queue-bound, cold_headroom=default, prefix_cache=on, short_prompt_bypass_tokens=256, stream_interval=1, host_pool=67.1MB, t1_min_prompt_tokens=4096
2026-05-14T15:58:29.999126+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:290 Scheduler worker placement: worker=7 gpu=7 numa=Some(1) cpus=90 nics=eth3,eth4
2026-05-14T15:58:30.014322+08:00   INFO infer::scheduler::cuda::core::emit_worker: emit_worker.rs:77 CUDA detokenizer worker ready: worker=4 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:30.021152+08:00   INFO infer::scheduler::cuda::core::emit_worker: emit_worker.rs:77 CUDA detokenizer worker ready: worker=7 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:30.048567+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:562 CUDA scheduler worker ready: worker=4 gpu=4 cuda_ordinal=Some(4) numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:30.048618+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:46 Graph capture disabled (eager decode, e.g. LoRA); running eager warmup + cublasLt autotune for 1 batch sizes (max 1)...
2026-05-14T15:58:30.055898+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:562 CUDA scheduler worker ready: worker=7 gpu=7 cuda_ordinal=Some(7) numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:30.055919+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:46 Graph capture disabled (eager decode, e.g. LoRA); running eager warmup + cublasLt autotune for 1 batch sizes (max 1)...
2026-05-14T15:58:30.081497+08:00   INFO infer::model::deepseek::weights: weights.rs:1915 DeepSeek V4 loaded GPU-resident layer weights: layers=43 local_experts_per_layer=32 tp_rank=6/8 ep_rank=6/8
2026-05-14T15:58:30.081519+08:00   INFO infer::model::deepseek::weights: weights.rs:313 DeepSeek V4 Phase 2A.1 CUDA top-level logits smoke loaded: sliding_window_layers=2 csa_layers=21 hca_layers=20 vocab_size=129280 hidden_size=4096 tp_rank=6/8 ep_rank=6/8 experts_per_rank=32 real_reference=false
2026-05-14T15:58:30.486593+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:388 GPU memory @ post_model_load: free=77.88 GB / total=102.25 GB
2026-05-14T15:58:30.487582+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:519 Scheduling envelope (resolved | SGLang-equiv): max_num_batched_tokens=16384 | 16384, chunked_prefill_size=16384 | 16384, max_prefill_tokens=16384 | 16384, mem_fraction_static=0.10 | 0.85, max_slots=1 | (n/a — SGLang has no fixed cap)
2026-05-14T15:58:30.487838+08:00   INFO infer::scheduler::cuda::core: core.rs:1010 KV cache: using explicit --max-seq-len=900000
2026-05-14T15:58:30.487921+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:132 Initialized state slot 1/1
2026-05-14T15:58:30.489873+08:00   WARN infer::scheduler::cuda::core::construction: construction.rs:197 TokenKVPool budget raised from 0.000 GB to 0.302 GB to honor explicit max_seq_len=900000 across 1 slot(s)
2026-05-14T15:58:30.489881+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:214 TokenKVPool budget: 0.3 GB (contiguous=0.0 GB, est_workspace=0.0 GB, fraction=10%)
2026-05-14T15:58:30.489885+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:333 TokenKVPool: 900000 max tokens (56250 pages @ page_size=16), 0.3 GB for 20 layers (1 kv_heads x 4 head_dim, kv_dim=4, format=FP8E4M3)
2026-05-14T15:58:30.511874+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:421 TokenKVPool FP8E4M3: data=7.2MB/layer scales=7.2MB/layer working=14.4MB
2026-05-14T15:58:30.529926+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:245 Scheduler ready: model=DeepSeek-V4-Flash, slots=1, seed=42, max_seq_len=900000, max_waiting=256, chunked_prefill_size=16384, max_num_batched_tokens=16384, max_prefill_tokens=16384, prefill_max_requests=none, schedule_policy=fcfs, admission_policy=queue-bound, cold_headroom=default, prefix_cache=on, short_prompt_bypass_tokens=256, stream_interval=1, host_pool=67.1MB, t1_min_prompt_tokens=4096
2026-05-14T15:58:30.530044+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:290 Scheduler worker placement: worker=6 gpu=6 numa=Some(1) cpus=90 nics=eth3,eth4
2026-05-14T15:58:30.553400+08:00   INFO infer::scheduler::cuda::core::emit_worker: emit_worker.rs:77 CUDA detokenizer worker ready: worker=6 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:30.577540+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:562 CUDA scheduler worker ready: worker=6 gpu=6 cuda_ordinal=Some(6) numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:30.577555+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:46 Graph capture disabled (eager decode, e.g. LoRA); running eager warmup + cublasLt autotune for 1 batch sizes (max 1)...
2026-05-14T15:58:30.737090+08:00   INFO infer::model::deepseek::weights: weights.rs:1915 DeepSeek V4 loaded GPU-resident layer weights: layers=43 local_experts_per_layer=32 tp_rank=5/8 ep_rank=5/8
2026-05-14T15:58:30.737118+08:00   INFO infer::model::deepseek::weights: weights.rs:313 DeepSeek V4 Phase 2A.1 CUDA top-level logits smoke loaded: sliding_window_layers=2 csa_layers=21 hca_layers=20 vocab_size=129280 hidden_size=4096 tp_rank=5/8 ep_rank=5/8 experts_per_rank=32 real_reference=false
2026-05-14T15:58:31.156790+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:388 GPU memory @ post_model_load: free=77.88 GB / total=102.25 GB
2026-05-14T15:58:31.157442+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:519 Scheduling envelope (resolved | SGLang-equiv): max_num_batched_tokens=16384 | 16384, chunked_prefill_size=16384 | 16384, max_prefill_tokens=16384 | 16384, mem_fraction_static=0.10 | 0.85, max_slots=1 | (n/a — SGLang has no fixed cap)
2026-05-14T15:58:31.157466+08:00   INFO infer::scheduler::cuda::core: core.rs:1010 KV cache: using explicit --max-seq-len=900000
2026-05-14T15:58:31.157561+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:132 Initialized state slot 1/1
2026-05-14T15:58:31.157576+08:00   WARN infer::scheduler::cuda::core::construction: construction.rs:197 TokenKVPool budget raised from 0.000 GB to 0.302 GB to honor explicit max_seq_len=900000 across 1 slot(s)
2026-05-14T15:58:31.157582+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:214 TokenKVPool budget: 0.3 GB (contiguous=0.0 GB, est_workspace=0.0 GB, fraction=10%)
2026-05-14T15:58:31.157586+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:333 TokenKVPool: 900000 max tokens (56250 pages @ page_size=16), 0.3 GB for 20 layers (1 kv_heads x 4 head_dim, kv_dim=4, format=FP8E4M3)
2026-05-14T15:58:31.158882+08:00   INFO cuda_kernels::paged_kv: paged_kv.rs:421 TokenKVPool FP8E4M3: data=7.2MB/layer scales=7.2MB/layer working=14.4MB
2026-05-14T15:58:31.173819+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:245 Scheduler ready: model=DeepSeek-V4-Flash, slots=1, seed=42, max_seq_len=900000, max_waiting=256, chunked_prefill_size=16384, max_num_batched_tokens=16384, max_prefill_tokens=16384, prefill_max_requests=none, schedule_policy=fcfs, admission_policy=queue-bound, cold_headroom=default, prefix_cache=on, short_prompt_bypass_tokens=256, stream_interval=1, host_pool=67.1MB, t1_min_prompt_tokens=4096
2026-05-14T15:58:31.173946+08:00   INFO infer::scheduler::cuda::core::construction: construction.rs:290 Scheduler worker placement: worker=5 gpu=5 numa=Some(1) cpus=90 nics=eth3,eth4
2026-05-14T15:58:31.198681+08:00   INFO infer::scheduler::cuda::core::emit_worker: emit_worker.rs:77 CUDA detokenizer worker ready: worker=5 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:31.223400+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:562 CUDA scheduler worker ready: worker=5 gpu=5 cuda_ordinal=Some(5) numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:31.223413+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:46 Graph capture disabled (eager decode, e.g. LoRA); running eager warmup + cublasLt autotune for 1 batch sizes (max 1)...
2026-05-14T15:58:31.242651+08:00   INFO infer: main.rs:1141 Config: model_path=/root/DeepSeek-V4-Flash, cuda_graph=false, num_slots=1 (explicit), kv_cache_mode=fp8 (explicit), cuda_workers=8
2026-05-14T15:58:31.242672+08:00   INFO infer: main.rs:1155 KV cache layout: contiguous=BF16, paged_pool=FP8E4M3
2026-05-14T15:58:31.242676+08:00   INFO infer: main.rs:1158 Model loaded: elapsed_ms=20787, model_id=DeepSeek-V4-Flash
2026-05-14T15:58:31.242679+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:418 Waiting for scheduler warmup before accepting traffic (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.709486+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:119 Autotuning cublasLt GEMM algorithms (1 shapes)...
2026-05-14T15:58:31.709513+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:126 cublasLt autotune done in 0ms
2026-05-14T15:58:31.709863+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:119 Autotuning cublasLt GEMM algorithms (1 shapes)...
2026-05-14T15:58:31.709887+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:126 cublasLt autotune done in 0ms
2026-05-14T15:58:31.709976+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:119 Autotuning cublasLt GEMM algorithms (1 shapes)...
2026-05-14T15:58:31.709993+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:126 cublasLt autotune done in 0ms
2026-05-14T15:58:31.710134+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:119 Autotuning cublasLt GEMM algorithms (1 shapes)...
2026-05-14T15:58:31.710152+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:126 cublasLt autotune done in 0ms
2026-05-14T15:58:31.710281+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:119 Autotuning cublasLt GEMM algorithms (1 shapes)...
2026-05-14T15:58:31.710296+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:126 cublasLt autotune done in 0ms
2026-05-14T15:58:31.710366+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:119 Autotuning cublasLt GEMM algorithms (1 shapes)...
2026-05-14T15:58:31.710379+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:126 cublasLt autotune done in 0ms
2026-05-14T15:58:31.710563+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:119 Autotuning cublasLt GEMM algorithms (1 shapes)...
2026-05-14T15:58:31.710579+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:126 cublasLt autotune done in 0ms
2026-05-14T15:58:31.710593+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:187 Pass 3 prefill warmup disabled by INFER_PREFILL_WARMUP=0
2026-05-14T15:58:31.710601+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:174 Eager warmup + cublasLt autotune done in 3894ms (decode=1 batch sizes, prefill=0 batch sizes, max decode 1)
2026-05-14T15:58:31.710607+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:115 Scheduler run loop started
2026-05-14T15:58:31.710643+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:119 Autotuning cublasLt GEMM algorithms (1 shapes)...
2026-05-14T15:58:31.710656+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:126 cublasLt autotune done in 0ms
2026-05-14T15:58:31.716489+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:187 Pass 3 prefill warmup disabled by INFER_PREFILL_WARMUP=0
2026-05-14T15:58:31.716498+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:174 Eager warmup + cublasLt autotune done in 2663ms (decode=1 batch sizes, prefill=0 batch sizes, max decode 1)
2026-05-14T15:58:31.716505+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:115 Scheduler run loop started
2026-05-14T15:58:31.716516+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:428 Scheduler warmup complete; HTTP readiness may open (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.716532+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:418 Waiting for scheduler warmup before accepting traffic (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.716810+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:187 Pass 3 prefill warmup disabled by INFER_PREFILL_WARMUP=0
2026-05-14T15:58:31.716821+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:174 Eager warmup + cublasLt autotune done in 2664ms (decode=1 batch sizes, prefill=0 batch sizes, max decode 1)
2026-05-14T15:58:31.716829+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:115 Scheduler run loop started
2026-05-14T15:58:31.716833+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:428 Scheduler warmup complete; HTTP readiness may open (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.716837+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:418 Waiting for scheduler warmup before accepting traffic (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.716851+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:428 Scheduler warmup complete; HTTP readiness may open (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.716854+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:418 Waiting for scheduler warmup before accepting traffic (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.717028+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:187 Pass 3 prefill warmup disabled by INFER_PREFILL_WARMUP=0
2026-05-14T15:58:31.717037+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:174 Eager warmup + cublasLt autotune done in 1668ms (decode=1 batch sizes, prefill=0 batch sizes, max decode 1)
2026-05-14T15:58:31.717042+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:115 Scheduler run loop started
2026-05-14T15:58:31.717043+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:187 Pass 3 prefill warmup disabled by INFER_PREFILL_WARMUP=0
2026-05-14T15:58:31.717050+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:174 Eager warmup + cublasLt autotune done in 1661ms (decode=1 batch sizes, prefill=0 batch sizes, max decode 1)
2026-05-14T15:58:31.717056+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:115 Scheduler run loop started
2026-05-14T15:58:31.717135+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:187 Pass 3 prefill warmup disabled by INFER_PREFILL_WARMUP=0
2026-05-14T15:58:31.717143+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:174 Eager warmup + cublasLt autotune done in 1140ms (decode=1 batch sizes, prefill=0 batch sizes, max decode 1)
2026-05-14T15:58:31.717147+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:115 Scheduler run loop started
2026-05-14T15:58:31.717169+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:187 Pass 3 prefill warmup disabled by INFER_PREFILL_WARMUP=0
2026-05-14T15:58:31.717170+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:187 Pass 3 prefill warmup disabled by INFER_PREFILL_WARMUP=0
2026-05-14T15:58:31.717187+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:174 Eager warmup + cublasLt autotune done in 494ms (decode=1 batch sizes, prefill=0 batch sizes, max decode 1)
2026-05-14T15:58:31.717197+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:115 Scheduler run loop started
2026-05-14T15:58:31.717181+08:00   INFO infer::scheduler::cuda::core::warmup: warmup.rs:174 Eager warmup + cublasLt autotune done in 2683ms (decode=1 batch sizes, prefill=0 batch sizes, max decode 1)
2026-05-14T15:58:31.717206+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:115 Scheduler run loop started
2026-05-14T15:58:31.717209+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:428 Scheduler warmup complete; HTTP readiness may open (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.717212+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:418 Waiting for scheduler warmup before accepting traffic (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.717214+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:428 Scheduler warmup complete; HTTP readiness may open (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.717216+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:418 Waiting for scheduler warmup before accepting traffic (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.717219+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:428 Scheduler warmup complete; HTTP readiness may open (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.717230+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:418 Waiting for scheduler warmup before accepting traffic (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.717232+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:428 Scheduler warmup complete; HTTP readiness may open (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.717234+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:418 Waiting for scheduler warmup before accepting traffic (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.717236+08:00   INFO infer::backend::cuda::bootstrap: bootstrap.rs:428 Scheduler warmup complete; HTTP readiness may open (model=DeepSeek-V4-Flash)
2026-05-14T15:58:31.937973+08:00   INFO infer: main.rs:1194 Using DeepSeek distributed scheduler group: ranks=8
2026-05-14T15:58:32.013341+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=0 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.032170+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=1 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.050580+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=2 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.068889+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=3 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.087212+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=4 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.105473+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=5 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.123720+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=6 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.142077+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=7 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.160373+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=8 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.178663+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=9 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.196904+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=10 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.215250+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=11 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.233573+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=12 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.251946+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=13 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.270271+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=14 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.288520+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=0 worker=15 numa=Some(0) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.306971+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=0 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.325226+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=1 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.343607+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=2 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.361806+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=3 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.380042+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=4 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.398252+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=5 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.416498+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=6 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.434760+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=7 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.453153+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=8 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.471419+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=9 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.489630+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=10 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.507895+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=11 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.526179+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=12 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.544477+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=13 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.562770+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=14 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.581026+08:00   INFO infer::http_server::preprocess: preprocess.rs:105 Tokenizer worker ready: group=1 worker=15 numa=Some(1) cpus=90 affinity_applied=true reason=applied
2026-05-14T15:58:32.590497+08:00   INFO infer: main.rs:1221 Server listening on 0.0.0.0:18084
2026-05-14T15:59:48.918612+08:00   INFO infer::http_server::handlers: handlers.rs:998 chat/completions: messages=1, prompt_bytes=102, max_tokens=4, stream=false
2026-05-14T15:59:48.919848+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 0 → slot 0 (prompt=14 tokens, queue=0)
2026-05-14T15:59:48.919868+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 0: prefix MISS
2026-05-14T15:59:48.919875+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 0: chunked prefill starting (14 effective tokens, chunk_size=16384)
2026-05-14T15:59:48.920948+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 0 → slot 0 (prompt=14 tokens, queue=0)
2026-05-14T15:59:48.920958+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 0 → slot 0 (prompt=14 tokens, queue=0)
2026-05-14T15:59:48.920965+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 0: prefix MISS
2026-05-14T15:59:48.920978+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 0: prefix MISS
2026-05-14T15:59:48.920982+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 0: chunked prefill starting (14 effective tokens, chunk_size=16384)
2026-05-14T15:59:48.920981+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 0: chunked prefill starting (14 effective tokens, chunk_size=16384)
2026-05-14T15:59:48.920982+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 0 → slot 0 (prompt=14 tokens, queue=0)
2026-05-14T15:59:48.920992+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 0 → slot 0 (prompt=14 tokens, queue=0)
2026-05-14T15:59:48.921011+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 0: prefix MISS
2026-05-14T15:59:48.921014+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 0: prefix MISS
2026-05-14T15:59:48.921015+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 0: chunked prefill starting (14 effective tokens, chunk_size=16384)
2026-05-14T15:59:48.921020+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 0: chunked prefill starting (14 effective tokens, chunk_size=16384)
2026-05-14T15:59:48.921702+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 0 → slot 0 (prompt=14 tokens, queue=0)
2026-05-14T15:59:48.921720+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 0: prefix MISS
2026-05-14T15:59:48.921718+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 0 → slot 0 (prompt=14 tokens, queue=0)
2026-05-14T15:59:48.921727+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 0 → slot 0 (prompt=14 tokens, queue=0)
2026-05-14T15:59:48.921724+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 0: chunked prefill starting (14 effective tokens, chunk_size=16384)
2026-05-14T15:59:48.921741+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 0: prefix MISS
2026-05-14T15:59:48.921745+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 0: chunked prefill starting (14 effective tokens, chunk_size=16384)
2026-05-14T15:59:48.921740+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 0: prefix MISS
2026-05-14T15:59:48.921754+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 0: chunked prefill starting (14 effective tokens, chunk_size=16384)
2026-05-14T15:59:49.229299+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=62us decode=0us emit=0us prefill=307535us total=307597us batch=1
2026-05-14T15:59:49.229301+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=82us decode=0us emit=0us prefill=307540us total=307622us batch=1
2026-05-14T15:59:49.229301+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=79us decode=0us emit=0us prefill=307526us total=307605us batch=1
2026-05-14T15:59:49.229301+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=81us decode=0us emit=0us prefill=308298us total=308379us batch=1
2026-05-14T15:59:49.229301+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=228us decode=0us emit=0us prefill=309390us total=309618us batch=1
2026-05-14T15:59:49.229298+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=76us decode=0us emit=0us prefill=308258us total=308334us batch=1
2026-05-14T15:59:49.229303+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=68us decode=0us emit=0us prefill=308306us total=308374us batch=1
2026-05-14T15:59:49.229301+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=82us decode=0us emit=0us prefill=308267us total=308349us batch=1
2026-05-14T15:59:49.229420+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=61us step=307572us cleanup=29us total=307728us active=1
2026-05-14T15:59:49.229479+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=81us step=307583us cleanup=30us total=307811us active=1
2026-05-14T15:59:49.229493+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=78us step=307579us cleanup=30us total=307810us active=1
2026-05-14T15:59:49.229524+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=80us step=308363us cleanup=29us total=308612us active=1
2026-05-14T15:59:49.229545+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=217us step=309484us cleanup=30us total=309879us active=1
2026-05-14T15:59:49.229565+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=74us step=308348us cleanup=30us total=308611us active=1
2026-05-14T15:59:49.229583+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=67us step=308394us cleanup=29us total=308661us active=1
2026-05-14T15:59:49.229599+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=79us step=308368us cleanup=28us total=308656us active=1
2026-05-14T15:59:49.346914+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=117409us emit=0us prefill=0us total=117413us batch=1
2026-05-14T15:59:49.346953+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=117435us cleanup=22us total=117459us active=1
2026-05-14T15:59:49.346949+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=117436us emit=0us prefill=0us total=117438us batch=1
2026-05-14T15:59:49.346988+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=117456us cleanup=23us total=117481us active=1
2026-05-14T15:59:49.347000+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=117396us emit=0us prefill=0us total=117398us batch=1
2026-05-14T15:59:49.347004+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=117460us emit=0us prefill=0us total=117463us batch=1
2026-05-14T15:59:49.347045+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=117486us cleanup=21us total=117509us active=1
2026-05-14T15:59:49.347045+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=117421us cleanup=25us total=117448us active=1
2026-05-14T15:59:49.347107+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=117489us emit=0us prefill=0us total=117491us batch=1
2026-05-14T15:59:49.347118+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=117556us emit=0us prefill=0us total=117558us batch=1
2026-05-14T15:59:49.347146+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=117510us cleanup=23us total=117534us active=1
2026-05-14T15:59:49.347142+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=117699us emit=0us prefill=0us total=117702us batch=1
2026-05-14T15:59:49.347153+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=117574us cleanup=22us total=117598us active=1
2026-05-14T15:59:49.347174+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=117590us emit=0us prefill=0us total=117592us batch=1
2026-05-14T15:59:49.347180+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=117722us cleanup=22us total=117746us active=1
2026-05-14T15:59:49.347213+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=117611us cleanup=22us total=117635us active=1
2026-05-14T15:59:49.465607+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=118367us emit=4us prefill=0us total=118373us batch=1
2026-05-14T15:59:49.465637+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=118391us cleanup=15us total=118407us active=1
2026-05-14T15:59:49.465654+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=118673us emit=5us prefill=0us total=118679us batch=1
2026-05-14T15:59:49.465690+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=118708us cleanup=20us total=118729us active=1
2026-05-14T15:59:49.465789+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=118718us emit=4us prefill=0us total=118723us batch=1
2026-05-14T15:59:49.465824+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=118742us cleanup=21us total=118764us active=1
2026-05-14T15:59:49.465986+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=118821us emit=4us prefill=0us total=118827us batch=1
2026-05-14T15:59:49.466018+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=118847us cleanup=15us total=118864us active=1
2026-05-14T15:59:49.466020+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=118848us emit=3us prefill=0us total=118852us batch=1
2026-05-14T15:59:49.466058+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=118873us cleanup=21us total=118896us active=1
2026-05-14T15:59:49.466062+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=118857us emit=4us prefill=0us total=118862us batch=1
2026-05-14T15:59:49.466094+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=118882us cleanup=16us total=118900us active=1
2026-05-14T15:59:49.466106+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=119096us emit=4us prefill=0us total=119101us batch=1
2026-05-14T15:59:49.466129+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=119063us emit=4us prefill=0us total=119069us batch=1
2026-05-14T15:59:49.466135+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=119119us cleanup=15us total=119136us active=1
2026-05-14T15:59:49.466166+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=119092us cleanup=18us total=119111us active=1
2026-05-14T15:59:49.584802+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=118692us emit=3us prefill=0us total=118696us batch=1
2026-05-14T15:59:49.584833+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=118715us cleanup=14us total=118731us active=1
2026-05-14T15:59:49.584913+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=119258us emit=4us prefill=0us total=119263us batch=1
2026-05-14T15:59:49.584922+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=118760us emit=3us prefill=0us total=118764us batch=1
2026-05-14T15:59:49.584939+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=119279us cleanup=14us total=119295us active=1
2026-05-14T15:59:49.584951+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=118782us cleanup=14us total=118798us active=1
2026-05-14T15:59:49.585057+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=118981us emit=4us prefill=0us total=118986us batch=1
2026-05-14T15:59:49.585066+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=118882us emit=4us prefill=0us total=118887us batch=1
2026-05-14T15:59:49.585083+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=119047us emit=4us prefill=0us total=119052us batch=1
2026-05-14T15:59:49.585091+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=119006us cleanup=19us total=119027us active=1
2026-05-14T15:59:49.585094+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=118902us cleanup=17us total=118920us active=1
2026-05-14T15:59:49.585089+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=119249us emit=3us prefill=0us total=119253us batch=1
2026-05-14T15:59:49.585111+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=119070us cleanup=14us total=119085us active=1
2026-05-14T15:59:49.585126+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=119274us cleanup=19us total=119295us active=1
2026-05-14T15:59:49.585168+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=119459us emit=4us prefill=0us total=119464us batch=1
2026-05-14T15:59:49.585200+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=119483us cleanup=18us total=119503us active=1
2026-05-14T15:59:49.585630+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 0 done: 4 tokens (active=0, waiting=0)
2026-05-14T15:59:49.585631+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 0 done: 4 tokens (active=0, waiting=0)
2026-05-14T15:59:49.585633+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 0 done: 4 tokens (active=0, waiting=0)
2026-05-14T15:59:49.585636+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 0 done: 4 tokens (active=0, waiting=0)
2026-05-14T15:59:49.585640+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 0 done: 4 tokens (active=0, waiting=0)
2026-05-14T15:59:49.585641+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 0 done: 4 tokens (active=0, waiting=0)
2026-05-14T15:59:49.585645+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 0 done: 4 tokens (active=0, waiting=0)
2026-05-14T15:59:49.585642+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 0 done: 4 tokens (active=0, waiting=0)
2026-05-14T15:59:49.585665+08:00   INFO infer::request_trace: handlers.rs:220 request_trace {"chunks_seen":5,"completion_tokens":4,"error":null,"finish_reason":"length","kv":{"fetch_backpressure":false,"fetch_queue_depth":0,"fetch_waiters":0,"gpu_util":0.0,"store_backpressure":false,"store_queue_depth":0},"max_tokens":4,"prefix":{"direct_gpu_attach":false,"hit_rate":0.0,"lookup_latency_us":0,"lookup_reusable_tokens":0,"matched_tokens":0,"prefetch":false,"ready_on_gpu":false,"recompute":false,"request_hit_rate":0.0,"request_skip_rate":0.0,"resume_prefill_tokens":14,"skip_rate":0.0,"staged":false},"preprocess":{"queue_depth":0,"tokenize_us":392,"wait_us":1},"prompt_bytes":102,"prompt_tokens":14,"request_id":"http-a04daf5d-b6f4-4554-9193-2987c7fb58f2","route":"/v1/chat/completions","scheduler":{"active":0,"batch_width":0,"decode_tokens":0,"loop_us":{"cleanup":27,"total":256544},"phase_us":{"admission":52,"decode":106014,"emit":4,"prefill":201768,"total":230784},"pipeline_us":{"cpu_plan":1,"gpu_command_queue_depth":0,"gpu_completion_wait":319,"snapshot":0},"prefill_queue":0,"prefill_tokens":0,"running_batch":0,"scheduled_decode_rows":0,"scheduled_prefill_rows":0,"scheduled_rows":0,"step_last_s":0.000676,"waiting":0},"stream":false,"terminal_seen":true,"text_bytes":17,"throughput":{"completion_tokens_per_s_e2e":5.996917866071979,"prompt_tokens_per_s_at_ttft":45.05079960342425,"total_tokens_per_s_e2e":26.986130397323908},"token_ids_seen":4,"total_ms":667.0093019999999,"total_tokens":18,"ttft_ms":310.7603}
2026-05-14T15:59:49.585700+08:00   INFO infer::http_server::handlers: handlers.rs:1063 chat/completions done: prompt_tokens=14, completion_tokens=4
2026-05-14T15:59:50.370759+08:00   INFO infer: main.rs:1323 cuProfilerStart fired (nsys capture begin)
2026-05-14T15:59:50.622757+08:00   INFO infer::http_server::handlers: handlers.rs:998 chat/completions: messages=1, prompt_bytes=202, max_tokens=32, stream=true
2026-05-14T15:59:50.624567+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 1 → slot 0 (prompt=29 tokens, queue=0)
2026-05-14T15:59:50.624567+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 1 → slot 0 (prompt=29 tokens, queue=0)
2026-05-14T15:59:50.624595+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 1 → slot 0 (prompt=29 tokens, queue=0)
2026-05-14T15:59:50.624619+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 1: prefix MISS
2026-05-14T15:59:50.624568+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 1 → slot 0 (prompt=29 tokens, queue=0)
2026-05-14T15:59:50.624675+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 1: prefix MISS
2026-05-14T15:59:50.624590+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 1: prefix MISS
2026-05-14T15:59:50.624584+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 1 → slot 0 (prompt=29 tokens, queue=0)
2026-05-14T15:59:50.624742+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 1: prefix MISS
2026-05-14T15:59:50.624601+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 1: prefix MISS
2026-05-14T15:59:50.624570+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 1 → slot 0 (prompt=29 tokens, queue=0)
2026-05-14T15:59:50.624815+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 1: prefix MISS
2026-05-14T15:59:50.624597+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 1 → slot 0 (prompt=29 tokens, queue=0)
2026-05-14T15:59:50.624856+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 1: prefix MISS
2026-05-14T15:59:50.624602+08:00   INFO infer::scheduler::cuda::runtime::admission: admission.rs:663 Request 1 → slot 0 (prompt=29 tokens, queue=0)
2026-05-14T15:59:50.624885+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:333 Request 1: prefix MISS
2026-05-14T15:59:50.637383+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 1: chunked prefill starting (29 effective tokens, chunk_size=16384)
2026-05-14T15:59:50.638059+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 1: chunked prefill starting (29 effective tokens, chunk_size=16384)
2026-05-14T15:59:50.639439+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 1: chunked prefill starting (29 effective tokens, chunk_size=16384)
2026-05-14T15:59:50.639462+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 1: chunked prefill starting (29 effective tokens, chunk_size=16384)
2026-05-14T15:59:50.639729+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 1: chunked prefill starting (29 effective tokens, chunk_size=16384)
2026-05-14T15:59:50.639893+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 1: chunked prefill starting (29 effective tokens, chunk_size=16384)
2026-05-14T15:59:50.640281+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 1: chunked prefill starting (29 effective tokens, chunk_size=16384)
2026-05-14T15:59:50.640499+08:00   INFO infer::scheduler::cuda::prefill: prefill.rs:376 Request 1: chunked prefill starting (29 effective tokens, chunk_size=16384)
2026-05-14T15:59:51.043578+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=15987us decode=0us emit=0us prefill=403057us total=419044us batch=1
2026-05-14T15:59:51.043576+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=12877us decode=0us emit=0us prefill=406164us total=419041us batch=1
2026-05-14T15:59:51.043612+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=14948us decode=0us emit=0us prefill=404125us total=419073us batch=1
2026-05-14T15:59:51.043584+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=14885us decode=0us emit=0us prefill=404112us total=418997us batch=1
2026-05-14T15:59:51.043600+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=15333us decode=0us emit=0us prefill=403688us total=419021us batch=1
2026-05-14T15:59:51.043639+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=13503us decode=0us emit=0us prefill=405556us total=419059us batch=1
2026-05-14T15:59:51.043626+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=15184us decode=0us emit=0us prefill=403873us total=419057us batch=1
2026-05-14T15:59:51.043651+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=prefill admission=15771us decode=0us emit=0us prefill=403343us total=419114us batch=1
2026-05-14T15:59:51.043687+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=15986us step=403091us cleanup=30us total=419161us active=1
2026-05-14T15:59:51.043720+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=12873us step=406225us cleanup=30us total=419196us active=1
2026-05-14T15:59:51.043751+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=14883us step=404178us cleanup=28us total=419173us active=1
2026-05-14T15:59:51.043771+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=14946us step=404151us cleanup=30us total=419241us active=1
2026-05-14T15:59:51.043790+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=13501us step=405577us cleanup=29us total=419218us active=1
2026-05-14T15:59:51.043805+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=15183us step=403916us cleanup=27us total=419244us active=1
2026-05-14T15:59:51.043822+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=15331us step=403746us cleanup=28us total=419250us active=1
2026-05-14T15:59:51.043840+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=15769us step=403365us cleanup=29us total=419311us active=1
2026-05-14T15:59:51.233730+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=189984us emit=0us prefill=0us total=189988us batch=1
2026-05-14T15:59:51.233784+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190018us cleanup=30us total=190051us active=1
2026-05-14T15:59:51.233803+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=190024us emit=0us prefill=0us total=190028us batch=1
2026-05-14T15:59:51.233852+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190056us cleanup=27us total=190085us active=1
2026-05-14T15:59:51.234263+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=190466us emit=0us prefill=0us total=190470us batch=1
2026-05-14T15:59:51.234290+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=5us decode=190567us emit=0us prefill=0us total=190572us batch=1
2026-05-14T15:59:51.234313+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=2us step=190496us cleanup=29us total=190528us active=1
2026-05-14T15:59:51.234335+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190598us cleanup=29us total=190630us active=1
2026-05-14T15:59:51.234507+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190643us emit=0us prefill=0us total=190646us batch=1
2026-05-14T15:59:51.234552+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190668us cleanup=29us total=190700us active=1
2026-05-14T15:59:51.234559+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190746us emit=0us prefill=0us total=190749us batch=1
2026-05-14T15:59:51.234606+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190774us cleanup=28us total=190804us active=1
2026-05-14T15:59:51.234625+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190785us emit=0us prefill=0us total=190787us batch=1
2026-05-14T15:59:51.234669+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190806us cleanup=28us total=190836us active=1
2026-05-14T15:59:51.234737+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190913us emit=0us prefill=0us total=190915us batch=1
2026-05-14T15:59:51.234781+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190936us cleanup=29us total=190967us active=1
2026-05-14T15:59:51.423825+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=190007us emit=6us prefill=0us total=190017us batch=1
2026-05-14T15:59:51.423872+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190046us cleanup=28us total=190077us active=1
2026-05-14T15:59:51.423928+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190046us emit=6us prefill=0us total=190054us batch=1
2026-05-14T15:59:51.423975+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190083us cleanup=26us total=190112us active=1
2026-05-14T15:59:51.424091+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=189393us emit=6us prefill=0us total=189401us batch=1
2026-05-14T15:59:51.424135+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=189424us cleanup=27us total=189453us active=1
2026-05-14T15:59:51.424643+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=189835us emit=6us prefill=0us total=189843us batch=1
2026-05-14T15:59:51.424686+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=189866us cleanup=27us total=189895us active=1
2026-05-14T15:59:51.424723+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190140us emit=6us prefill=0us total=190149us batch=1
2026-05-14T15:59:51.424746+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=190380us emit=5us prefill=0us total=190389us batch=1
2026-05-14T15:59:51.424771+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190174us cleanup=29us total=190206us active=1
2026-05-14T15:59:51.424789+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=2us step=190410us cleanup=28us total=190442us active=1
2026-05-14T15:59:51.424853+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190507us emit=5us prefill=0us total=190515us batch=1
2026-05-14T15:59:51.424897+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190538us cleanup=29us total=190570us active=1
2026-05-14T15:59:51.425106+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190471us emit=6us prefill=0us total=190479us batch=1
2026-05-14T15:59:51.425150+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190502us cleanup=28us total=190532us active=1
2026-05-14T15:59:51.612440+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=188538us emit=6us prefill=0us total=188547us batch=1
2026-05-14T15:59:51.612502+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=188587us cleanup=28us total=188619us active=1
2026-05-14T15:59:51.612610+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=188606us emit=6us prefill=0us total=188614us batch=1
2026-05-14T15:59:51.612615+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=187693us emit=5us prefill=0us total=187700us batch=1
2026-05-14T15:59:51.612664+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=188648us cleanup=27us total=188678us active=1
2026-05-14T15:59:51.612681+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=187744us cleanup=29us total=187776us active=1
2026-05-14T15:59:51.612838+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=188674us emit=6us prefill=0us total=188682us batch=1
2026-05-14T15:59:51.612885+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=188709us cleanup=27us total=188738us active=1
2026-05-14T15:59:51.613215+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=188041us emit=6us prefill=0us total=188049us batch=1
2026-05-14T15:59:51.613262+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=188465us emit=7us prefill=0us total=188474us batch=1
2026-05-14T15:59:51.613267+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=188077us cleanup=28us total=188107us active=1
2026-05-14T15:59:51.613312+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=188501us cleanup=28us total=188531us active=1
2026-05-14T15:59:51.613342+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=188631us emit=6us prefill=0us total=188639us batch=1
2026-05-14T15:59:51.613385+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=188661us cleanup=27us total=188689us active=1
2026-05-14T15:59:51.613408+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=188593us emit=5us prefill=0us total=188600us batch=1
2026-05-14T15:59:51.613460+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=188627us cleanup=34us total=188662us active=1
2026-05-14T15:59:51.802393+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=189859us emit=5us prefill=0us total=189868us batch=1
2026-05-14T15:59:51.802439+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=189894us cleanup=27us total=189925us active=1
2026-05-14T15:59:51.802701+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=189358us emit=5us prefill=0us total=189366us batch=1
2026-05-14T15:59:51.802746+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=189390us cleanup=29us total=189421us active=1
2026-05-14T15:59:51.802798+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=189884us emit=6us prefill=0us total=189892us batch=1
2026-05-14T15:59:51.802848+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=189922us cleanup=28us total=189953us active=1
2026-05-14T15:59:51.803006+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=189691us emit=6us prefill=0us total=189700us batch=1
2026-05-14T15:59:51.803051+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=189722us cleanup=28us total=189753us active=1
2026-05-14T15:59:51.803102+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=189692us emit=6us prefill=0us total=189699us batch=1
2026-05-14T15:59:51.803144+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=189720us cleanup=27us total=189749us active=1
2026-05-14T15:59:51.803364+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190670us emit=5us prefill=0us total=190677us batch=1
2026-05-14T15:59:51.803392+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=190676us emit=5us prefill=0us total=190685us batch=1
2026-05-14T15:59:51.803407+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190701us cleanup=27us total=190730us active=1
2026-05-14T15:59:51.803437+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190710us cleanup=27us total=190741us active=1
2026-05-14T15:59:51.803527+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190039us emit=5us prefill=0us total=190046us batch=1
2026-05-14T15:59:51.803569+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190066us cleanup=27us total=190096us active=1
2026-05-14T15:59:51.993190+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190719us emit=4us prefill=0us total=190726us batch=1
2026-05-14T15:59:51.993241+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190751us cleanup=33us total=190787us active=1
2026-05-14T15:59:51.993277+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=189843us emit=5us prefill=0us total=189851us batch=1
2026-05-14T15:59:51.993322+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=189876us cleanup=27us total=189905us active=1
2026-05-14T15:59:51.993635+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190162us emit=4us prefill=0us total=190168us batch=1
2026-05-14T15:59:51.993676+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190190us cleanup=24us total=190216us active=1
2026-05-14T15:59:51.993728+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190853us emit=6us prefill=0us total=190861us batch=1
2026-05-14T15:59:51.993773+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190883us cleanup=28us total=190914us active=1
2026-05-14T15:59:51.993863+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190787us emit=6us prefill=0us total=190795us batch=1
2026-05-14T15:59:51.993904+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190814us cleanup=27us total=190843us active=1
2026-05-14T15:59:51.993967+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190799us emit=5us prefill=0us total=190806us batch=1
2026-05-14T15:59:51.994006+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190826us cleanup=26us total=190854us active=1
2026-05-14T15:59:51.994071+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=191299us emit=4us prefill=0us total=191306us batch=1
2026-05-14T15:59:51.994075+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=190483us emit=4us prefill=0us total=190488us batch=1
2026-05-14T15:59:51.994113+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=191329us cleanup=24us total=191356us active=1
2026-05-14T15:59:51.994122+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190519us cleanup=22us total=190544us active=1
2026-05-14T15:59:52.183718+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190451us emit=5us prefill=0us total=190458us batch=1
2026-05-14T15:59:52.183837+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190481us cleanup=23us total=190584us active=1
2026-05-14T15:59:52.184052+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190252us emit=6us prefill=0us total=190260us batch=1
2026-05-14T15:59:52.184058+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=190359us emit=5us prefill=0us total=190365us batch=1
2026-05-14T15:59:52.184087+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190056us emit=6us prefill=0us total=190064us batch=1
2026-05-14T15:59:52.184186+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190293us cleanup=28us total=190403us active=1
2026-05-14T15:59:52.184207+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190400us cleanup=23us total=190523us active=1
2026-05-14T15:59:52.184213+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=190067us emit=4us prefill=0us total=190072us batch=1
2026-05-14T15:59:52.184264+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190084us cleanup=27us total=190248us active=1
2026-05-14T15:59:52.184302+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190099us cleanup=24us total=190170us active=1
2026-05-14T15:59:52.184305+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190959us emit=5us prefill=0us total=190966us batch=1
2026-05-14T15:59:52.184358+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=190211us emit=4us prefill=0us total=190216us batch=1
2026-05-14T15:59:52.184391+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190985us cleanup=27us total=191059us active=1
2026-05-14T15:59:52.184441+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190247us cleanup=24us total=190318us active=1
2026-05-14T15:59:52.184502+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190574us emit=6us prefill=0us total=190582us batch=1
2026-05-14T15:59:52.184592+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190603us cleanup=28us total=190678us active=1
2026-05-14T15:59:52.374087+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=189667us emit=5us prefill=0us total=189674us batch=1
2026-05-14T15:59:52.374134+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=189700us cleanup=28us total=189730us active=1
2026-05-14T15:59:52.374502+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190207us emit=6us prefill=0us total=190216us batch=1
2026-05-14T15:59:52.374545+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190239us cleanup=27us total=190267us active=1
2026-05-14T15:59:52.374710+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190466us emit=4us prefill=0us total=190472us batch=1
2026-05-14T15:59:52.374749+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190497us cleanup=20us total=190520us active=1
2026-05-14T15:59:52.374921+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=7us decode=190703us emit=5us prefill=0us total=190715us batch=1
2026-05-14T15:59:52.374941+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190327us emit=5us prefill=0us total=190334us batch=1
2026-05-14T15:59:52.374968+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=5us step=190734us cleanup=29us total=190771us active=1
2026-05-14T15:59:52.374983+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190354us cleanup=27us total=190383us active=1
2026-05-14T15:59:52.374983+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190653us emit=4us prefill=0us total=190659us batch=1
2026-05-14T15:59:52.375016+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190679us cleanup=20us total=190701us active=1
2026-05-14T15:59:52.375038+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=5us decode=191158us emit=4us prefill=0us total=191167us batch=1
2026-05-14T15:59:52.375075+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=3us step=191201us cleanup=22us total=191228us active=1
2026-05-14T15:59:52.375131+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190649us emit=4us prefill=0us total=190655us batch=1
2026-05-14T15:59:52.375167+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190677us cleanup=21us total=190700us active=1
2026-05-14T15:59:52.565821+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191662us emit=5us prefill=0us total=191669us batch=1
2026-05-14T15:59:52.565868+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191695us cleanup=26us total=191724us active=1
2026-05-14T15:59:52.566197+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191098us emit=5us prefill=0us total=191105us batch=1
2026-05-14T15:59:52.566249+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191132us cleanup=31us total=191165us active=1
2026-05-14T15:59:52.566435+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191441us emit=5us prefill=0us total=191448us batch=1
2026-05-14T15:59:52.566489+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191480us cleanup=28us total=191510us active=1
2026-05-14T15:59:52.566504+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191933us emit=6us prefill=0us total=191941us batch=1
2026-05-14T15:59:52.566545+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191962us cleanup=27us total=191991us active=1
2026-05-14T15:59:52.566792+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192018us emit=4us prefill=0us total=192024us batch=1
2026-05-14T15:59:52.566834+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192051us cleanup=22us total=192076us active=1
2026-05-14T15:59:52.566877+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191687us emit=5us prefill=0us total=191694us batch=1
2026-05-14T15:59:52.566915+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191714us cleanup=23us total=191740us active=1
2026-05-14T15:59:52.566917+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191907us emit=6us prefill=0us total=191915us batch=1
2026-05-14T15:59:52.566957+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191934us cleanup=27us total=191963us active=1
2026-05-14T15:59:52.567009+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191963us emit=5us prefill=0us total=191970us batch=1
2026-05-14T15:59:52.567047+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191997us cleanup=21us total=192019us active=1
2026-05-14T15:59:52.761564+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=194987us emit=6us prefill=0us total=194995us batch=1
2026-05-14T15:59:52.761612+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=195025us cleanup=26us total=195053us active=1
2026-05-14T15:59:52.761713+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=195197us emit=6us prefill=0us total=195204us batch=1
2026-05-14T15:59:52.761757+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=195228us cleanup=26us total=195257us active=1
2026-05-14T15:59:52.761878+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=195012us emit=7us prefill=0us total=195022us batch=1
2026-05-14T15:59:52.761917+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=195048us cleanup=21us total=195073us active=1
2026-05-14T15:59:52.762101+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=196209us emit=4us prefill=0us total=196215us batch=1
2026-05-14T15:59:52.762144+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=196237us cleanup=27us total=196266us active=1
2026-05-14T15:59:52.762216+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=195937us emit=4us prefill=0us total=195943us batch=1
2026-05-14T15:59:52.762267+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=195981us cleanup=22us total=196005us active=1
2026-05-14T15:59:52.762282+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=9us decode=195201us emit=4us prefill=0us total=195214us batch=1
2026-05-14T15:59:52.762318+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=7us step=195231us cleanup=21us total=195260us active=1
2026-05-14T15:59:52.762383+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=195399us emit=5us prefill=0us total=195406us batch=1
2026-05-14T15:59:52.762425+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=195428us cleanup=26us total=195456us active=1
2026-05-14T15:59:52.762492+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=195547us emit=5us prefill=0us total=195555us batch=1
2026-05-14T15:59:52.762530+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=195580us cleanup=21us total=195604us active=1
2026-05-14T15:59:52.955703+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193534us emit=5us prefill=0us total=193541us batch=1
2026-05-14T15:59:52.955747+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193566us cleanup=26us total=193594us active=1
2026-05-14T15:59:52.956295+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=194354us emit=4us prefill=0us total=194360us batch=1
2026-05-14T15:59:52.956330+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194382us cleanup=19us total=194403us active=1
2026-05-14T15:59:52.956405+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=194766us emit=6us prefill=0us total=194774us batch=1
2026-05-14T15:59:52.956458+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194795us cleanup=36us total=194834us active=1
2026-05-14T15:59:52.956788+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=195007us emit=5us prefill=0us total=195014us batch=1
2026-05-14T15:59:52.956829+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=195035us cleanup=26us total=195063us active=1
2026-05-14T15:59:52.956865+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=194575us emit=4us prefill=0us total=194581us batch=1
2026-05-14T15:59:52.956884+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=194437us emit=5us prefill=0us total=194443us batch=1
2026-05-14T15:59:52.956902+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194603us cleanup=20us total=194626us active=1
2026-05-14T15:59:52.956906+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=194566us emit=4us prefill=0us total=194571us batch=1
2026-05-14T15:59:52.956928+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194465us cleanup=27us total=194494us active=1
2026-05-14T15:59:52.956943+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194594us cleanup=20us total=194616us active=1
2026-05-14T15:59:52.957005+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=194454us emit=4us prefill=0us total=194459us batch=1
2026-05-14T15:59:52.957041+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194480us cleanup=21us total=194503us active=1
2026-05-14T15:59:53.147614+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=190657us emit=7us prefill=0us total=190665us batch=1
2026-05-14T15:59:53.147622+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190767us emit=6us prefill=0us total=190775us batch=1
2026-05-14T15:59:53.147659+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=190688us emit=4us prefill=0us total=190693us batch=1
2026-05-14T15:59:53.147669+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190698us cleanup=29us total=190730us active=1
2026-05-14T15:59:53.147677+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190808us cleanup=28us total=190838us active=1
2026-05-14T15:59:53.147681+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191910us emit=5us prefill=0us total=191917us batch=1
2026-05-14T15:59:53.147699+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190722us cleanup=20us total=190744us active=1
2026-05-14T15:59:53.147700+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191218us emit=6us prefill=0us total=191226us batch=1
2026-05-14T15:59:53.147723+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191936us cleanup=28us total=191966us active=1
2026-05-14T15:59:53.147723+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=191371us emit=4us prefill=0us total=191376us batch=1
2026-05-14T15:59:53.147740+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191243us cleanup=28us total=191273us active=1
2026-05-14T15:59:53.147756+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191398us cleanup=18us total=191418us active=1
2026-05-14T15:59:53.147924+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=191001us emit=4us prefill=0us total=191006us batch=1
2026-05-14T15:59:53.147958+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191026us cleanup=19us total=191047us active=1
2026-05-14T15:59:53.147993+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=190930us emit=4us prefill=0us total=190935us batch=1
2026-05-14T15:59:53.148026+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190956us cleanup=19us total=190977us active=1
2026-05-14T15:59:53.340459+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192464us emit=17us prefill=0us total=192483us batch=1
2026-05-14T15:59:53.340567+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192506us cleanup=18us total=192601us active=1
2026-05-14T15:59:53.340767+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192983us emit=4us prefill=0us total=192989us batch=1
2026-05-14T15:59:53.340856+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=193011us cleanup=18us total=193087us active=1
2026-05-14T15:59:53.340858+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193112us emit=5us prefill=0us total=193119us batch=1
2026-05-14T15:59:53.340977+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193143us cleanup=27us total=193246us active=1
2026-05-14T15:59:53.341134+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=193429us emit=6us prefill=0us total=193438us batch=1
2026-05-14T15:59:53.341248+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193462us cleanup=27us total=193561us active=1
2026-05-14T15:59:53.341459+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=193729us emit=5us prefill=0us total=193735us batch=1
2026-05-14T15:59:53.341540+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193767us cleanup=18us total=193832us active=1
2026-05-14T15:59:53.341620+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193849us emit=5us prefill=0us total=193856us batch=1
2026-05-14T15:59:53.341641+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=7us decode=193583us emit=4us prefill=0us total=193594us batch=1
2026-05-14T15:59:53.341699+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193999us emit=5us prefill=0us total=194006us batch=1
2026-05-14T15:59:53.341711+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193883us cleanup=27us total=193959us active=1
2026-05-14T15:59:53.341744+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=5us step=193616us cleanup=18us total=193708us active=1
2026-05-14T15:59:53.341790+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194030us cleanup=27us total=194107us active=1
2026-05-14T15:59:53.532942+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=192348us emit=6us prefill=0us total=192355us batch=1
2026-05-14T15:59:53.532944+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=192063us emit=5us prefill=0us total=192069us batch=1
2026-05-14T15:59:53.532993+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192389us cleanup=25us total=192416us active=1
2026-05-14T15:59:53.533000+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192108us cleanup=23us total=192134us active=1
2026-05-14T15:59:53.533054+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191777us emit=5us prefill=0us total=191784us batch=1
2026-05-14T15:59:53.533103+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191812us cleanup=27us total=191843us active=1
2026-05-14T15:59:53.533410+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192408us emit=5us prefill=0us total=192415us batch=1
2026-05-14T15:59:53.533462+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192437us cleanup=36us total=192475us active=1
2026-05-14T15:59:53.533596+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=191858us emit=6us prefill=0us total=191867us batch=1
2026-05-14T15:59:53.533636+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=191886us cleanup=25us total=191914us active=1
2026-05-14T15:59:53.533750+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=192178us emit=4us prefill=0us total=192185us batch=1
2026-05-14T15:59:53.533790+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=2us step=192212us cleanup=23us total=192239us active=1
2026-05-14T15:59:53.533891+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=192116us emit=5us prefill=0us total=192124us batch=1
2026-05-14T15:59:53.533929+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=2us step=192144us cleanup=24us total=192172us active=1
2026-05-14T15:59:53.533990+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192174us emit=5us prefill=0us total=192181us batch=1
2026-05-14T15:59:53.534034+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192203us cleanup=27us total=192232us active=1
2026-05-14T15:59:53.723782+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190650us emit=6us prefill=0us total=190658us batch=1
2026-05-14T15:59:53.723830+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190687us cleanup=27us total=190717us active=1
2026-05-14T15:59:53.724071+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=191050us emit=5us prefill=0us total=191058us batch=1
2026-05-14T15:59:53.724112+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191083us cleanup=23us total=191108us active=1
2026-05-14T15:59:53.724510+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191488us emit=4us prefill=0us total=191494us batch=1
2026-05-14T15:59:53.724548+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191516us cleanup=22us total=191540us active=1
2026-05-14T15:59:53.724713+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190899us emit=5us prefill=0us total=190906us batch=1
2026-05-14T15:59:53.724750+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190926us cleanup=22us total=190951us active=1
2026-05-14T15:59:53.724793+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191132us emit=6us prefill=0us total=191140us batch=1
2026-05-14T15:59:53.724837+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191164us cleanup=26us total=191192us active=1
2026-05-14T15:59:53.724867+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190811us emit=5us prefill=0us total=190818us batch=1
2026-05-14T15:59:53.724892+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=191406us emit=5us prefill=0us total=191412us batch=1
2026-05-14T15:59:53.724909+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190837us cleanup=28us total=190867us active=1
2026-05-14T15:59:53.724934+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191431us cleanup=28us total=191461us active=1
2026-05-14T15:59:53.725053+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191104us emit=4us prefill=0us total=191110us batch=1
2026-05-14T15:59:53.725093+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191132us cleanup=22us total=191156us active=1
2026-05-14T15:59:53.919037+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=194464us emit=4us prefill=0us total=194471us batch=1
2026-05-14T15:59:53.919074+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=194491us cleanup=22us total=194517us active=1
2026-05-14T15:59:53.919252+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=194388us emit=7us prefill=0us total=194397us batch=1
2026-05-14T15:59:53.919298+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194423us cleanup=26us total=194452us active=1
2026-05-14T15:59:53.919511+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=194396us emit=4us prefill=0us total=194402us batch=1
2026-05-14T15:59:53.919550+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194426us cleanup=21us total=194449us active=1
2026-05-14T15:59:53.919627+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=195491us emit=4us prefill=0us total=195497us batch=1
2026-05-14T15:59:53.919629+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=195770us emit=6us prefill=0us total=195779us batch=1
2026-05-14T15:59:53.919661+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=195517us cleanup=20us total=195539us active=1
2026-05-14T15:59:53.919672+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=195801us cleanup=27us total=195831us active=1
2026-05-14T15:59:53.919678+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=194746us emit=5us prefill=0us total=194752us batch=1
2026-05-14T15:59:53.919718+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194771us cleanup=27us total=194800us active=1
2026-05-14T15:59:53.919727+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=194950us emit=5us prefill=0us total=194957us batch=1
2026-05-14T15:59:53.919739+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=194782us emit=4us prefill=0us total=194788us batch=1
2026-05-14T15:59:53.919764+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=194980us cleanup=20us total=195003us active=1
2026-05-14T15:59:53.919778+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194807us cleanup=26us total=194836us active=1
2026-05-14T15:59:54.111903+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192577us emit=6us prefill=0us total=192585us batch=1
2026-05-14T15:59:54.111951+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192613us cleanup=27us total=192643us active=1
2026-05-14T15:59:54.112002+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192901us emit=5us prefill=0us total=192908us batch=1
2026-05-14T15:59:54.112042+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=192934us cleanup=22us total=192959us active=1
2026-05-14T15:59:54.112205+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=6us decode=192396us emit=5us prefill=0us total=192407us batch=1
2026-05-14T15:59:54.112264+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=4us step=192439us cleanup=28us total=192473us active=1
2026-05-14T15:59:54.112617+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192876us emit=5us prefill=0us total=192883us batch=1
2026-05-14T15:59:54.112660+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192902us cleanup=29us total=192932us active=1
2026-05-14T15:59:54.112772+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193072us emit=6us prefill=0us total=193080us batch=1
2026-05-14T15:59:54.112815+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193101us cleanup=27us total=193130us active=1
2026-05-14T15:59:54.112816+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=193024us emit=7us prefill=0us total=193032us batch=1
2026-05-14T15:59:54.112810+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193127us emit=5us prefill=0us total=193134us batch=1
2026-05-14T15:59:54.112818+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=193244us emit=5us prefill=0us total=193250us batch=1
2026-05-14T15:59:54.112854+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193057us cleanup=21us total=193080us active=1
2026-05-14T15:59:54.112861+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193169us cleanup=20us total=193192us active=1
2026-05-14T15:59:54.112871+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193288us cleanup=22us total=193312us active=1
2026-05-14T15:59:54.305120+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192829us emit=5us prefill=0us total=192836us batch=1
2026-05-14T15:59:54.305168+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192863us cleanup=28us total=192894us active=1
2026-05-14T15:59:54.305387+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192544us emit=5us prefill=0us total=192551us batch=1
2026-05-14T15:59:54.305390+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193412us emit=5us prefill=0us total=193419us batch=1
2026-05-14T15:59:54.305433+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192578us cleanup=27us total=192606us active=1
2026-05-14T15:59:54.305455+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193456us cleanup=35us total=193493us active=1
2026-05-14T15:59:54.305753+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193682us emit=6us prefill=0us total=193690us batch=1
2026-05-14T15:59:54.305793+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193718us cleanup=21us total=193741us active=1
2026-05-14T15:59:54.305973+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=193092us emit=5us prefill=0us total=193098us batch=1
2026-05-14T15:59:54.306009+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193120us cleanup=20us total=193142us active=1
2026-05-14T15:59:54.306084+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=193189us emit=6us prefill=0us total=193196us batch=1
2026-05-14T15:59:54.306088+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193205us emit=5us prefill=0us total=193212us batch=1
2026-05-14T15:59:54.306124+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193221us cleanup=21us total=193244us active=1
2026-05-14T15:59:54.306135+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193244us cleanup=20us total=193266us active=1
2026-05-14T15:59:54.306175+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=193492us emit=5us prefill=0us total=193499us batch=1
2026-05-14T15:59:54.306230+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193522us cleanup=37us total=193561us active=1
2026-05-14T15:59:54.497342+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=191193us emit=5us prefill=0us total=191199us batch=1
2026-05-14T15:59:54.497472+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191224us cleanup=21us total=191337us active=1
2026-05-14T15:59:54.497618+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=191798us emit=4us prefill=0us total=191805us batch=1
2026-05-14T15:59:54.497682+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=192481us emit=5us prefill=0us total=192489us batch=1
2026-05-14T15:59:54.497683+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=192200us emit=6us prefill=0us total=192209us batch=1
2026-05-14T15:59:54.497709+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=191826us cleanup=20us total=191906us active=1
2026-05-14T15:59:54.497813+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=192519us cleanup=27us total=192630us active=1
2026-05-14T15:59:54.497842+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=192243us cleanup=27us total=192376us active=1
2026-05-14T15:59:54.497877+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191614us emit=5us prefill=0us total=191621us batch=1
2026-05-14T15:59:54.497888+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=191726us emit=4us prefill=0us total=191733us batch=1
2026-05-14T15:59:54.497968+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191641us cleanup=28us total=191721us active=1
2026-05-14T15:59:54.498002+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=191759us cleanup=21us total=191857us active=1
2026-05-14T15:59:54.498155+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=192118us emit=4us prefill=0us total=192125us batch=1
2026-05-14T15:59:54.498170+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192709us emit=5us prefill=0us total=192716us batch=1
2026-05-14T15:59:54.498247+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=192147us cleanup=21us total=192227us active=1
2026-05-14T15:59:54.498284+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=192742us cleanup=27us total=192840us active=1
2026-05-14T15:59:54.687277+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=189405us emit=6us prefill=0us total=189413us batch=1
2026-05-14T15:59:54.687327+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=189444us cleanup=27us total=189474us active=1
2026-05-14T15:59:54.687605+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=189763us emit=6us prefill=0us total=189771us batch=1
2026-05-14T15:59:54.687651+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=189797us cleanup=28us total=189827us active=1
2026-05-14T15:59:54.687798+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190061us emit=4us prefill=0us total=190067us batch=1
2026-05-14T15:59:54.687838+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190094us cleanup=22us total=190117us active=1
2026-05-14T15:59:54.688092+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190591us emit=5us prefill=0us total=190599us batch=1
2026-05-14T15:59:54.688133+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190623us cleanup=23us total=190649us active=1
2026-05-14T15:59:54.688162+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=189850us emit=5us prefill=0us total=189857us batch=1
2026-05-14T15:59:54.688207+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=189880us cleanup=28us total=189910us active=1
2026-05-14T15:59:54.688262+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=189984us emit=5us prefill=0us total=189990us batch=1
2026-05-14T15:59:54.688270+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190273us emit=6us prefill=0us total=190281us batch=1
2026-05-14T15:59:54.688294+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190261us emit=5us prefill=0us total=190269us batch=1
2026-05-14T15:59:54.688300+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190015us cleanup=21us total=190038us active=1
2026-05-14T15:59:54.688313+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190302us cleanup=29us total=190332us active=1
2026-05-14T15:59:54.688334+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=190295us cleanup=22us total=190320us active=1
2026-05-14T15:59:54.888354+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=200115us emit=7us prefill=0us total=200124us batch=1
2026-05-14T15:59:54.888411+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=200160us cleanup=29us total=200193us active=1
2026-05-14T15:59:54.889070+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=200706us emit=5us prefill=0us total=200714us batch=1
2026-05-14T15:59:54.889126+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=200748us cleanup=27us total=200780us active=1
2026-05-14T15:59:54.889259+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=201580us emit=6us prefill=0us total=201589us batch=1
2026-05-14T15:59:54.889294+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=201427us emit=4us prefill=0us total=201434us batch=1
2026-05-14T15:59:54.889311+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=201618us cleanup=30us total=201650us active=1
2026-05-14T15:59:54.889340+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=201462us cleanup=26us total=201491us active=1
2026-05-14T15:59:54.889590+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=202235us emit=5us prefill=0us total=202242us batch=1
2026-05-14T15:59:54.889636+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=202268us cleanup=29us total=202299us active=1
2026-05-14T15:59:54.889648+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=201305us emit=7us prefill=0us total=201314us batch=1
2026-05-14T15:59:54.889691+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=201339us cleanup=26us total=201368us active=1
2026-05-14T15:59:54.889731+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=201389us emit=5us prefill=0us total=201396us batch=1
2026-05-14T15:59:54.889777+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=201421us cleanup=28us total=201452us active=1
2026-05-14T15:59:54.889775+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=201614us emit=5us prefill=0us total=201623us batch=1
2026-05-14T15:59:54.889818+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=2us step=201646us cleanup=27us total=201676us active=1
2026-05-14T15:59:55.082006+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=192341us emit=6us prefill=0us total=192350us batch=1
2026-05-14T15:59:55.082062+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=192382us cleanup=29us total=192415us active=1
2026-05-14T15:59:55.082441+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=193101us emit=6us prefill=0us total=193110us batch=1
2026-05-14T15:59:55.082496+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193144us cleanup=29us total=193175us active=1
2026-05-14T15:59:55.082562+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=193192us emit=5us prefill=0us total=193200us batch=1
2026-05-14T15:59:55.082607+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193229us cleanup=26us total=193257us active=1
2026-05-14T15:59:55.082698+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=194257us emit=6us prefill=0us total=194266us batch=1
2026-05-14T15:59:55.082707+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192990us emit=5us prefill=0us total=192997us batch=1
2026-05-14T15:59:55.082744+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=194290us cleanup=29us total=194322us active=1
2026-05-14T15:59:55.082748+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=193018us cleanup=26us total=193046us active=1
2026-05-14T15:59:55.082775+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=192971us emit=6us prefill=0us total=192980us batch=1
2026-05-14T15:59:55.082780+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=192934us emit=5us prefill=0us total=192941us batch=1
2026-05-14T15:59:55.082787+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=193630us emit=4us prefill=0us total=193637us batch=1
2026-05-14T15:59:55.082819+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=193000us cleanup=28us total=193031us active=1
2026-05-14T15:59:55.082823+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=192962us cleanup=28us total=192993us active=1
2026-05-14T15:59:55.082833+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=193666us cleanup=27us total=193696us active=1
2026-05-14T15:59:55.276860+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=194227us emit=5us prefill=0us total=194235us batch=1
2026-05-14T15:59:55.276904+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=194258us cleanup=26us total=194287us active=1
2026-05-14T15:59:55.277072+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=194298us emit=4us prefill=0us total=194305us batch=1
2026-05-14T15:59:55.277112+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=194326us cleanup=25us total=194353us active=1
2026-05-14T15:59:55.277156+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=194299us emit=4us prefill=0us total=194306us batch=1
2026-05-14T15:59:55.277197+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194328us cleanup=26us total=194356us active=1
2026-05-14T15:59:55.277319+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=194546us emit=6us prefill=0us total=194554us batch=1
2026-05-14T15:59:55.277375+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=194587us cleanup=30us total=194620us active=1
2026-05-14T15:59:55.278042+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=195516us emit=6us prefill=0us total=195525us batch=1
2026-05-14T15:59:55.278089+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=195551us cleanup=29us total=195583us active=1
2026-05-14T15:59:55.278101+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=196010us emit=6us prefill=0us total=196019us batch=1
2026-05-14T15:59:55.278137+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=195287us emit=5us prefill=0us total=195294us batch=1
2026-05-14T15:59:55.278151+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=195298us emit=6us prefill=0us total=195307us batch=1
2026-05-14T15:59:55.278146+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=196040us cleanup=29us total=196072us active=1
2026-05-14T15:59:55.278184+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=195321us cleanup=26us total=195349us active=1
2026-05-14T15:59:55.278193+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=195326us cleanup=29us total=195357us active=1
2026-05-14T15:59:55.468320+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190915us emit=6us prefill=0us total=190924us batch=1
2026-05-14T15:59:55.468346+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=191124us emit=5us prefill=0us total=191132us batch=1
2026-05-14T15:59:55.468371+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190952us cleanup=30us total=190985us active=1
2026-05-14T15:59:55.468389+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=191156us cleanup=23us total=191182us active=1
2026-05-14T15:59:55.468549+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190366us emit=6us prefill=0us total=190374us batch=1
2026-05-14T15:59:55.468599+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190398us cleanup=31us total=190431us active=1
2026-05-14T15:59:55.468776+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=190661us emit=4us prefill=0us total=190668us batch=1
2026-05-14T15:59:55.468798+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190578us emit=6us prefill=0us total=190586us batch=1
2026-05-14T15:59:55.468820+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190690us cleanup=28us total=190720us active=1
2026-05-14T15:59:55.468832+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191903us emit=4us prefill=0us total=191909us batch=1
2026-05-14T15:59:55.468842+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190605us cleanup=29us total=190636us active=1
2026-05-14T15:59:55.468878+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191938us cleanup=24us total=191964us active=1
2026-05-14T15:59:55.468964+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=190756us emit=5us prefill=0us total=190763us batch=1
2026-05-14T15:59:55.469004+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=190784us cleanup=23us total=190810us active=1
2026-05-14T15:59:55.469036+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=191900us emit=4us prefill=0us total=191906us batch=1
2026-05-14T15:59:55.469075+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=191926us cleanup=24us total=191953us active=1
2026-05-14T15:59:55.674700+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=206295us emit=8us prefill=0us total=206306us batch=1
2026-05-14T15:59:55.674846+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=206341us cleanup=30us total=206463us active=1
2026-05-14T15:59:55.674861+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=206015us emit=6us prefill=0us total=206023us batch=1
2026-05-14T15:59:55.674878+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=206252us emit=6us prefill=0us total=206260us batch=1
2026-05-14T15:59:55.674950+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=206044us emit=6us prefill=0us total=206053us batch=1
2026-05-14T15:59:55.675358+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=206944us emit=5us prefill=0us total=206951us batch=1
2026-05-14T15:59:55.675488+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=206390us emit=5us prefill=0us total=206397us batch=1
2026-05-14T15:59:55.675551+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=1us decode=206674us emit=5us prefill=0us total=206680us batch=1
2026-05-14T15:59:55.675587+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=206556us emit=6us prefill=0us total=206564us batch=1
2026-05-14T15:59:55.675674+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=206048us cleanup=29us total=206844us active=1
2026-05-14T15:59:55.676494+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=206281us cleanup=29us total=207884us active=1
2026-05-14T15:59:55.676557+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=206085us cleanup=29us total=207668us active=1
2026-05-14T15:59:55.677361+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=206977us cleanup=28us total=208963us active=1
2026-05-14T15:59:55.678170+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=206419us cleanup=29us total=209087us active=1
2026-05-14T15:59:55.678342+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=206706us cleanup=29us total=209480us active=1
2026-05-14T15:59:55.679163+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=206588us cleanup=28us total=210149us active=1
2026-05-14T15:59:55.874432+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=198721us emit=7us prefill=0us total=198731us batch=1
2026-05-14T15:59:55.874497+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=198774us cleanup=29us total=198806us active=1
2026-05-14T15:59:55.874648+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=198124us emit=5us prefill=0us total=198131us batch=1
2026-05-14T15:59:55.874694+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=198155us cleanup=28us total=198186us active=1
2026-05-14T15:59:55.874987+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=5us decode=200111us emit=6us prefill=0us total=200122us batch=1
2026-05-14T15:59:55.875032+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=200142us cleanup=30us total=200174us active=1
2026-05-14T15:59:55.875199+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=198609us emit=5us prefill=0us total=198617us batch=1
2026-05-14T15:59:55.875254+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=198643us cleanup=36us total=198682us active=1
2026-05-14T15:59:55.875367+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=196996us emit=5us prefill=0us total=197003us batch=1
2026-05-14T15:59:55.875414+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=197026us cleanup=29us total=197057us active=1
2026-05-14T15:59:55.875417+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=7us decode=198022us emit=5us prefill=0us total=198034us batch=1
2026-05-14T15:59:55.875467+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=198059us cleanup=32us total=198093us active=1
2026-05-14T15:59:55.875495+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=197293us emit=6us prefill=0us total=197302us batch=1
2026-05-14T15:59:55.875505+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=196304us emit=5us prefill=0us total=196313us batch=1
2026-05-14T15:59:55.875536+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=197323us cleanup=26us total=197352us active=1
2026-05-14T15:59:55.875547+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=3us step=196335us cleanup=27us total=196367us active=1
2026-05-14T15:59:56.074349+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=199504us emit=323us prefill=0us total=199830us batch=1
2026-05-14T15:59:56.074403+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199864us cleanup=29us total=199896us active=1
2026-05-14T15:59:56.074630+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199578us emit=336us prefill=0us total=199916us batch=1
2026-05-14T15:59:56.074654+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=199032us emit=129us prefill=0us total=199164us batch=1
2026-05-14T15:59:56.074677+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199941us cleanup=30us total=199973us active=1
2026-05-14T15:59:56.074691+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199257us emit=381us prefill=0us total=199640us batch=1
2026-05-14T15:59:56.074703+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=199194us cleanup=26us total=199224us active=1
2026-05-14T15:59:56.074738+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199666us cleanup=29us total=199697us active=1
2026-05-14T15:59:56.074770+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=199044us emit=167us prefill=0us total=199214us batch=1
2026-05-14T15:59:56.074781+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199328us emit=175us prefill=0us total=199505us batch=1
2026-05-14T15:59:56.074820+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=199244us cleanup=28us total=199274us active=1
2026-05-14T15:59:56.074825+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199528us cleanup=29us total=199559us active=1
2026-05-14T15:59:56.074854+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199150us emit=135us prefill=0us total=199287us batch=1
2026-05-14T15:59:56.074896+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=199310us cleanup=27us total=199339us active=1
2026-05-14T15:59:56.075017+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199223us emit=358us prefill=0us total=199583us batch=1
2026-05-14T15:59:56.075063+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199608us cleanup=29us total=199639us active=1
2026-05-14T15:59:56.279796+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=204944us emit=4us prefill=0us total=204951us batch=1
2026-05-14T15:59:56.279841+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=204977us cleanup=26us total=205006us active=1
2026-05-14T15:59:56.280031+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=205319us emit=7us prefill=0us total=205328us batch=1
2026-05-14T15:59:56.280091+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=205372us cleanup=29us total=205404us active=1
2026-05-14T15:59:56.280437+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=9us decode=205999us emit=6us prefill=0us total=206014us batch=1
2026-05-14T15:59:56.280498+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=6us step=206046us cleanup=29us total=206083us active=1
2026-05-14T15:59:56.280552+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=205698us emit=5us prefill=0us total=205706us batch=1
2026-05-14T15:59:56.280596+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=205732us cleanup=26us total=205761us active=1
2026-05-14T15:59:56.280593+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=205825us emit=5us prefill=0us total=205834us batch=1
2026-05-14T15:59:56.280630+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=205892us emit=5us prefill=0us total=205901us batch=1
2026-05-14T15:59:56.280653+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=205870us cleanup=30us total=205902us active=1
2026-05-14T15:59:56.280675+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=205930us cleanup=26us total=205959us active=1
2026-05-14T15:59:56.280812+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=5us decode=205873us emit=6us prefill=0us total=205884us batch=1
2026-05-14T15:59:56.280832+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=205744us emit=5us prefill=0us total=205752us batch=1
2026-05-14T15:59:56.280855+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=3us step=205905us cleanup=26us total=205936us active=1
2026-05-14T15:59:56.280879+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=205774us cleanup=29us total=205805us active=1
2026-05-14T15:59:56.488580+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=208712us emit=6us prefill=0us total=208721us batch=1
2026-05-14T15:59:56.488629+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=208746us cleanup=27us total=208777us active=1
2026-05-14T15:59:56.488820+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=208291us emit=6us prefill=0us total=208299us batch=1
2026-05-14T15:59:56.488874+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=208332us cleanup=29us total=208364us active=1
2026-05-14T15:59:56.489003+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=208296us emit=6us prefill=0us total=208305us batch=1
2026-05-14T15:59:56.489034+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=208125us emit=5us prefill=0us total=208132us batch=1
2026-05-14T15:59:56.489048+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=208332us cleanup=26us total=208361us active=1
2026-05-14T15:59:56.489083+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=208158us cleanup=29us total=208190us active=1
2026-05-14T15:59:56.489149+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=209025us emit=8us prefill=0us total=209036us batch=1
2026-05-14T15:59:56.489160+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=208529us emit=7us prefill=0us total=208539us batch=1
2026-05-14T15:59:56.489160+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=208273us emit=7us prefill=0us total=208282us batch=1
2026-05-14T15:59:56.489188+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=208506us emit=6us prefill=0us total=208514us batch=1
2026-05-14T15:59:56.489195+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=209059us cleanup=31us total=209092us active=1
2026-05-14T15:59:56.489215+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=208570us cleanup=32us total=208604us active=1
2026-05-14T15:59:56.489237+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=208325us cleanup=41us total=208369us active=1
2026-05-14T15:59:56.489252+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=208543us cleanup=43us total=208588us active=1
2026-05-14T15:59:56.686758+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=197511us emit=7us prefill=0us total=197520us batch=1
2026-05-14T15:59:56.686887+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=197557us cleanup=28us total=197668us active=1
2026-05-14T15:59:56.687623+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=198545us emit=5us prefill=0us total=198554us batch=1
2026-05-14T15:59:56.687752+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=198586us cleanup=28us total=198694us active=1
2026-05-14T15:59:56.687800+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=199142us emit=5us prefill=0us total=199150us batch=1
2026-05-14T15:59:56.687856+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=198577us emit=5us prefill=0us total=198584us batch=1
2026-05-14T15:59:56.687902+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=199175us cleanup=27us total=199262us active=1
2026-05-14T15:59:56.687925+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=198813us emit=4us prefill=0us total=198820us batch=1
2026-05-14T15:59:56.687957+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=198609us cleanup=29us total=198694us active=1
2026-05-14T15:59:56.688020+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=198844us cleanup=29us total=198925us active=1
2026-05-14T15:59:56.688106+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=198840us emit=5us prefill=0us total=198847us batch=1
2026-05-14T15:59:56.688198+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=198872us cleanup=27us total=198949us active=1
2026-05-14T15:59:56.688237+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=199325us emit=6us prefill=0us total=199334us batch=1
2026-05-14T15:59:56.688237+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=5us decode=198976us emit=5us prefill=0us total=198986us batch=1
2026-05-14T15:59:56.688334+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199370us cleanup=28us total=199449us active=1
2026-05-14T15:59:56.688368+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=3us step=199029us cleanup=27us total=199130us active=1
2026-05-14T15:59:56.883795+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=195862us emit=5us prefill=0us total=195870us batch=1
2026-05-14T15:59:56.883838+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=195892us cleanup=27us total=195922us active=1
2026-05-14T15:59:56.884392+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=4us decode=196610us emit=5us prefill=0us total=196619us batch=1
2026-05-14T15:59:56.884432+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=196640us cleanup=25us total=196668us active=1
2026-05-14T15:59:56.884459+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=196465us emit=13us prefill=0us total=196481us batch=1
2026-05-14T15:59:56.884506+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=196508us cleanup=28us total=196539us active=1
2026-05-14T15:59:56.884500+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=11us decode=196266us emit=5us prefill=0us total=196282us batch=1
2026-05-14T15:59:56.884560+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=196321us cleanup=27us total=196351us active=1
2026-05-14T15:59:56.884602+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=196241us emit=5us prefill=0us total=196248us batch=1
2026-05-14T15:59:56.884647+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=196272us cleanup=27us total=196301us active=1
2026-05-14T15:59:56.884772+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=197859us emit=6us prefill=0us total=197868us batch=1
2026-05-14T15:59:56.884814+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=197888us cleanup=27us total=197917us active=1
2026-05-14T15:59:56.884828+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=196782us emit=5us prefill=0us total=196789us batch=1
2026-05-14T15:59:56.884869+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=196810us cleanup=27us total=196839us active=1
2026-05-14T15:59:56.884946+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=3us decode=196548us emit=5us prefill=0us total=196556us batch=1
2026-05-14T15:59:56.884992+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=1us step=196580us cleanup=28us total=196611us active=1
2026-05-14T15:59:57.083586+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199050us emit=6us prefill=0us total=199058us batch=1
2026-05-14T15:59:57.083637+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199087us cleanup=28us total=199118us active=1
2026-05-14T15:59:57.083688+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=198665us emit=8us prefill=0us total=198675us batch=1
2026-05-14T15:59:57.083744+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=198710us cleanup=28us total=198742us active=1
2026-05-14T15:59:57.084079+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199490us emit=6us prefill=0us total=199498us batch=1
2026-05-14T15:59:57.084128+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199527us cleanup=29us total=199558us active=1
2026-05-14T15:59:57.084155+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199258us emit=4us prefill=0us total=199264us batch=1
2026-05-14T15:59:57.084203+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199289us cleanup=29us total=199320us active=1
2026-05-14T15:59:57.084234+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199770us emit=13us prefill=0us total=199785us batch=1
2026-05-14T15:59:57.084279+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199809us cleanup=27us total=199838us active=1
2026-05-14T15:59:57.084356+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=9us decode=200482us emit=5us prefill=0us total=200496us batch=1
2026-05-14T15:59:57.084370+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199530us emit=7us prefill=0us total=199539us batch=1
2026-05-14T15:59:57.084402+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=200522us cleanup=28us total=200552us active=1
2026-05-14T15:59:57.084400+08:00   INFO infer::scheduler::cuda::execution: execution.rs:988 step breakdown: plan=decode admission=2us decode=199728us emit=6us prefill=0us total=199736us batch=1
2026-05-14T15:59:57.084416+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199562us cleanup=28us total=199592us active=1
2026-05-14T15:59:57.084459+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:190 Scheduler step: assign=0us step=199761us cleanup=39us total=199803us active=1
2026-05-14T15:59:57.084655+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 1 done: 32 tokens (active=0, waiting=0)
2026-05-14T15:59:57.084664+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 1 done: 32 tokens (active=0, waiting=0)
2026-05-14T15:59:57.084666+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 1 done: 32 tokens (active=0, waiting=0)
2026-05-14T15:59:57.084665+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 1 done: 32 tokens (active=0, waiting=0)
2026-05-14T15:59:57.084666+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 1 done: 32 tokens (active=0, waiting=0)
2026-05-14T15:59:57.084784+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 1 done: 32 tokens (active=0, waiting=0)
2026-05-14T15:59:57.084795+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 1 done: 32 tokens (active=0, waiting=0)
2026-05-14T15:59:57.084852+08:00   INFO infer::scheduler::cuda::runtime::scheduler_loop: scheduler_loop.rs:387 Request 1 done: 32 tokens (active=0, waiting=0)
2026-05-14T15:59:57.084964+08:00   INFO infer::request_trace: handlers.rs:220 request_trace {"chunks_seen":31,"completion_tokens":32,"error":null,"finish_reason":"length","kv":{"fetch_backpressure":false,"fetch_queue_depth":0,"fetch_waiters":0,"gpu_util":0.0,"store_backpressure":false,"store_queue_depth":0},"max_tokens":32,"prefix":{"direct_gpu_attach":false,"hit_rate":0.0,"lookup_latency_us":0,"lookup_reusable_tokens":0,"matched_tokens":0,"prefetch":false,"ready_on_gpu":false,"recompute":false,"request_hit_rate":0.0,"request_skip_rate":0.0,"resume_prefill_tokens":29,"skip_rate":0.0,"staged":false},"preprocess":{"queue_depth":0,"tokenize_us":394,"wait_us":1},"prompt_bytes":202,"prompt_tokens":29,"request_id":"chatcmpl-ec1af7a9-f9f3-4a66-bf9a-2fba657127cf","route":"/v1/chat/completions","scheduler":{"active":0,"batch_width":0,"decode_tokens":0,"loop_us":{"cleanup":32,"total":180111},"phase_us":{"admission":50,"decode":174567,"emit":23,"prefill":7628,"total":179881},"pipeline_us":{"cpu_plan":2,"gpu_command_queue_depth":0,"gpu_completion_wait":364,"snapshot":0},"prefill_queue":0,"prefill_tokens":0,"running_batch":0,"scheduled_decode_rows":0,"scheduled_prefill_rows":0,"scheduled_rows":0,"step_last_s":0.000373,"waiting":0},"stream":true,"terminal_seen":true,"text_bytes":119,"throughput":{"completion_tokens_per_s_e2e":4.952033815105277,"prompt_tokens_per_s_at_ttft":68.8886178847613,"total_tokens_per_s_e2e":9.439814460044435},"token_ids_seen":32,"total_ms":6461.991415,"total_tokens":61,"ttft_ms":420.969398}
Capture range started in the application.
Generating '/tmp/nsys-report-4d59.qdstrm'
Capture range ended in the application.

[1/1] [0%                          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [0%                          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==========49%               ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [0%                          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [0%                          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [6%                          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [5%                          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [6%                          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [9%                          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [12%                         ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [11%                         ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [14%                         ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [13%                         ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=16%                        ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=15%                        ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=17%                        ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=16%                        ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==19%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==18%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==20%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==19%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==21%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==20%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===22%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==21%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===23%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===22%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===24%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [====25%                     ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===24%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===23%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===22%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==21%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==20%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==19%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==18%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=17%                        ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==18%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==19%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==20%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==21%                       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===22%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===23%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===24%                      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [====25%                     ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [====26%                     ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [====27%                     ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [====28%                     ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=====29%                    ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=====30%                    ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=====31%                    ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=====32%                    ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [======33%                   ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [======34%                   ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [======35%                   ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=======36%                  ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=======37%                  ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=======38%                  ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=======39%                  ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [========40%                 ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [========41%                 ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [========42%                 ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=========43%                ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=========44%                ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=========45%                ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=========46%                ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==========47%               ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==========48%               ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==========49%               ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===========50%              ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===========51%              ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===========52%              ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===========53%              ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [============54%             ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [============55%             ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [============56%             ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [============57%             ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=============58%            ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=============59%            ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=============60%            ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==============61%           ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==============62%           ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==============63%           ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==============64%           ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===============65%          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===============66%          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===============67%          ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [================68%         ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [================69%         ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [================70%         ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [================71%         ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=================72%        ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=================73%        ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=================74%        ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==================75%       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==================76%       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==================77%       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [==================78%       ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===================79%      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===================80%      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===================81%      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [===================82%      ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [====================83%     ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [====================84%     ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [====================85%     ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=====================86%    ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=====================87%    ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=====================88%    ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [=====================89%    ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [======================90%   ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [======================91%   ] arle-dsv4-decode-nsys.nsys-rep
[1/1] [========================100%] arle-dsv4-decode-nsys.nsys-rep
[1/1] [========================100%] arle-dsv4-decode-nsys.nsys-rep
2026-05-14T16:00:40.432555+08:00   INFO infer: main.rs:1335 cuProfilerStop fired (nsys capture end)
Generated:
    /tmp/arle-dsv4-decode-nsys.nsys-rep
