Request-level profiler

Request-level profiler#

sglang-omni ships two complementary profilers that share the same run_id and are controlled by the same HTTP surface:

  • a request-level event recorder that writes a JSONL stream of per-request milestones (admission, preprocess, encoder, prefill, first token / first code chunk, hops, terminal response) — used to reconstruct a single request’s end-to-end timeline and to aggregate stage / hop costs across a batch;

  • a torch profiler that produces a Chrome trace of kernel-level CPU / device activity — used to drill into a specific window once the event recorder has identified where the time is going. Activities are CPU plus whatever device activity this torch build reports via torch.profiler.supported_activities() — CUDA on NVIDIA / ROCm, XPU on Intel.

Most diagnostics use the event recorder. The torch profiler is opt-in for deeper kernel investigation.

Event model#

Every instrumentation point records one logical event. After the run is deactivated, each retained event is serialized as one line of JSON in a per-process JSONL file. The shape is:

{
  "request_id": "req-123",
  "stage": "thinker",
  "event_name": "scheduler_first_emit",
  "timestamp_ns": 1717000000123456789,
  "run_id": "demo-run",
  "pid": 42,
  "metadata": {"chunk_id": 0}
}

Files are written under <event_dir>/events_<stage>_<pid>.jsonl. Multiple co-located stages in the same OS process share one JSONL file — the filename uses the first stage to start, and the per-event stage field identifies the owner. The views layer merges files from every process by request_id. The writer creates each JSONL file exclusively; an existing file is a storage failure rather than an append target.

The recorder uses one bounded producer-private buffer per OS thread and one low-priority writer thread per process, created only after the run stops. Each producer can retain 1024 events by default. event_buffer_capacity overrides that per-producer limit for one recording; any positive integer is accepted, with no hard-coded maximum. The number of producer buffers remains separately bounded at 16 per process. An omitted value uses the recorder’s constructor default on each new run, and capacity cannot change during an active run. Buffers grow dynamically as events are retained; event objects are not preallocated.

To estimate memory, multiply the per-recording event capacity by each process’s producer-buffer count and sum the results:

retained_events <= sum(process producer_buffer_count * event_buffer_capacity)
approximate_memory = retained_events * estimated_bytes_per_event

Bytes per event depends on the workload and Python object contents; measure it when accurate memory budgeting matters. A larger capacity can increase post-stop serialization and flush time. Overflow still drops events and marks the trace incomplete. Linux SCHED_IDLE is best effort and cannot guarantee zero Python GIL or CPU interference.

Each OS thread registers its buffer once under a small control lock. Cached producers then capture timestamps, stage attribution, and bounded metadata without acquiring that lock. Buffer admission is the stop cutoff: the post-stop writer waits for admitted operations, while a capture that has not reserved a buffer before stop is ignored and does not consume its snapshots. RequestEventBuffer uses the same producer buffer: deferred records count against the same event limit and are snapshotted once. During capture, producers do not start a writer, open files, serialize JSON, flush, or enqueue into a shared queue. JSON serialization, file operations, and flushes run only after deactivation.

Events do not exist on disk until the run has stopped. Consumers must treat a missing sidecar, or a sidecar with complete: false, as incomplete.

Each finalized run also attempts to write run_status_<pid>.json beside the JSONL file. When publication succeeds, it records run_id, pid, stages, the effective event_buffer_capacity, producer_buffer_count, and producer_buffer_event_counts (accepted plus dropped records per registered buffer), followed by event counters, metadata snapshot and truncation counts, serialization/write/finalization failures, incomplete_reasons, and complete; that flag has completeness_scope set to event_storage and does not claim semantic timing or cross-process coverage. The sidecar also records whether the writer obtained SCHED_IDLE or used the default scheduling policy. RequestEventFinalization.wait() reports whether the status sidecar was published; inspect complete separately to determine whether the trace is complete. Producer-buffer overflow, writer failure, metadata snapshot failure, metadata truncation, and a missing or failed drain mark the run incomplete. Consumers must not treat a missing sidecar, or a sidecar with complete: false, as a complete trace.

Metadata is intentionally limited to scalars, JSON-like mappings/sequences, and tensor-like values represented by shape/dtype/device summaries. Tensor contents are never materialized by the producer. Unsupported values are rejected without calling arbitrary repr; the serving path records a metadata snapshot failure and continues. Strings are bounded, and bytes are unsupported rather than copied into the trace. Bounded depth/item truncation is recorded in the event metadata and in the status sidecar rather than reported as complete.

