16 min read5 sections

Lab 12 · for chapter 09-03

Trace one request through the source

Instrument both engines with logging at every hop and watch a single request traverse the whole stack.

Download lab script · CPU reference checks · Environment preflight.

Chapter §9.3 walks one streaming request through both engines and names a function at every hop. This lab makes the engine say it out loud. You turn on the instrumentation that already exists, send one request, and finish with a table whose left column is a line the server printed and whose right column is the file:line that printed it.

Hardware

One GPU, any size, any small model — the request path does not care what the weights are, and a 1B model on a 24 GB card exercises exactly the same code as a 70B on eight H100s. Two of the four modes need no server at all: --mode map prints the hop table offline, and --mode annotate works on a log file a colleague sent you. This is the one lab in the book where the deliverable is reading, and where nothing is substituted for missing hardware because nothing here is a performance number.

Not executed here

The hop table in run.py was built by reading the pinned source, not by matching it against a real capture — no engine was run while writing, because no GPU was available. Each regex was written against the format string in the cited file, so a line whose arguments render unexpectedly may not match. If a hop you can see in your log does not get labelled, that is a defect in this lab and worth reporting; --unmatched lists exactly those lines.

§1

What you measure

Three things, and only the first is a number:

Client-side TTFT and the ITL distribution for one streaming request, measured from the socket rather than from the engine's own clock.
A hop table: every log line this request produced, in emission order, each mapped to a file:line and to the process that owns it.
The hops that produced no line at all. These are the interesting ones. A hop with no log line is either a flag you did not pass or a path this request did not take, and deciding which is the exercise.

Start with the table, before any server exists:

shell — labs/12-read-a-request-through-the-code shell

$ python3 run.py --mode map --engine vllm
$ python3 run.py --mode map --engine sglang
$ python3 run.py --help          # every knob, all four modes

The asymmetry that shapes this lab

vLLM's log format carries the emitting file and line on every line: "[%(fileinfo)s:%(lineno)d] %(message)s" (vllm/logger.py:L22-L25). SGLang's carries neither: f"[%(asctime)s{maybe_ms}{prefix}] %(message)s" (python/sglang/srt/utils/common.py:L2338-L2343). So half of this lab's deliverable is free on vLLM and has to be built by hand on SGLang — which is why the hop table exists, and why you should check it against vLLM's own prefix as a cross-validation.

§2

Running it

Part A — turn the instrumentation on

Neither engine logs per-request detail by default, and both make you ask twice: once for the feature, once for the verbosity. vLLM's flag says so in its own help text:

vllm/engine/arg_utils.py:L2891-L2899 vLLM

        parser.add_argument(
            "--enable-log-requests",
            action=argparse.BooleanOptionalAction,
            default=AsyncEngineArgs.enable_log_requests,
            help="Enable logging request information, dependent on log level:\n"
            "- INFO: Request ID, parameters and LoRA request.\n"
            "- DEBUG: Prompt inputs (e.g: text, token IDs).\n"
            "You can set the minimum log level via `VLLM_LOGGING_LEVEL`.",
        )

Both levels come out of one call, and the DEBUG branch runs first — so an INFO-level server with --enable-log-requests emits the second line only:

vllm/entrypoints/serve/utils/request_logger.py:L44-L68 vLLM

        if logger.isEnabledFor(logging.DEBUG):
            max_log_len = self.max_log_len
            if max_log_len is not None:
                if prompt is not None:
                    prompt = prompt[:max_log_len]

                if prompt_token_ids is not None:
                    prompt_token_ids = prompt_token_ids[:max_log_len]

            logger.debug(
                "Request %s details: prompt: %r, "
                "prompt_token_ids: %s, "
                "prompt_embeds shape: %s.",
                request_id,
                prompt,
                prompt_token_ids,
                prompt_embeds.shape if prompt_embeds is not None else None,
            )

        logger.info(
            "Received request %s: params: %s, lora_request: %s.",
            request_id,
            params,
            lora_request,
        )

SGLang splits the same decision into a boolean and a level, and the level is not a log level — it is a redaction level:

