feat: add phase timing markers to ray.sub for diagnosing startup stalls

[terrykong]

What does this PR do ?

Adds coarse, timestamped phase markers to ray.sub so that startup/teardown stalls (before Ray, and after the driver) can be localized from the job log.

Motivation: a recent run burned ~20 min of a fixed wall-clock budget before the training driver even started, and it was impossible to tell from the log where that time went — ray.sub runs with set -x, but the xtrace has no timestamps, and the slow region was a mix of pre-script SLURM launch (prolog/allocation), controller RPCs (sinfo/scontrol), DNS resolution, and container image import. None of those were individually attributable after the fact.

This adds a log_phase helper that stamps an ISO wall-clock time plus seconds-since-job-start, called at the key phase boundaries on the submit host and inside the head/worker containers. Subtract two adjacent markers' elapsed counters to get that phase's duration. The timeline is bookended so the two things ray.sub can't see itself are still measurable:

• prolog/allocation = first marker − SLURM StartTime
• epilog/teardown = SLURM EndTime − last marker (via a trap … EXIT TERM HUP INT, so a time-limit kill / scancel is stamped too — a bare EXIT trap doesn't fire on an uncaught signal)

Markers — submit host: ray.sub started · shared-FS log dir ready · GRES (sinfo) · CPU (scontrol show node) · node→IP resolution · srun launch · Ray head GCS up · attach-helper (scontrol show job, interactive path) · ray.sub exiting (trap).
Inside the containers (reuse the propagated NRL_JOB_START_EPOCH so all counters share one timeline): head — container started / starting ray head / GCS listening / cluster ready, launching driver / worker-join poll / sandbox-readiness poll. worker — container started / connecting / per-attempt ray start.

Kept deliberately coarse (phase boundaries, not per-command); the rationale (which op is a controller RPC, where image import happens, etc.) lives in code comments, not the runtime log lines.

Issues

None.

Usage

ray.sub runs under set -x, so grep the timestamped form ([NRL_PHASE][2…) to skip the xtrace/definition lines:

grep -hE '\[NRL_PHASE\]\[2' slurm-*.out <jobid>-logs/ray-*.log | sort -t+ -k2 -n

Example (from live 2-node validation runs)

SLURM StartTime was …:12:39. Merged submit + head + worker markers (node names genericized):

[NRL_PHASE][…:13:11][+0s]  ray.sub started (job=<id> nodes=2 partition=batch node=node-a)
[NRL_PHASE][…:13:11][+0s]  shared-FS log dir ready (/…/<id>-logs)
[NRL_PHASE][…:13:11][+0s]  detecting GRES support (sinfo)
[NRL_PHASE][…:13:12][+1s]  auto-detecting CPUs per node (scontrol show node)
[NRL_PHASE][…:13:13][+2s]  resolving 2 node hostname(s) to IPs
[NRL_PHASE][…:13:13][+2s]  launching Ray head + worker sruns
[NRL_PHASE][…:14:18][+67s] head container started on node-a
[NRL_PHASE][…:14:21][+70s] head: starting Ray head
[NRL_PHASE][…:14:22][+71s] worker 0 container started on node-b
[NRL_PHASE][…:14:34][+83s] head: Ray GCS listening (STARTED_RAY_HEAD written)
[NRL_PHASE][…:14:35][+84s] Ray head GCS up (STARTED_RAY_HEAD observed)
[NRL_PHASE][…:14:35][+84s] worker 0 connecting to Ray head
[NRL_PHASE][…:14:47][+96s] head: cluster ready, launching driver
        …driver runs…
[NRL_PHASE][…exit ][+…s]   ray.sub exiting (exit_code=0)   # last marker; EndTime − this = epilog

Reading phase durations straight off the counters:

Phase	How to compute	Measured
prolog / allocation (pre-script)	first marker − SLURM StartTime	32 s
GRES + CPU + DNS	+2s − +0s	~2 s
enroot image import	+67s (head started) − +2s (srun launch)	~65 s
ray head bringup	+83s − +70s	~13 s
worker registration	+96s − +84s	~12 s
epilog / teardown (post-script)	SLURM EndTime − last marker	~4 s (from a scancel test)

The point: in the incident that motivated this, a ~20-min gap was unattributable. It now lands unambiguously as either a large StartTime → started gap (prolog), or a large srun launch → container started gap (image import), or a large exiting → EndTime gap (epilog) — separated instead of hidden in an untimestamped trace.

Before your PR is "Ready for review"

Pre checks:

• Make sure you read and followed Contributor guidelines
• Did you write any new necessary tests? (N/A — diagnostic log lines; bash -n validated the outer script + the heredoc-generated head/worker scripts, the exit-trap was unit-tested to fire on SIGTERM, and the whole thing was exercised end-to-end on live 2-node runs including a scancel to confirm the epilog marker)
• Did you run the unit tests and functional tests locally? Live 2-node bringup + cancel; markers confirmed on submit host + both containers + on teardown.
• Did you add or update any necessary documentation? (N/A)

Additional Information

• Only ray.sub changes; purely additive echo/log_phase lines plus a logging-only exit trap — no change to the launch path's behavior.
• log_phase reuses NRL_JOB_START_EPOCH; the container copies read it from the propagated env so all markers share one timeline.
• Because ray.sub runs under set -x, each marker also appears once as a + echo … xtrace line; grep the [NRL_PHASE][2… timestamped form to get just the markers.

[copy-pr-bot]

This pull request requires additional validation before any workflows can run on NVIDIA's runners.

Pull request vetters can view their responsibilities here.

Contributors can view more details about this message here.

[terrykong]

/ok to test 21d2523

[terrykong]

/ok to test 8229e93