Standard event names#

The recorder always attaches the active stage name to every event, so the same scheduler_prefill_start becomes “thinker prefill start” when emitted from the thinker process and “talker prefill start” when emitted from the talker process. scheduler_queue_enter marks a built request entering the scheduler queue; scheduler_prefill_start is emitted later, when the request’s first executable prefill / extend batch is selected.

Pipeline milestone

Concrete event

Source

Request admission

request_admission

Coordinator._submit_request

Preprocessing start / end

preprocess_start / preprocess_end

model preprocessor __call__

Encoder start / end

encoder_start / encoder_end (metadata modality, batch_size)

image / audio encoder executors

Aggregate ready

stage_aggregate_ready

Stage._on_data_ready after InputHandler.receive returns a merged payload

Thinker prefill start

scheduler_prefill_start (stage = thinker)

OmniScheduler.run_batch

Thinker first token

stage_first_stream_chunk_sent (stage = thinker)

Stage._send_stream_to_target / _send_stream_to_coordinator

First stream chunk to client

stage_first_stream_chunk_sent (terminal stage → coordinator)

same

Talker request build execution start / end

scheduler_request_build_start / _end (stage = talker)

OmniScheduler._run_request_builder

Talker prefill start

scheduler_prefill_start (stage = talker)

same

First code chunk

stage_first_stream_chunk_sent (stage = talker)

Stage._send_stream_to_target

Code2Wav first audio

code2wav_first_audio

Code2WavScheduler.keep_audio (every decoded or flushed window)

Terminal response

terminal_response

Coordinator._handle_completion

Supporting events used for finer-grained breakdown:

Layer

Event

Notes

Coordinator

coordinator_stream_received

Each StreamMessage received on the coordinator

Stage

stage_input_received

Submit or relay payload accepted (metadata from_stage)

Stage

stage_dispatch

Scheduler inbox put

Stage

stage_complete

Scheduler result routed onward (metadata terminal, next)

Stage

stage_hop_sent

Payload DataReadyMessage sent to next stage

Stage

stage_stream_chunk_sent

Each stream chunk (metadata to_stage, chunk_id, modality)

Stage

stage_stream_chunk_received

Each stream chunk materialized and ready for the receiver scheduler, including coordinator terminal chunks

AR scheduler

scheduler_queue_enter

Built request entered the scheduler queue

AR scheduler

scheduler_first_emit

First stream_output_builder emission per request

AR scheduler

session_kv_snapshot

Streaming-session KV after a completed Unit has checkpointed: logical/session-window lengths, allocated/available pool positions and cache-evictable positions

Code2Wav

code2wav_decode_start

Each window’s decode start: trigger, start/end/new/context/window frames, rows (the windows its replay decodes together), active and threshold-ready requests, inbox depth

Code2Wav

code2wav_decode_launched

Pipelined window whose vocoder work and asynchronous D2H copy have been enqueued; includes execution mode, window/new-frame counts and rows

Code2Wav

code2wav_decode_end

Repeats start metadata and adds the current decode’s audio_samples plus execution metadata; output-overlap runs also include pipelined and the previous window’s post-EOS-scan d2h_wait_ns

Drama 3 vocoder

drama3_vocoder_window_decode_started

Each streaming window’s decode start, and the tail flush’s when frames remain after the last window: window_index, chunk_id (the stream chunk that completed the window, -1 for frames only the final result holds and for the tail), is_final, emitted_frames, decoded_frames (with the overlap context) and emitted_audio_s (audio the earlier windows produced)

Drama 3 vocoder

drama3_vocoder_window_decode_finished

Repeats the start metadata once the window’s audio chunk is built. The span from the start event is the scheduler thread’s wall time for the window, not GPU decode time alone: it includes copying the audio to the host and serializing it, and for the tail flush, building the request’s final result

Read d2h_wait_ns narrowly. With output overlap on, the lazy codec-EOS scan calls .tolist() on the staged frame heads, which is itself a host synchronization point, and it runs before code2wav_decode_start. So d2h_wait_ns measures only the residual wait left after that scan, not the whole overlap interval. Use the process-wide CUDA API trace as the load-bearing measurement of whether blocking synchronization was actually removed.