python/sglang/srt/server_args.py:L1518-L1528 SGLang

    log_requests: A[
        bool,
        "Log metadata, inputs, outputs of all requests. The verbosity is decided by --log-requests-level",
        NS("observability"),
    ] = False
    log_requests_level: A[
        int,
        Arg(
            help="0: Log metadata (no sampling parameters). 1: Log metadata and sampling parameters. 2: Log metadata, sampling parameters and partial input/output. 3: Log every input/output.",
            choices=[0, 1, 2, 3],
        ),

Three lines come out of that logger; the two that bracket the whole lifecycle sit in one file, both emitted from the HTTP worker process (the third, hop 1's Receive OpenAI, needs level 2 or higher):

python/sglang/srt/utils/request_logger.py:L107-L111 and L185-L191 SGLang

        else:
            headers_str = f", headers={headers}" if headers else ""
            self._log(
                f"Receive: obj={_dataclass_to_string_truncated(obj, max_length, skip_names=skip_names)}{headers_str}"
            )
        else:
            obj_str = _dataclass_to_string_truncated(
                obj, max_length, skip_names=skip_names
            )
            out_str = f", out={_dataclass_to_string_truncated(out, max_length, skip_names=out_skip_names)}"
            headers_str = f", headers={headers}" if headers else ""
            self._log(f"Finish: obj={obj_str}{headers_str}{out_str}")

Between those two, everything happens in a different process, and SGLang gives you a per-request timing breakdown from the scheduler side — the closest thing either engine has to a hop-by-hop stopwatch:

python/sglang/srt/managers/schedule_batch.py:L1803-L1813 SGLang

        prefix = (
            f"ReqTimeStats("
            f"rid={self.rid}{bootstrap_info}, "
            f"input_len={len(self.origin_input_ids)}, "
            f"cached_input_len={self.cached_tokens}, "
            f"output_len={len(self.output_ids)}, "
            f"attempts={self.prefill_attempt_count}, "
            f"type={self.time_stats.disagg_mode_str()})"
        )
        logger.info(f"{prefix}: {self.time_stats.convert_to_duration()}")
        self.has_log_time_stats = True

It is gated twice — on the flag and on rank — which is worth knowing before you grep a TP=8 log and conclude the line does not exist:

python/sglang/srt/managers/scheduler_components/output_streamer.py:L184-L190 SGLang

    def _maybe_log_time_stats(self, *, req: Req) -> None:
        if (
            req.finished()
            and self.ps.attn_tp_rank == 0
            and get_observability().enable_request_time_stats_logging
        ):
            req.log_time_stats()

shell — both engines, fully instrumented (synthetic data only) shell

Run these commands only in an isolated local/test environment with synthetic prompts. Full request logging can expose prompts, responses and identifiers; never use customer data or credentials, restrict access to log files and debug endpoints, redact before sharing, and define deletion/retention. Start one engine at a time, poll readiness rather than sleeping, and stop it before starting the other. Across processes, correlate request IDs and clock domains; interleaved file order is not a causal trace.

$ VLLM_LOGGING_LEVEL=DEBUG vllm serve meta-llama/Llama-3.2-1B-Instruct \
    --enable-log-requests --max-log-len 256 2>&1 | tee vllm.log

$ SGLANG_LOG_MS=1 SGLANG_LOG_FORWARD_ITERS=1 python3 -m sglang.launch_server \
    --model-path meta-llama/Llama-3.2-1B-Instruct \
    --log-level debug --log-requests --log-requests-level 3 \
    --enable-request-time-stats-logging --decode-log-interval 1 2>&1 | tee sgl.log

SGLANG_LOG_MS is not optional

SGLang's default datefmt is "%Y-%m-%d %H:%M:%S" — whole seconds. Without SGLANG_LOG_MS=1 every hop delta in your table rounds to 0 ms or 1000 ms and the timing half of the lab is unusable. The millisecond field is spliced in at python/sglang/srt/utils/common.py:L2338-L2339. To get file and line as well, take the other branch: point SGLANG_LOGGING_CONFIG_PATH at a dictConfig JSON with %(pathname)s:%(lineno)d in its format (python/sglang/srt/utils/common.py:L2328-L2337).

Part B — send one request and annotate the log

shell — one streaming request, then the hop table shell

$ python3 run.py --mode send --engine vllm --url http://localhost:8000 \
    --model meta-llama/Llama-3.2-1B-Instruct --max-tokens 32 --frames

$ python3 run.py --mode annotate --engine vllm --log vllm.log
$ python3 run.py --mode annotate --engine sglang --log sgl.log --unmatched

--mode send reports two TTFTs on purpose: from the first frame that carried content, and from the first frame at all. They differ, and the difference is a real bug in a lot of client code. vLLM's stream generator explicitly emits and then suppresses empty chunks under chunked prefill; a client that timestamps the first SSE frame reports a TTFT that is too low. See §9.3, "The first chunk is empty and you filtered it out".

Part C — ground truth, when the log is not enough

A log line only exists where somebody wrote one. For the hops nobody logs — schedule(), allocate_slots, update_from_output — vLLM has a blunter instrument that prints the answer this lab is asking for, in the format this lab is asking for:

vllm/logger.py:L271-L287 vLLM

                last_func_name = ""
            with open(log_path, "a") as f:
                ts = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f")
                if event == "call":
                    f.write(
                        f"{ts} Call to"
                        f" {func_name} in {filename}:{lineno}"
                        f" from {last_func_name} in {last_filename}:"
                        f"{last_lineno}\n"
                    )
                else:
                    f.write(
                        f"{ts} Return from"
                        f" {func_name} in {filename}:{lineno}"
                        f" to {last_func_name} in {last_filename}:"
                        f"{last_lineno}\n"
                    )

One file per process per thread, named after the pid and the thread id, under a temp directory:

vllm/config/vllm.py:L796-L812 vLLM

    def enable_trace_function_call_for_thread(self) -> None:
        """
        Set up function tracing for the current thread,
        if enabled via the `VLLM_TRACE_FUNCTION` environment variable.
        """
        if envs.VLLM_TRACE_FUNCTION:
            tmp_dir = tempfile.gettempdir()
            # add username to tmp_dir to avoid permission issues
            tmp_dir = os.path.join(tmp_dir, getpass.getuser())
            filename = (
                f"VLLM_TRACE_FUNCTION_for_process_{os.getpid()}"
                f"_thread_{threading.get_ident()}_at_{datetime.now()}.log"
            ).replace(" ", "_")
            log_path = os.path.join(
                tmp_dir,
                "vllm",
                f"vllm-instance-{self.instance_id}",

That per-process, per-thread split is the process boundary, on disk. A hop that appears in the API-server file and not in the EngineCore file crossed ZMQ, and you did not have to infer it.

shell — the slow, exact way shell

$ VLLM_TRACE_FUNCTION=1 VLLM_LOGGING_LEVEL=DEBUG \
    vllm serve meta-llama/Llama-3.2-1B-Instruct --enforce-eager

$ python3 run.py --mode send --engine vllm --max-tokens 4      # ONE small request
$ python3 run.py --mode calltrace --trace-dir /tmp/$USER/vllm
$ python3 run.py --mode calltrace --trace-dir /tmp/$USER/vllm --filter '' --limit 200

Read the warning it prints

The tracer's own log line says it: "It will record every function executed by Python. This will slow down the code." (vllm/logger.py:L305-L310). Send one request with a handful of tokens. Under load this writes gigabytes and the engine stops resembling itself, which makes any timing you take from it fiction. SGLang has no in-tree equivalent — see the flag below.

Unverified — SGLang has the tracer but not the wiring

SGLang carries a byte-identical port of vLLM's tracer, down to the "Call to {func_name} in {filename}:{lineno} from ..." line format, at python/sglang/multimodal_gen/runtime/utils/logging_utils.py:L431-L451. At 7d89325 it is unreachable from the serving path: nothing under python/sglang/srt/ calls enable_trace_function_call, its root_dir defaults to the diffusion package rather than srt/, and SGLANG_DIFFUSION_TRACE_FUNCTION is declared at python/sglang/multimodal_gen/envs.py:L23 and never read outside that file (grep -rn over python/sglang/ returns only the declaration and the registry entry). I read python/sglang/srt/utils/'s logging and profiling modules and found no serving-side equivalent. Because the format matches, --mode calltrace parses its output unchanged — see exercise 5's second half. For SGLang out of the box, Part C is py-spy dump or a debugger, and Part B's hop table is the deliverable.

§3

What to expect

The finished table for vLLM has eight rows and two processes; SGLang's has nine rows and three. Both are printed by --mode map, so the point is not to memorise them but to check them — against your own log, and against §9.3's fourteen-hop trace.

The lines that will be missing, and why — read at a556f3f / 7d89325

Hop with no line	Engine	Reason
`EngineCore waiting for work.`	vLLM	`logger.isEnabledFor(DEBUG)` guards it (`vllm/v1/engine/core.py:L1428-L1430`). At INFO you get neither this nor `EngineCore loop active.`, and the process boundary becomes invisible.
`ReqTimeStats(rid=...)`	SGLang	Needs `--enable-request-time-stats-logging` and `attn_tp_rank == 0`.
`Decode batch, ...`	SGLang	Emitted once per `--decode-log-interval` iterations, default 40 (`python/sglang/srt/server_args.py:L1642-L1646`) — not once per step. A 32-token generation may produce none at all.
`Aborted request(s) ...`	vLLM	Only on a disconnect or a stop string. A clean `max_tokens` finish never aborts, so its absence is correct.
anything from the scheduler	vLLM	vLLM's V1 scheduler is almost silent per request; what it does emit is the aggregate stats line every `VLLM_LOG_STATS_INTERVAL` seconds (`vllm/v1/metrics/loggers.py:L310-L313`), which is a sampler, not a trace.

On timing, expect the engine's own numbers and yours to disagree, in a specific direction. Both engines start the request clock after FastAPI has parsed and validated the body, and stop it at yield rather than at the socket. SGLang's queue_duration and forward_duration together are strictly less than your client-side latency, and the residual is JSON parsing, ZMQ, detokenisation in a third process, and the ASGI write. That residual is the subject of §9.3's latency-accounting table, whose right-hand column reads "unmeasured" — this lab is where you fill it in.

Two ITL signatures are worth recognising in the --mode send output. A long tail of near-zero gaps with one large spike is coalescing: the frontend fell behind and the per-request mailbox merged deltas, so the tokens survived and the timestamps did not. On SGLang, twenty or more queued chunks also prints the warning at python/sglang/srt/managers/tokenizer_manager.py:L1619-L1624; vLLM merges on put and therefore has nothing to warn about. A regular sawtooth instead means --stream-interval is above 1 and the engine is emitting every nth token deliberately.

§4

Exercises

Run --mode annotate on a vLLM log and compare this lab's file:line column against the [file:line] prefix vLLM itself printed. Where they disagree, one of them is wrong. Which, and how do you tell?
Read the file. Start vLLM with --enable-log-requests but leave VLLM_LOGGING_LEVEL at its default. Predict which of the two lines in request_logger.py:L44-L68 you get, then read request_logger.py:L21-L33 and say what the server tells you about your own configuration at startup.
Predict, then verify. On SGLang, send one request with 32 output tokens at the default --decode-log-interval. How many Decode batch lines appear? Now set --decode-log-interval 1 and predict the count before re-running.
Predict, then verify. Run a vLLM server at VLLM_LOGGING_LEVEL=DEBUG and find the EngineCore waiting for work. / EngineCore loop active. pair around your request. What does the interval between them measure, and what does it not measure? Then explain why the pair appears at most once even if you send ten requests back to back.
Design. You need per-hop timing on SGLang in production, where --log-requests-level 3 would print customer prompts to disk. Propose a configuration that gets the timing without the content, name the two flags that do it, and say what you lose. Then, separately: SGLang ships vLLM's tracer verbatim but never calls it. Without editing the pinned tree, how would you turn it on for python/sglang/srt/, and what would you point root_dir at?

Answers

vLLM's own prefix is authoritative — it comes from the LogRecord, so it cannot drift. This lab's column was typed by a human reading the tree and can. If they disagree, the lab is wrong; the useful case is when they disagree by one or two lines, which means the file moved under the citation. That is precisely the failure mode tools/check_quotes.py exists to catch in the chapters, and it is why SGLang, whose format carries no line number, is the harder half of this lab.
Only the logger.info("Received request %s: params: ...") line: the logger.debug branch above it is guarded by logger.isEnabledFor(logging.DEBUG). The constructor anticipates this and says so — it emits "`--enable-log-requests` is set but the minimum log level is higher than DEBUG. Only limited information will be logged to minimize overhead. To view more details, set `VLLM_LOGGING_LEVEL=DEBUG`." once, at startup. Read your own startup log before concluding a flag did nothing.
Zero, or at most one. The default interval is 40 decode iterations and the request runs 32, so the counter may never reach the threshold during its lifetime. At --decode-log-interval 1 you get one line per decode step the scheduler ran, which is not the same as one per token of your request: the line reports the whole batch, and if another request is running you will see steps that predate and outlive yours.
It measures the wall time the EngineCore busy loop spent blocked on an empty input queue — so its end is when your request crossed the process boundary, but its start is only "when the engine last went idle". It does not measure ZMQ transit, because the pair brackets the wait, not the send. It appears at most once because waited is a local flag set on the first empty poll and the loop stops going idle as soon as there is work: with ten requests in flight the engine never re-enters the wait, so nothing more is printed until it drains.
--log-requests --log-requests-level 0 plus --enable-request-time-stats-logging. Level 0 adds text, input_ids, sampling_params and the multimodal fields to the skip list (python/sglang/srt/utils/request_logger.py:L198-L211), so you keep the rid, the lengths and the Receive/Finish timestamps but never write a prompt. You lose the ability to reproduce the request from the log, and you lose sampling parameters — which matters, because a determinism or quality report that cannot say what temperature was is not a report. (Level 1 keeps sampling parameters and still skips the prompt, which is usually the right trade.) One cost you did not ask for: hop 1 vanishes, because log_openai_received_request is gated on log_requests_level >= 2 (python/sglang/srt/entrypoints/openai/serving_base.py:L88-L90), so at level 0 or 1 the OpenAI-shaped payload is never logged and your table starts at hop 2.

For the tracer: import it from outside the tree and call it yourself, before the server starts — a two-line launcher, or a sitecustomize.py on PYTHONPATH, that calls enable_trace_function_call(path, root_dir=os.path.dirname(sglang.srt.__file__)). Pointing root_dir at srt/ rather than letting it default is the whole trick; with the default it filters out every frame you care about and writes an empty file. Note the scope this buys you: sys.settrace is per-thread and set in the process that calls it, so a launcher-level call covers the HTTP worker and nothing else. The scheduler and detokeniser are separate processes and need the same call at their own entry points.

§5

Key takeaways

Both engines already emit enough to trace a request end to end; neither does it by default, and both need two flags rather than one — the feature and the verbosity.
vLLM prints the emitting file:line on every log line and SGLang prints neither, which is why the SGLang half of the hop table has to be maintained by hand and re-checked against the source every time the SHA moves.
Frequency-gated lines are not per-request lines. Decode batch fires every 40 iterations by default and the aggregate stats line every 10 seconds — both are samplers, and reading them as a trace is how a request's history acquires gaps that were never there.
The engine's own TTFT starts after parse and stops at yield. Yours starts at the socket. Use the engine's for relative comparisons between runs and never against an SLO.
VLLM_TRACE_FUNCTION=1 is the only instrument wired into either engine's serving path that prints file:line for hops nobody logged, and its per-process, per-thread files make the ZMQ boundary visible without inferring it. It is also slow enough to invalidate every timing you take under it, so use it for structure and the annotated log for timing.