profile decode path and optimize tiny batch moe

qwen3_6_scripts/qwen3_5.py

@@ -3,6 +3,9 @@
 # Text-only (no VL, no MTP).
 
 from collections import OrderedDict
+from contextlib import contextmanager
+import os
+import time
 from typing import Dict, Iterable, List, Optional, Tuple
 
 import torch
@@ -41,6 +44,59 @@ from vllm.model_executor.models.interfaces import HasInnerState, SupportsLoRA
 
 logger = init_logger(__name__)
 
+_ENGINEX_PROFILE_ENABLED = os.getenv("ENGINEX_PROFILE_DECODE", "0") == "1"
+_ENGINEX_PROFILE_EVERY = int(os.getenv("ENGINEX_PROFILE_EVERY", "32"))
+_ENGINEX_PROFILE_SYNC = os.getenv("ENGINEX_PROFILE_SYNC", "1") != "0"
+_enginex_profile_stats: Dict[str, List[float]] = {}
+_enginex_profile_steps = 0
+_enginex_profile_mode = "unknown"
+
+
+def _enginex_profile_active() -> bool:
+    return _ENGINEX_PROFILE_ENABLED and torch.cuda.is_available()
+
+
+def _enginex_profile_sync() -> None:
+    if _ENGINEX_PROFILE_SYNC:
+        torch.cuda.synchronize()
+
+
+@contextmanager
+def _enginex_profile(label: str):
+    if not _enginex_profile_active():
+        yield
+        return
+    label = f"{_enginex_profile_mode}.{label}"
+    _enginex_profile_sync()
+    start = time.perf_counter()
+    try:
+        yield
+    finally:
+        _enginex_profile_sync()
+        elapsed_ms = (time.perf_counter() - start) * 1000.0
+        stat = _enginex_profile_stats.setdefault(label, [0.0, 0.0])
+        stat[0] += elapsed_ms
+        stat[1] += 1.0
+
+
+def _enginex_profile_log(mode: str) -> None:
+    global _enginex_profile_steps
+    if not _enginex_profile_active():
+        return
+    _enginex_profile_steps += 1
+    if _enginex_profile_steps % max(_ENGINEX_PROFILE_EVERY, 1) != 0:
+        return
+    tp_rank = get_tensor_model_parallel_rank()
+    parts = []
+    for label, (total_ms, count) in sorted(
+            _enginex_profile_stats.items(),
+            key=lambda item: item[1][0],
+            reverse=True):
+        avg_ms = total_ms / max(count, 1.0)
+        parts.append(f"{label}: total={total_ms:.2f}ms avg={avg_ms:.3f}ms n={int(count)}")
+    logger.info("[ENGINEX_PROFILE_QWEN] rank=%d steps=%d mode=%s %s",
+                tp_rank, _enginex_profile_steps, mode, " | ".join(parts))
+
 
 # ---------------------------------------------------------------------------
 # Pure-PyTorch DeltaNet kernels (fallbacks from transformers 5.2.0)
@@ -613,44 +669,48 @@ class Qwen3_5FullAttention(nn.Module):
         total_tokens = hidden_states.shape[0]
 
         # q_proj output includes gate (dim doubled)
-        qg, _ = self.q_proj(hidden_states)  # (total, local_num_heads * head_dim * 2)
+        with _enginex_profile("full_attn.qkv_proj"):
-        qg = qg.view(total_tokens, self.local_num_heads, self.head_dim * 2)
+            qg, _ = self.q_proj(hidden_states)  # (total, local_num_heads * head_dim * 2)
-        q = qg[:, :, :self.head_dim].reshape(total_tokens, -1)
+            qg = qg.view(total_tokens, self.local_num_heads, self.head_dim * 2)
-        gate = qg[:, :, self.head_dim:].reshape(total_tokens, -1)
+            q = qg[:, :, :self.head_dim].reshape(total_tokens, -1)
+            gate = qg[:, :, self.head_dim:].reshape(total_tokens, -1)
 
-        k, _ = self.k_proj(hidden_states)   # (total, proj_kv_heads * head_dim)
+            k, _ = self.k_proj(hidden_states)   # (total, proj_kv_heads * head_dim)
-        v, _ = self.v_proj(hidden_states)
+            v, _ = self.v_proj(hidden_states)
 
         # q_norm on local Q heads
-        q = self.q_norm.forward_cuda(
+        with _enginex_profile("full_attn.norm_rope"):
-            q.view(total_tokens, self.local_num_heads, self.head_dim)
+            q = self.q_norm.forward_cuda(
-            .contiguous()).view(total_tokens, -1)
+                q.view(total_tokens, self.local_num_heads, self.head_dim)
+                .contiguous()).view(total_tokens, -1)
 
-        # GQA-aware TP: select rank-local KV head BEFORE k_norm and rope so
+            # GQA-aware TP: select rank-local KV head BEFORE k_norm and rope so
-        # that ixformer kernels always see num_kv_heads=1 (same as 27B path).
+            # that ixformer kernels always see num_kv_heads=1 (same as 27B path).
-        # Doing k_norm/rope on 2 KV heads (proj_kv_heads=2) triggers ixformer
+            # Doing k_norm/rope on 2 KV heads (proj_kv_heads=2) triggers ixformer
-        # paths that can produce NaN; restricting to 1 head avoids the issue.
+            # paths that can produce NaN; restricting to 1 head avoids the issue.
-        if self.q_per_kv_global is not None:
+            if self.q_per_kv_global is not None:
-            tp_rank = get_tensor_model_parallel_rank()
+                tp_rank = get_tensor_model_parallel_rank()
-            kv_idx = (tp_rank * self.local_num_heads) // self.q_per_kv_global
+                kv_idx = (tp_rank * self.local_num_heads) // self.q_per_kv_global
-            k = (k.view(total_tokens, self.proj_kv_heads, self.head_dim)
+                k = (k.view(total_tokens, self.proj_kv_heads, self.head_dim)
-                  [:, kv_idx, :].contiguous())   # (T, head_dim) — 1 head
+                      [:, kv_idx, :].contiguous())   # (T, head_dim) — 1 head
-            v = (v.view(total_tokens, self.proj_kv_heads, self.head_dim)
+                v = (v.view(total_tokens, self.proj_kv_heads, self.head_dim)
-                  [:, kv_idx, :].contiguous())   # (T, head_dim) — 1 head
+                      [:, kv_idx, :].contiguous())   # (T, head_dim) — 1 head
 
-        # k_norm on the (now always 1) rank-local KV head
+            # k_norm on the (now always 1) rank-local KV head
-        k = self.k_norm.forward_cuda(
+            k = self.k_norm.forward_cuda(
-            k.view(total_tokens, self.local_num_kv_heads, self.head_dim)
+                k.view(total_tokens, self.local_num_kv_heads, self.head_dim)
-            .contiguous()).view(total_tokens, -1)
+                .contiguous()).view(total_tokens, -1)
 
-        # rope: q=(T, local_num_heads*head_dim), k=(T, 1*head_dim) — mirrors 27B
+            # rope: q=(T, local_num_heads*head_dim), k=(T, 1*head_dim) — mirrors 27B
-        q, k = self.rotary_emb(positions, q, k)
+            q, k = self.rotary_emb(positions, q, k)
 
-        attn_out = self.attn(q, k, v, kv_cache, attn_metadata)
+        with _enginex_profile("full_attn.paged_attention"):
+            attn_out = self.attn(q, k, v, kv_cache, attn_metadata)
 
         # Multiply by sigmoid gate before output projection
-        attn_out = attn_out * torch.sigmoid(gate.float()).to(attn_out.dtype)
+        with _enginex_profile("full_attn.gate_o_proj"):
-        output, _ = self.o_proj(attn_out)
+            attn_out = attn_out * torch.sigmoid(gate.float()).to(attn_out.dtype)
+            output, _ = self.o_proj(attn_out)
         return output
 
 
