Profile a decode step

Four quantities, and the order matters because each one is only interpretable given the one before it:

1. The floor. Compulsory HBM traffic divided by bandwidth, for your exact batch and context. Pure arithmetic — the derivation is §10.5 and the roofline behind it is §0.4.
2. Wall time of one step span, from the engine's own trace annotation.
3. Kernel-busy time, as the union of kernel intervals on the device timeline — not their sum. Kernels on different streams overlap, and a naive sum double-counts them. vLLM's own nsys post-processor exists for exactly this reason (tools/profiler/nsys_profile_tools/gputrc2graph.py, which computes non-overlapped GPU cycles).
4. The gap: wall minus busy. Time the GPU spent doing nothing.

The gap is the lab. vLLM prints a self_cuda_time_total table on every capture stop, by default (torch_profiler_dump_cuda_time_total defaults to True; vllm/profiler/wrapper.py:L308-L320), and it is genuinely useful — it answers "which kernel was slowest". It cannot answer "was the GPU idle", because a table of kernel durations has thrown away the timeline that would show you. Reading a summary table and concluding the step is bandwidth-bound is the specific mistake this lab prevents.

Predict all four before you capture anything:

$ python3 run.py --mode floor --batch 32 --seq 2048
$ python3 run.py --mode floor --batch 1 --seq 512 --launches 330
$ python3 run.py --help          # every knob, all four modes

For Llama-3-8B at B=32, s=2048 on an H100 SXM this reproduces §10.5's numbers exactly, because it is the same arithmetic: 23.60 GB of compulsory traffic, a 7.04 ms floor, and a 0.78 ms launch budget that is 11% of it.

Both engines drive torch.profiler from an HTTP endpoint, and they differ in one instructive place: where the capture window is configured.

vLLM — the window is bound at launch

