feat(profiling): adopt the Dynamo Benchmark Playbook nsys recipe for TRT-LLM workers

[nv-yna]

What

profiling.type: nsys on TRT-LLM workers now emits the capture recipe from the Dynamo Benchmark Playbook §9.5.1.1 "Dynamo + TRTLLM" instead of -t cuda,nvtx,ucx --cuda-graph-trace=node:

nsys profile --force-overwrite=true -t cuda-sw,nvtx,python-gil --cuda-graph-trace=graph
  --sample=none --cpuctxsw=none --python-sampling=false --python-sampling-frequency=1000
  --gpu-metrics-devices=none --flush-on-cudaprofilerstop=false --cuda-flush-interval=0
  -c cudaProfilerApi --capture-range-end=stop [extra_nsys_args] --kill none --wait all
  -o /logs/profiles/<mode>/<leader>_<mode>_w<i>_profile_rank%q{SLURM_PROCID}
  trtllm-llmapi-launch python3 -m dynamo.trtllm ...

Why (from the playbook campaign on nsys 2026.3.x / VR200 disagg): plain -t cuda selects the HES hardware trace and SIGSEGVs the KV transceiver's device-to-device cudaMemcpyAsync; --cuda-graph-trace=node hides CUDA-graph decode work (0.3 % GPU busy reads as idle); --sample=process-tree wedged workers at cudaProfilerStop; finalise-at-exit never produced a report, -c cudaProfilerApi --capture-range-end=stop does. Each flag is documented with its reason in docs/profiling.md and the field comments.

New ProfilingConfig knobs relax the recipe explicitly: nsys_trace, nsys_cuda_graph_trace, nsys_sample, nsys_cpuctxsw (context switches without IP sampling is the safer experiment; both need kernel.perf_event_paranoid <= 2), nsys_python_sampling(+_frequency), nsys_gpu_metrics_devices. Validation checks the enum-like values and warns when IP sampling is requested. nsys-time shares the trace flags with --delay/--duration.

Worker env gains TLLM_PROFILE_LOG_RANKS (new log_ranks, default all), DYN_ENABLE_RUST_NVTX=1 (effective on a wheel built with the nvtx cargo feature) and NVTX_INJECTION64_PATH when nvtx_injection_path is set (TRT-LLM containers ship it at /usr/local/cuda-0.gpgpu/NsightSystems-cli-<ver>/target-linux-sbsa-armv8/libToolsInjection64.so). The profiling: block remains independent of observability.enabled, so the capture cost can be measured against a default-visibility run.

First run: hecate 570810 (2026-09-10)