@@ -754,12 +814,13 @@ class Qwen3_5MoeSparseBlock(nn.Module):
         Output is partial (pre-all-reduce), same contract as FusedMoE
         with reduce_results=False.
         """
-        # Routing: softmax → topk → renormalise
+        # Routing: softmax -> topk -> renormalise
-        routing_weights = torch.softmax(router_logits.float(), dim=-1)
+        with _enginex_profile("moe.routing_topk"):
-        topk_weights, topk_ids = torch.topk(
+            routing_weights = torch.softmax(router_logits.float(), dim=-1)
-            routing_weights, self.top_k, dim=-1)           # (T, top_k)
+            topk_weights, topk_ids = torch.topk(
-        topk_weights = topk_weights / topk_weights.sum(dim=-1, keepdim=True)
+                routing_weights, self.top_k, dim=-1)       # (T, top_k)
-        topk_weights = topk_weights.to(hidden_states.dtype)
+            topk_weights = topk_weights / topk_weights.sum(dim=-1, keepdim=True)
+            topk_weights = topk_weights.to(hidden_states.dtype)
 
         w13 = self.experts.w13_weight  # (E, 2*I, H)
         w2  = self.experts.w2_weight   # (E, H, I)
@@ -771,59 +832,90 @@ class Qwen3_5MoeSparseBlock(nn.Module):
             # gate_up: 1 large GEMM  (1,H) × (K*2*I,H)^T → (1, K*2*I)
             # down:    1 bmm         (K,H,I) @ (K,I,1)    → (K,H)
             # Total: 3 kernel launches vs previous 16 (top_k*2).
-            eids    = topk_ids[0]                              # (K,)
+            with _enginex_profile("moe.routed_decode_experts"):
-            ws      = topk_weights[0].to(hidden_states.dtype)  # (K,)
+                eids    = topk_ids[0]                              # (K,)
-            w13_sel = w13[eids]                                # (K, 2*I, H)
+                ws      = topk_weights[0].to(hidden_states.dtype)  # (K,)
-            w2_sel  = w2[eids]                                 # (K, H, I)
+                w13_sel = w13[eids]                                # (K, 2*I, H)
+                w2_sel  = w2[eids]                                 # (K, H, I)
 
-            H = hidden_states.shape[-1]
+                H = hidden_states.shape[-1]
 
-            gate_up = F.linear(
+                gate_up = F.linear(
-                hidden_states,
+                    hidden_states,
-                w13_sel.reshape(-1, H),                        # (K*2*I, H) — contiguous after indexing
+                    w13_sel.reshape(-1, H),                        # (K*2*I, H) - contiguous after indexing
-            )                                                  # (1, K*2*I)
+                )                                                  # (1, K*2*I)
-            gate_up = gate_up.view(self.top_k, -1)             # (K, 2*I)
+                gate_up = gate_up.view(self.top_k, -1)             # (K, 2*I)
-            gate, up = gate_up.chunk(2, dim=-1)                # (K, I) each
+                gate, up = gate_up.chunk(2, dim=-1)                # (K, I) each
-            act = F.silu(gate) * up                            # (K, I)
+                act = F.silu(gate) * up                            # (K, I)
 
-            # bmm: (K,H,I) @ (K,I,1) → (K,H,1) → (K,H)
+                # bmm: (K,H,I) @ (K,I,1) -> (K,H,1) -> (K,H)
-            expert_out = torch.bmm(w2_sel, act.unsqueeze(-1)).squeeze(-1)  # (K, H)
+                expert_out = torch.bmm(w2_sel, act.unsqueeze(-1)).squeeze(-1)  # (K, H)
 
-            out = (expert_out * ws.unsqueeze(-1)).sum(0, keepdim=True).to(
+                out = (expert_out * ws.unsqueeze(-1)).sum(0, keepdim=True).to(
-                hidden_states.dtype)                           # (1, H)
+                    hidden_states.dtype)                           # (1, H)
+        elif T <= 2:
+            # Fast path: tiny decode batch. With max_num_seqs=2, normal decode
+            # often has T=2 and should not fall back to the Python per-expert
+            # loop used for long prefill chunks.
+            with _enginex_profile("moe.routed_tiny_batch_experts"):
+                H = hidden_states.shape[-1]
+                flat_eids = topk_ids.reshape(-1)                  # (T*K,)
+                flat_ws = topk_weights.reshape(-1).to(hidden_states.dtype)
+
+                w13_sel = w13[flat_eids]                          # (T*K, 2*I, H)
+                w2_sel = w2[flat_eids]                             # (T*K, H, I)
+                x = (hidden_states[:, None, :]
+                     .expand(T, self.top_k, H)
+                     .reshape(-1, 1, H))                           # (T*K, 1, H)
+
+                gate_up = torch.bmm(
+                    x, w13_sel.transpose(1, 2)).squeeze(1)         # (T*K, 2*I)
+                gate, up = gate_up.chunk(2, dim=-1)
+                act = F.silu(gate) * up                           # (T*K, I)
+                expert_out = torch.bmm(
+                    w2_sel, act.unsqueeze(-1)).squeeze(-1)         # (T*K, H)
+
+                out = (expert_out * flat_ws.unsqueeze(-1)).view(
+                    T, self.top_k, H).sum(1).to(hidden_states.dtype)
         else:
             # General path (prefill / multi-seq): loop over unique active experts.
             # At most T*top_k unique experts, always <= num_experts.
-            out = torch.zeros_like(hidden_states)
+            with _enginex_profile("moe.routed_prefill_experts"):
-            unique_eids = topk_ids.view(-1).unique().tolist()
+                out = torch.zeros_like(hidden_states)
-            for eid in unique_eids:
+                unique_eids = topk_ids.view(-1).unique().tolist()
-                eid = int(eid)
+                for eid in unique_eids:
-                mask = (topk_ids == eid)                       # (T, top_k)
+                    eid = int(eid)
-                tok_ids, topk_pos = mask.nonzero(as_tuple=True)
+                    mask = (topk_ids == eid)                       # (T, top_k)
-                tokens = hidden_states[tok_ids]                # (n, H)
+                    tok_ids, topk_pos = mask.nonzero(as_tuple=True)
-                gate_up = F.linear(tokens, w13[eid])           # (n, 2*I)
+                    tokens = hidden_states[tok_ids]                # (n, H)
-                gate, up = gate_up.chunk(2, dim=-1)
+                    gate_up = F.linear(tokens, w13[eid])           # (n, 2*I)
-                act = F.silu(gate) * up                        # (n, I)
+                    gate, up = gate_up.chunk(2, dim=-1)
-                expert_out = F.linear(act, w2[eid])            # (n, H)
+                    act = F.silu(gate) * up                        # (n, I)
-                weights = topk_weights[tok_ids, topk_pos].unsqueeze(-1)
+                    expert_out = F.linear(act, w2[eid])            # (n, H)
-                out.index_add_(0, tok_ids, (expert_out * weights).to(out.dtype))
+                    weights = topk_weights[tok_ids, topk_pos].unsqueeze(-1)
+                    out.index_add_(0, tok_ids, (expert_out * weights).to(out.dtype))
 
         return out  # partial, all-reduce done in forward()
 
     def forward(self, hidden_states: torch.Tensor) -> torch.Tensor:
-        router_logits, _ = self.gate(hidden_states)
+        with _enginex_profile("moe.gate"):
-        routed_out = self._pure_pytorch_experts(hidden_states, router_logits)
+            router_logits, _ = self.gate(hidden_states)
+        with _enginex_profile("moe.routed_total"):
+            routed_out = self._pure_pytorch_experts(hidden_states, router_logits)
 
-        gate_up, _ = self.shared_expert_gate_up(hidden_states)
+        with _enginex_profile("moe.shared_expert"):
-        shared_out = self.act_fn(gate_up)
+            gate_up, _ = self.shared_expert_gate_up(hidden_states)
-        shared_out, _ = self.shared_expert_down(shared_out)
+            shared_out = self.act_fn(gate_up)
-        # Scalar sigmoid gate (Qwen2-MoE / Qwen3.5-MoE style)
+            shared_out, _ = self.shared_expert_down(shared_out)
-        gate_score, _ = self.shared_expert_gate(hidden_states)  # (T, 1)
+            # Scalar sigmoid gate (Qwen2-MoE / Qwen3.5-MoE style)
-        shared_out = shared_out * torch.sigmoid(gate_score)
+            gate_score, _ = self.shared_expert_gate(hidden_states)  # (T, 1)
+            shared_out = shared_out * torch.sigmoid(gate_score)
 
-        out = routed_out + shared_out
+        with _enginex_profile("moe.combine"):
+            out = routed_out + shared_out
         if self.experts.tp_size > 1:
-            out = tensor_model_parallel_all_reduce(out)
+            with _enginex_profile("moe.tp_all_reduce"):
+                out = tensor_model_parallel_all_reduce(out)
         return out
 
 
@@ -883,21 +975,27 @@ class Qwen3_5DecoderLayer(nn.Module):
     ) -> Tuple[torch.Tensor, torch.Tensor]:
         if residual is None:
             residual = hidden_states
-            hidden_states = self.input_layernorm(hidden_states)
+            with _enginex_profile("layer.input_norm"):
+                hidden_states = self.input_layernorm(hidden_states)
         else:
-            hidden_states, residual = self.input_layernorm(hidden_states, residual)
+            with _enginex_profile("layer.input_norm"):
+                hidden_states, residual = self.input_layernorm(hidden_states, residual)
 
         if self.layer_type == "linear_attention":
-            hidden_states = self.linear_attn(
+            with _enginex_profile("layer.linear_attention"):
-                hidden_states, attn_metadata, conv_state, temporal_state)
+                hidden_states = self.linear_attn(
+                    hidden_states, attn_metadata, conv_state, temporal_state)
         else:
-            hidden_states = self.self_attn(
+            with _enginex_profile("layer.full_attention"):
-                positions, hidden_states, kv_cache, attn_metadata)
+                hidden_states = self.self_attn(
+                    positions, hidden_states, kv_cache, attn_metadata)
 
-        hidden_states, residual = self.post_attention_layernorm(
+        with _enginex_profile("layer.post_attn_norm"):
-            hidden_states, residual)
+            hidden_states, residual = self.post_attention_layernorm(
+                hidden_states, residual)
 
-        hidden_states = self.mlp(hidden_states)
+        with _enginex_profile("layer.mlp"):
+            hidden_states = self.mlp(hidden_states)
 
         return hidden_states, residual
 
@@ -934,6 +1032,9 @@ class Qwen3_5Model(nn.Module):
         conv_states: torch.Tensor,     # (num_linear_layers, batch, ...)
         temporal_states: torch.Tensor, # (num_linear_layers, batch, ...)
     ) -> torch.Tensor:
+        global _enginex_profile_mode
+        mode = "prefill" if attn_metadata.num_prefill_tokens > 0 else "decode"
+        _enginex_profile_mode = mode
         hidden_states = self.embed_tokens(input_ids)
         residual = None
 
@@ -961,6 +1062,7 @@ class Qwen3_5Model(nn.Module):
                 attn_idx += 1
 
         hidden_states, _ = self.norm(hidden_states, residual)
+        _enginex_profile_log(mode)
         return hidden_states
 
 

vllm/worker/model_runner.py

@@ -2,9 +2,11 @@ import dataclasses
 import gc
 import inspect
 import itertools
+import os
 import time
 import warnings
 import weakref
+from contextlib import contextmanager
 from dataclasses import dataclass
 from typing import (TYPE_CHECKING, Any, Callable, Dict, List, Optional, Set,
                     Tuple, Type, TypeVar, Union)
@@ -62,6 +64,56 @@ if TYPE_CHECKING:
 
 logger = init_logger(__name__)
 
+_ENGINEX_PROFILE_ENABLED = os.getenv("ENGINEX_PROFILE_DECODE", "0") == "1"
+_ENGINEX_PROFILE_EVERY = int(os.getenv("ENGINEX_PROFILE_EVERY", "32"))
+_ENGINEX_PROFILE_SYNC = os.getenv("ENGINEX_PROFILE_SYNC", "1") != "0"
+_enginex_profile_stats: Dict[str, List[float]] = {}
+_enginex_profile_steps = 0
+
+
+def _enginex_profile_active() -> bool:
+    return _ENGINEX_PROFILE_ENABLED and torch.cuda.is_available()
+
+
+def _enginex_profile_sync() -> None:
+    if _ENGINEX_PROFILE_SYNC:
+        torch.cuda.synchronize()
+
+
+@contextmanager
+def _enginex_profile(label: str):
+    if not _enginex_profile_active():
+        yield
+        return
+    _enginex_profile_sync()
+    start = time.perf_counter()
+    try:
+        yield
+    finally:
+        _enginex_profile_sync()
+        elapsed_ms = (time.perf_counter() - start) * 1000.0
+        stat = _enginex_profile_stats.setdefault(label, [0.0, 0.0])
+        stat[0] += elapsed_ms
+        stat[1] += 1.0
+
+
+def _enginex_profile_log(mode: Optional[str]) -> None:
+    global _enginex_profile_steps
+    if not _enginex_profile_active():
+        return
+    _enginex_profile_steps += 1
+    if _enginex_profile_steps % max(_ENGINEX_PROFILE_EVERY, 1) != 0:
+        return
+    parts = []
+    for label, (total_ms, count) in sorted(
+            _enginex_profile_stats.items(),
+            key=lambda item: item[1][0],
+            reverse=True):
+        avg_ms = total_ms / max(count, 1.0)
+        parts.append(f"{label}: total={total_ms:.2f}ms avg={avg_ms:.3f}ms n={int(count)}")
+    logger.info("[ENGINEX_PROFILE_MODEL_RUNNER] steps=%d mode=%s %s",
+                _enginex_profile_steps, mode, " | ".join(parts))
+
 LORA_WARMUP_RANK = 8
 _BATCH_SIZE_ALIGNMENT = 8
 # all the token sizes that **can** be captured by cudagraph.
@@ -1633,7 +1685,9 @@ class ModelRunner(GPUModelRunnerBase[ModelInputForGPUWithSamplingMetadata]):
                 model_input.prompt_adapter_requests,
                 model_input.prompt_adapter_mapping)
 
-        self.attn_state.begin_forward(model_input)
+        profile_mode = "prompt" if model_input.is_prompt else "decode"
+        with _enginex_profile(f"{profile_mode}.attn_begin_forward"):
+            self.attn_state.begin_forward(model_input)
 
         # Currently cuda graph is only supported by the decode phase.
         assert model_input.attn_metadata is not None
@@ -1661,16 +1715,17 @@ class ModelRunner(GPUModelRunnerBase[ModelInputForGPUWithSamplingMetadata]):
             model_forward_end = torch.cuda.Event(enable_timing=True)
             model_forward_start.record()
 
-        with set_forward_context(model_input.attn_metadata):
+        with _enginex_profile(f"{profile_mode}.model_forward"):
-            hidden_or_intermediate_states = model_executable(
+            with set_forward_context(model_input.attn_metadata):
-                input_ids=model_input.input_tokens,
+                hidden_or_intermediate_states = model_executable(
-                positions=model_input.input_positions,
+                    input_ids=model_input.input_tokens,
-                kv_caches=kv_caches,
+                    positions=model_input.input_positions,
-                attn_metadata=model_input.attn_metadata,
+                    kv_caches=kv_caches,
-                intermediate_tensors=intermediate_tensors,
+                    attn_metadata=model_input.attn_metadata,
-                **MultiModalInputs.as_kwargs(multi_modal_kwargs,
+                    intermediate_tensors=intermediate_tensors,
-                                             device=self.device),
+                    **MultiModalInputs.as_kwargs(multi_modal_kwargs,
-                **seqlen_agnostic_kwargs)
+                                                 device=self.device),
+                    **seqlen_agnostic_kwargs)
 
         if (self.observability_config is not None
                 and self.observability_config.collect_model_forward_time):
@@ -1695,20 +1750,23 @@ class ModelRunner(GPUModelRunnerBase[ModelInputForGPUWithSamplingMetadata]):
                     torch.tensor(model_forward_time + orig_model_forward_time))
             return hidden_or_intermediate_states
 
-        logits = self.model.compute_logits(hidden_or_intermediate_states,
+        with _enginex_profile(f"{profile_mode}.compute_logits"):
-                                           model_input.sampling_metadata)
+            logits = self.model.compute_logits(hidden_or_intermediate_states,
+                                               model_input.sampling_metadata)
 
         if not self.is_driver_worker:
             return []
 
         if model_input.async_callback is not None:
-            model_input.async_callback()
+            with _enginex_profile(f"{profile_mode}.async_callback"):
+                model_input.async_callback()
 
         # Sample the next token.
-        output: SamplerOutput = self.model.sample(
+        with _enginex_profile(f"{profile_mode}.sample"):
-            logits=logits,
+            output: SamplerOutput = self.model.sample(
-            sampling_metadata=model_input.sampling_metadata,
+                logits=logits,
-        )
+                sampling_metadata=model_input.sampling_metadata,
+            )
         if (self.observability_config is not None
                 and self.observability_config.collect_model_forward_time
                 and output is not None):
@@ -1741,6 +1799,7 @@ class ModelRunner(GPUModelRunnerBase[ModelInputForGPUWithSamplingMetadata]):
 
             output.hidden_states = hidden_states
 
+        _enginex_profile_log(profile_mode)
         return [output]
 
 

worklogs/decode_analysis_report_2026-07-14.md

@@ -535,3 +535,135 @@ decode microbench 结果：
 4. 用 `ENGINEX_PROFILE_DECODE=1` 这类环境变量控制插桩，只在短压测时开启，避免污染正式结果。
 
 初步判断：custom all-reduce 不是第一大瓶颈；更可能的主战场是 xFormers decode attention、MoE 小 batch kernel、以及 TP 下大量小 kernel / 同步造成的低 GPU 利用率。
+
+## 2026-07-14：代码级 profiling 与第一轮 MoE 优化
+
+### profiling 插桩
+
+新增环境变量控制的 profiling：
+
+- `ENGINEX_PROFILE_DECODE=1`：开启 profiling。
+- `ENGINEX_PROFILE_EVERY=N`：每 N 次 model forward 打印一次累计统计。
+- `ENGINEX_PROFILE_SYNC=1`：每段计时前后 `torch.cuda.synchronize()`，用于定位 GPU 时间。
+
+插桩位置：
+
+- `vllm/worker/model_runner.py`
+  - `attn_state.begin_forward`
+  - `model_forward`
+  - `compute_logits`
+  - `sample`
+- `qwen3_6_scripts/qwen3_5.py`
+  - `full_attention`: qkv projection / norm+rope / paged attention / gate+o_proj
+  - `linear_attention`: GatedDeltaNet 整层
+  - `MoE`: gate / routing topk / routed experts / shared expert / TP all-reduce
+  - `DecoderLayer`: norm / attention / MLP
+
+注意：profiling 强制同步会显著拖慢请求，因此 profiling 结果只用于定位瓶颈，不作为真实性能分数。
+
+本地归档：
+
+- `worklogs/remote_results/2026-07-14-code-profile/server_profile_mode_eager_custom_ar_seq2_b8192.log`
+- `worklogs/remote_results/2026-07-14-code-profile/profile_mode_eager_custom_ar_short_c1_t24_r1.json`
+
+### 关键 profiling 结果
+
+短请求 `c1, max_tokens=24`，修正标签后，rank0 在 step=24 的主要累计耗时：
+
+| 模块 | 总耗时 | 平均单层/次 | 次数 | 判断 |
+| --- | ---: | ---: | ---: | --- |
+| `prefill.moe.routed_prefill_experts` | 5239.90ms | 65.50ms | 80 | 首 token 慢的最大来源 |
+| `prefill.layer.linear_attention` | 2944.76ms | 49.08ms | 60 | prefill 第二大来源 |
+| `decode.layer.mlp` | 1456.57ms | 1.66ms | 880 | decode 最大来源 |
+| `decode.layer.linear_attention` | 942.63ms | 1.43ms | 660 | decode 第二大来源 |
+| `decode.moe.routed_total` | 785.65ms | 0.89ms | 880 | MLP 中 routed expert 为主 |
+| `decode.moe.routed_decode_experts` | 540.24ms | 0.61ms | 880 | 单 token MoE expert 计算 |
+| `decode.layer.full_attention` | 322.06ms | 1.46ms | 220 | full attention 不是第一瓶颈 |
+| `decode.moe.tp_all_reduce` | 265.92ms | 0.30ms | 880 | 通信有成本，但不是最大项 |
+
+`ModelRunner` 粗粒度：
+
+```text
+decode.model_forward avg ~= 145.6ms
+decode.compute_logits avg ~= 1.17ms
+decode.sample avg ~= 1.01ms
+```
+
+结论：decode 慢主要发生在模型 forward 内部；logits 和 sampler 不是主瓶颈。
+
+### 为什么 GPU 算力打不满
+
+当前路径的 GPU 利用率低，不是因为单个大矩阵乘算不过来，而是因为每 token 被拆成大量小工作：
+
+1. **MoE 没有真正 fused kernel**
+   - 注释里已经说明 BI-V100 上缺少 `vllm_moe_topk_softmax / vllm_invoke_fused_moe_kernel`。
+   - 当前 routed expert 是纯 PyTorch 实现。
+   - prefill 通用路径按 expert 做 Python 循环，长 prompt 下会产生大量小 GEMM 和 CPU/GPU 同步点。
+
+2. **decode batch 太小**
+   - `max_num_seqs=2` 时每步只有 1-2 token。
+   - 小 batch 下矩阵乘规模小，kernel launch、Python 调度、TP 同步成本占比很高。
+
+3. **模型结构有大量 GatedDeltaNet linear_attention 层**
+   - profiling 显示 linear_attention 在 prefill 和 decode 都是大头之一。
+   - 这部分不是标准 paged attention，不能靠换 xFormers attention backend 直接解决。
+
+4. **TP all-reduce 不是第一瓶颈，但放大了小 kernel 问题**
+   - decode MoE all-reduce 单次约 0.30ms。
+   - 单次看不大，但每层一次、每 token 多次累积，且会让 rank 间等待更明显。
+
+### 第一轮针对性优化：MoE tiny-batch fast path
+
+发现：原代码只有 `T == 1` 的 MoE decode fast path。一旦并发 decode `T == 2`，会落入通用 `routed_prefill_experts` 路径：
+
+```python
+unique_eids = topk_ids.view(-1).unique().tolist()
+for eid in unique_eids:
+    ...
+```
+
+这条路径适合大 prefill，但不适合 `max_num_seqs=2` 的小批量 decode。
+
+本轮新增 `T <= 2` fast path：
+
+- 将 `T * top_k` 个选中 expert 展平。
+- 用两次 batched `torch.bmm` 计算 gate/up 和 down。
+- 避免 Python per-expert loop。
+- 保留 `T == 1` 原 fast path 不变。
+
+### 优化结果
+
+对比同口径 `short c2, max_tokens=128, requests=4`：
+
+| 版本 | 成功率 | TTFT P90 | per-request Output TPS P10 | Aggregate Output TPS |
+| --- | ---: | ---: | ---: | ---: |
+| 优化前 custom all-reduce on | 100% | 1.46s | 4.22 | 8.07 |
+| tiny-batch MoE fast path | 100% | 4.42s | 5.95 | 10.60 |
+
+decode 聚合吞吐提升约 **31%**。TTFT 变差可能来自冷缓存/加载后首次请求抖动，后续需要用多轮 warmup 后再复测。
+
+本地归档：
+
+- `worklogs/remote_results/2026-07-14-code-profile/decode_tiny_batch_moe_short_c2_t128_r4.json`
+- `worklogs/remote_results/2026-07-14-code-profile/server_tiny_batch_moe_eager_custom_ar_seq2_b8192.log`
+
+### 下一步优化方向
+
+优先级从高到低：
+
+1. **MoE prefill 路径**
+   - 当前 `prefill.moe.routed_prefill_experts` 是 TTFT 最大来源。
+   - 需要把 Python per-expert loop 替换成更批量化的 grouped GEMM / batched GEMM。
+   - 官方负载长上下文输入占比极高，提升 prefill 会直接改善 TTFT 和 weighted throughput。
+
+2. **GatedDeltaNet linear_attention**
+   - decode 和 prefill 都是大头。
+   - 需要进一步拆分 projection、conv/update、state update、out_proj，确认是 recurrent update 还是投影占主。
+
+3. **更稳的并发策略**
+   - tiny-batch MoE 已证明 `T=2` 能受益。
+   - 后续可测试 `max_num_seqs=3/4`，但受 100K 上下文 KV cache 与 TTFT 影响，需要小心。
+
+4. **TP all-reduce 合并**
+   - 当前 MoE 每层 routed+shared 后做一次 all-reduce。
+   - 如果后续能将若干小通信或 residual 路径合并，可能进一步改善 decode 抖动，但优先级低于 MoE/linear_attention 计算本体。

worklogs/remote_results/2026-07-14-code-profile/decode_tiny_batch_moe_short_c2_t128_r4.json

@@ -0,0 +1,75 @@
+{
+  "created_at": "2026-07-14T12:30:35",
+  "label": "tiny_batch_moe_short_c2_t128_r4",
+  "url": "http://127.0.0.1:1111",
+  "model": "llm",
+  "prompt_mode": "short",
+  "with_tools": false,
+  "tool_count": 0,
+  "concurrency": 2,
+  "requests": 4,
+  "max_tokens": 128,
+  "wall_sec": 48.280083537101746,
+  "success_rate": 1.0,
+  "ttft_p50_sec": 2.915760966949165,
+  "ttft_p90_sec": 4.415460329316557,
+  "output_tps_p10_per_request": 5.954912943833064,
+  "output_tps_p50_per_request": 6.032240452288079,
+  "aggregate_output_tps": 10.604786953331262,
+  "prompt_tokens": 156,
+  "cached_tokens": 64,
+  "completion_tokens": 512,
+  "reasoning_tokens": 512,
+  "chars": 1796,
+  "monitor": null,
+  "results": [
+    {
+      "ok": true,
+      "elapsed_sec": 25.909583542495966,
+      "ttft_sec": 4.414824679493904,
+      "completion_tokens": 128,
+      "prompt_tokens": 39,
+      "cached_tokens": 0,
+      "reasoning_tokens": 128,
+      "output_tps": 5.95494003053556,
+      "chars": 449,
+      "error": null
+    },
+    {
+      "ok": true,
+      "elapsed_sec": 25.91063128784299,
+      "ttft_sec": 4.415732750669122,
+      "completion_tokens": 128,
+      "prompt_tokens": 39,
+      "cached_tokens": 0,
+      "reasoning_tokens": 128,
+      "output_tps": 5.954901335246281,
+      "chars": 449,
+      "error": null
+    },
+    {
+      "ok": true,
+      "elapsed_sec": 22.367535073310137,
+      "ttft_sec": 1.4166972544044256,
+      "completion_tokens": 128,
+      "prompt_tokens": 39,
+      "cached_tokens": 32,
+      "reasoning_tokens": 128,
+      "output_tps": 6.109540874040597,
+      "chars": 449,
+      "error": null
+    },
+    {
+      "ok": true,
+      "elapsed_sec": 22.36741546355188,
+      "ttft_sec": 1.4165842793881893,
+      "completion_tokens": 128,
+      "prompt_tokens": 39,
+      "cached_tokens": 32,
+      "reasoning_tokens": 128,
+      "output_tps": 6.109542808819567,
+      "chars": 449,
+      "error": null
+    }
+  ]
+}

worklogs/remote_results/2026-07-14-code-profile/profile_eager_custom_ar_short_c1_t48_r1.json

@@ -0,0 +1,39 @@
+{
+  "created_at": "2026-07-14T11:39:06",
+  "label": "profile_eager_custom_ar_short_c1_t48_r1",
+  "url": "http://127.0.0.1:1111",
+  "model": "llm",
+  "prompt_mode": "short",
+  "with_tools": false,
+  "tool_count": 0,
+  "concurrency": 1,
+  "requests": 1,
+  "max_tokens": 48,
+  "wall_sec": 11.252297107130289,
+  "success_rate": 1.0,
+  "ttft_p50_sec": 4.141036370769143,
+  "ttft_p90_sec": 4.141036370769143,
+  "output_tps_p10_per_request": 6.7517276250194165,
+  "output_tps_p50_per_request": 6.7517276250194165,
+  "aggregate_output_tps": 4.265795645369481,
+  "prompt_tokens": 39,
+  "cached_tokens": 0,
+  "completion_tokens": 48,
+  "reasoning_tokens": 48,
+  "chars": 173,
+  "monitor": null,
+  "results": [
+    {
+      "ok": true,
+      "elapsed_sec": 11.250327898189425,
+      "ttft_sec": 4.141036370769143,
+      "completion_tokens": 48,
+      "prompt_tokens": 39,
+      "cached_tokens": 0,
+      "reasoning_tokens": 48,
+      "output_tps": 6.7517276250194165,
+      "chars": 173,
+      "error": null
+    }
+  ]
+}

worklogs/remote_results/2026-07-14-code-profile/profile_eager_custom_ar_short_c2_t32_r2.json

@@ -0,0 +1,51 @@
+{
+  "created_at": "2026-07-14T11:39:16",
+  "label": "profile_eager_custom_ar_short_c2_t32_r2",
+  "url": "http://127.0.0.1:1111",
+  "model": "llm",
+  "prompt_mode": "short",
+  "with_tools": false,
+  "tool_count": 0,
+  "concurrency": 2,
+  "requests": 2,
+  "max_tokens": 32,
+  "wall_sec": 10.011093640699983,
+  "success_rate": 1.0,
+  "ttft_p50_sec": 1.5351156890392303,
+  "ttft_p90_sec": 1.5355193987488747,
+  "output_tps_p10_per_request": 3.776407383659353,
+  "output_tps_p50_per_request": 3.7764316482081455,
+  "aggregate_output_tps": 6.392907937631185,
+  "prompt_tokens": 78,
+  "cached_tokens": 64,
+  "completion_tokens": 64,
+  "reasoning_tokens": 64,
+  "chars": 210,
+  "monitor": null,
+  "results": [
+    {
+      "ok": true,
+      "elapsed_sec": 10.00828673131764,
+      "ttft_sec": 1.534611051902175,
+      "completion_tokens": 32,
+      "prompt_tokens": 39,
+      "cached_tokens": 32,
+      "reasoning_tokens": 32,
+      "output_tps": 3.7764013175221547,
+      "chars": 105,
+      "error": null
+    },
+    {
+      "ok": true,
+      "elapsed_sec": 10.00915989279747,
+      "ttft_sec": 1.5356203261762857,
+      "completion_tokens": 32,
+      "prompt_tokens": 39,
+      "cached_tokens": 32,
+      "reasoning_tokens": 32,
+      "output_tps": 3.7764619788941363,
+      "chars": 105,
+      "error": null
+    }
+  ]
+}

worklogs/remote_results/2026-07-14-code-profile/profile_mode_eager_custom_ar_short_c1_t24_r1.json

@@ -0,0 +1,39 @@
+{
+  "created_at": "2026-07-14T12:02:31",
+  "label": "profile_mode_eager_custom_ar_short_c1_t24_r1",
+  "url": "http://127.0.0.1:1111",
+  "model": "llm",
+  "prompt_mode": "short",
+  "with_tools": false,
+  "tool_count": 0,
+  "concurrency": 1,
+  "requests": 1,
+  "max_tokens": 24,
+  "wall_sec": 7.6276699639856815,
+  "success_rate": 1.0,
+  "ttft_p50_sec": 4.090665258467197,
+  "ttft_p90_sec": 4.090665258467197,
+  "output_tps_p10_per_request": 6.788945343504622,
+  "output_tps_p50_per_request": 6.788945343504622,
+  "aggregate_output_tps": 3.1464392289279512,
+  "prompt_tokens": 39,
+  "cached_tokens": 0,
+  "completion_tokens": 24,
+  "reasoning_tokens": 24,
+  "chars": 78,
+  "monitor": null,
+  "results": [
+    {
+      "ok": true,
+      "elapsed_sec": 7.625824077054858,
+      "ttft_sec": 4.090665258467197,
+      "completion_tokens": 24,
+      "prompt_tokens": 39,
+      "cached_tokens": 0,
+      "reasoning_tokens": 24,
+      "output_tps": 6.788945343504622,
+      "chars": 78,
+      "error": null
+    }
+  ]
+}

worklogs/remote_results/2026-07-14-code-profile/server_profile_eager_custom_ar_seq2_b8192.log

@@ -0,0 +1,407 @@
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+INFO 07-14 11:34:16 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+2026-07-14 11:34:18.268441: I tensorflow/core/util/port.cc:110] oneDNN custom operations are on. You may see slightly different numerical results due to floating-point round-off errors from different computation orders. To turn them off, set the environment variable `TF_ENABLE_ONEDNN_OPTS=0`.
+2026-07-14 11:34:18.320614: I tensorflow/core/platform/cpu_feature_guard.cc:182] This TensorFlow binary is optimized to use available CPU instructions in performance-critical operations.
+To enable the following instructions: SSE3 SSE4.1 SSE4.2 AVX AVX2 AVX512F AVX512_VNNI AVX512_BF16 AVX_VNNI AMX_TILE AMX_INT8 AMX_BF16 FMA, in other operations, rebuild TensorFlow with the appropriate compiler flags.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+INFO 07-14 11:34:23 api_server.py:530] vLLM API server version 0.6.3
+INFO 07-14 11:34:23 api_server.py:531] args: Namespace(host='0.0.0.0', port=1111, uvicorn_log_level='info', allow_credentials=False, allowed_origins=['*'], allowed_methods=['*'], allowed_headers=['*'], api_key=None, lora_modules=None, prompt_adapters=None, chat_template=None, response_role='assistant', ssl_keyfile=None, ssl_certfile=None, ssl_ca_certs=None, ssl_cert_reqs=0, root_path=None, middleware=[], return_tokens_as_token_ids=False, disable_frontend_multiprocessing=True, enable_auto_tool_choice=True, tool_call_parser='qwen3_coder', tool_parser_plugin='', reasoning_parser='qwen3', model='/root/public-storage/models/Qwen/Qwen3.6-35B-A3B', tokenizer=None, skip_tokenizer_init=False, revision=None, code_revision=None, tokenizer_revision=None, tokenizer_mode='auto', trust_remote_code=True, download_dir=None, load_format='auto', config_format='auto', dtype='auto', kv_cache_dtype='auto', quantization_param_path=None, max_model_len=100000, guided_decoding_backend='outlines', distributed_executor_backend=None, worker_use_ray=False, pipeline_parallel_size=1, tensor_parallel_size=4, max_parallel_loading_workers=None, ray_workers_use_nsight=False, block_size=16, enable_prefix_caching=True, disable_sliding_window=False, use_v2_block_manager=True, num_lookahead_slots=0, seed=0, swap_space=4, cpu_offload_gb=0, gpu_memory_utilization=0.95, num_gpu_blocks_override=None, max_num_batched_tokens=8192, max_num_seqs=2, max_logprobs=20, disable_log_stats=False, quantization=None, rope_scaling=None, rope_theta=None, enforce_eager=True, max_context_len_to_capture=None, max_seq_len_to_capture=32768, disable_custom_all_reduce=False, tokenizer_pool_size=0, tokenizer_pool_type='ray', tokenizer_pool_extra_config=None, limit_mm_per_prompt=None, mm_processor_kwargs=None, enable_lora=False, max_loras=1, max_lora_rank=16, lora_extra_vocab_size=256, lora_dtype='auto', long_lora_scaling_factors=None, max_cpu_loras=None, fully_sharded_loras=False, enable_prompt_adapter=False, max_prompt_adapters=1, max_prompt_adapter_token=0, device='auto', num_scheduler_steps=1, multi_step_stream_outputs=True, scheduler_delay_factor=0.0, enable_chunked_prefill=True, speculative_model=None, speculative_model_quantization=None, num_speculative_tokens=None, speculative_disable_mqa_scorer=False, speculative_draft_tensor_parallel_size=None, speculative_max_model_len=None, speculative_disable_by_batch_size=None, ngram_prompt_lookup_max=None, ngram_prompt_lookup_min=None, spec_decoding_acceptance_method='rejection_sampler', typical_acceptance_sampler_posterior_threshold=None, typical_acceptance_sampler_posterior_alpha=None, disable_logprobs_during_spec_decoding=None, model_loader_extra_config=None, ignore_patterns=[], preemption_mode=None, served_model_name=['llm'], qlora_adapter_name_or_path=None, otlp_traces_endpoint=None, collect_detailed_traces=None, disable_async_output_proc=False, override_neuron_config=None, scheduling_policy='fcfs', disable_log_requests=True, max_log_len=None, disable_fastapi_docs=False)
+INFO 07-14 11:34:23 config.py:1670] Downcasting torch.float32 to torch.float16.
+INFO 07-14 11:34:34 config.py:887] Defaulting to use mp for distributed inference
+INFO 07-14 11:34:34 config.py:1005] Chunked prefill is enabled with max_num_batched_tokens=8192.
+WARNING 07-14 11:34:34 config.py:380] To see benefits of async output processing, enable CUDA graph. Since, enforce-eager is enabled, async output processor cannot be used
+INFO 07-14 11:34:34 llm_engine.py:237] Initializing an LLM engine (v0.6.3) with config: model='/root/public-storage/models/Qwen/Qwen3.6-35B-A3B', speculative_config=None, tokenizer='/root/public-storage/models/Qwen/Qwen3.6-35B-A3B', skip_tokenizer_init=False, tokenizer_mode=auto, revision=None, override_neuron_config=None, rope_scaling=None, rope_theta=None, tokenizer_revision=None, trust_remote_code=True, dtype=torch.float16, max_seq_len=100000, download_dir=None, load_format=LoadFormat.AUTO, tensor_parallel_size=4, pipeline_parallel_size=1, disable_custom_all_reduce=False, quantization=None, enforce_eager=True, kv_cache_dtype=auto, quantization_param_path=None, device_config=cuda, decoding_config=DecodingConfig(guided_decoding_backend='outlines'), observability_config=ObservabilityConfig(otlp_traces_endpoint=None, collect_model_forward_time=False, collect_model_execute_time=False), seed=0, served_model_name=llm, use_v2_block_manager=True, num_scheduler_steps=1, chunked_prefill_enabled=True multi_step_stream_outputs=True, enable_prefix_caching=True, use_async_output_proc=False, use_cached_outputs=False, mm_processor_kwargs=None)
+WARNING 07-14 11:34:35 multiproc_gpu_executor.py:53] Reducing Torch parallelism from 64 threads to 1 to avoid unnecessary CPU contention. Set OMP_NUM_THREADS in the external environment to tune this value as needed.
+INFO 07-14 11:34:35 custom_cache_manager.py:17] Setting Triton cache manager to: vllm.triton_utils.custom_cache_manager:CustomCacheManager
+INFO 07-14 11:34:35 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+INFO 07-14 11:34:35 selector.py:115] Using XFormers backend.
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+INFO 07-14 11:34:37 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+INFO 07-14 11:34:37 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+INFO 07-14 11:34:37 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+(VllmWorkerProcess pid=10987) INFO 07-14 11:34:44 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=10987) INFO 07-14 11:34:44 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=10987) INFO 07-14 11:34:44 multiproc_worker_utils.py:216] Worker ready; awaiting tasks
+(VllmWorkerProcess pid=10988) INFO 07-14 11:34:44 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=10988) INFO 07-14 11:34:44 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=10988) INFO 07-14 11:34:44 multiproc_worker_utils.py:216] Worker ready; awaiting tasks
+(VllmWorkerProcess pid=10989) INFO 07-14 11:34:44 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=10989) INFO 07-14 11:34:44 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=10989) INFO 07-14 11:34:44 multiproc_worker_utils.py:216] Worker ready; awaiting tasks
+INFO 07-14 11:34:45 shm_broadcast.py:242] vLLM message queue communication handle: Handle(connect_ip='127.0.0.1', local_reader_ranks=[1, 2, 3], buffer=<vllm.distributed.device_communicators.shm_broadcast.ShmRingBuffer object at 0x7f5623116410>, local_subscribe_port=42265, remote_subscribe_port=None)
+INFO 07-14 11:34:45 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+(VllmWorkerProcess pid=10987) INFO 07-14 11:34:45 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+(VllmWorkerProcess pid=10988) INFO 07-14 11:34:45 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+(VllmWorkerProcess pid=10989) INFO 07-14 11:34:45 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+INFO 07-14 11:34:45 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+INFO 07-14 11:34:45 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=10988) INFO 07-14 11:34:45 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=10987) INFO 07-14 11:34:45 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=10988) INFO 07-14 11:34:45 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=10987) INFO 07-14 11:34:45 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=10989) INFO 07-14 11:34:45 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=10989) INFO 07-14 11:34:45 selector.py:115] Using XFormers backend.
+
+Loading safetensors checkpoint shards:   0% Completed | 0/26 [00:00<?, ?it/s]
+
+Loading safetensors checkpoint shards:   4% Completed | 1/26 [00:01<00:44,  1.79s/it]
+
+Loading safetensors checkpoint shards:   8% Completed | 2/26 [00:02<00:23,  1.00it/s]
+
+Loading safetensors checkpoint shards:  12% Completed | 3/26 [00:04<00:31,  1.36s/it]
+
+Loading safetensors checkpoint shards:  15% Completed | 4/26 [00:05<00:34,  1.57s/it]
+
+Loading safetensors checkpoint shards:  19% Completed | 5/26 [00:06<00:28,  1.36s/it]
+
+Loading safetensors checkpoint shards:  23% Completed | 6/26 [00:08<00:31,  1.58s/it]
+
+Loading safetensors checkpoint shards:  27% Completed | 7/26 [00:09<00:22,  1.20s/it]
+
+Loading safetensors checkpoint shards:  31% Completed | 8/26 [00:11<00:25,  1.39s/it]
+
+Loading safetensors checkpoint shards:  35% Completed | 9/26 [00:12<00:21,  1.25s/it]
+
+Loading safetensors checkpoint shards:  38% Completed | 10/26 [00:14<00:23,  1.47s/it]
+
+Loading safetensors checkpoint shards:  42% Completed | 11/26 [00:14<00:16,  1.11s/it]
+
+Loading safetensors checkpoint shards:  46% Completed | 12/26 [00:16<00:18,  1.33s/it]
+
+Loading safetensors checkpoint shards:  50% Completed | 13/26 [00:18<00:19,  1.50s/it]
+
+Loading safetensors checkpoint shards:  54% Completed | 14/26 [00:20<00:20,  1.68s/it]
+
+Loading safetensors checkpoint shards:  58% Completed | 15/26 [00:20<00:15,  1.42s/it]
+
+Loading safetensors checkpoint shards:  62% Completed | 16/26 [00:23<00:17,  1.72s/it]
+
+Loading safetensors checkpoint shards:  65% Completed | 17/26 [00:23<00:11,  1.33s/it]
+
+Loading safetensors checkpoint shards:  69% Completed | 18/26 [00:25<00:11,  1.47s/it]
+
+Loading safetensors checkpoint shards:  73% Completed | 19/26 [00:27<00:10,  1.55s/it]
+
+Loading safetensors checkpoint shards:  77% Completed | 20/26 [00:29<00:10,  1.83s/it]
+
+Loading safetensors checkpoint shards:  81% Completed | 21/26 [00:30<00:07,  1.59s/it]
+
+Loading safetensors checkpoint shards:  85% Completed | 22/26 [00:31<00:05,  1.33s/it]
+
+Loading safetensors checkpoint shards:  88% Completed | 23/26 [00:33<00:04,  1.65s/it]
+
+Loading safetensors checkpoint shards:  92% Completed | 24/26 [00:35<00:03,  1.72s/it]
+
+Loading safetensors checkpoint shards:  96% Completed | 25/26 [00:37<00:01,  1.78s/it]
+
+Loading safetensors checkpoint shards: 100% Completed | 26/26 [00:38<00:00,  1.40s/it]
+
+Loading safetensors checkpoint shards: 100% Completed | 26/26 [00:38<00:00,  1.47s/it]
+
+(VllmWorkerProcess pid=10987) INFO 07-14 11:35:24 model_runner.py:1123] Loading model weights took 16.2303 GB
+INFO 07-14 11:35:24 model_runner.py:1123] Loading model weights took 16.2303 GB
+(VllmWorkerProcess pid=10989) INFO 07-14 11:35:24 model_runner.py:1123] Loading model weights took 16.2303 GB
+(VllmWorkerProcess pid=10988) INFO 07-14 11:35:24 model_runner.py:1123] Loading model weights took 16.2303 GB
+INFO 07-14 11:35:33 distributed_gpu_executor.py:57] # GPU blocks: 21100, # CPU blocks: 6553
+INFO 07-14 11:35:33 distributed_gpu_executor.py:61] Maximum concurrency for 100000 tokens per request: 3.38x
+INFO 07-14 11:35:38 serving_chat.py:79] "auto" tool choice has been enabled please note that while the parallel_tool_calls client option is preset for compatibility reasons, it will be ignored.
+INFO 07-14 11:35:38 serving_chat.py:101] Reasoning parser 'qwen3' enabled.
+WARNING 07-14 11:35:38 serving_embedding.py:199] embedding_mode is False. Embedding API will not work.
+INFO 07-14 11:35:38 launcher.py:19] Available routes are:
+INFO 07-14 11:35:38 launcher.py:27] Route: /openapi.json, Methods: HEAD, GET
+INFO 07-14 11:35:38 launcher.py:27] Route: /docs, Methods: HEAD, GET
+INFO 07-14 11:35:38 launcher.py:27] Route: /docs/oauth2-redirect, Methods: HEAD, GET
+INFO 07-14 11:35:38 launcher.py:27] Route: /redoc, Methods: HEAD, GET
+INFO 07-14 11:35:38 launcher.py:27] Route: /health, Methods: GET
+INFO 07-14 11:35:38 launcher.py:27] Route: /tokenize, Methods: POST
+INFO 07-14 11:35:38 launcher.py:27] Route: /detokenize, Methods: POST
+INFO 07-14 11:35:38 launcher.py:27] Route: /v1/models, Methods: GET
+INFO 07-14 11:35:38 launcher.py:27] Route: /version, Methods: GET
+INFO 07-14 11:35:38 launcher.py:27] Route: /v1/chat/completions, Methods: POST
+INFO 07-14 11:35:38 launcher.py:27] Route: /v1/completions, Methods: POST
+INFO 07-14 11:35:38 launcher.py:27] Route: /v1/embeddings, Methods: POST
+INFO:     Started server process [10648]
+INFO:     Waiting for application startup.
+INFO:     Application startup complete.
+INFO:     Uvicorn running on socket ('0.0.0.0', 1111) (Press CTRL+C to quit)
+INFO 07-14 11:35:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:35:48 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:35:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:35:58 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:36:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:36:08 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:36:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:36:18 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:36:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:36:28 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:36:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:36:38 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:36:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:36:48 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO:     127.0.0.1:35518 - "GET /health HTTP/1.1" 200 OK
+INFO 07-14 11:36:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:36:58 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:37:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:37:08 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:37:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:37:18 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:37:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:37:28 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:37:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:37:38 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:37:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:37:48 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:37:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:37:58 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:38:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:38:08 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO:     127.0.0.1:46034 - "GET /health HTTP/1.1" 200 OK
+INFO 07-14 11:38:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:38:18 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:38:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:38:28 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:38:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:38:38 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:38:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:38:48 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO:     127.0.0.1:56962 - "POST /v1/chat/completions HTTP/1.1" 200 OK
+/usr/local/lib/python3.10/site-packages/pyairports/airports.py:1: UserWarning: pkg_resources is deprecated as an API. See https://setuptools.pypa.io/en/latest/pkg_resources.html. The pkg_resources package is slated for removal as early as 2025-11-30. Refrain from using this package or pin to Setuptools<81.
+  from pkg_resources import resource_string
+INFO 07-14 11:38:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:38:58 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:39:01 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=0 steps=16 mode=decode layer.mlp: total=6479.37ms avg=10.124ms n=640 | moe.routed_total: total=5732.82ms avg=8.958ms n=640 | moe.routed_prefill_experts: total=5138.29ms avg=64.229ms n=80 | layer.linear_attention: total=4877.66ms avg=10.162ms n=480 | layer.full_attention: total=701.53ms avg=4.385ms n=160 | full_attn.paged_attention: total=428.46ms avg=2.678ms n=160 | moe.tp_all_reduce: total=380.35ms avg=0.594ms n=640 | moe.routed_decode_experts: total=342.04ms avg=0.611ms n=560 | layer.input_norm: total=229.22ms avg=0.358ms n=640 | layer.post_attn_norm: total=216.38ms avg=0.338ms n=640 | moe.routing_topk: total=216.08ms avg=0.338ms n=640 | moe.shared_expert: total=209.64ms avg=0.328ms n=640 | full_attn.gate_o_proj: total=110.16ms avg=0.688ms n=160 | full_attn.norm_rope: total=84.41ms avg=0.528ms n=160 | full_attn.qkv_proj: total=63.63ms avg=0.398ms n=160 | moe.gate: total=57.67ms avg=0.090ms n=640 | moe.combine: total=32.51ms avg=0.051ms n=640
+(VllmWorkerProcess pid=10988) INFO 07-14 11:39:01 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=2 steps=16 mode=decode layer.mlp: total=6477.48ms avg=10.121ms n=640 | moe.routed_total: total=5756.75ms avg=8.995ms n=640 | moe.routed_prefill_experts: total=5166.53ms avg=64.582ms n=80 | layer.linear_attention: total=4881.80ms avg=10.170ms n=480 | layer.full_attention: total=701.10ms avg=4.382ms n=160 | full_attn.paged_attention: total=420.51ms avg=2.628ms n=160 | moe.routed_decode_experts: total=344.50ms avg=0.615ms n=560 | moe.tp_all_reduce: total=342.37ms avg=0.535ms n=640 | layer.input_norm: total=225.86ms avg=0.353ms n=640 | layer.post_attn_norm: total=218.22ms avg=0.341ms n=640 | moe.shared_expert: total=210.19ms avg=0.328ms n=640 | moe.routing_topk: total=209.87ms avg=0.328ms n=640 | full_attn.gate_o_proj: total=117.54ms avg=0.735ms n=160 | full_attn.norm_rope: total=84.89ms avg=0.531ms n=160 | full_attn.qkv_proj: total=63.45ms avg=0.397ms n=160 | moe.gate: total=59.30ms avg=0.093ms n=640 | moe.combine: total=42.91ms avg=0.067ms n=640
+(VllmWorkerProcess pid=10989) INFO 07-14 11:39:01 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=3 steps=16 mode=decode layer.mlp: total=6477.64ms avg=10.121ms n=640 | moe.routed_total: total=5780.92ms avg=9.033ms n=640 | moe.routed_prefill_experts: total=5196.83ms avg=64.960ms n=80 | layer.linear_attention: total=4881.38ms avg=10.170ms n=480 | layer.full_attention: total=701.03ms avg=4.381ms n=160 | full_attn.paged_attention: total=420.14ms avg=2.626ms n=160 | moe.routed_decode_experts: total=343.09ms avg=0.613ms n=560 | moe.tp_all_reduce: total=326.79ms avg=0.511ms n=640 | layer.input_norm: total=226.41ms avg=0.354ms n=640 | layer.post_attn_norm: total=218.14ms avg=0.341ms n=640 | moe.shared_expert: total=209.91ms avg=0.328ms n=640 | moe.routing_topk: total=204.80ms avg=0.320ms n=640 | full_attn.gate_o_proj: total=116.90ms avg=0.731ms n=160 | full_attn.norm_rope: total=85.65ms avg=0.535ms n=160 | full_attn.qkv_proj: total=63.79ms avg=0.399ms n=160 | moe.gate: total=59.58ms avg=0.093ms n=640 | moe.combine: total=34.85ms avg=0.054ms n=640
+(VllmWorkerProcess pid=10987) INFO 07-14 11:39:01 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=1 steps=16 mode=decode layer.mlp: total=6479.94ms avg=10.125ms n=640 | moe.routed_total: total=5735.46ms avg=8.962ms n=640 | moe.routed_prefill_experts: total=5154.84ms avg=64.436ms n=80 | layer.linear_attention: total=4881.74ms avg=10.170ms n=480 | layer.full_attention: total=702.39ms avg=4.390ms n=160 | full_attn.paged_attention: total=427.34ms avg=2.671ms n=160 | moe.tp_all_reduce: total=377.53ms avg=0.590ms n=640 | moe.routed_decode_experts: total=341.55ms avg=0.610ms n=560 | layer.input_norm: total=225.32ms avg=0.352ms n=640 | layer.post_attn_norm: total=215.76ms avg=0.337ms n=640 | moe.shared_expert: total=209.99ms avg=0.328ms n=640 | moe.routing_topk: total=203.00ms avg=0.317ms n=640 | full_attn.gate_o_proj: total=113.29ms avg=0.708ms n=160 | full_attn.norm_rope: total=83.79ms avg=0.524ms n=160 | full_attn.qkv_proj: total=63.15ms avg=0.395ms n=160 | moe.gate: total=57.93ms avg=0.091ms n=640 | moe.combine: total=33.78ms avg=0.053ms n=640
+INFO 07-14 11:39:01 model_runner.py:114] [ENGINEX_PROFILE_MODEL_RUNNER] steps=16 mode=decode prompt.model_forward: total=10698.55ms avg=5349.273ms n=2 | decode.model_forward: total=2037.07ms avg=145.505ms n=14 | prompt.compute_logits: total=202.86ms avg=101.429ms n=2 | prompt.sample: total=40.62ms avg=20.308ms n=2 | decode.compute_logits: total=16.65ms avg=1.189ms n=14 | decode.sample: total=14.14ms avg=1.010ms n=14 | decode.attn_begin_forward: total=0.22ms avg=0.016ms n=14 | prompt.attn_begin_forward: total=0.05ms avg=0.025ms n=2
+INFO 07-14 11:39:03 metrics.py:345] Avg prompt throughput: 7.7 tokens/s, Avg generation throughput: 4.8 tokens/s, Running: 1 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:39:03 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+(VllmWorkerProcess pid=10988) INFO 07-14 11:39:04 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=2 steps=32 mode=decode layer.mlp: total=7512.25ms avg=5.869ms n=1280 | moe.routed_total: total=6320.62ms avg=4.938ms n=1280 | layer.linear_attention: total=5549.77ms avg=5.781ms n=960 | moe.routed_prefill_experts: total=5166.53ms avg=64.582ms n=80 | layer.full_attention: total=923.27ms avg=2.885ms n=320 | moe.routed_decode_experts: total=735.47ms avg=0.613ms n=1200 | moe.tp_all_reduce: total=531.76ms avg=0.415ms n=1280 | full_attn.paged_attention: total=463.63ms avg=1.449ms n=320 | moe.shared_expert: total=359.85ms avg=0.281ms n=1280 | layer.input_norm: total=357.80ms avg=0.280ms n=1280 | layer.post_attn_norm: total=349.09ms avg=0.273ms n=1280 | moe.routing_topk: total=348.27ms avg=0.272ms n=1280 | full_attn.gate_o_proj: total=184.63ms avg=0.577ms n=320 | full_attn.norm_rope: total=148.94ms avg=0.465ms n=320 | moe.gate: total=102.29ms avg=0.080ms n=1280 | full_attn.qkv_proj: total=97.08ms avg=0.303ms n=320 | moe.combine: total=67.92ms avg=0.053ms n=1280
+INFO 07-14 11:39:04 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=0 steps=32 mode=decode layer.mlp: total=7514.73ms avg=5.871ms n=1280 | moe.routed_total: total=6297.44ms avg=4.920ms n=1280 | layer.linear_attention: total=5544.35ms avg=5.775ms n=960 | moe.routed_prefill_experts: total=5138.29ms avg=64.229ms n=80 | layer.full_attention: total=923.60ms avg=2.886ms n=320 | moe.routed_decode_experts: total=731.56ms avg=0.610ms n=1200 | moe.tp_all_reduce: total=568.78ms avg=0.444ms n=1280 | full_attn.paged_attention: total=471.55ms avg=1.474ms n=320 | layer.input_norm: total=361.94ms avg=0.283ms n=1280 | moe.shared_expert: total=359.86ms avg=0.281ms n=1280 | moe.routing_topk: total=356.01ms avg=0.278ms n=1280 | layer.post_attn_norm: total=346.28ms avg=0.271ms n=1280 | full_attn.gate_o_proj: total=176.48ms avg=0.552ms n=320 | full_attn.norm_rope: total=148.59ms avg=0.464ms n=320 | moe.gate: total=100.46ms avg=0.078ms n=1280 | full_attn.qkv_proj: total=97.63ms avg=0.305ms n=320 | moe.combine: total=56.61ms avg=0.044ms n=1280
+(VllmWorkerProcess pid=10989) INFO 07-14 11:39:04 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=3 steps=32 mode=decode layer.mlp: total=7511.89ms avg=5.869ms n=1280 | moe.routed_total: total=6346.78ms avg=4.958ms n=1280 | layer.linear_attention: total=5546.91ms avg=5.778ms n=960 | moe.routed_prefill_experts: total=5196.83ms avg=64.960ms n=80 | layer.full_attention: total=923.09ms avg=2.885ms n=320 | moe.routed_decode_experts: total=734.27ms avg=0.612ms n=1200 | moe.tp_all_reduce: total=507.39ms avg=0.396ms n=1280 | full_attn.paged_attention: total=464.27ms avg=1.451ms n=320 | moe.shared_expert: total=361.08ms avg=0.282ms n=1280 | layer.input_norm: total=360.13ms avg=0.281ms n=1280 | layer.post_attn_norm: total=350.27ms avg=0.274ms n=1280 | moe.routing_topk: total=344.92ms avg=0.269ms n=1280 | full_attn.gate_o_proj: total=181.82ms avg=0.568ms n=320 | full_attn.norm_rope: total=150.20ms avg=0.469ms n=320 | moe.gate: total=104.89ms avg=0.082ms n=1280 | full_attn.qkv_proj: total=98.08ms avg=0.306ms n=320 | moe.combine: total=62.51ms avg=0.049ms n=1280
+(VllmWorkerProcess pid=10987) INFO 07-14 11:39:04 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=1 steps=32 mode=decode layer.mlp: total=7515.10ms avg=5.871ms n=1280 | moe.routed_total: total=6298.23ms avg=4.920ms n=1280 | layer.linear_attention: total=5549.96ms avg=5.781ms n=960 | moe.routed_prefill_experts: total=5154.84ms avg=64.436ms n=80 | layer.full_attention: total=924.95ms avg=2.890ms n=320 | moe.routed_decode_experts: total=731.88ms avg=0.610ms n=1200 | moe.tp_all_reduce: total=567.74ms avg=0.444ms n=1280 | full_attn.paged_attention: total=469.88ms avg=1.468ms n=320 | moe.shared_expert: total=359.93ms avg=0.281ms n=1280 | layer.input_norm: total=356.63ms avg=0.279ms n=1280 | layer.post_attn_norm: total=346.43ms avg=0.271ms n=1280 | moe.routing_topk: total=340.77ms avg=0.266ms n=1280 | full_attn.gate_o_proj: total=181.26ms avg=0.566ms n=320 | full_attn.norm_rope: total=147.83ms avg=0.462ms n=320 | moe.gate: total=101.03ms avg=0.079ms n=1280 | full_attn.qkv_proj: total=96.90ms avg=0.303ms n=320 | moe.combine: total=58.88ms avg=0.046ms n=1280
+INFO 07-14 11:39:04 model_runner.py:114] [ENGINEX_PROFILE_MODEL_RUNNER] steps=32 mode=decode prompt.model_forward: total=10698.55ms avg=5349.273ms n=2 | decode.model_forward: total=4300.50ms avg=143.350ms n=30 | prompt.compute_logits: total=202.86ms avg=101.429ms n=2 | prompt.sample: total=40.62ms avg=20.308ms n=2 | decode.compute_logits: total=35.17ms avg=1.172ms n=30 | decode.sample: total=30.18ms avg=1.006ms n=30 | decode.attn_begin_forward: total=0.46ms avg=0.015ms n=30 | prompt.attn_begin_forward: total=0.05ms avg=0.025ms n=2
+(VllmWorkerProcess pid=10988) INFO 07-14 11:39:06 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=2 steps=48 mode=decode layer.mlp: total=8565.64ms avg=4.461ms n=1920 | moe.routed_total: total=6883.91ms avg=3.585ms n=1920 | layer.linear_attention: total=6230.86ms avg=4.327ms n=1440 | moe.routed_prefill_experts: total=5166.53ms avg=64.582ms n=80 | layer.full_attention: total=1149.78ms avg=2.395ms n=480 | moe.routed_decode_experts: total=1125.25ms avg=0.612ms n=1840 | moe.tp_all_reduce: total=740.06ms avg=0.385ms n=1920 | moe.shared_expert: total=510.07ms avg=0.266ms n=1920 | full_attn.paged_attention: total=507.77ms avg=1.058ms n=480 | layer.input_norm: total=490.33ms avg=0.255ms n=1920 | moe.routing_topk: total=487.27ms avg=0.254ms n=1920 | layer.post_attn_norm: total=478.23ms avg=0.249ms n=1920 | full_attn.gate_o_proj: total=254.73ms avg=0.531ms n=480 | full_attn.norm_rope: total=213.20ms avg=0.444ms n=480 | moe.gate: total=144.81ms avg=0.075ms n=1920 | full_attn.qkv_proj: total=130.70ms avg=0.272ms n=480 | moe.combine: total=92.98ms avg=0.048ms n=1920
+INFO 07-14 11:39:06 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=0 steps=48 mode=decode layer.mlp: total=8565.83ms avg=4.461ms n=1920 | moe.routed_total: total=6862.20ms avg=3.574ms n=1920 | layer.linear_attention: total=6220.48ms avg=4.320ms n=1440 | moe.routed_prefill_experts: total=5138.29ms avg=64.229ms n=80 | layer.full_attention: total=1149.99ms avg=2.396ms n=480 | moe.routed_decode_experts: total=1121.57ms avg=0.610ms n=1840 | moe.tp_all_reduce: total=770.33ms avg=0.401ms n=1920 | full_attn.paged_attention: total=515.91ms avg=1.075ms n=480 | moe.shared_expert: total=511.62ms avg=0.266ms n=1920 | layer.input_norm: total=497.87ms avg=0.259ms n=1920 | moe.routing_topk: total=495.48ms avg=0.258ms n=1920 | layer.post_attn_norm: total=476.22ms avg=0.248ms n=1920 | full_attn.gate_o_proj: total=245.20ms avg=0.511ms n=480 | full_attn.norm_rope: total=213.11ms avg=0.444ms n=480 | moe.gate: total=143.33ms avg=0.075ms n=1920 | full_attn.qkv_proj: total=131.71ms avg=0.274ms n=480 | moe.combine: total=80.87ms avg=0.042ms n=1920
+(VllmWorkerProcess pid=10987) INFO 07-14 11:39:06 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=1 steps=48 mode=decode layer.mlp: total=8565.70ms avg=4.461ms n=1920 | moe.routed_total: total=6865.80ms avg=3.576ms n=1920 | layer.linear_attention: total=6230.90ms avg=4.327ms n=1440 | moe.routed_prefill_experts: total=5154.84ms avg=64.436ms n=80 | layer.full_attention: total=1151.16ms avg=2.398ms n=480 | moe.routed_decode_experts: total=1124.60ms avg=0.611ms n=1840 | moe.tp_all_reduce: total=764.42ms avg=0.398ms n=1920 | full_attn.paged_attention: total=513.29ms avg=1.069ms n=480 | moe.shared_expert: total=512.39ms avg=0.267ms n=1920 | layer.input_norm: total=490.33ms avg=0.255ms n=1920 | moe.routing_topk: total=480.44ms avg=0.250ms n=1920 | layer.post_attn_norm: total=477.60ms avg=0.249ms n=1920 | full_attn.gate_o_proj: total=249.26ms avg=0.519ms n=480 | full_attn.norm_rope: total=213.91ms avg=0.446ms n=480 | moe.gate: total=144.66ms avg=0.075ms n=1920 | full_attn.qkv_proj: total=131.07ms avg=0.273ms n=480 | moe.combine: total=84.43ms avg=0.044ms n=1920
+(VllmWorkerProcess pid=10989) INFO 07-14 11:39:06 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=3 steps=48 mode=decode layer.mlp: total=8560.84ms avg=4.459ms n=1920 | moe.routed_total: total=6913.41ms avg=3.601ms n=1920 | layer.linear_attention: total=6224.60ms avg=4.323ms n=1440 | moe.routed_prefill_experts: total=5196.83ms avg=64.960ms n=80 | layer.full_attention: total=1149.35ms avg=2.394ms n=480 | moe.routed_decode_experts: total=1124.91ms avg=0.611ms n=1840 | moe.tp_all_reduce: total=700.04ms avg=0.365ms n=1920 | moe.shared_expert: total=513.69ms avg=0.268ms n=1920 | full_attn.paged_attention: total=509.40ms avg=1.061ms n=480 | layer.input_norm: total=497.02ms avg=0.259ms n=1920 | moe.routing_topk: total=486.26ms avg=0.253ms n=1920 | layer.post_attn_norm: total=482.80ms avg=0.251ms n=1920 | full_attn.gate_o_proj: total=249.50ms avg=0.520ms n=480 | full_attn.norm_rope: total=215.13ms avg=0.448ms n=480 | moe.gate: total=150.55ms avg=0.078ms n=1920 | full_attn.qkv_proj: total=132.46ms avg=0.276ms n=480 | moe.combine: total=90.08ms avg=0.047ms n=1920
+INFO 07-14 11:39:06 model_runner.py:114] [ENGINEX_PROFILE_MODEL_RUNNER] steps=48 mode=decode prompt.model_forward: total=10698.55ms avg=5349.273ms n=2 | decode.model_forward: total=6600.11ms avg=143.481ms n=46 | prompt.compute_logits: total=202.86ms avg=101.429ms n=2 | decode.compute_logits: total=54.04ms avg=1.175ms n=46 | decode.sample: total=46.30ms avg=1.007ms n=46 | prompt.sample: total=40.62ms avg=20.308ms n=2 | decode.attn_begin_forward: total=0.71ms avg=0.015ms n=46 | prompt.attn_begin_forward: total=0.05ms avg=0.025ms n=2
+INFO:     127.0.0.1:44782 - "POST /v1/chat/completions HTTP/1.1" 200 OK
+INFO:     127.0.0.1:44794 - "POST /v1/chat/completions HTTP/1.1" 200 OK
+INFO 07-14 11:39:08 metrics.py:345] Avg prompt throughput: 14.9 tokens/s, Avg generation throughput: 5.0 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:39:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+(VllmWorkerProcess pid=10988) INFO 07-14 11:39:12 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=2 steps=64 mode=decode layer.mlp: total=11760.09ms avg=4.594ms n=2560 | moe.routed_total: total=9359.14ms avg=3.656ms n=2560 | moe.routed_prefill_experts: total=7427.27ms avg=10.922ms n=680 | layer.linear_attention: total=7360.67ms avg=3.834ms n=1920 | layer.full_attention: total=1439.20ms avg=2.249ms n=640 | moe.routed_decode_experts: total=1149.53ms avg=0.611ms n=1880 | moe.tp_all_reduce: total=1129.49ms avg=0.441ms n=2560 | moe.shared_expert: total=683.54ms avg=0.267ms n=2560 | layer.input_norm: total=653.91ms avg=0.255ms n=2560 | moe.routing_topk: total=632.62ms avg=0.247ms n=2560 | layer.post_attn_norm: total=630.36ms avg=0.246ms n=2560 | full_attn.paged_attention: total=570.22ms avg=0.891ms n=640 | full_attn.gate_o_proj: total=349.73ms avg=0.546ms n=640 | full_attn.norm_rope: total=288.81ms avg=0.451ms n=640 | moe.gate: total=193.10ms avg=0.075ms n=2560 | full_attn.qkv_proj: total=169.83ms avg=0.265ms n=640 | moe.combine: total=121.20ms avg=0.047ms n=2560
+(VllmWorkerProcess pid=10989) INFO 07-14 11:39:12 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=3 steps=64 mode=decode layer.mlp: total=11752.09ms avg=4.591ms n=2560 | moe.routed_total: total=9479.63ms avg=3.703ms n=2560 | moe.routed_prefill_experts: total=7543.04ms avg=11.093ms n=680 | layer.linear_attention: total=7352.66ms avg=3.830ms n=1920 | layer.full_attention: total=1437.73ms avg=2.246ms n=640 | moe.routed_decode_experts: total=1149.26ms avg=0.611ms n=1880 | moe.tp_all_reduce: total=987.66ms avg=0.386ms n=2560 | moe.shared_expert: total=690.96ms avg=0.270ms n=2560 | layer.input_norm: total=663.22ms avg=0.259ms n=2560 | layer.post_attn_norm: total=638.01ms avg=0.249ms n=2560 | moe.routing_topk: total=636.55ms avg=0.249ms n=2560 | full_attn.paged_attention: total=574.24ms avg=0.897ms n=640 | full_attn.gate_o_proj: total=337.69ms avg=0.528ms n=640 | full_attn.norm_rope: total=293.83ms avg=0.459ms n=640 | moe.gate: total=201.22ms avg=0.079ms n=2560 | full_attn.qkv_proj: total=171.31ms avg=0.268ms n=640 | moe.combine: total=120.35ms avg=0.047ms n=2560
+INFO 07-14 11:39:12 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=0 steps=64 mode=decode layer.mlp: total=11758.85ms avg=4.593ms n=2560 | moe.routed_total: total=9348.77ms avg=3.652ms n=2560 | moe.routed_prefill_experts: total=7406.06ms avg=10.891ms n=680 | layer.linear_attention: total=7349.52ms avg=3.828ms n=1920 | layer.full_attention: total=1438.51ms avg=2.248ms n=640 | moe.tp_all_reduce: total=1146.09ms avg=0.448ms n=2560 | moe.routed_decode_experts: total=1145.85ms avg=0.609ms n=1880 | moe.shared_expert: total=685.01ms avg=0.268ms n=2560 | layer.input_norm: total=662.05ms avg=0.259ms n=2560 | moe.routing_topk: total=643.44ms avg=0.251ms n=2560 | layer.post_attn_norm: total=628.23ms avg=0.245ms n=2560 | full_attn.paged_attention: total=578.66ms avg=0.904ms n=640 | full_attn.gate_o_proj: total=334.92ms avg=0.523ms n=640 | full_attn.norm_rope: total=291.31ms avg=0.455ms n=640 | moe.gate: total=191.05ms avg=0.075ms n=2560 | full_attn.qkv_proj: total=171.27ms avg=0.268ms n=640 | moe.combine: total=108.34ms avg=0.042ms n=2560
+(VllmWorkerProcess pid=10987) INFO 07-14 11:39:12 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=1 steps=64 mode=decode layer.mlp: total=11758.80ms avg=4.593ms n=2560 | moe.routed_total: total=9366.70ms avg=3.659ms n=2560 | moe.routed_prefill_experts: total=7438.39ms avg=10.939ms n=680 | layer.linear_attention: total=7358.41ms avg=3.833ms n=1920 | layer.full_attention: total=1440.15ms avg=2.250ms n=640 | moe.routed_decode_experts: total=1148.88ms avg=0.611ms n=1880 | moe.tp_all_reduce: total=1118.88ms avg=0.437ms n=2560 | moe.shared_expert: total=690.07ms avg=0.270ms n=2560 | layer.input_norm: total=656.06ms avg=0.256ms n=2560 | layer.post_attn_norm: total=629.74ms avg=0.246ms n=2560 | moe.routing_topk: total=626.92ms avg=0.245ms n=2560 | full_attn.paged_attention: total=576.96ms avg=0.901ms n=640 | full_attn.gate_o_proj: total=338.44ms avg=0.529ms n=640 | full_attn.norm_rope: total=291.45ms avg=0.455ms n=640 | moe.gate: total=193.07ms avg=0.075ms n=2560 | full_attn.qkv_proj: total=171.28ms avg=0.268ms n=640 | moe.combine: total=113.70ms avg=0.044ms n=2560
+INFO 07-14 11:39:12 model_runner.py:114] [ENGINEX_PROFILE_MODEL_RUNNER] steps=64 mode=decode prompt.model_forward: total=11655.73ms avg=3885.243ms n=3 | decode.model_forward: total=10665.29ms avg=174.841ms n=61 | prompt.compute_logits: total=204.78ms avg=68.261ms n=3 | decode.compute_logits: total=74.24ms avg=1.217ms n=61 | decode.sample: total=63.94ms avg=1.048ms n=61 | prompt.sample: total=42.29ms avg=14.097ms n=3 | decode.attn_begin_forward: total=1.00ms avg=0.016ms n=61 | prompt.attn_begin_forward: total=0.07ms avg=0.023ms n=3
+INFO 07-14 11:39:13 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 7.1 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:39:13 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+(VllmWorkerProcess pid=10988) INFO 07-14 11:39:16 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=2 steps=80 mode=decode layer.mlp: total=14470.51ms avg=4.522ms n=3200 | moe.routed_total: total=11510.65ms avg=3.597ms n=3200 | moe.routed_prefill_experts: total=9399.98ms avg=7.121ms n=1320 | layer.linear_attention: total=8056.26ms avg=3.357ms n=2400 | layer.full_attention: total=1673.93ms avg=2.092ms n=800 | moe.tp_all_reduce: total=1391.61ms avg=0.435ms n=3200 | moe.routed_decode_experts: total=1149.53ms avg=0.611ms n=1880 | moe.shared_expert: total=842.90ms avg=0.263ms n=3200 | layer.input_norm: total=807.29ms avg=0.252ms n=3200 | moe.routing_topk: total=773.90ms avg=0.242ms n=3200 | layer.post_attn_norm: total=772.95ms avg=0.242ms n=3200 | full_attn.paged_attention: total=614.17ms avg=0.768ms n=800 | full_attn.gate_o_proj: total=418.93ms avg=0.524ms n=800 | full_attn.norm_rope: total=359.94ms avg=0.450ms n=800 | moe.gate: total=237.22ms avg=0.074ms n=3200 | full_attn.qkv_proj: total=205.89ms avg=0.257ms n=800 | moe.combine: total=148.40ms avg=0.046ms n=3200
+(VllmWorkerProcess pid=10989) INFO 07-14 11:39:16 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=3 steps=80 mode=decode layer.mlp: total=14463.88ms avg=4.520ms n=3200 | moe.routed_total: total=11683.10ms avg=3.651ms n=3200 | moe.routed_prefill_experts: total=9566.20ms avg=7.247ms n=1320 | layer.linear_attention: total=8045.62ms avg=3.352ms n=2400 | layer.full_attention: total=1671.73ms avg=2.090ms n=800 | moe.tp_all_reduce: total=1195.25ms avg=0.374ms n=3200 | moe.routed_decode_experts: total=1149.26ms avg=0.611ms n=1880 | moe.shared_expert: total=852.38ms avg=0.266ms n=3200 | layer.input_norm: total=817.45ms avg=0.255ms n=3200 | layer.post_attn_norm: total=781.93ms avg=0.244ms n=3200 | moe.routing_topk: total=779.28ms avg=0.244ms n=3200 | full_attn.paged_attention: total=618.81ms avg=0.774ms n=800 | full_attn.gate_o_proj: total=406.43ms avg=0.508ms n=800 | full_attn.norm_rope: total=365.17ms avg=0.456ms n=800 | moe.gate: total=246.83ms avg=0.077ms n=3200 | full_attn.qkv_proj: total=206.17ms avg=0.258ms n=800 | moe.combine: total=148.03ms avg=0.046ms n=3200
+INFO 07-14 11:39:16 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=0 steps=80 mode=decode layer.mlp: total=14467.70ms avg=4.521ms n=3200 | moe.routed_total: total=11514.73ms avg=3.598ms n=3200 | moe.routed_prefill_experts: total=9391.98ms avg=7.115ms n=1320 | layer.linear_attention: total=8045.36ms avg=3.352ms n=2400 | layer.full_attention: total=1672.70ms avg=2.091ms n=800 | moe.tp_all_reduce: total=1390.05ms avg=0.434ms n=3200 | moe.routed_decode_experts: total=1145.85ms avg=0.609ms n=1880 | moe.shared_expert: total=845.93ms avg=0.264ms n=3200 | layer.input_norm: total=815.85ms avg=0.255ms n=3200 | moe.routing_topk: total=785.51ms avg=0.245ms n=3200 | layer.post_attn_norm: total=771.29ms avg=0.241ms n=3200 | full_attn.paged_attention: total=622.70ms avg=0.778ms n=800 | full_attn.gate_o_proj: total=403.63ms avg=0.505ms n=800 | full_attn.norm_rope: total=362.91ms avg=0.454ms n=800 | moe.gate: total=235.10ms avg=0.073ms n=3200 | full_attn.qkv_proj: total=206.57ms avg=0.258ms n=800 | moe.combine: total=134.88ms avg=0.042ms n=3200
+(VllmWorkerProcess pid=10987) INFO 07-14 11:39:16 qwen3_5.py:95] [ENGINEX_PROFILE_QWEN] rank=1 steps=80 mode=decode layer.mlp: total=14469.28ms avg=4.522ms n=3200 | moe.routed_total: total=11523.73ms avg=3.601ms n=3200 | moe.routed_prefill_experts: total=9417.05ms avg=7.134ms n=1320 | layer.linear_attention: total=8054.17ms avg=3.356ms n=2400 | layer.full_attention: total=1674.95ms avg=2.094ms n=800 | moe.tp_all_reduce: total=1373.87ms avg=0.429ms n=3200 | moe.routed_decode_experts: total=1148.88ms avg=0.611ms n=1880 | moe.shared_expert: total=850.87ms avg=0.266ms n=3200 | layer.input_norm: total=809.03ms avg=0.253ms n=3200 | layer.post_attn_norm: total=772.33ms avg=0.241ms n=3200 | moe.routing_topk: total=767.56ms avg=0.240ms n=3200 | full_attn.paged_attention: total=620.61ms avg=0.776ms n=800 | full_attn.gate_o_proj: total=409.41ms avg=0.512ms n=800 | full_attn.norm_rope: total=362.21ms avg=0.453ms n=800 | moe.gate: total=237.50ms avg=0.074ms n=3200 | full_attn.qkv_proj: total=206.08ms avg=0.258ms n=800 | moe.combine: total=140.22ms avg=0.044ms n=3200
+INFO 07-14 11:39:16 model_runner.py:114] [ENGINEX_PROFILE_MODEL_RUNNER] steps=80 mode=decode decode.model_forward: total=14680.40ms avg=190.655ms n=77 | prompt.model_forward: total=11655.73ms avg=3885.243ms n=3 | prompt.compute_logits: total=204.78ms avg=68.261ms n=3 | decode.compute_logits: total=93.92ms avg=1.220ms n=77 | decode.sample: total=81.77ms avg=1.062ms n=77 | prompt.sample: total=42.29ms avg=14.097ms n=3 | decode.attn_begin_forward: total=1.26ms avg=0.016ms n=77 | prompt.attn_begin_forward: total=0.07ms avg=0.023ms n=3
+INFO 07-14 11:39:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 1.8 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:39:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:39:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:39:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:39:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:39:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:39:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:39:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:40:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:40:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:40:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:40:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:40:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:40:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:40:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:40:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:40:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:40:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:40:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:40:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:41:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:41:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:41:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:41:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:41:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:41:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:41:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:41:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:41:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:41:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:41:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:41:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:42:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:42:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:42:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:42:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:42:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:42:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:42:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:42:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:42:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:42:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:42:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:42:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:43:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:43:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:43:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:43:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:43:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:43:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:43:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:43:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:43:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:43:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:43:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:43:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:44:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:44:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:44:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:44:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:44:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:44:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:44:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:44:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:44:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:44:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:44:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:44:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:45:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:45:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:45:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:45:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:45:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:45:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:45:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:45:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:45:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:45:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:45:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:45:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:46:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:46:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:46:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:46:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:46:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:46:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:46:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:46:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:46:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:46:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:46:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:46:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:47:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:47:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:47:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:47:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:47:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:47:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:47:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:47:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:47:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:47:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:47:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:47:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:48:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:48:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:48:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:48:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:48:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:48:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:48:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:48:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:48:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:48:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:48:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:48:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:49:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:49:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:49:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:49:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:49:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:49:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:49:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:49:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:49:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:49:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:49:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:49:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:50:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:50:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:50:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:50:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:50:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:50:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:50:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:50:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:50:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:50:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:50:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:50:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:51:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:51:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:51:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:51:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:51:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:51:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:51:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:51:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:51:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:51:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:51:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:51:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:52:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:52:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:52:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:52:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:52:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:52:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:52:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:52:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:52:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:52:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:52:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:52:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:53:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:53:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:53:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:53:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:53:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:53:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:53:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:53:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:53:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:53:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:53:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:53:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:54:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:54:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:54:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:54:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:54:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:54:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:54:38 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:54:38 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:54:48 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:54:48 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:54:58 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:54:58 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:55:08 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:55:08 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:55:18 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:55:18 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%
+INFO 07-14 11:55:28 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:55:28 metrics.py:361] Prefix cache hit rate: GPU: 66.67%, CPU: 0.00%

worklogs/remote_results/2026-07-14-code-profile/server_profile_mode_eager_custom_ar_seq2_b8192.log

@@ -0,0 +1,325 @@
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+INFO 07-14 11:57:38 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+2026-07-14 11:57:40.260421: I tensorflow/core/util/port.cc:110] oneDNN custom operations are on. You may see slightly different numerical results due to floating-point round-off errors from different computation orders. To turn them off, set the environment variable `TF_ENABLE_ONEDNN_OPTS=0`.
+2026-07-14 11:57:40.312205: I tensorflow/core/platform/cpu_feature_guard.cc:182] This TensorFlow binary is optimized to use available CPU instructions in performance-critical operations.
+To enable the following instructions: SSE3 SSE4.1 SSE4.2 AVX AVX2 AVX512F AVX512_VNNI AVX512_BF16 AVX_VNNI AMX_TILE AMX_INT8 AMX_BF16 FMA, in other operations, rebuild TensorFlow with the appropriate compiler flags.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+INFO 07-14 11:57:45 api_server.py:530] vLLM API server version 0.6.3
+INFO 07-14 11:57:45 api_server.py:531] args: Namespace(host='0.0.0.0', port=1111, uvicorn_log_level='info', allow_credentials=False, allowed_origins=['*'], allowed_methods=['*'], allowed_headers=['*'], api_key=None, lora_modules=None, prompt_adapters=None, chat_template=None, response_role='assistant', ssl_keyfile=None, ssl_certfile=None, ssl_ca_certs=None, ssl_cert_reqs=0, root_path=None, middleware=[], return_tokens_as_token_ids=False, disable_frontend_multiprocessing=True, enable_auto_tool_choice=True, tool_call_parser='qwen3_coder', tool_parser_plugin='', reasoning_parser='qwen3', model='/root/public-storage/models/Qwen/Qwen3.6-35B-A3B', tokenizer=None, skip_tokenizer_init=False, revision=None, code_revision=None, tokenizer_revision=None, tokenizer_mode='auto', trust_remote_code=True, download_dir=None, load_format='auto', config_format='auto', dtype='auto', kv_cache_dtype='auto', quantization_param_path=None, max_model_len=100000, guided_decoding_backend='outlines', distributed_executor_backend=None, worker_use_ray=False, pipeline_parallel_size=1, tensor_parallel_size=4, max_parallel_loading_workers=None, ray_workers_use_nsight=False, block_size=16, enable_prefix_caching=True, disable_sliding_window=False, use_v2_block_manager=True, num_lookahead_slots=0, seed=0, swap_space=4, cpu_offload_gb=0, gpu_memory_utilization=0.95, num_gpu_blocks_override=None, max_num_batched_tokens=8192, max_num_seqs=2, max_logprobs=20, disable_log_stats=False, quantization=None, rope_scaling=None, rope_theta=None, enforce_eager=True, max_context_len_to_capture=None, max_seq_len_to_capture=32768, disable_custom_all_reduce=False, tokenizer_pool_size=0, tokenizer_pool_type='ray', tokenizer_pool_extra_config=None, limit_mm_per_prompt=None, mm_processor_kwargs=None, enable_lora=False, max_loras=1, max_lora_rank=16, lora_extra_vocab_size=256, lora_dtype='auto', long_lora_scaling_factors=None, max_cpu_loras=None, fully_sharded_loras=False, enable_prompt_adapter=False, max_prompt_adapters=1, max_prompt_adapter_token=0, device='auto', num_scheduler_steps=1, multi_step_stream_outputs=True, scheduler_delay_factor=0.0, enable_chunked_prefill=True, speculative_model=None, speculative_model_quantization=None, num_speculative_tokens=None, speculative_disable_mqa_scorer=False, speculative_draft_tensor_parallel_size=None, speculative_max_model_len=None, speculative_disable_by_batch_size=None, ngram_prompt_lookup_max=None, ngram_prompt_lookup_min=None, spec_decoding_acceptance_method='rejection_sampler', typical_acceptance_sampler_posterior_threshold=None, typical_acceptance_sampler_posterior_alpha=None, disable_logprobs_during_spec_decoding=None, model_loader_extra_config=None, ignore_patterns=[], preemption_mode=None, served_model_name=['llm'], qlora_adapter_name_or_path=None, otlp_traces_endpoint=None, collect_detailed_traces=None, disable_async_output_proc=False, override_neuron_config=None, scheduling_policy='fcfs', disable_log_requests=True, max_log_len=None, disable_fastapi_docs=False)
+INFO 07-14 11:57:45 config.py:1670] Downcasting torch.float32 to torch.float16.
+INFO 07-14 11:57:56 config.py:887] Defaulting to use mp for distributed inference
+INFO 07-14 11:57:56 config.py:1005] Chunked prefill is enabled with max_num_batched_tokens=8192.
+WARNING 07-14 11:57:56 config.py:380] To see benefits of async output processing, enable CUDA graph. Since, enforce-eager is enabled, async output processor cannot be used
+INFO 07-14 11:57:56 llm_engine.py:237] Initializing an LLM engine (v0.6.3) with config: model='/root/public-storage/models/Qwen/Qwen3.6-35B-A3B', speculative_config=None, tokenizer='/root/public-storage/models/Qwen/Qwen3.6-35B-A3B', skip_tokenizer_init=False, tokenizer_mode=auto, revision=None, override_neuron_config=None, rope_scaling=None, rope_theta=None, tokenizer_revision=None, trust_remote_code=True, dtype=torch.float16, max_seq_len=100000, download_dir=None, load_format=LoadFormat.AUTO, tensor_parallel_size=4, pipeline_parallel_size=1, disable_custom_all_reduce=False, quantization=None, enforce_eager=True, kv_cache_dtype=auto, quantization_param_path=None, device_config=cuda, decoding_config=DecodingConfig(guided_decoding_backend='outlines'), observability_config=ObservabilityConfig(otlp_traces_endpoint=None, collect_model_forward_time=False, collect_model_execute_time=False), seed=0, served_model_name=llm, use_v2_block_manager=True, num_scheduler_steps=1, chunked_prefill_enabled=True multi_step_stream_outputs=True, enable_prefix_caching=True, use_async_output_proc=False, use_cached_outputs=False, mm_processor_kwargs=None)
+WARNING 07-14 11:57:57 multiproc_gpu_executor.py:53] Reducing Torch parallelism from 64 threads to 1 to avoid unnecessary CPU contention. Set OMP_NUM_THREADS in the external environment to tune this value as needed.
+INFO 07-14 11:57:57 custom_cache_manager.py:17] Setting Triton cache manager to: vllm.triton_utils.custom_cache_manager:CustomCacheManager
+INFO 07-14 11:57:57 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+INFO 07-14 11:57:57 selector.py:115] Using XFormers backend.
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+INFO 07-14 11:57:59 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+INFO 07-14 11:57:59 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+INFO 07-14 11:57:59 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+(VllmWorkerProcess pid=12142) INFO 07-14 11:58:06 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=12142) INFO 07-14 11:58:06 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=12142) INFO 07-14 11:58:06 multiproc_worker_utils.py:216] Worker ready; awaiting tasks
+(VllmWorkerProcess pid=12140) INFO 07-14 11:58:06 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=12140) INFO 07-14 11:58:06 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=12140) INFO 07-14 11:58:06 multiproc_worker_utils.py:216] Worker ready; awaiting tasks
+(VllmWorkerProcess pid=12141) INFO 07-14 11:58:06 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=12141) INFO 07-14 11:58:06 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=12141) INFO 07-14 11:58:06 multiproc_worker_utils.py:216] Worker ready; awaiting tasks
+INFO 07-14 11:58:07 shm_broadcast.py:242] vLLM message queue communication handle: Handle(connect_ip='127.0.0.1', local_reader_ranks=[1, 2, 3], buffer=<vllm.distributed.device_communicators.shm_broadcast.ShmRingBuffer object at 0x7f815230ec50>, local_subscribe_port=60007, remote_subscribe_port=None)
+INFO 07-14 11:58:07 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+(VllmWorkerProcess pid=12140) INFO 07-14 11:58:07 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+(VllmWorkerProcess pid=12141) INFO 07-14 11:58:07 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+(VllmWorkerProcess pid=12142) INFO 07-14 11:58:07 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+INFO 07-14 11:58:07 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+INFO 07-14 11:58:07 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=12142) INFO 07-14 11:58:07 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=12140) INFO 07-14 11:58:07 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=12141) INFO 07-14 11:58:07 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=12142) INFO 07-14 11:58:07 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=12140) INFO 07-14 11:58:07 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=12141) INFO 07-14 11:58:07 selector.py:115] Using XFormers backend.
+
+Loading safetensors checkpoint shards:   0% Completed | 0/26 [00:00<?, ?it/s]
+
+Loading safetensors checkpoint shards:   4% Completed | 1/26 [00:01<00:45,  1.84s/it]
+
+Loading safetensors checkpoint shards:   8% Completed | 2/26 [00:02<00:25,  1.06s/it]
+
+Loading safetensors checkpoint shards:  12% Completed | 3/26 [00:04<00:32,  1.40s/it]
+
+Loading safetensors checkpoint shards:  15% Completed | 4/26 [00:06<00:35,  1.62s/it]
+
+Loading safetensors checkpoint shards:  19% Completed | 5/26 [00:07<00:29,  1.39s/it]
+
+Loading safetensors checkpoint shards:  23% Completed | 6/26 [00:09<00:31,  1.60s/it]
+
+Loading safetensors checkpoint shards:  27% Completed | 7/26 [00:09<00:23,  1.22s/it]
+
+Loading safetensors checkpoint shards:  31% Completed | 8/26 [00:11<00:24,  1.39s/it]
+
+Loading safetensors checkpoint shards:  35% Completed | 9/26 [00:12<00:21,  1.26s/it]
+
+Loading safetensors checkpoint shards:  38% Completed | 10/26 [00:14<00:23,  1.48s/it]
+
+Loading safetensors checkpoint shards:  42% Completed | 11/26 [00:14<00:16,  1.12s/it]
+
+Loading safetensors checkpoint shards:  46% Completed | 12/26 [00:16<00:18,  1.35s/it]
+
+Loading safetensors checkpoint shards:  50% Completed | 13/26 [00:18<00:19,  1.53s/it]
+
+Loading safetensors checkpoint shards:  54% Completed | 14/26 [00:20<00:20,  1.72s/it]
+
+Loading safetensors checkpoint shards:  58% Completed | 15/26 [00:21<00:15,  1.44s/it]
+
+Loading safetensors checkpoint shards:  62% Completed | 16/26 [00:23<00:17,  1.72s/it]
+
+Loading safetensors checkpoint shards:  65% Completed | 17/26 [00:24<00:12,  1.34s/it]
+
+Loading safetensors checkpoint shards:  69% Completed | 18/26 [00:25<00:11,  1.48s/it]
+
+Loading safetensors checkpoint shards:  73% Completed | 19/26 [00:27<00:10,  1.54s/it]
+
+Loading safetensors checkpoint shards:  77% Completed | 20/26 [00:30<00:10,  1.81s/it]
+
+Loading safetensors checkpoint shards:  81% Completed | 21/26 [00:31<00:07,  1.58s/it]
+
+Loading safetensors checkpoint shards:  85% Completed | 22/26 [00:31<00:05,  1.34s/it]
+
+Loading safetensors checkpoint shards:  88% Completed | 23/26 [00:34<00:04,  1.66s/it]
+
+Loading safetensors checkpoint shards:  92% Completed | 24/26 [00:36<00:03,  1.75s/it]
+
+Loading safetensors checkpoint shards:  96% Completed | 25/26 [00:38<00:01,  1.81s/it]
+
+Loading safetensors checkpoint shards: 100% Completed | 26/26 [00:38<00:00,  1.42s/it]
+
+Loading safetensors checkpoint shards: 100% Completed | 26/26 [00:38<00:00,  1.49s/it]
+
+(VllmWorkerProcess pid=12140) INFO 07-14 11:58:46 model_runner.py:1123] Loading model weights took 16.2303 GB
+(VllmWorkerProcess pid=12141) INFO 07-14 11:58:46 model_runner.py:1123] Loading model weights took 16.2303 GB
+(VllmWorkerProcess pid=12142) INFO 07-14 11:58:46 model_runner.py:1123] Loading model weights took 16.2303 GB
+INFO 07-14 11:58:46 model_runner.py:1123] Loading model weights took 16.2303 GB
+INFO 07-14 11:58:54 distributed_gpu_executor.py:57] # GPU blocks: 21100, # CPU blocks: 6553
+INFO 07-14 11:58:54 distributed_gpu_executor.py:61] Maximum concurrency for 100000 tokens per request: 3.38x
+INFO 07-14 11:58:59 serving_chat.py:79] "auto" tool choice has been enabled please note that while the parallel_tool_calls client option is preset for compatibility reasons, it will be ignored.
+INFO 07-14 11:58:59 serving_chat.py:101] Reasoning parser 'qwen3' enabled.
+WARNING 07-14 11:58:59 serving_embedding.py:199] embedding_mode is False. Embedding API will not work.
+INFO 07-14 11:58:59 launcher.py:19] Available routes are:
+INFO 07-14 11:58:59 launcher.py:27] Route: /openapi.json, Methods: HEAD, GET
+INFO 07-14 11:58:59 launcher.py:27] Route: /docs, Methods: HEAD, GET
+INFO 07-14 11:58:59 launcher.py:27] Route: /docs/oauth2-redirect, Methods: HEAD, GET
+INFO 07-14 11:58:59 launcher.py:27] Route: /redoc, Methods: HEAD, GET
+INFO 07-14 11:58:59 launcher.py:27] Route: /health, Methods: GET
+INFO 07-14 11:58:59 launcher.py:27] Route: /tokenize, Methods: POST
+INFO 07-14 11:58:59 launcher.py:27] Route: /detokenize, Methods: POST
+INFO 07-14 11:58:59 launcher.py:27] Route: /v1/models, Methods: GET
+INFO 07-14 11:58:59 launcher.py:27] Route: /version, Methods: GET
+INFO 07-14 11:58:59 launcher.py:27] Route: /v1/chat/completions, Methods: POST
+INFO 07-14 11:58:59 launcher.py:27] Route: /v1/completions, Methods: POST
+INFO 07-14 11:58:59 launcher.py:27] Route: /v1/embeddings, Methods: POST
+INFO:     Started server process [11801]
+INFO:     Waiting for application startup.
+INFO:     Application startup complete.
+INFO:     Uvicorn running on socket ('0.0.0.0', 1111) (Press CTRL+C to quit)
+INFO 07-14 11:59:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:59:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:59:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:59:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:59:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:59:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:59:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:59:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:59:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:59:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 11:59:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 11:59:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:00:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:00:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:00:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:00:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO:     127.0.0.1:37318 - "GET /health HTTP/1.1" 200 OK
+INFO 07-14 12:00:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:00:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:00:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:00:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:00:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:00:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:00:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:00:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:01:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:01:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:01:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:01:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:01:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:01:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:01:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:01:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO:     127.0.0.1:40612 - "GET /health HTTP/1.1" 200 OK
+INFO 07-14 12:01:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:01:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:01:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:01:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:02:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:02:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:02:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:02:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO:     127.0.0.1:49042 - "POST /v1/chat/completions HTTP/1.1" 200 OK
+/usr/local/lib/python3.10/site-packages/pyairports/airports.py:1: UserWarning: pkg_resources is deprecated as an API. See https://setuptools.pypa.io/en/latest/pkg_resources.html. The pkg_resources package is slated for removal as early as 2025-11-30. Refrain from using this package or pin to Setuptools<81.
+  from pkg_resources import resource_string
+INFO 07-14 12:02:27 metrics.py:345] Avg prompt throughput: 4.6 tokens/s, Avg generation throughput: 0.1 tokens/s, Running: 1 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:02:27 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:02:28 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=0 steps=8 mode=decode prefill.layer.mlp: total=5627.88ms avg=70.348ms n=80 | prefill.moe.routed_total: total=5336.07ms avg=66.701ms n=80 | prefill.moe.routed_prefill_experts: total=5239.90ms avg=65.499ms n=80 | prefill.layer.linear_attention: total=2944.76ms avg=49.079ms n=60 | prefill.layer.full_attention: total=481.27ms avg=24.063ms n=20 | decode.layer.mlp: total=396.37ms avg=1.652ms n=240 | prefill.full_attn.paged_attention: total=371.38ms avg=18.569ms n=20 | decode.layer.linear_attention: total=253.48ms avg=1.408ms n=180 | decode.moe.routed_total: total=213.18ms avg=0.888ms n=240 | prefill.moe.tp_all_reduce: total=177.55ms avg=2.219ms n=80 | decode.moe.routed_decode_experts: total=146.93ms avg=0.612ms n=240 | prefill.layer.input_norm: total=108.49ms avg=1.356ms n=80 | prefill.layer.post_attn_norm: total=101.60ms avg=1.270ms n=80 | decode.layer.full_attention: total=95.56ms avg=1.593ms n=60 | prefill.moe.routing_topk: total=91.04ms avg=1.138ms n=80 | prefill.moe.shared_expert: total=74.97ms avg=0.937ms n=80 | decode.moe.tp_all_reduce: total=73.79ms avg=0.307ms n=240 | decode.moe.shared_expert: total=57.71ms avg=0.240ms n=240 | decode.moe.routing_topk: total=52.85ms avg=0.220ms n=240 | decode.layer.input_norm: total=50.83ms avg=0.212ms n=240 | decode.layer.post_attn_norm: total=50.66ms avg=0.211ms n=240 | prefill.full_attn.gate_o_proj: total=47.06ms avg=2.353ms n=20 | prefill.full_attn.qkv_proj: total=33.28ms avg=1.664ms n=20 | decode.full_attn.paged_attention: total=27.86ms avg=0.464ms n=60 | prefill.full_attn.norm_rope: total=27.44ms avg=1.372ms n=20 | decode.full_attn.gate_o_proj: total=25.08ms avg=0.418ms n=60 | decode.full_attn.norm_rope: total=24.31ms avg=0.405ms n=60 | prefill.moe.gate: total=19.43ms avg=0.243ms n=80 | decode.moe.gate: total=16.86ms avg=0.070ms n=240 | decode.full_attn.qkv_proj: total=12.79ms avg=0.213ms n=60 | prefill.moe.combine: total=11.04ms avg=0.138ms n=80 | decode.moe.combine: total=10.02ms avg=0.042ms n=240
+(VllmWorkerProcess pid=12141) INFO 07-14 12:02:28 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=2 steps=8 mode=decode prefill.layer.mlp: total=5629.85ms avg=70.373ms n=80 | prefill.moe.routed_total: total=5306.20ms avg=66.327ms n=80 | prefill.moe.routed_prefill_experts: total=5215.66ms avg=65.196ms n=80 | prefill.layer.linear_attention: total=2945.59ms avg=49.093ms n=60 | prefill.layer.full_attention: total=481.58ms avg=24.079ms n=20 | decode.layer.mlp: total=397.69ms avg=1.657ms n=240 | prefill.full_attn.paged_attention: total=370.72ms avg=18.536ms n=20 | decode.layer.linear_attention: total=253.55ms avg=1.409ms n=180 | decode.moe.routed_total: total=212.43ms avg=0.885ms n=240 | prefill.moe.tp_all_reduce: total=209.76ms avg=2.622ms n=80 | decode.moe.routed_decode_experts: total=146.82ms avg=0.612ms n=240 | prefill.layer.input_norm: total=106.27ms avg=1.328ms n=80 | prefill.layer.post_attn_norm: total=100.86ms avg=1.261ms n=80 | decode.layer.full_attention: total=95.54ms avg=1.592ms n=60 | prefill.moe.routing_topk: total=85.44ms avg=1.068ms n=80 | decode.moe.tp_all_reduce: total=76.40ms avg=0.318ms n=240 | prefill.moe.shared_expert: total=74.77ms avg=0.935ms n=80 | decode.moe.shared_expert: total=57.43ms avg=0.239ms n=240 | decode.moe.routing_topk: total=52.43ms avg=0.218ms n=240 | decode.layer.post_attn_norm: total=50.27ms avg=0.209ms n=240 | decode.layer.input_norm: total=49.99ms avg=0.208ms n=240 | prefill.full_attn.gate_o_proj: total=48.41ms avg=2.420ms n=20 | prefill.full_attn.qkv_proj: total=33.20ms avg=1.660ms n=20 | decode.full_attn.paged_attention: total=27.29ms avg=0.455ms n=60 | prefill.full_attn.norm_rope: total=27.29ms avg=1.364ms n=20 | decode.full_attn.gate_o_proj: total=25.68ms avg=0.428ms n=60 | decode.full_attn.norm_rope: total=24.27ms avg=0.404ms n=60 | prefill.moe.gate: total=19.33ms avg=0.242ms n=80 | decode.moe.gate: total=16.68ms avg=0.069ms n=240 | decode.full_attn.qkv_proj: total=12.81ms avg=0.214ms n=60 | prefill.moe.combine: total=10.99ms avg=0.137ms n=80 | decode.moe.combine: total=10.03ms avg=0.042ms n=240
+(VllmWorkerProcess pid=12142) INFO 07-14 12:02:28 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=3 steps=8 mode=decode prefill.layer.mlp: total=5628.82ms avg=70.360ms n=80 | prefill.moe.routed_total: total=5306.10ms avg=66.326ms n=80 | prefill.moe.routed_prefill_experts: total=5214.38ms avg=65.180ms n=80 | prefill.layer.linear_attention: total=2944.17ms avg=49.070ms n=60 | prefill.layer.full_attention: total=481.30ms avg=24.065ms n=20 | decode.layer.mlp: total=398.03ms avg=1.658ms n=240 | prefill.full_attn.paged_attention: total=370.76ms avg=18.538ms n=20 | decode.layer.linear_attention: total=254.00ms avg=1.411ms n=180 | decode.moe.routed_total: total=211.60ms avg=0.882ms n=240 | prefill.moe.tp_all_reduce: total=209.17ms avg=2.615ms n=80 | decode.moe.routed_decode_experts: total=146.21ms avg=0.609ms n=240 | prefill.layer.input_norm: total=108.67ms avg=1.358ms n=80 | prefill.layer.post_attn_norm: total=101.07ms avg=1.263ms n=80 | decode.layer.full_attention: total=95.75ms avg=1.596ms n=60 | prefill.moe.routing_topk: total=86.53ms avg=1.082ms n=80 | decode.moe.tp_all_reduce: total=78.58ms avg=0.327ms n=240 | prefill.moe.shared_expert: total=74.52ms avg=0.931ms n=80 | decode.moe.shared_expert: total=56.73ms avg=0.236ms n=240 | decode.moe.routing_topk: total=52.04ms avg=0.217ms n=240 | decode.layer.post_attn_norm: total=49.95ms avg=0.208ms n=240 | decode.layer.input_norm: total=49.23ms avg=0.205ms n=240 | prefill.full_attn.gate_o_proj: total=48.03ms avg=2.402ms n=20 | prefill.full_attn.qkv_proj: total=33.18ms avg=1.659ms n=20 | decode.full_attn.paged_attention: total=27.44ms avg=0.457ms n=60 | prefill.full_attn.norm_rope: total=27.33ms avg=1.366ms n=20 | decode.full_attn.gate_o_proj: total=26.08ms avg=0.435ms n=60 | decode.full_attn.norm_rope: total=24.07ms avg=0.401ms n=60 | prefill.moe.gate: total=19.19ms avg=0.240ms n=80 | decode.moe.gate: total=16.60ms avg=0.069ms n=240 | decode.full_attn.qkv_proj: total=12.70ms avg=0.212ms n=60 | prefill.moe.combine: total=10.96ms avg=0.137ms n=80 | decode.moe.combine: total=9.96ms avg=0.042ms n=240
+(VllmWorkerProcess pid=12140) INFO 07-14 12:02:28 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=1 steps=8 mode=decode prefill.layer.mlp: total=5629.78ms avg=70.372ms n=80 | prefill.moe.routed_total: total=5372.03ms avg=67.150ms n=80 | prefill.moe.routed_prefill_experts: total=5280.95ms avg=66.012ms n=80 | prefill.layer.linear_attention: total=2944.91ms avg=49.082ms n=60 | prefill.layer.full_attention: total=481.27ms avg=24.064ms n=20 | decode.layer.mlp: total=395.86ms avg=1.649ms n=240 | prefill.full_attn.paged_attention: total=371.47ms avg=18.574ms n=20 | decode.layer.linear_attention: total=253.23ms avg=1.407ms n=180 | decode.moe.routed_total: total=213.96ms avg=0.892ms n=240 | decode.moe.routed_decode_experts: total=147.30ms avg=0.614ms n=240 | prefill.moe.tp_all_reduce: total=143.85ms avg=1.798ms n=80 | prefill.layer.input_norm: total=107.20ms avg=1.340ms n=80 | prefill.layer.post_attn_norm: total=101.07ms avg=1.263ms n=80 | decode.layer.full_attention: total=95.48ms avg=1.591ms n=60 | prefill.moe.routing_topk: total=86.03ms avg=1.075ms n=80 | prefill.moe.shared_expert: total=74.58ms avg=0.932ms n=80 | decode.moe.tp_all_reduce: total=70.90ms avg=0.295ms n=240 | decode.moe.shared_expert: total=58.24ms avg=0.243ms n=240 | decode.moe.routing_topk: total=53.61ms avg=0.223ms n=240 | decode.layer.input_norm: total=51.24ms avg=0.214ms n=240 | decode.layer.post_attn_norm: total=51.23ms avg=0.213ms n=240 | prefill.full_attn.gate_o_proj: total=47.30ms avg=2.365ms n=20 | prefill.full_attn.qkv_proj: total=33.16ms avg=1.658ms n=20 | decode.full_attn.paged_attention: total=27.88ms avg=0.465ms n=60 | prefill.full_attn.norm_rope: total=27.36ms avg=1.368ms n=20 | decode.full_attn.gate_o_proj: total=24.87ms avg=0.414ms n=60 | decode.full_attn.norm_rope: total=24.44ms avg=0.407ms n=60 | prefill.moe.gate: total=19.37ms avg=0.242ms n=80 | decode.moe.gate: total=17.31ms avg=0.072ms n=240 | decode.full_attn.qkv_proj: total=12.87ms avg=0.215ms n=60 | prefill.moe.combine: total=11.14ms avg=0.139ms n=80 | decode.moe.combine: total=10.87ms avg=0.045ms n=240
+INFO 07-14 12:02:28 model_runner.py:114] [ENGINEX_PROFILE_MODEL_RUNNER] steps=8 mode=decode prompt.model_forward: total=9427.11ms avg=4713.555ms n=2 | decode.model_forward: total=876.39ms avg=146.065ms n=6 | prompt.compute_logits: total=204.51ms avg=102.255ms n=2 | prompt.sample: total=34.98ms avg=17.492ms n=2 | decode.compute_logits: total=7.07ms avg=1.178ms n=6 | decode.sample: total=6.06ms avg=1.010ms n=6 | decode.attn_begin_forward: total=0.10ms avg=0.016ms n=6 | prompt.attn_begin_forward: total=0.03ms avg=0.017ms n=2
+(VllmWorkerProcess pid=12141) INFO 07-14 12:02:29 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=2 steps=16 mode=decode prefill.layer.mlp: total=5629.85ms avg=70.373ms n=80 | prefill.moe.routed_total: total=5306.20ms avg=66.327ms n=80 | prefill.moe.routed_prefill_experts: total=5215.66ms avg=65.196ms n=80 | prefill.layer.linear_attention: total=2945.59ms avg=49.093ms n=60 | decode.layer.mlp: total=925.00ms avg=1.652ms n=560 | decode.layer.linear_attention: total=591.69ms avg=1.409ms n=420 | decode.moe.routed_total: total=493.80ms avg=0.882ms n=560 | prefill.layer.full_attention: total=481.58ms avg=24.079ms n=20 | prefill.full_attn.paged_attention: total=370.72ms avg=18.536ms n=20 | decode.moe.routed_decode_experts: total=341.90ms avg=0.611ms n=560 | prefill.moe.tp_all_reduce: total=209.76ms avg=2.622ms n=80 | decode.layer.full_attention: total=207.84ms avg=1.485ms n=140 | decode.moe.tp_all_reduce: total=178.18ms avg=0.318ms n=560 | decode.moe.shared_expert: total=133.05ms avg=0.238ms n=560 | decode.moe.routing_topk: total=121.08ms avg=0.216ms n=560 | decode.layer.input_norm: total=116.38ms avg=0.208ms n=560 | decode.layer.post_attn_norm: total=114.92ms avg=0.205ms n=560 | prefill.layer.input_norm: total=106.27ms avg=1.328ms n=80 | prefill.layer.post_attn_norm: total=100.86ms avg=1.261ms n=80 | prefill.moe.routing_topk: total=85.44ms avg=1.068ms n=80 | prefill.moe.shared_expert: total=74.77ms avg=0.935ms n=80 | decode.full_attn.gate_o_proj: total=60.31ms avg=0.431ms n=140 | decode.full_attn.norm_rope: total=56.45ms avg=0.403ms n=140 | decode.full_attn.paged_attention: total=48.46ms avg=0.346ms n=140 | prefill.full_attn.gate_o_proj: total=48.41ms avg=2.420ms n=20 | decode.moe.gate: total=39.64ms avg=0.071ms n=560 | prefill.full_attn.qkv_proj: total=33.20ms avg=1.660ms n=20 | decode.full_attn.qkv_proj: total=29.77ms avg=0.213ms n=140 | prefill.full_attn.norm_rope: total=27.29ms avg=1.364ms n=20 | decode.moe.combine: total=22.66ms avg=0.040ms n=560 | prefill.moe.gate: total=19.33ms avg=0.242ms n=80 | prefill.moe.combine: total=10.99ms avg=0.137ms n=80
+(VllmWorkerProcess pid=12142) INFO 07-14 12:02:29 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=3 steps=16 mode=decode prefill.layer.mlp: total=5628.82ms avg=70.360ms n=80 | prefill.moe.routed_total: total=5306.10ms avg=66.326ms n=80 | prefill.moe.routed_prefill_experts: total=5214.38ms avg=65.180ms n=80 | prefill.layer.linear_attention: total=2944.17ms avg=49.070ms n=60 | decode.layer.mlp: total=925.51ms avg=1.653ms n=560 | decode.layer.linear_attention: total=592.23ms avg=1.410ms n=420 | decode.moe.routed_total: total=491.76ms avg=0.878ms n=560 | prefill.layer.full_attention: total=481.30ms avg=24.065ms n=20 | prefill.full_attn.paged_attention: total=370.76ms avg=18.538ms n=20 | decode.moe.routed_decode_experts: total=339.95ms avg=0.607ms n=560 | prefill.moe.tp_all_reduce: total=209.17ms avg=2.615ms n=80 | decode.layer.full_attention: total=208.09ms avg=1.486ms n=140 | decode.moe.tp_all_reduce: total=182.78ms avg=0.326ms n=560 | decode.moe.shared_expert: total=131.57ms avg=0.235ms n=560 | decode.moe.routing_topk: total=120.78ms avg=0.216ms n=560 | decode.layer.input_norm: total=114.97ms avg=0.205ms n=560 | decode.layer.post_attn_norm: total=114.38ms avg=0.204ms n=560 | prefill.layer.input_norm: total=108.67ms avg=1.358ms n=80 | prefill.layer.post_attn_norm: total=101.07ms avg=1.263ms n=80 | prefill.moe.routing_topk: total=86.53ms avg=1.082ms n=80 | prefill.moe.shared_expert: total=74.52ms avg=0.931ms n=80 | decode.full_attn.gate_o_proj: total=60.87ms avg=0.435ms n=140 | decode.full_attn.norm_rope: total=56.11ms avg=0.401ms n=140 | decode.full_attn.paged_attention: total=48.71ms avg=0.348ms n=140 | prefill.full_attn.gate_o_proj: total=48.03ms avg=2.402ms n=20 | decode.moe.gate: total=39.45ms avg=0.070ms n=560 | prefill.full_attn.qkv_proj: total=33.18ms avg=1.659ms n=20 | decode.full_attn.qkv_proj: total=29.58ms avg=0.211ms n=140 | prefill.full_attn.norm_rope: total=27.33ms avg=1.366ms n=20 | decode.moe.combine: total=22.44ms avg=0.040ms n=560 | prefill.moe.gate: total=19.19ms avg=0.240ms n=80 | prefill.moe.combine: total=10.96ms avg=0.137ms n=80
+INFO 07-14 12:02:29 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=0 steps=16 mode=decode prefill.layer.mlp: total=5627.88ms avg=70.348ms n=80 | prefill.moe.routed_total: total=5336.07ms avg=66.701ms n=80 | prefill.moe.routed_prefill_experts: total=5239.90ms avg=65.499ms n=80 | prefill.layer.linear_attention: total=2944.76ms avg=49.079ms n=60 | decode.layer.mlp: total=920.78ms avg=1.644ms n=560 | decode.layer.linear_attention: total=591.72ms avg=1.409ms n=420 | decode.moe.routed_total: total=496.91ms avg=0.887ms n=560 | prefill.layer.full_attention: total=481.27ms avg=24.063ms n=20 | prefill.full_attn.paged_attention: total=371.38ms avg=18.569ms n=20 | decode.moe.routed_decode_experts: total=342.49ms avg=0.612ms n=560 | decode.layer.full_attention: total=207.43ms avg=1.482ms n=140 | prefill.moe.tp_all_reduce: total=177.55ms avg=2.219ms n=80 | decode.moe.tp_all_reduce: total=168.09ms avg=0.300ms n=560 | decode.moe.shared_expert: total=134.68ms avg=0.241ms n=560 | decode.moe.routing_topk: total=122.92ms avg=0.219ms n=560 | decode.layer.input_norm: total=118.83ms avg=0.212ms n=560 | decode.layer.post_attn_norm: total=116.47ms avg=0.208ms n=560 | prefill.layer.input_norm: total=108.49ms avg=1.356ms n=80 | prefill.layer.post_attn_norm: total=101.60ms avg=1.270ms n=80 | prefill.moe.routing_topk: total=91.04ms avg=1.138ms n=80 | prefill.moe.shared_expert: total=74.97ms avg=0.937ms n=80 | decode.full_attn.gate_o_proj: total=58.00ms avg=0.414ms n=140 | decode.full_attn.norm_rope: total=56.74ms avg=0.405ms n=140 | decode.full_attn.paged_attention: total=49.77ms avg=0.355ms n=140 | prefill.full_attn.gate_o_proj: total=47.06ms avg=2.353ms n=20 | decode.moe.gate: total=40.44ms avg=0.072ms n=560 | prefill.full_attn.qkv_proj: total=33.28ms avg=1.664ms n=20 | decode.full_attn.qkv_proj: total=30.03ms avg=0.214ms n=140 | prefill.full_attn.norm_rope: total=27.44ms avg=1.372ms n=20 | decode.moe.combine: total=22.89ms avg=0.041ms n=560 | prefill.moe.gate: total=19.43ms avg=0.243ms n=80 | prefill.moe.combine: total=11.04ms avg=0.138ms n=80
+(VllmWorkerProcess pid=12140) INFO 07-14 12:02:29 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=1 steps=16 mode=decode prefill.layer.mlp: total=5629.78ms avg=70.372ms n=80 | prefill.moe.routed_total: total=5372.03ms avg=67.150ms n=80 | prefill.moe.routed_prefill_experts: total=5280.95ms avg=66.012ms n=80 | prefill.layer.linear_attention: total=2944.91ms avg=49.082ms n=60 | decode.layer.mlp: total=920.89ms avg=1.644ms n=560 | decode.layer.linear_attention: total=591.73ms avg=1.409ms n=420 | decode.moe.routed_total: total=497.21ms avg=0.888ms n=560 | prefill.layer.full_attention: total=481.27ms avg=24.064ms n=20 | prefill.full_attn.paged_attention: total=371.47ms avg=18.574ms n=20 | decode.moe.routed_decode_experts: total=343.09ms avg=0.613ms n=560 | decode.layer.full_attention: total=207.57ms avg=1.483ms n=140 | decode.moe.tp_all_reduce: total=166.13ms avg=0.297ms n=560 | prefill.moe.tp_all_reduce: total=143.85ms avg=1.798ms n=80 | decode.moe.shared_expert: total=134.40ms avg=0.240ms n=560 | decode.moe.routing_topk: total=123.62ms avg=0.221ms n=560 | decode.layer.input_norm: total=118.60ms avg=0.212ms n=560 | decode.layer.post_attn_norm: total=116.99ms avg=0.209ms n=560 | prefill.layer.input_norm: total=107.20ms avg=1.340ms n=80 | prefill.layer.post_attn_norm: total=101.07ms avg=1.263ms n=80 | prefill.moe.routing_topk: total=86.03ms avg=1.075ms n=80 | prefill.moe.shared_expert: total=74.58ms avg=0.932ms n=80 | decode.full_attn.gate_o_proj: total=58.25ms avg=0.416ms n=140 | decode.full_attn.norm_rope: total=56.87ms avg=0.406ms n=140 | decode.full_attn.paged_attention: total=49.87ms avg=0.356ms n=140 | prefill.full_attn.gate_o_proj: total=47.30ms avg=2.365ms n=20 | decode.moe.gate: total=41.26ms avg=0.074ms n=560 | prefill.full_attn.qkv_proj: total=33.16ms avg=1.658ms n=20 | decode.full_attn.qkv_proj: total=29.95ms avg=0.214ms n=140 | prefill.full_attn.norm_rope: total=27.36ms avg=1.368ms n=20 | decode.moe.combine: total=24.68ms avg=0.044ms n=560 | prefill.moe.gate: total=19.37ms avg=0.242ms n=80 | prefill.moe.combine: total=11.14ms avg=0.139ms n=80
+INFO 07-14 12:02:29 model_runner.py:114] [ENGINEX_PROFILE_MODEL_RUNNER] steps=16 mode=decode prompt.model_forward: total=9427.11ms avg=4713.555ms n=2 | decode.model_forward: total=2023.26ms avg=144.518ms n=14 | prompt.compute_logits: total=204.51ms avg=102.255ms n=2 | prompt.sample: total=34.98ms avg=17.492ms n=2 | decode.compute_logits: total=16.28ms avg=1.163ms n=14 | decode.sample: total=14.08ms avg=1.006ms n=14 | decode.attn_begin_forward: total=0.23ms avg=0.016ms n=14 | prompt.attn_begin_forward: total=0.03ms avg=0.017ms n=2
+(VllmWorkerProcess pid=12142) INFO 07-14 12:02:30 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=3 steps=24 mode=decode prefill.layer.mlp: total=5628.82ms avg=70.360ms n=80 | prefill.moe.routed_total: total=5306.10ms avg=66.326ms n=80 | prefill.moe.routed_prefill_experts: total=5214.38ms avg=65.180ms n=80 | prefill.layer.linear_attention: total=2944.17ms avg=49.070ms n=60 | decode.layer.mlp: total=1464.30ms avg=1.664ms n=880 | decode.layer.linear_attention: total=941.70ms avg=1.427ms n=660 | decode.moe.routed_total: total=775.83ms avg=0.882ms n=880 | decode.moe.routed_decode_experts: total=535.16ms avg=0.608ms n=880 | prefill.layer.full_attention: total=481.30ms avg=24.065ms n=20 | prefill.full_attn.paged_attention: total=370.76ms avg=18.538ms n=20 | decode.layer.full_attention: total=323.02ms avg=1.468ms n=220 | decode.moe.tp_all_reduce: total=291.99ms avg=0.332ms n=880 | prefill.moe.tp_all_reduce: total=209.17ms avg=2.615ms n=80 | decode.moe.shared_expert: total=207.50ms avg=0.236ms n=880 | decode.moe.routing_topk: total=191.33ms avg=0.217ms n=880 | decode.layer.input_norm: total=184.46ms avg=0.210ms n=880 | decode.layer.post_attn_norm: total=180.84ms avg=0.205ms n=880 | prefill.layer.input_norm: total=108.67ms avg=1.358ms n=80 | prefill.layer.post_attn_norm: total=101.07ms avg=1.263ms n=80 | decode.full_attn.gate_o_proj: total=96.14ms avg=0.437ms n=220 | decode.full_attn.norm_rope: total=88.66ms avg=0.403ms n=220 | prefill.moe.routing_topk: total=86.53ms avg=1.082ms n=80 | prefill.moe.shared_expert: total=74.52ms avg=0.931ms n=80 | decode.full_attn.paged_attention: total=71.05ms avg=0.323ms n=220 | decode.moe.gate: total=61.77ms avg=0.070ms n=880 | prefill.full_attn.gate_o_proj: total=48.03ms avg=2.402ms n=20 | decode.full_attn.qkv_proj: total=46.77ms avg=0.213ms n=220 | decode.moe.combine: total=35.39ms avg=0.040ms n=880 | prefill.full_attn.qkv_proj: total=33.18ms avg=1.659ms n=20 | prefill.full_attn.norm_rope: total=27.33ms avg=1.366ms n=20 | prefill.moe.gate: total=19.19ms avg=0.240ms n=80 | prefill.moe.combine: total=10.96ms avg=0.137ms n=80
+(VllmWorkerProcess pid=12141) INFO 07-14 12:02:30 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=2 steps=24 mode=decode prefill.layer.mlp: total=5629.85ms avg=70.373ms n=80 | prefill.moe.routed_total: total=5306.20ms avg=66.327ms n=80 | prefill.moe.routed_prefill_experts: total=5215.66ms avg=65.196ms n=80 | prefill.layer.linear_attention: total=2945.59ms avg=49.093ms n=60 | decode.layer.mlp: total=1463.70ms avg=1.663ms n=880 | decode.layer.linear_attention: total=943.19ms avg=1.429ms n=660 | decode.moe.routed_total: total=779.57ms avg=0.886ms n=880 | decode.moe.routed_decode_experts: total=538.76ms avg=0.612ms n=880 | prefill.layer.full_attention: total=481.58ms avg=24.079ms n=20 | prefill.full_attn.paged_attention: total=370.72ms avg=18.536ms n=20 | decode.layer.full_attention: total=322.62ms avg=1.466ms n=220 | decode.moe.tp_all_reduce: total=283.04ms avg=0.322ms n=880 | decode.moe.shared_expert: total=210.88ms avg=0.240ms n=880 | prefill.moe.tp_all_reduce: total=209.76ms avg=2.622ms n=80 | decode.moe.routing_topk: total=191.55ms avg=0.218ms n=880 | decode.layer.input_norm: total=184.49ms avg=0.210ms n=880 | decode.layer.post_attn_norm: total=181.60ms avg=0.206ms n=880 | prefill.layer.input_norm: total=106.27ms avg=1.328ms n=80 | prefill.layer.post_attn_norm: total=100.86ms avg=1.261ms n=80 | decode.full_attn.gate_o_proj: total=95.24ms avg=0.433ms n=220 | decode.full_attn.norm_rope: total=89.21ms avg=0.406ms n=220 | prefill.moe.routing_topk: total=85.44ms avg=1.068ms n=80 | prefill.moe.shared_expert: total=74.77ms avg=0.935ms n=80 | decode.full_attn.paged_attention: total=70.81ms avg=0.322ms n=220 | decode.moe.gate: total=62.05ms avg=0.071ms n=880 | prefill.full_attn.gate_o_proj: total=48.41ms avg=2.420ms n=20 | decode.full_attn.qkv_proj: total=46.98ms avg=0.214ms n=220 | decode.moe.combine: total=35.85ms avg=0.041ms n=880 | prefill.full_attn.qkv_proj: total=33.20ms avg=1.660ms n=20 | prefill.full_attn.norm_rope: total=27.29ms avg=1.364ms n=20 | prefill.moe.gate: total=19.33ms avg=0.242ms n=80 | prefill.moe.combine: total=10.99ms avg=0.137ms n=80
+INFO 07-14 12:02:30 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=0 steps=24 mode=decode prefill.layer.mlp: total=5627.88ms avg=70.348ms n=80 | prefill.moe.routed_total: total=5336.07ms avg=66.701ms n=80 | prefill.moe.routed_prefill_experts: total=5239.90ms avg=65.499ms n=80 | prefill.layer.linear_attention: total=2944.76ms avg=49.079ms n=60 | decode.layer.mlp: total=1456.57ms avg=1.655ms n=880 | decode.layer.linear_attention: total=942.63ms avg=1.428ms n=660 | decode.moe.routed_total: total=785.65ms avg=0.893ms n=880 | decode.moe.routed_decode_experts: total=540.24ms avg=0.614ms n=880 | prefill.layer.full_attention: total=481.27ms avg=24.063ms n=20 | prefill.full_attn.paged_attention: total=371.38ms avg=18.569ms n=20 | decode.layer.full_attention: total=322.06ms avg=1.464ms n=220 | decode.moe.tp_all_reduce: total=265.92ms avg=0.302ms n=880 | decode.moe.shared_expert: total=213.28ms avg=0.242ms n=880 | decode.moe.routing_topk: total=195.06ms avg=0.222ms n=880 | decode.layer.input_norm: total=188.81ms avg=0.215ms n=880 | decode.layer.post_attn_norm: total=184.60ms avg=0.210ms n=880 | prefill.moe.tp_all_reduce: total=177.55ms avg=2.219ms n=80 | prefill.layer.input_norm: total=108.49ms avg=1.356ms n=80 | prefill.layer.post_attn_norm: total=101.60ms avg=1.270ms n=80 | decode.full_attn.gate_o_proj: total=91.78ms avg=0.417ms n=220 | prefill.moe.routing_topk: total=91.04ms avg=1.138ms n=80 | decode.full_attn.norm_rope: total=89.66ms avg=0.408ms n=220 | prefill.moe.shared_expert: total=74.97ms avg=0.937ms n=80 | decode.full_attn.paged_attention: total=72.73ms avg=0.331ms n=220 | decode.moe.gate: total=63.37ms avg=0.072ms n=880 | decode.full_attn.qkv_proj: total=47.46ms avg=0.216ms n=220 | prefill.full_attn.gate_o_proj: total=47.06ms avg=2.353ms n=20 | decode.moe.combine: total=36.03ms avg=0.041ms n=880 | prefill.full_attn.qkv_proj: total=33.28ms avg=1.664ms n=20 | prefill.full_attn.norm_rope: total=27.44ms avg=1.372ms n=20 | prefill.moe.gate: total=19.43ms avg=0.243ms n=80 | prefill.moe.combine: total=11.04ms avg=0.138ms n=80
+(VllmWorkerProcess pid=12140) INFO 07-14 12:02:30 qwen3_5.py:97] [ENGINEX_PROFILE_QWEN] rank=1 steps=24 mode=decode prefill.layer.mlp: total=5629.78ms avg=70.372ms n=80 | prefill.moe.routed_total: total=5372.03ms avg=67.150ms n=80 | prefill.moe.routed_prefill_experts: total=5280.95ms avg=66.012ms n=80 | prefill.layer.linear_attention: total=2944.91ms avg=49.082ms n=60 | decode.layer.mlp: total=1457.27ms avg=1.656ms n=880 | decode.layer.linear_attention: total=943.04ms avg=1.429ms n=660 | decode.moe.routed_total: total=783.51ms avg=0.890ms n=880 | decode.moe.routed_decode_experts: total=540.23ms avg=0.614ms n=880 | prefill.layer.full_attention: total=481.27ms avg=24.064ms n=20 | prefill.full_attn.paged_attention: total=371.47ms avg=18.574ms n=20 | decode.layer.full_attention: total=322.30ms avg=1.465ms n=220 | decode.moe.tp_all_reduce: total=267.01ms avg=0.303ms n=880 | decode.moe.shared_expert: total=212.02ms avg=0.241ms n=880 | decode.moe.routing_topk: total=194.56ms avg=0.221ms n=880 | decode.layer.input_norm: total=187.87ms avg=0.213ms n=880 | decode.layer.post_attn_norm: total=185.10ms avg=0.210ms n=880 | prefill.moe.tp_all_reduce: total=143.85ms avg=1.798ms n=80 | prefill.layer.input_norm: total=107.20ms avg=1.340ms n=80 | prefill.layer.post_attn_norm: total=101.07ms avg=1.263ms n=80 | decode.full_attn.gate_o_proj: total=92.80ms avg=0.422ms n=220 | decode.full_attn.norm_rope: total=89.57ms avg=0.407ms n=220 | prefill.moe.routing_topk: total=86.03ms avg=1.075ms n=80 | prefill.moe.shared_expert: total=74.58ms avg=0.932ms n=80 | decode.full_attn.paged_attention: total=72.43ms avg=0.329ms n=220 | decode.moe.gate: total=64.64ms avg=0.073ms n=880 | decode.full_attn.qkv_proj: total=47.37ms avg=0.215ms n=220 | prefill.full_attn.gate_o_proj: total=47.30ms avg=2.365ms n=20 | decode.moe.combine: total=38.74ms avg=0.044ms n=880 | prefill.full_attn.qkv_proj: total=33.16ms avg=1.658ms n=20 | prefill.full_attn.norm_rope: total=27.36ms avg=1.368ms n=20 | prefill.moe.gate: total=19.37ms avg=0.242ms n=80 | prefill.moe.combine: total=11.14ms avg=0.139ms n=80
+INFO 07-14 12:02:30 model_runner.py:114] [ENGINEX_PROFILE_MODEL_RUNNER] steps=24 mode=decode prompt.model_forward: total=9427.11ms avg=4713.555ms n=2 | decode.model_forward: total=3204.14ms avg=145.643ms n=22 | prompt.compute_logits: total=204.51ms avg=102.255ms n=2 | prompt.sample: total=34.98ms avg=17.492ms n=2 | decode.compute_logits: total=25.62ms avg=1.165ms n=22 | decode.sample: total=22.16ms avg=1.007ms n=22 | decode.attn_begin_forward: total=0.36ms avg=0.017ms n=22 | prompt.attn_begin_forward: total=0.03ms avg=0.017ms n=2
+INFO 07-14 12:02:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 2.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:02:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:02:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:02:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:02:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:02:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:03:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:03:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:03:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:03:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:03:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:03:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:03:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:03:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:03:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:03:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:03:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:03:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:04:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:04:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:04:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:04:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:04:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:04:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:04:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:04:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:04:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:04:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:04:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:04:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:05:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:05:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:05:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:05:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:05:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:05:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:05:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:05:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:05:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:05:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:05:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:05:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:06:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:06:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:06:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:06:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:06:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:06:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:06:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:06:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:06:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:06:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:06:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:06:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:07:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:07:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:07:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:07:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:07:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:07:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:07:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:07:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:07:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:07:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:07:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:07:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:08:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:08:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:08:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:08:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:08:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:08:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:08:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:08:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:08:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:08:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:08:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:08:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:09:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:09:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:09:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:09:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:09:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:09:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:09:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:09:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:09:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:09:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:09:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:09:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:10:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:10:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:10:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:10:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:10:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:10:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:10:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:10:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:10:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:10:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:10:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:10:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:11:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:11:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:11:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:11:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:11:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:11:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:11:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:11:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:11:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:11:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:11:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:11:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:12:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:12:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:12:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:12:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:12:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:12:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:12:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:12:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:12:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:12:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:12:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:12:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:13:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:13:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%

worklogs/remote_results/2026-07-14-code-profile/server_tiny_batch_moe_eager_custom_ar_seq2_b8192.log

@@ -0,0 +1,303 @@
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+INFO 07-14 12:25:08 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+2026-07-14 12:25:10.276354: I tensorflow/core/util/port.cc:110] oneDNN custom operations are on. You may see slightly different numerical results due to floating-point round-off errors from different computation orders. To turn them off, set the environment variable `TF_ENABLE_ONEDNN_OPTS=0`.
+2026-07-14 12:25:10.327684: I tensorflow/core/platform/cpu_feature_guard.cc:182] This TensorFlow binary is optimized to use available CPU instructions in performance-critical operations.
+To enable the following instructions: SSE3 SSE4.1 SSE4.2 AVX AVX2 AVX512F AVX512_VNNI AVX512_BF16 AVX_VNNI AMX_TILE AMX_INT8 AMX_BF16 FMA, in other operations, rebuild TensorFlow with the appropriate compiler flags.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+INFO 07-14 12:25:15 api_server.py:530] vLLM API server version 0.6.3
+INFO 07-14 12:25:15 api_server.py:531] args: Namespace(host='0.0.0.0', port=1111, uvicorn_log_level='info', allow_credentials=False, allowed_origins=['*'], allowed_methods=['*'], allowed_headers=['*'], api_key=None, lora_modules=None, prompt_adapters=None, chat_template=None, response_role='assistant', ssl_keyfile=None, ssl_certfile=None, ssl_ca_certs=None, ssl_cert_reqs=0, root_path=None, middleware=[], return_tokens_as_token_ids=False, disable_frontend_multiprocessing=True, enable_auto_tool_choice=True, tool_call_parser='qwen3_coder', tool_parser_plugin='', reasoning_parser='qwen3', model='/root/public-storage/models/Qwen/Qwen3.6-35B-A3B', tokenizer=None, skip_tokenizer_init=False, revision=None, code_revision=None, tokenizer_revision=None, tokenizer_mode='auto', trust_remote_code=True, download_dir=None, load_format='auto', config_format='auto', dtype='auto', kv_cache_dtype='auto', quantization_param_path=None, max_model_len=100000, guided_decoding_backend='outlines', distributed_executor_backend=None, worker_use_ray=False, pipeline_parallel_size=1, tensor_parallel_size=4, max_parallel_loading_workers=None, ray_workers_use_nsight=False, block_size=16, enable_prefix_caching=True, disable_sliding_window=False, use_v2_block_manager=True, num_lookahead_slots=0, seed=0, swap_space=4, cpu_offload_gb=0, gpu_memory_utilization=0.95, num_gpu_blocks_override=None, max_num_batched_tokens=8192, max_num_seqs=2, max_logprobs=20, disable_log_stats=False, quantization=None, rope_scaling=None, rope_theta=None, enforce_eager=True, max_context_len_to_capture=None, max_seq_len_to_capture=32768, disable_custom_all_reduce=False, tokenizer_pool_size=0, tokenizer_pool_type='ray', tokenizer_pool_extra_config=None, limit_mm_per_prompt=None, mm_processor_kwargs=None, enable_lora=False, max_loras=1, max_lora_rank=16, lora_extra_vocab_size=256, lora_dtype='auto', long_lora_scaling_factors=None, max_cpu_loras=None, fully_sharded_loras=False, enable_prompt_adapter=False, max_prompt_adapters=1, max_prompt_adapter_token=0, device='auto', num_scheduler_steps=1, multi_step_stream_outputs=True, scheduler_delay_factor=0.0, enable_chunked_prefill=True, speculative_model=None, speculative_model_quantization=None, num_speculative_tokens=None, speculative_disable_mqa_scorer=False, speculative_draft_tensor_parallel_size=None, speculative_max_model_len=None, speculative_disable_by_batch_size=None, ngram_prompt_lookup_max=None, ngram_prompt_lookup_min=None, spec_decoding_acceptance_method='rejection_sampler', typical_acceptance_sampler_posterior_threshold=None, typical_acceptance_sampler_posterior_alpha=None, disable_logprobs_during_spec_decoding=None, model_loader_extra_config=None, ignore_patterns=[], preemption_mode=None, served_model_name=['llm'], qlora_adapter_name_or_path=None, otlp_traces_endpoint=None, collect_detailed_traces=None, disable_async_output_proc=False, override_neuron_config=None, scheduling_policy='fcfs', disable_log_requests=True, max_log_len=None, disable_fastapi_docs=False)
+INFO 07-14 12:25:15 config.py:1670] Downcasting torch.float32 to torch.float16.
+INFO 07-14 12:25:26 config.py:887] Defaulting to use mp for distributed inference
+INFO 07-14 12:25:26 config.py:1005] Chunked prefill is enabled with max_num_batched_tokens=8192.
+WARNING 07-14 12:25:26 config.py:380] To see benefits of async output processing, enable CUDA graph. Since, enforce-eager is enabled, async output processor cannot be used
+INFO 07-14 12:25:26 llm_engine.py:237] Initializing an LLM engine (v0.6.3) with config: model='/root/public-storage/models/Qwen/Qwen3.6-35B-A3B', speculative_config=None, tokenizer='/root/public-storage/models/Qwen/Qwen3.6-35B-A3B', skip_tokenizer_init=False, tokenizer_mode=auto, revision=None, override_neuron_config=None, rope_scaling=None, rope_theta=None, tokenizer_revision=None, trust_remote_code=True, dtype=torch.float16, max_seq_len=100000, download_dir=None, load_format=LoadFormat.AUTO, tensor_parallel_size=4, pipeline_parallel_size=1, disable_custom_all_reduce=False, quantization=None, enforce_eager=True, kv_cache_dtype=auto, quantization_param_path=None, device_config=cuda, decoding_config=DecodingConfig(guided_decoding_backend='outlines'), observability_config=ObservabilityConfig(otlp_traces_endpoint=None, collect_model_forward_time=False, collect_model_execute_time=False), seed=0, served_model_name=llm, use_v2_block_manager=True, num_scheduler_steps=1, chunked_prefill_enabled=True multi_step_stream_outputs=True, enable_prefix_caching=True, use_async_output_proc=False, use_cached_outputs=False, mm_processor_kwargs=None)
+WARNING 07-14 12:25:27 multiproc_gpu_executor.py:53] Reducing Torch parallelism from 64 threads to 1 to avoid unnecessary CPU contention. Set OMP_NUM_THREADS in the external environment to tune this value as needed.
+INFO 07-14 12:25:27 custom_cache_manager.py:17] Setting Triton cache manager to: vllm.triton_utils.custom_cache_manager:CustomCacheManager
+INFO 07-14 12:25:27 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+INFO 07-14 12:25:27 selector.py:115] Using XFormers backend.
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+/usr/local/corex/lib/python3/dist-packages/torch/cuda/__init__.py:51: FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead. If you did not install pynvml directly, please report this to the maintainers of the package that installed pynvml for you.
+  import pynvml  # type: ignore[import]
+INFO 07-14 12:25:29 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+INFO 07-14 12:25:29 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+INFO 07-14 12:25:29 importing.py:10] Triton not installed; certain GPU-related functions will not be available.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+WARNING:tensorflow:Deprecation warnings have been disabled. Set TF_ENABLE_DEPRECATION_WARNINGS=1 to re-enable them.
+(VllmWorkerProcess pid=14382) INFO 07-14 12:25:36 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=14382) INFO 07-14 12:25:36 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=14380) INFO 07-14 12:25:36 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=14380) INFO 07-14 12:25:36 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=14381) INFO 07-14 12:25:36 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=14381) INFO 07-14 12:25:36 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=14382) INFO 07-14 12:25:36 multiproc_worker_utils.py:216] Worker ready; awaiting tasks
+(VllmWorkerProcess pid=14380) INFO 07-14 12:25:36 multiproc_worker_utils.py:216] Worker ready; awaiting tasks
+(VllmWorkerProcess pid=14381) INFO 07-14 12:25:36 multiproc_worker_utils.py:216] Worker ready; awaiting tasks
+INFO 07-14 12:25:36 shm_broadcast.py:242] vLLM message queue communication handle: Handle(connect_ip='127.0.0.1', local_reader_ranks=[1, 2, 3], buffer=<vllm.distributed.device_communicators.shm_broadcast.ShmRingBuffer object at 0x7f5175238550>, local_subscribe_port=52711, remote_subscribe_port=None)
+INFO 07-14 12:25:36 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+(VllmWorkerProcess pid=14380) INFO 07-14 12:25:36 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+(VllmWorkerProcess pid=14381) INFO 07-14 12:25:36 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+(VllmWorkerProcess pid=14382) INFO 07-14 12:25:36 model_runner.py:1112] Starting to load model /root/public-storage/models/Qwen/Qwen3.6-35B-A3B...
+INFO 07-14 12:25:36 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+INFO 07-14 12:25:36 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=14380) INFO 07-14 12:25:36 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=14382) INFO 07-14 12:25:36 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=14380) INFO 07-14 12:25:36 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=14382) INFO 07-14 12:25:36 selector.py:115] Using XFormers backend.
+(VllmWorkerProcess pid=14381) INFO 07-14 12:25:36 selector.py:266] Cannot use FlashAttention-2 backend because the vllm.vllm_flash_attn package is not found. Make sure that vllm_flash_attn was built and installed (on by default).
+(VllmWorkerProcess pid=14381) INFO 07-14 12:25:36 selector.py:115] Using XFormers backend.
+
+Loading safetensors checkpoint shards:   0% Completed | 0/26 [00:00<?, ?it/s]
+
+Loading safetensors checkpoint shards:   4% Completed | 1/26 [00:01<00:45,  1.81s/it]
+
+Loading safetensors checkpoint shards:   8% Completed | 2/26 [00:02<00:24,  1.02s/it]
+
+Loading safetensors checkpoint shards:  12% Completed | 3/26 [00:04<00:32,  1.42s/it]
+
+Loading safetensors checkpoint shards:  15% Completed | 4/26 [00:06<00:34,  1.59s/it]
+
+Loading safetensors checkpoint shards:  19% Completed | 5/26 [00:06<00:28,  1.37s/it]
+
+Loading safetensors checkpoint shards:  23% Completed | 6/26 [00:09<00:31,  1.59s/it]
+
+Loading safetensors checkpoint shards:  27% Completed | 7/26 [00:09<00:23,  1.22s/it]
+
+Loading safetensors checkpoint shards:  31% Completed | 8/26 [00:11<00:24,  1.39s/it]
+
+Loading safetensors checkpoint shards:  35% Completed | 9/26 [00:12<00:21,  1.25s/it]
+
+Loading safetensors checkpoint shards:  38% Completed | 10/26 [00:14<00:23,  1.47s/it]
+
+Loading safetensors checkpoint shards:  42% Completed | 11/26 [00:14<00:16,  1.11s/it]
+
+Loading safetensors checkpoint shards:  46% Completed | 12/26 [00:16<00:18,  1.31s/it]
+
+Loading safetensors checkpoint shards:  50% Completed | 13/26 [00:18<00:19,  1.48s/it]
+
+Loading safetensors checkpoint shards:  54% Completed | 14/26 [00:20<00:19,  1.66s/it]
+
+Loading safetensors checkpoint shards:  58% Completed | 15/26 [00:20<00:15,  1.39s/it]
+
+Loading safetensors checkpoint shards:  62% Completed | 16/26 [00:23<00:16,  1.68s/it]
+
+Loading safetensors checkpoint shards:  65% Completed | 17/26 [00:23<00:11,  1.31s/it]
+
+Loading safetensors checkpoint shards:  69% Completed | 18/26 [00:25<00:11,  1.46s/it]
+
+Loading safetensors checkpoint shards:  73% Completed | 19/26 [00:27<00:10,  1.52s/it]
+
+Loading safetensors checkpoint shards:  77% Completed | 20/26 [00:29<00:10,  1.78s/it]
+
+Loading safetensors checkpoint shards:  81% Completed | 21/26 [00:30<00:07,  1.55s/it]
+
+Loading safetensors checkpoint shards:  85% Completed | 22/26 [00:31<00:05,  1.30s/it]
+
+Loading safetensors checkpoint shards:  88% Completed | 23/26 [00:33<00:04,  1.61s/it]
+
+Loading safetensors checkpoint shards:  92% Completed | 24/26 [00:35<00:03,  1.70s/it]
+
+Loading safetensors checkpoint shards:  96% Completed | 25/26 [00:37<00:01,  1.76s/it]
+
+Loading safetensors checkpoint shards: 100% Completed | 26/26 [00:37<00:00,  1.38s/it]
+
+Loading safetensors checkpoint shards: 100% Completed | 26/26 [00:37<00:00,  1.46s/it]
+
+(VllmWorkerProcess pid=14380) INFO 07-14 12:26:15 model_runner.py:1123] Loading model weights took 16.2303 GB
+INFO 07-14 12:26:15 model_runner.py:1123] Loading model weights took 16.2303 GB
+(VllmWorkerProcess pid=14381) INFO 07-14 12:26:15 model_runner.py:1123] Loading model weights took 16.2303 GB
+(VllmWorkerProcess pid=14382) INFO 07-14 12:26:16 model_runner.py:1123] Loading model weights took 16.2303 GB
+INFO 07-14 12:26:24 distributed_gpu_executor.py:57] # GPU blocks: 21100, # CPU blocks: 6553
+INFO 07-14 12:26:24 distributed_gpu_executor.py:61] Maximum concurrency for 100000 tokens per request: 3.38x
+INFO 07-14 12:26:28 serving_chat.py:79] "auto" tool choice has been enabled please note that while the parallel_tool_calls client option is preset for compatibility reasons, it will be ignored.
+INFO 07-14 12:26:28 serving_chat.py:101] Reasoning parser 'qwen3' enabled.
+WARNING 07-14 12:26:28 serving_embedding.py:199] embedding_mode is False. Embedding API will not work.
+INFO 07-14 12:26:28 launcher.py:19] Available routes are:
+INFO 07-14 12:26:28 launcher.py:27] Route: /openapi.json, Methods: HEAD, GET
+INFO 07-14 12:26:28 launcher.py:27] Route: /docs, Methods: HEAD, GET
+INFO 07-14 12:26:28 launcher.py:27] Route: /docs/oauth2-redirect, Methods: HEAD, GET
+INFO 07-14 12:26:28 launcher.py:27] Route: /redoc, Methods: HEAD, GET
+INFO 07-14 12:26:28 launcher.py:27] Route: /health, Methods: GET
+INFO 07-14 12:26:28 launcher.py:27] Route: /tokenize, Methods: POST
+INFO 07-14 12:26:28 launcher.py:27] Route: /detokenize, Methods: POST
+INFO 07-14 12:26:28 launcher.py:27] Route: /v1/models, Methods: GET
+INFO 07-14 12:26:28 launcher.py:27] Route: /version, Methods: GET
+INFO 07-14 12:26:28 launcher.py:27] Route: /v1/chat/completions, Methods: POST
+INFO 07-14 12:26:28 launcher.py:27] Route: /v1/completions, Methods: POST
+INFO 07-14 12:26:28 launcher.py:27] Route: /v1/embeddings, Methods: POST
+INFO:     Started server process [14041]
+INFO:     Waiting for application startup.
+INFO:     Application startup complete.
+INFO:     Uvicorn running on socket ('0.0.0.0', 1111) (Press CTRL+C to quit)
+INFO 07-14 12:26:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:26:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:26:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:26:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:26:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:26:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:27:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:27:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:27:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:27:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:27:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:27:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:27:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:27:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO:     127.0.0.1:46086 - "GET /health HTTP/1.1" 200 OK
+INFO 07-14 12:27:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:27:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:27:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:27:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:28:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:28:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:28:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:28:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:28:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:28:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:28:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:28:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:28:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:28:49 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:28:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:28:59 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO:     127.0.0.1:40074 - "GET /health HTTP/1.1" 200 OK
+INFO 07-14 12:29:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:29:09 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:29:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:29:19 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:29:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:29:29 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO 07-14 12:29:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:29:39 metrics.py:361] Prefix cache hit rate: GPU: 0.00%, CPU: 0.00%
+INFO:     127.0.0.1:46954 - "POST /v1/chat/completions HTTP/1.1" 200 OK
+INFO:     127.0.0.1:46970 - "POST /v1/chat/completions HTTP/1.1" 200 OK
+/usr/local/lib/python3.10/site-packages/pyairports/airports.py:1: UserWarning: pkg_resources is deprecated as an API. See https://setuptools.pypa.io/en/latest/pkg_resources.html. The pkg_resources package is slated for removal as early as 2025-11-30. Refrain from using this package or pin to Setuptools<81.
+  from pkg_resources import resource_string
+INFO 07-14 12:29:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:29:49 metrics.py:361] Prefix cache hit rate: GPU: 50.00%, CPU: 0.00%
+INFO 07-14 12:29:54 metrics.py:345] Avg prompt throughput: 15.4 tokens/s, Avg generation throughput: 7.5 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:29:54 metrics.py:361] Prefix cache hit rate: GPU: 50.00%, CPU: 0.00%
+INFO 07-14 12:29:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 12.0 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:29:59 metrics.py:361] Prefix cache hit rate: GPU: 50.00%, CPU: 0.00%
+INFO 07-14 12:30:05 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 11.8 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:30:05 metrics.py:361] Prefix cache hit rate: GPU: 50.00%, CPU: 0.00%
+INFO 07-14 12:30:10 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 11.6 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.1%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:30:10 metrics.py:361] Prefix cache hit rate: GPU: 50.00%, CPU: 0.00%
+INFO:     127.0.0.1:51990 - "POST /v1/chat/completions HTTP/1.1" 200 OK
+INFO:     127.0.0.1:51998 - "POST /v1/chat/completions HTTP/1.1" 200 OK
+INFO 07-14 12:30:15 metrics.py:345] Avg prompt throughput: 15.1 tokens/s, Avg generation throughput: 9.3 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:30:15 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:30:20 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 12.0 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:30:20 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:30:25 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 12.1 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:30:25 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:30:30 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 12.2 tokens/s, Running: 2 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:30:30 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:30:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 6.6 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:30:39 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:30:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:30:49 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:30:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:30:59 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:31:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:31:09 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:31:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:31:19 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:31:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:31:29 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:31:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:31:39 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:31:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:31:49 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:31:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:31:59 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:32:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:32:09 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:32:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:32:19 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:32:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:32:29 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:32:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:32:39 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:32:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:32:49 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:32:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:32:59 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:33:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:33:09 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:33:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:33:19 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:33:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:33:29 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:33:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:33:39 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:33:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:33:49 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:33:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:33:59 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:34:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:34:09 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:34:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:34:19 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:34:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:34:29 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:34:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:34:39 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:34:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:34:49 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:34:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:34:59 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:35:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:35:09 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:35:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:35:19 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:35:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:35:29 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:35:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:35:39 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:35:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:35:49 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:35:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:35:59 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:36:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:36:09 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:36:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:36:19 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:36:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:36:29 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:36:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:36:39 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:36:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:36:49 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:36:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:36:59 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:37:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:37:09 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:37:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:37:19 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:37:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:37:29 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:37:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:37:39 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:37:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:37:49 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:37:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:37:59 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:38:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:38:09 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:38:19 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:38:19 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:38:29 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:38:29 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:38:39 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:38:39 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:38:49 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:38:49 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:38:59 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:38:59 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%
+INFO 07-14 12:39:09 metrics.py:345] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.0%, CPU KV cache usage: 0.0%.
+INFO 07-14 12:39:09 metrics.py:361] Prefix cache hit rate: GPU: 75.00%, CPU: 0.00%