Custom callsites can call sglang_omni.profiler.event_recorder.emit(...) to add domain-specific events. Events from inactive recorders are no-ops, so instrumentation sites do not need to guard against the disabled case.

Full Duplex session Unit metrics#

Pass event_buffer_capacity to POST /start_request_profile, or to POST /start_profile when request-event recording is enabled. For example:

curl -X POST http://127.0.0.1:8000/start_request_profile \
  -H 'Content-Type: application/json' \
  -d '{"run_id":"performance_test","event_dir":"/tmp/performance_test/events","event_buffer_capacity":1500}'

The value applies per producer for that run and can be changed on the next profiling run without restarting the server.

Enable the existing request event recorder with POST /start_request_profile and stop it with POST /stop_request_profile. The JSONL files then include a small session vocabulary that can be converted with sglang_omni.profiler.duplex_metrics.build_duplex_session_metrics.

Each session-specific event carries its request_id; the report uses session metadata to name the Unit as (session_id, session_open_index, input_seq). Unit lifecycle and start events carry the input modality and media clock. Output events carry the output sequence, modality, media clock, duration, and kind. Payload bytes are never stored.

session_kv_snapshot is emitted after a completed AR Unit releases its request row into the streaming-session cache. Its cache_type and kv_allocator_type fields identify the active cache path. session_logical_length is the record’s logical sequence length and can exceed the physical pool for a sliding-window model. session_swa_evicted_length is the record’s SWA eviction cursor, and session_window_kv_positions is their difference. kv_pool_capacity_positions, kv_pool_allocated_positions, available_kv_positions, and evictable_kv_positions describe the allocator at that boundary. For a single PureSWA session with radix caching disabled, the session-window and pool-allocated counts must agree; their plateau, not the logical length or process GPU memory, shows whether the pool reuses expired slots during a long call.

The event boundaries have these meanings:

  • session_unit_ready is declared by the ingress owner when a logical Unit has all required input needed to run without waiting for more required input. It is modality-independent and is not inferred by the profiler from PCM, frames, or any other payload boundary.

  • session_unit_admitted is emitted after the coordinator accepts an append; a rejected QueueFullError has no event.

  • stage_dispatch is the existing stage ingress observation used as the queue boundary for a non-AR session Unit.

  • scheduler_queue_enter and scheduler_prefill_start are the existing AR scheduler boundaries. For an AR Unit, they replace stage_dispatch and session_stage_started for queue and start timing.

  • session_stage_started marks execution after per-session ordering for a SessionScheduler stage.

  • session_stage_bypassed is the authoritative AR decision that an input Unit completed without generation. Its reason metadata identifies the bypass path, such as generation_bypassed or finish_input.

  • stage_complete is the existing stage result observation used as the finish boundary for a session Unit.

  • session_output_emitted marks a model content chunk entering the coordinator output buffer. input_done is a lifecycle completion and is recorded as session_unit_finished, not as model output.

The report joins generic stage events by request_id. For AR stages, queue_ms is scheduler_queue_enter -> scheduler_prefill_start; for SessionScheduler stages, it is stage_dispatch -> session_stage_started. service_ms is the observed execution-start to stage_complete interval, not pure GPU compute time. A stage is observed when its selected boundaries are complete, bypassed when session_stage_bypassed is present, and incomplete when a boundary is missing. Bypassed stages retain their timestamp and reason; queue and service durations remain null. handoff_from_previous_ms ends at the current stage’s generic stage_dispatch boundary. The recorder carries the input media clock for later benchmarking, but this slice does not claim semantic input-to-output latency, playback underrun, or deadline misses.

Readiness is observed only while the request event recorder is active. The internal observation carries that profiler run ID, and admission emits the ready event only when the same run is still active; a run rotation leaves the admitted-based values valid while ready-based values remain unavailable.

The report names the ready-based values explicitly: ready_to_admitted_ms, ready_to_first_output_ms, and ready_to_finished_ms. They measure ingress wait, ready-to-first-output, and ready-to-finish directly from their event timestamps. The admitted-based decomposition remains available as admitted_to_first_output_ms and admitted_to_finished_ms; those intervals start when CoordinatorSessions.append_session accepts the Unit. They exclude any earlier SessionRuntime.pending_pcm buffering before submission and do not claim producer-ready, client/network, semantic-response, playback, or deadline latency. For a complete Unit, ready_to_first_output_ms is the ready-to-admission wait plus the post-admission time to first output; each value is derived per Unit before aggregation.