As of a556f3f profiling is a config object, not an environment variable. Forget to set it and the worker tells you the exact flags, which makes this the friendliest error string in this part of the tree:

    def profile(self, is_start: bool = True, profile_prefix: str | None = None):
        # Check if profiling is enabled
        if self.profiler_config is None or self.profiler_config.profiler is None:
            raise RuntimeError(
                "Profiling is not enabled. Please set --profiler-config to enable "
                "profiling. Example: "
                "'--profiler-config.profiler=torch --profiler-config.torch_profiler_dir"
                "=YOUR_DIR_PATH_TO_DUMP_TRACE'"

The endpoints themselves take no body at all — when to capture was decided before the server started:

@router.post("/start_profile")
async def start_profile(raw_request: Request):
    logger.info("Starting profiler...")
    await engine_client(raw_request).start_profile()
    logger.info("Profiler started.")
    return Response(status_code=200)


@router.post("/stop_profile")
async def stop_profile(raw_request: Request):
    logger.info("Stopping profiler...")
    await engine_client(raw_request).stop_profile()
    logger.info("Profiler stopped.")
    return Response(status_code=200)

Which is why the iteration knobs exist. A capture that starts on a freshly started server and stops two seconds later records torch.compile, autotuning and first-touch allocations, not steady state:

    delay_iterations: int = Field(default=0, ge=0)
    """Number of engine iterations to skip before starting profiling.
    Defaults to 0, meaning profiling starts immediately after receiving /start_profile.
    """

    max_iterations: int = Field(default=0, ge=0)
    """Maximum number of engine iterations to profile after starting profiling.
    Defaults to 0, meaning no limit.
    """

# ... proton and torch_profiler_* fields elided ...
    active_iterations: int = Field(default=5, ge=1)
    """Number of active iterations for PyTorch profiler schedule.
    This is the number of iterations where profiling data is actually collected.
    Defaults to 5 active iterations.
    """

Note the gate: the torch.profiler.schedule is built only if warmup_iterations or wait_iterations is positive (vllm/profiler/wrapper.py:L215-L232). Set active_iterations alone and nothing changes; you get an unscheduled capture that records everything between your two POSTs.

$ vllm serve meta-llama/Meta-Llama-3-8B-Instruct \
    --max-num-seqs 32 \
    --profiler-config.profiler=torch \
    --profiler-config.torch_profiler_dir=/abs/path/traces \
    --profiler-config.detailed_trace_annotation=true \
    --profiler-config.warmup_iterations=3 \
    --profiler-config.active_iterations=5 \
    --profiler-config.ignore_frontend=true

# drive load, arm, disarm — all three from one command:
$ python3 run.py --mode capture --engine vllm --url http://localhost:8000 \
    --drive --concurrency 32 --warmup-s 8 --hold-s 2

SGLang — the window travels in the request

    # Start profiler. The API replies when all steps are processed
    # and files are generated.
    json_data = {
        "output_dir": str(output_dir),
        "num_steps": str(num_steps),
        "activities": activities,
        "profile_by_stage": profile_by_stage,
        "merge_profiles": merge_profiles,
        "profile_prefix": profile_prefix,
    }
    if start_step is not None:
        json_data["start_step"] = str(start_step)

    response = requests.post(url=url + "/start_profile", json=json_data)
    response.raise_for_status()

    trace_link = str(output_dir)
    return trace_link

Two consequences. First, /start_profile blocks until the requested steps have run and the trace is flushed — so run_profile never calls /stop_profile, even though the route exists (python/sglang/srt/entrypoints/http_server.py:L1168-L1173), and a short HTTP timeout looks like a hang. Second, start_step is reachable from run_profile() and from a raw POST, but the python3 -m sglang.profiler CLI does not expose a flag for it (python/sglang/profiler.py:L73-L137): to arm on a specific forward pass you have to POST the body yourself.

$ SGLANG_TORCH_PROFILER_DIR=/abs/path/traces \
    python3 -m sglang.launch_server --model-path meta-llama/Meta-Llama-3-8B-Instruct

$ python3 -m sglang.profiler --url http://localhost:30000 \
    --num-steps 5 --profile-by-stage --output-dir /abs/path/traces

# or drive the load and the capture together:
$ python3 run.py --mode capture --engine sglang --url http://localhost:30000 \
    --out /abs/path/traces --steps 5 --by-stage --drive

Reading the trace

You cannot analyse a trace of "some steps". You need one named step, because under continuous batching consecutive steps have different composition. Both engines name the per-step span after the batch, which is what makes selection possible. vLLM assembles it from the scheduler output:

            annotation = "".join(
                [
                    "execute_",
                    str(total_scheduled_tokens),
                    "_context_",
                    str(iteration_details.num_ctx_requests),
                    "(sq",
                    str(iteration_details.num_ctx_tokens),
                    "sk",
                    str(ctx_seq_len_sum),
                    "sqsq",
                    str(ctx_qq_compute),
                    "sqsk",
                    str(ctx_qk_compute),
                    ")_generation_",
                    str(iteration_details.num_generation_requests),

So a pure decode step at batch 32 reads execute_32_context_0(sq0sk0...)_generation_32(sq32sk...), and sk in the generation group is $\Sigma N_{KV}$ — the KV bytes that step actually read, which is the input to your own floor for that step rather than the batch you assumed. SGLang's equivalent is step[DECODE bs=32 g_sq=... g_sk=...], built at python/sglang/srt/utils/profile_utils.py:L476-L487. Without --profiler-config.detailed_trace_annotation vLLM falls back to a shorter form carrying request and token counts only (vllm/v1/worker/gpu_worker.py:L1027-L1041).

$ python3 run.py --mode analyze --trace traces/rank0.pt.trace.json.gz --spans
$ python3 run.py --mode analyze --trace traces/rank0.pt.trace.json.gz \
    --span "execute_32_context_0" --floor 7.046 --top 15

# and the number the book had to cite from a paper:
$ python3 run.py --mode launch-probe --iters 4000
$ python3 run.py --mode analyze --trace ... --launchcost 3.9   # feed yours back in

Four common shapes organize an initial diagnosis for a decode step, and the script prints which one it thinks you have. The decision procedure is mechanical — §10.5, Figure 3, draws them:

Now the part that makes this a lab rather than a demo. Capture the same operating point twice, with CUDA graphs on and off, and diff the gap. That single experiment is the one §8.1 could not run:

# vLLM: graphs off
$ vllm serve meta-llama/Meta-Llama-3-8B-Instruct --enforce-eager \
    --profiler-config.profiler=torch --profiler-config.torch_profiler_dir=/abs/eager

# SGLang: graphs off for the decode phase only
$ python3 -m sglang.launch_server --model-path meta-llama/Meta-Llama-3-8B-Instruct \
    --cuda-graph-backend-decode=disabled

--enforce-eager can change compilation and kernel selection as well as graph replay. Record the selected path and compare profiles; the difference is not necessarily pure launch overhead.

Predict the direction before you run it. Graphs off should raise the gap and leave kernel-busy roughly unchanged — the same kernels, issued one at a time. §8.1 derives 330 launches × 2.374 µs = 0.78 ms of pure driver time for a TP=1 step, so at batch 1 (4.48 ms of device work) that is 17% and at batch 32 (7.04 ms) it is 11%. Batching buys launch headroom, not just throughput. Tensor parallelism moves it the other way: at TP=8 the launch count rises to 395 while device work falls to roughly an eighth, giving 0.94 ms of launches against 0.56 ms of work — launch-bound on driver cost alone, before any Python is considered.

Your measured per-launch cost will be larger than 2.374 µs, and that is the point: the cited figure is driver-only, while --mode launch-probe measures a real PyTorch op through the dispatcher. The difference is exactly the framework cost §8.1 has to call unquantified.