动手 3：调试 Scheduler

python -m sglang.launch_server --log-level debug ...

SGLANG_LOG_LEVEL=debug \
SGLANG_LOG_BATCH_STATS=1 \
python -m sglang.launch_server ...

[INFO] Prefill batch. #new-seq: 5, #new-token: 1024, #cached-token: 4096, #queue-req: 2
[INFO] Decode batch. #running-req: 32, #token: 16384, gen throughput: 234 token/s

def event_loop_normal(self):
    """A normal scheduler loop."""
    while True:
        recv_reqs = self.request_receiver.recv_requests()
        self.process_input_requests(recv_reqs)

        # ───── DEBUG ─────
        if recv_reqs:
            print(f"[recv] +{len(recv_reqs)} reqs, waiting={len(self.waiting_queue)} running={self.running_batch.batch_size()}", flush=True)
        # ─────────────────

        batch = self.get_next_batch_to_run()
        self.cur_batch = batch

        # ───── DEBUG ─────
        if batch:
            mode = "prefill" if batch.forward_mode.is_extend() else "decode"
            tokens = batch.input_ids.numel() if batch.input_ids is not None else 0
            print(f"[batch] {mode} n_reqs={batch.batch_size()} tokens={tokens}", flush=True)
        # ─────────────────

        if batch:
            result = self.run_batch(batch)
            self.process_batch_result(batch, result)
        else:
            self.on_idle()

        self.last_batch = batch

[recv] +3 reqs, waiting=3 running=0
[batch] prefill n_reqs=3 tokens=3000
[batch] decode n_reqs=3 tokens=3
[batch] decode n_reqs=3 tokens=3
[recv] +1 reqs, waiting=1 running=3
[batch] prefill n_reqs=1 tokens=200
[batch] decode n_reqs=4 tokens=4
...

if batch and batch.forward_mode.is_extend():
    cached = sum(req.prefix_indices.shape[0] for req in batch.reqs if req.prefix_indices is not None)
    total = batch.extend_seq_lens.sum().item()
    print(f"[cache] cached={cached}/{total} ({100*cached/(cached+total):.1f}%)", flush=True)

# 在 Scheduler 的某个空闲点调用：
def dump_tree(node, prefix=""):
    print(f"{prefix}└── tokens={len(node.key.token_ids) if node.key else 0} value_len={node.value.shape[0] if node.value is not None else 0} lock_ref={node.lock_ref}")
    for child in node.children.values():
        dump_tree(child, prefix + "    ")

# 在 event_loop 里隔几轮调用一次
if self.forward_ct % 100 == 0:
    print("[tree]")
    dump_tree(self.tree_cache.root_node)

# 实时刷新
watch -n 1 'curl -s localhost:30000/metrics | grep -E "cache_hit|waiting|running|kv_pool"'

pip install py-spy
sudo py-spy top --pid <scheduler_pid>
# 或者抓 profile:
sudo py-spy record -o profile.svg --pid <scheduler_pid> --duration 30

nsys profile --gpu-metrics-device=0 -o sglang.qdrep \
    python -m sglang.launch_server ... &

# 跑请求...

# 用 nsys-ui 打开 sglang.qdrep 看时间轴

1. 客户端实测：TTFT、TPOT、E2E 各多少？
2. 看 /metrics 端：
   - cache_hit_rate
   - waiting_queue_size
   - gen_throughput
   - kv_pool_used
3. 看 scheduler log：
   - 这个 rid 是什么时候进 queue、什么时候开始 prefill、什么时候开始 decode
4. 如果 server 端时间和客户端基本一致 → 网络问题
   如果 server 端时间 << 客户端 → 客户端代码或网络
5. 如果 prefill 慢：
   - cache 没命中？
   - prompt 太长被 chunked prefill 切了多步？
   - 排队等其它请求？
6. 如果 decode 慢：
   - cuda graph fallback？
   - 并发太大 KV pool 紧？
   - quantization / attention backend 配错？

# 找到 scheduler pid
ps -ef | grep sglang | head

# 用 py-spy dump 一下栈
sudo py-spy dump --pid <pid>