The SessionScheduler scalar hook emits one start event per Unit immediately before append. BatchedSessionHooks.append_batch emits one event per row with one shared directly observed batch-start timestamp.

Active-stage attribution#

emit(...) accepts an explicit stage=... parameter; when the caller can’t plumb the stage name down (preprocessor __call__, encoder callables, OmniScheduler / Code2WavScheduler internals), it can pass stage=None and the recorder fills it in from the per-thread / per-task active stage.

Stage._run_scheduler binds set_active_stage(self.name) on the scheduler thread before invoking the scheduler. The binding uses both a threading.local slot (for plain threading.Thread workers) and a contextvars.ContextVar (so it propagates through asyncio.to_thread / loop.run_in_executor, which copy contextvars but not thread-local). Explicit stage=... on emit always wins; the active-stage binding is only consulted when the caller passes stage=None.

To bind / unbind manually from your own thread:

from sglang_omni.profiler.event_recorder import set_active_stage, reset_active_stage

token = set_active_stage("my_stage")
try:
    ...
finally:
    reset_active_stage(token)

reset_active_stage(None) is the “scrub” form (used by test fixtures) and clears both the thread-local slot and the contextvar.

Lifecycle#

Intended use and assumptions: Request event profiling is an opt-in tool for controlled performance investigations, not an always-on logging or recovery service. Use a unique run_id and a fresh, empty event_dir for each recording. Only one run can be active or draining in a process. A new run is rejected until the prior post-stop writer has finished; this prevents a new measured window from sharing a writer with the old one.

The recorder is process-local. It is started on every stage and on the coordinator when POST /start_profile (or POST /start_request_profile) is hit:

  1. Launcher receives the HTTP request.

  2. Coordinator starts its local recorder pointed at <event_dir>.

  3. Launcher broadcasts ProfilerStartMessage over ZMQ to every stage, carrying both the torch trace template and the event_dir.

  4. Each stage joins the per-process recorder. In a shared-process topology the first stage to call start() wins the filename; every subsequent stage in the same process writes to the same file and the per-event stage field disambiguates.

  5. On POST /stop_profile, every process deactivates its current run without joining the writer on its serving/control loop. Accepted events still drain and the writer creates the status sidecar during finalization. The HTTP response is not an acknowledgement that every process has finalized its artifact; inspect every expected process sidecar before analysis.

The Python API is nonblocking by default: RequestEventRecorder.stop() is equivalent to stop(wait=False). It deactivates promptly and returns the event path; it does not wait for disk finalization. Administrative code may use stop(wait=True), the returned RequestEventFinalization handle, or wait_for_finalizations(timeout_seconds=...). Serving control paths use stop(wait=False) or deactivate(). A stalled or failed writer cannot block serving, but the resulting status must be treated as incomplete.

POST /stop_profile and POST /stop_request_profile accept an optional run_id field. When omitted, the request is a wildcard: every stage stops whatever profiler session is currently active. When set, only stages whose active run matches stop. This makes the common case (caller didn’t specify a run_id on either start or stop) work without ceremony.

The torch profiler and the event recorder share a run_id. Setting enable_torch=false on the start request records JSONL events without paying for a kernel trace.

Generating reports#

Use the views module directly:

from sglang_omni.profiler.views import build_report
report = build_report("/tmp/profiles/demo-run/events")
print(report["request_count"], len(report["stage_breakdown"]))
print(report["completeness"]["state"])

build_report validates the process-local run_status_<pid>.json sidecars against the supplied event filenames. It reports complete, incomplete, or unknown; missing or malformed sidecars are always unknown with complete: false. This checks only the files supplied to the report. A directory containing one TP rank’s files can establish local event-storage completeness for that rank, but cannot establish that every expected TP rank or process is present. Global completeness requires an expected-process inventory, which this report does not provide.

…or via the CLI:

python -m sglang_omni.profiler /tmp/profiles/demo-run/events --format table
python -m sglang_omni.profiler /tmp/profiles/demo-run/events --format json --out report.json