AgentX 8-node recipe (3 prefill + 1 decode TP8 workers over 2 nodes each), default visibility, prefill: 1200-1300, decode: 6000-6600 (sized from the reference run's iteration rates: ~2.7 prefill it/s, 8-20 decode it/s).

• All four workers launched under the recipe (sweep log), env carried the window, TLLM_PROFILE_LOG_RANKS=all, DYN_ENABLE_RUST_NVTX=1, NVTX_INJECTION64_PATH. Workers loaded normally; benchmark started at +16 min, exactly like the unprofiled run.
• Profiling started at iteration 1200 on all 8 ranks of each prefill worker at 21:08:53, ... iteration 6000 on all 8 decode ranks at 21:09:47; 32 of 32 .nsys-rep files (71–75 MB each) landed under logs/profiles/{prefill,decode}/ within ~50 s of each window closing, while the benchmark kept running (--kill none).
• Scheduling shape during the window matched the unprofiled run at the same offset (one scheduled request per decode iteration, 8–11 it/s), so the capture did not starve the pipeline. Cost visible in the iteration log: report generation runs in-line and stalled a decode rank for 1.8 s and 4.4 s around cudaProfilerStop.
• Compute nodes report kernel.perf_event_paranoid = -1, so nsys_cpuctxsw: process-tree is available there for a follow-up run.

Report validation with nsys stats (inside the container, the workstation's 2025.5 nsys refuses 2026.3 reports) and the throughput comparison against the unprofiled run follow when the job completes.

Outcome of runs 1 and 2: capture works everywhere, but a worker hangs minutes after its window (n=2)

run	reports	what happened after the capture windows closed
570810	32/32, validated with in-container nsys stats (exact 1200-1299 window, 111 kernel families, GIL tracer active)	decode worker: all 8 ranks stopped at iter 7624, 229 s after its window; Hang detected after 300 seconds on ranks 2/3 in tp_allgather; MPI_Abort, exit 137
570978	32/32 (1.8 GB), written 22:47:59-22:48:01	prefill worker 0: all 8 ranks stopped at iter 2324, ~5.5 min after its window; [RANK 2] Hang detected after 300 seconds in communicator.py:378 _serialize_and_exchange_lengths; "hard-killing and propagating to peer ranks", exit 137. Decode reached iter 14323 with no hang and was shut down by the cleanup

Both hangs are in TRT-LLM collective / MPI paths on a worker whose nsys capture had ended minutes earlier; the
same recipe without profiling (job 567529) completed. aiperf aborted its warmup in both runs, so there is no
throughput number for the playbook flag set yet.

Discriminating run 571266 (same recipe, srt-slurm's pre-playbook flag set nsys_trace: cuda,nvtx,
nsys_cuda_graph_trace: node, no python-gil, no NVTX_INJECTION64_PATH): worse. prefill worker 2 died
the moment its capture range opened: all 8 ranks' last log line is iter = 1200 (the start step) and the log ends
with !!!!!!! Segfault encountered !!!!!!! in cuMemcpyHtoDAsync_v2 <- cudaMemcpyAsync <- at::native::copy_kernel_cuda;
exit 137, 0 reports.

So on this stack (nsys 2026.3.0 in the image, CUDA 13.1, VR200): -t cuda hardware tracing segfaults at
cudaProfilerStart, while the playbook's -t cuda-sw,nvtx,python-gil captures reliably (2 x 32 valid reports) but
leaves a worker wedged a few minutes after its window. The playbook's choice of cuda-sw looks deliberate. The
capture path this PR implements works; a completed benchmark with nsys attached is not obtainable here, so the
"performance impact of profiling" number has to come from a stack where the post-capture hang does not reproduce
(or from --capture-range-end=stop-shutdown capture-only runs, which by construction give no throughput).

Also: profiling.frontend (679483e, b5f8ff4)

The nsys prefix only ever wrapped the worker ranks. profiling.frontend {delay_secs, duration_secs, trace} now also
wraps python3 -m dynamo.frontend in nsys profile -t nvtx --delay/--duration --kill none --wait all (time window;
the frontend has no CUDA work and never calls cudaProfilerStart) and exports DYN_ENABLE_RUST_NVTX=1 /
NVTX_INJECTION64_PATH to it, so Dynamo's Rust NVTX ranges land in /logs/profiles/frontend/<node>_frontend_<i>.nsys-rep.

Why the profiled runs hang (log forensics over all 8 hang runs)

• Every hang: the executor thread is in tp_allgather -> safe_allgather -> _serialize_and_exchange_lengths -> comm.Allgather (MPI, host buffers). Only some ranks report it; the silent rank is the one whose Python threads
  cannot run (native code holding the GIL).
• Every hang follows a KV-transfer first-contact between a decode rank and a prefill worker
  (Registering peer in first request to endpoint / Initialized ZMQMessenger(...), i.e. NIXL/UCX peer setup with
  CUDA memory registration) that happens after the nsys capture range has closed. Baseline job 4 formed its
  whole peer mesh by iteration ~1153 (decode) / ~2138 (prefill) and never needed a new connection later. In the
  profiled runs one decode-rank/prefill-worker pair connected late (routing chance): 570810 rank 7 at iter 7433 with
  the window 6000-6600 closed, hang 8 s later at 7624; 572590 at iter 6612, hang at 7624; prefill runs: connections
  at 2115-2310 after the 1200-1300 window, hang at 2317-2324. First-contacts before the window always succeeded,
  in both --capture-range-end=stop (this PR) and repeat (PR feat(profiling): nsight-slurm profiling type (Nsight Cloud for Slurm) #419) modes.
• Working hypothesis: NIXL/UCX's CUDA driver calls from non-Python threads deadlock in nsys's CUDA API interception
  once a range has ended. Two isolation runs are queued: E1 -t nvtx,python-gil (no CUDA interception) and E2
  -t cuda-sw,nvtx (no GIL tracer), both with the frontend profiled.

Validation

• pytest tests/ → 1793 passed, 2 skipped; 14 new tests in tests/test_profiling_playbook.py (recipe flags, time mode, knobs, env, validation, warning).
• Recipe loaded through SrtConfig.Schema and srtctl dry-run on hecate.

Two launcher fixes from the overnight isolation runs (4b03091, a40335f)

• profiling.teardown_grace_secs (default 180): ProcessRegistry.cleanup() is now two-phase (SIGTERM every process, then wait for each up to its own terminate_timeout, then SIGKILL). nsys-wrapped worker sruns and the profiled frontend get the grace; everything else keeps 10 s. Needed when a capture range is still open at exit — nsys writes that report only after the engine exits.
• srtctl.core.nsys_keepalive: nsys profile --delay D --duration T --kill none <app> exits after writing its report; under Slurm nsys is the srun task, so the step ends and slurmstepd kills the orphaned app. Verified on hecate 595056: frontend report 02:09:45, frontend step COMPLETED (0:0) 02:09:48, decode step COMPLETED 02:09:52, benchmark aborted. The wrapper runs nsys in the background, records its child PID, waits for nsys, then keeps the task alive while the child runs (exit code = nsys's). Applied to profiling.frontend (always time-windowed) and to nsys-time workers; iteration-based captures are untouched. Tests execute the generated script against a fake nsys.

Hang forensics, second pass (verified in the logs)

• The post-window hang is at exactly stop_step + 1024 iterations in every hang run: decode 6600 → 7624 (path A stop and path B repeat), prefill 1300 → 2324 (4 runs; 2319/2317 in two). The stuck iteration onboards a new request (KV receive). Every late Initialized ZMQMessenger line is a genuine first contact (zero re-initialisations across 5 runs).
• -c cudaProfilerApi without a CUDA tracer in -t makes nsys enable the default tracer ("CUDA tracing is required for cudaProfilerStart/Stop API support. Turning it on by default."); on VR200 every decode rank then deadlocks in the first per-iteration cudaEventRecord (594484). Keep cuda-sw in -t whenever the capture range is used, or switch to nsys-time.

🤖 Generated with Claude Code

[nv-yna]

Report validated inside the container (hecate0057, nsys 2026.3.0, while 570810 was still running)

nsys stats --report cuda_gpu_kern_sum,nvtx_sum,cuda_api_sum on prefill/hecate0057_prefill_w0_profile_rank0.nsys-rep (74.7 MB):

• Window is exact: nvtx_sum has 100 TensorRT-LLM:_forward_step instances and per-iteration ranges [Executor] _forward_step 1200 … 1299 — the configured prefill: 1200-1300.
• CUDA trace is real: 111 kernel families; top entries MegaMoE FC1/FC2 38.8 % (6,100 instances = 61 per iteration), FMHA 12.9 %, deep_gemm::sm100_mqa_logits 11.3 %, topK-per-row prefill 5.2 %. cuda_api_sum: cudaEventSynchronize 56.7 % of API time.
• python-gil tracer is active: GIL Trace:Holding GIL 4.03 M instances, Waiting for GIL 23 k.
• Stats CSVs written next to the reports under logs/profiles/.

All 32 reports (24 prefill ranks, 8 decode ranks) were produced during the run; decode ones landed ~40 s after its window closed at iteration 6600. Note for readers: the workstation's nsys 2025.5 refuses these reports ("created in a newer version"), so post-processing has to happen with a 2026.3+ nsys, e.g. inside the same container.

[nv-yna]

570810 did not complete — decode worker hung 4 minutes after its capture window

Timeline (all from the run's logs):

time	event
21:00:50	benchmark starts (+16 min after job start, same as the unprofiled run)
21:08:53 → 21:09:54	prefill capture (iter 1200–1300 on all 3 workers), 24 reports written
21:09:47 → 21:11:19	decode capture (iter 6000–6600), 8 reports written by 21:11:46
21:12–21:14	decode GPU utilisation 12 % → 6.6 → 3.5 → 1.9 %; frontend completions +108–152/min → +84 / +31 / +43
21:15:08	all 8 decode ranks log iteration 7624 with host_step_time = 343 ms and never log again
21:20:08	TRT-LLM hang detector on ranks 2 and 3: "Hang detected after 300 seconds", both stuck in tp_allgather → safe_allgather → _serialize_and_exchange_lengths from cuda_graph_runner.pad_batch; KV transceiver idle (0 sessions)
21:20:08	worker killed (exit 137) → srtctl critical-process failure → aiperf ServerDisconnected, ProfileAborted (still in the ~36-min AgentX warmup) → sweep exit 1 at 21:28:43

The prefill workers, captured 6 minutes earlier, ran fine until teardown. Request rate while nsys was armed but not capturing was within 4 % of the unprofiled run (+10 min: 1,462 vs 1,516 completions).

What this does and does not say: eight runs of this recipe without nsys never hung; the one run with nsys hung 229 s after the decode capture closed and the reports were generated. That makes nsys's post-capture state (--capture-range-end=stop leaves the injection in the process) the prime suspect, but n = 1 and the stacks show a collective waiting for a rank whose own stack was not dumped, so the trigger is not identified. Job 570978 is a resubmission of the identical recipe to get n = 2 and, if it completes, the throughput comparison. The 32 reports from 570810 are intact and valid regardless.