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.

Short proof runs (2026-09-16 morning): what each one established

Short recipes (1 request/lane warmup, 300 s measured phase with --unsafe-override, 70-minute limit, -p batch-xdr,batch-spx) backfilled within minutes where the 2 h 10 min runs never scheduled.

Run	nsys mode	Result
E5s 596172	time window --duration 120, -t nvtx,python-gil	31/33 reports written at the window end; the decode engine stalled within 1 s of its nsys process exiting, lost its etcd lease, router dropped it (Removing worker ...), aiperf aborted
E6s 596173	same + cuda-sw on workers, nvtx,osrt on the frontend	all 33 reports written (24 prefill 4.6 GB, 8 decode, frontend), then the same stall after nsys exited
E7s 596299	capture from --delay 1200 until exit (no --duration)	benchmark completed (8,748 requests, 21k tok/s) with nsys attached to all 32 ranks + frontend throughout; 0 reports because cleanup SIGTERMed the srun clients → srun: forcing job termination → tasks SIGKILLed 2–5 s later

Two more commits follow from that:

• f379e862 capture until exit: duration_secs is optional for nsys-time workers and the profiled frontend (now the default for the frontend); the launcher wrapper starts nsys in its own session (setsid) and forwards SIGTERM to the profiled app only, so nsys can finalise the report at teardown.
• 80b0de3f graceful step teardown: worker/frontend steps are named (srun --job-name); ProcessRegistry.cleanup() first delivers SIGTERM to those steps' processes (scancel --signal=TERM <jobid>.<stepid>) and waits up to teardown_grace_secs, escalating to srun SIGTERM/SIGKILL only on expiry. Verified on the production image that nsys writes its report within 2 s of receiving SIGTERM.

Also learned: -c cudaProfilerApi without a CUDA tracer in -t makes nsys enable the default tracer, which deadlocked every decode rank in the first cudaEventRecord (594484). Keep cuda-sw in -t with the capture range, or use nsys-time.

Proof runs completed (2026-09-16 afternoon)

Job	Topology	nsys	Result
596422 (E8s)	3P+1D, 32 ranks + frontend	nvtx,python-gil, capture launch+1200 s → exit	Slurm COMPLETED 1h07, benchmark + sweep completed; 25/33 reports (8 prefill lost: their step's 8 × 1.5 GB reports outran the 600 s grace)
596507 (E9s)	1P+1D	same	COMPLETED 56 min; 9/17 reports (prefill step outlived the grace)
596583 (E10s)	1P+1D	nvtx, capture launch+1500 s → exit, grace 900 s	COMPLETED 1h02; 9/17 — the TRT-LLM MPI rank processes (mgmn_worker_node) stayed alive >10 min after the Dynamo worker had shut down, so nsys --wait all never finished
596762 (E11s)	1P+1D	as E10s + app-tree escalation (7deed3f1)	COMPLETED 47 min, all 17 reports (8 prefill, 8 decode, frontend), all steps COMPLETED 0:0 within 2 min of the teardown SIGTERM, no hang lines

Report validation (in-image nsys 2026.3.0): prefill rank 0 of 596422 holds 131.6 M NVTX events (TRT-LLM KV-transfer ranges included), decode ranks 10–15 M; the frontend report contains the thread table but no NVTX events — Dynamo's Rust NVTX ranges do not reach nsys with this wheel, so the frontend capture proves attachment only.

Last commit in this series: 7deed3f1 — when the profiled app ignores the teardown SIGTERM, the launcher wrapper TERMs then KILLs the app's process tree (snapshotted at signal time, nsys never touched) after profiling.app_exit_grace_secs (default 120, must be < teardown_grace_secs), so nsys can finalise its report.

Operational lessons baked into the docs: functional/profiling proofs use the shortest recipe (1P+1D, 1 request/lane warmup, 300 s measured phase with --unsafe-override, -t nvtx, ≤ 70 min, both fabric partitions) — the 2 h 10 min full-length jobs never scheduled in a day, the 70-minute ones backfilled within an hour every 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.