The CLI / build_report returns three views derived from the same event stream:

  1. Timeline — per-request event list with t_rel_ms anchored at admission.

  2. Stage breakdown — (open_event, close_event) interval durations aggregated per stage (count, total, avg, p50, p95, max). The same opener can participate in multiple pairs (e.g. scheduler_prefill_start closes against both scheduler_first_emit AND stage_first_stream_chunk_sent); every pair gets its own pending stack so a close event for pair A does not consume the opener of pair B.

  3. Hop breakdown — stage_hop_sent / stage_input_received and stage_stream_chunk_sent / stage_stream_chunk_received durations per (source, destination, kind). Terminal stage stream chunks are paired the same way with destination coordinator.

Hop pairs match across processes by (request_id, source_stage, dest_stage, chunk_id?), so a single request’s path through subprocesses can be reconstructed even when each stage runs in its own process.

Torch profiler#

The torch profiler runs alongside the event recorder when enable_torch=true (the default for /start_profile). It records continuously between start() and stop() — no schedule(...), no step() requirement — and exports a Chrome trace *.trace.json.gz on stop. CPU ops are recorded from every thread in the process, including scheduler threads that existed before start().

The expensive introspection flags are opt-in via env vars so the default trace stays small enough to load in chrome://tracing or ui.perfetto.dev:

Env var

Effect

SGLANG_TORCH_PROFILER_RECORD_SHAPES=1

Record input tensor shapes per op

SGLANG_TORCH_PROFILER_PROFILE_MEMORY=1

Record tensor memory allocation / free events. Disables all-thread capture: only the thread that starts the profiler is recorded, so worker thread CPU ops and memory events are excluded

SGLANG_TORCH_PROFILER_WITH_STACK=1

Record the Python (and C++) call stack per op

SGLANG_TORCH_PROFILER_WITH_FLOPS=1

Estimate FLOPs per op

With all four off (the default), a typical 10-sample MMMU run produces a trace in the tens of MB. With all four on, the same workload can produce a multi-GB trace — only opt in when you need that specific information.

HTTP surface#

Method

Path

Body

Notes

POST

/start_profile

{"run_id": ?, "trace_path_template": ?, "event_dir": ?, "enable_torch": true | false, "config": ?}

Starts torch trace + event recorder. run_id auto-generated if omitted.

POST

/stop_profile

{"run_id": ?}

Stops torch trace + event recorder. Omitting run_id is a wildcard (“stop whatever’s active”).

POST

/start_request_profile

{"run_id": ?, "event_dir": ?}

Event recorder only — no torch trace. Lower overhead; still intended for short, opt-in captures.

POST

/stop_request_profile

{"run_id": ?}

Same wildcard semantics as /stop_profile.

Example: record cheap events on every request without a kernel trace:

curl -X POST http://localhost:8000/start_request_profile \
     -d '{"run_id":"demo","event_dir":"/tmp/profiles/demo/events"}'
# … run traffic …
curl -X POST http://localhost:8000/stop_request_profile -d '{}'
python -m sglang_omni.profiler /tmp/profiles/demo/events --format table

Discipline#

  • Profiling must never break serving. While active, the emitter performs no JSON serialization or file I/O, takes no recorder-wide lock after its one-time producer registration, and never waits for capacity or a writer. Producer-buffer overflow and bounded registration failures are counted as drops; writer failures are recorded in the run status.

  • Finalization is deferred. The writer starts only after the last local stage releases the run or an administrative stop deactivates it. It waits for in-flight producers to quiesce before freezing buffers, then flushes and closes the JSONL file before publishing the status sidecar. A new run is rejected while this drain is in progress.

  • Tensors and large blobs stay out of event metadata. Keep metadata to small scalars (ids, counts, durations, modality, error strings). The recorder enforces this defensively: if a tensor / numpy array ends up in metadata, the JSON default serializer emits a summary ({"__tensor_summary__": true, "type": ..., "shape": [...], "dtype":   "...", "device": "..."}) instead of materializing the contents. CPU 0-D tensors / numpy scalars still serialize as plain scalars; device-backed 0-D values remain summaries.

  • Event naming. Lowercase snake_case, prefix with the layer that owns the event (stage_*, scheduler_*, encoder_*, etc.). Use the stage name (not the event name) to distinguish “thinker prefill start” from “talker prefill start”.