Profiling the loop: NVTX, Nsight, and the robot twist

You have spent years reading Nsight timelines, so this lesson will not explain what a CUDA hardware row is. Point nsys at an OpenPI policy server and you will feel at home: a warmup cliff, a repeating denoise loop, familiar Python launch gaps. The robot twist is everything the timeline does not show. Half of your system — two RealSense-class cameras, the Ethernet-connected iNerve controller in the arm's base, a WidowX AI arm with a payload in flight — emits no CUPTI events, and the only metric that ultimately matters (did the gripper close on the block?) lives on that invisible half. Profiling a robot is therefore a trace fusion problem: get the GPU timeline and the physical timeline onto one clock first, and only then start assigning blame.

Conceptual Foundation: Physical Constraints and Clock Alignment

Before instrumenting the software, we must define the physical quantities that make latency a safety-critical variable. In a standard LLM server, latency is a user experience metric; in robotics, it is a geometric error. We define Chunk Staleness as the time interval $\Delta t_{stale}$ between the moment an action chunk is computed by the policy and the moment the robot executes the first command in that chunk. We define Overshoot as the physical displacement error incurred if the robot continues moving based on outdated state information. If the robot's true state has changed significantly during $\Delta t_{stale}$, the planned trajectory may collide with obstacles or miss targets. This is why the 'Time-To-First-Action' (TTFT) in robotics is not merely a startup delay but a direct contributor to the safety envelope.

To measure these quantities, we must align the clocks of the workstation (running the policy) and the robot host (running the controller). Network Time Protocol (NTP) is insufficient for this task because it operates on second-level accuracy with high jitter, whereas robotics requires sub-millisecond precision. Instead, we use a four-timestamp handshake. Let $t_1$ and $t_4$ be timestamps recorded on the workstation's monotonic clock, and $t_2$ and $t_3$ be timestamps recorded on the robot host's monotonic clock. The workstation sends a ping at $t_1$, the robot receives it at $t_2$, the robot sends a reply at $t_3$, and the workstation receives the reply at $t_4$. This setup allows us to solve for the clock offset $\theta$ and the round-trip time $\delta$ without assuming symmetric network paths.

The error bound $\delta/2$ represents the maximum possible asymmetry in the network path. By selecting the handshake with the minimum $\delta$, we minimize the potential for asymmetric queuing delays, thereby tightening the bound on the clock offset. This is critical because a 1 ms error in clock alignment can be indistinguishable from a 1 ms latency spike in the control loop, leading to false diagnoses.

When profiling middleware, two specific gaps are critical. The Executor Gap is the time from when a message arrives at the ROS 2 executor to when the callback function actually starts executing. This gap grows if the executor is single-threaded and other callbacks (like image processing) are blocking the thread. The Transport Gap is the time from when a message is published to when it is received, including network latency and serialization. In DDS (Data Distribution Service), large messages are fragmented into smaller network packets; if one packet is lost, the entire message is delayed or dropped, causing a spike in the transport gap.

Worked Example: Clock Synchronization and Spike Census

Consider a scenario where a policy server runs on a workstation and the robot host is connected via Ethernet. We perform 200 handshakes to estimate the clock offset. For the best handshake (minimum round trip), we record the following timestamps in milliseconds: $t_1 = 1000.000$, $t_2 = 1000.400$, $t_3 = 1000.600$, and $t_4 = 1001.000$. We will use these values to calculate the offset estimate and the error bound, and then interpret the results in the context of a 55 ms inference loop.

1. Calculate the Round Trip Time ($\delta$): $\delta = (t_4 - t_1) - (t_3 - t_2) = (1001.000 - 1000.000) - (1000.600 - 1000.400) = 1.000 - 0.200 = 0.800$ ms.
2. Calculate the Offset Estimate ($\hat{\theta}$): $\hat{\theta} = 0.5 \times [(t_2 - t_1) + (t_3 - t_4)] = 0.5 \times [(1000.400 - 1000.000) + (1000.600 - 1001.000)] = 0.5 \times [0.400 - 0.400] = 0$ ms.
3. Calculate the Error Bound: $\delta / 2 = 0.800 / 2 = 0.400$ ms.

The robot host's clock is estimated to be 0 ms ahead of the workstation. The true offset is within $\pm 0.4$ ms. This is tight enough to merge traces for a 55 ms inference loop, as the error bound is less than 1% of the total loop time. If the error bound were larger, say 5 ms, we would not be able to distinguish between a 5 ms latency spike and a clock drift, making diagnosis impossible.

Instrumentation layout: NVTX ranges that mirror the loop

Annotate the policy server so the trace speaks the loop's language, not the framework's. Four ranges carry a π₀-class server: preprocess (decode, resize to 224×224, normalize, pin, H2D two camera streams), encode (vision tower plus language prefix through the PaliGemma-class backbone, once per inference), denoise_k (one range per flow-matching step, ten of them, each a forward pass of the ~300M-parameter action expert), and postprocess (integrate to a 50×7 action chunk, unnormalize, serialize). Hold the granularity there — per stage, not per layer. You are attributing milliseconds to loop stages, not tuning kernels, and a few dozen ranges per tick is the ceiling before the instrumentation becomes its own noise source.

Two conventions pay for themselves. First, wrap each tick in a range whose message carries the tick index, so a spike in the robot-side log can be located in the GPU trace by number instead of by eyeball. Second, emit anchor marks in a dedicated NVTX domain, each carrying the tick index plus host monotonic time — the raw material for merging this trace with everything the profiler cannot see.

import time
import nvtx


class InstrumentedPolicyServer:
    """Wraps a pi0-style policy with NVTX ranges matching the loop anatomy."""

    def __init__(self, policy, num_flow_steps: int = 10):
        self.policy = policy
        self.num_flow_steps = num_flow_steps
        self.tick = 0

    def infer(self, obs: dict) -> dict:
        self.tick += 1
        # Anchor: identical payload goes into the NVTX stream and the robot log.
        anchor = "tick=" + str(self.tick) + " mono=" + repr(time.monotonic())
        nvtx.mark(message=anchor, domain="anchors")

        with nvtx.annotate("tick_" + str(self.tick), domain="loop"):
            with nvtx.annotate("preprocess", color="blue"):
                imgs = self.policy.preprocess(obs["images"])   # resize, normalize
                imgs = imgs.pin_memory().to("cuda", non_blocking=True)

            with nvtx.annotate("encode", color="green"):
                prefix = self.policy.encode(imgs, obs["prompt"])

            latent = self.policy.init_noise()
            for k in range(self.num_flow_steps):
                with nvtx.annotate("denoise_" + str(k), color="orange"):
                    latent = self.policy.denoise_step(prefix, latent, k)

            with nvtx.annotate("postprocess", color="red"):
                chunk = self.policy.decode(latent)             # (50, 7) chunk
                chunk = self.policy.unnormalize(chunk.float().cpu().numpy())

        return {"actions": chunk, "tick": self.tick,
                "server_mono": time.monotonic()}

Now the correlation problem. nsys timestamps events on the workstation's monotonic timebase; the robot-side trace — the episode logger from Phase 01, the ROS trace, the joint command log — uses its own clocks, possibly on another host. Neither wall-clock time nor luck will merge them at the millisecond level. The fix is the four-timestamp handshake the critical-path lesson already rode on every inference request: the policy server pings the robot-side logger, both sides stamp send and receive on their own monotonic clocks, and you solve for the offset. That lesson's derivation assumed a symmetric path; redo it here without the assumption, so the error bound is yours and not folklore. Let $\theta$ be the true offset of the robot-host clock relative to the workstation clock, with unknown one-way trip times.

Concrete numbers: over Ethernet to a control host, round trips of 0.4–1.2 ms are typical, so a single handshake bounds the offset to ±0.2–0.6 ms. Fire 200 handshakes, keep the one with minimum $\delta$ — least queueing implies least asymmetry — and you are inside ±0.3 ms, an order of magnitude tighter than the 3–5 ms effects you are hunting. Re-estimate at the start and end of every capture: two commodity crystals drift apart at 10–50 ppm, which is 0.6–3 ms per minute if uncorrected. When policy server and robot driver share one workstation the problem collapses to a single monotonic clock — keep the anchors anyway; they cost microseconds and make the merge script host-agnostic.

import numpy as np


def estimate_offset(samples: np.ndarray) -> dict:
    """samples: (n, 4) array of handshakes (t1, t2, t3, t4).

    t1 request send, t4 reply receive: workstation monotonic clock.
    t2 request receive, t3 reply send: robot-host monotonic clock.
    """
    t1, t2, t3, t4 = samples.T
    theta = 0.5 * ((t2 - t1) + (t3 - t4))   # per-sample offset estimate
    delta = (t4 - t1) - (t3 - t2)           # round trip minus remote hold
    best = int(np.argmin(delta))            # min-RTT sample: tightest bound
    drift = np.polyfit(t1, theta, 1)[0]     # slope = relative clock drift
    return {
        "offset_s": float(theta[best]),
        "bound_s": float(0.5 * delta[best]),
        "drift_ppm": float(drift * 1e6),
        "n": int(len(delta)),
    }

What Nsight Systems shows on a VLA serving workload

Capture from process start and the first thing on screen is a cliff: tick 1 takes 2–8 seconds while steady state runs near 55 ms on an RTX 4090-class card. The suspects are all visible if you know their shapes — cuDNN autotune, JIT or torch.compile specialization on first shapes, lazy CUDA context initialization, the caching allocator growing its pool through a burst of cudaMalloc calls that never reappears. None of that is news to you. What is news: on a robot, warmup is not amortized away by the next million requests. Episodes are short, processes restart often, and a 5-second freeze with the arm already powered is a physical behavior. Phase 06 protocols will mandate N burn-in inferences before the first real observation — and N is a number this capture determines, not a guess.

If the denoise loop is captured into a CUDA graph — the standard batch-1 fix, applied below — the timeline changes character. During stream capture nothing executes, so a capture-time trace shows a hole where work should be. At replay, the GPU rows show the same kernels, but the CPU row shows one graph launch where 140 used to be — and your per-step NVTX ranges now measure almost nothing, because host-side ranges bracket launches, not GPU execution. Keep per-step attribution by reading kernel timestamps off the GPU rows, or accept step-level opacity and keep only the loop-level range. Decide before the capture.

The signature worth memorizing is the periodic latency spike. Healthy steady-state serving shows zero allocation activity — the caching allocator recycles blocks. But if the language prompt changes length between episodes, or one image path occasionally produces a new shape, the allocator misses its cached sizes, fragments, and every so often drops into a genuine cudaMalloc/cudaFree pair costing 10–80 ms while the driver walks its heap. In the trace: a clean comb of 55 ms ticks, then one 130 ms tick whose OS-runtime row is full of driver calls, recurring every few hundred ticks. The robot-side symptom, priced by the previous two lessons: a chunk arriving ~75 ms late, a controller that holds or blends, a metronome-regular hitch in the trajectory. Python garbage collection produces the same comb with a different confirming row — a pure CPU pause with no driver calls underneath.

The image transfer is small but instructive. Two 640×480×3 uint8 frames total 1.84 MB; over PCIe gen4 that is roughly 75 µs of pure transfer from pinned memory. From pageable memory the driver inserts a staging copy and the same transfer costs 0.5–2 ms with load-dependent jitter. On a 55 ms inference the mean is noise, but the jitter reduction is not, and the fix is one pin_memory() call. That is the recurring pattern of robot profiling: chase variance before mean, because the controller can plan around a constant but not around a surprise.

Batch-1 pathologies: an idle GPU can still be the bottleneck

Steady state at batch 1 shows the regime you recognize from single-request LLM decode: hundreds of short kernels and a GPU row that looks like a barcode. Count from a real capture: about 1,400 kernel launches per inference, a GPU-busy sum near 32 ms, wall time 55 ms. The missing 23 ms is CPU-side — Python dispatch at 15–30 µs per launch, interleaved with small synchronizations and the stray .item() left in the sampling code. Whenever per-kernel dispatch cost exceeds kernel duration, the launch queue drains and the GPU idles on the interpreter. Split the kernel population and the arithmetic tells the story.

The classic fixes rank differently than in throughput serving. CUDA graphs attack the 18 ms of launch-gated time directly and typically cut batch-1 latency by 30–40% on this workload; torch.compile buys a related win. Quantization attacks the 21 ms of GPU-gated time — real, but second in line. And notice what sits on the critical path before any kernel: tokenizing the language prompt and resizing two images in CPU Python costs 3–8 ms per tick with stock tooling, visible as dead time between the anchor mark and the first H2D copy. The instruction rarely changes mid-task, so tokenize once per episode; move the resize onto the GPU; that dead time drops under a millisecond. Then there is the number a colleague will eventually quote at you — nvidia-smi utilization. With the asynchronous executor from the previous lesson replanning every 500 ms, the GPU is busy 39 ms per replan:

When it is not the GPU: middleware and the wire

The merged trace gives you a decision procedure that runs before any middleware tooling: find the offending tick by number, then check where the time went. If the NVTX tick range is tight — anchor mark to postprocess-end within budget — but the robot-side log shows the action arriving late, the GPU is innocent and transport is the suspect. If arrival is on time but motion starts late, look past software entirely: that is the command-to-motion floor you measured in the instrumentation phase. Only then reach for middleware-level tracing, and only if ROS 2 is actually on your path — an OpenPI-style websocket server talking to a Python driver process has no DDS in it, and the suspect list collapses to the socket, the driver loop, and the UDP hop to the arm.

When ROS 2 is on the path, ros2_tracing is the right instrument: LTTng tracepoints built into rclcpp, rcl, and the rmw layer, captured alongside the nsys run and merged with the same anchor technique. Two gaps carry most diagnoses. The executor gap — callback ready to callback start — grows when a single-threaded executor serializes your action subscriber behind a chatty timer or an image callback; tens of milliseconds of queueing at near-zero CPU load is its signature, and the fix is executor assignment, not optimization. The transport gap — publish to take — grows with fragmentation: a 1.84 MB image on default UDP-based DDS settings shatters into over a thousand datagrams, and one lost fragment stalls the whole sample. Keep bulk images off DDS or use a zero-copy transport; action messages are a few hundred bytes and are almost never the problem.

The deliverable: a profiling packet Phase 06 can cite

Everything above compresses into a fixed, boring, repeatable sequence — not one heroic debugging session but an artifact generator that runs before every experimental campaign. Three captures, always in the same order. The warmup capture starts the process cold and records the first 40 seconds; it determines, with evidence, how many burn-in inferences the protocol must discard. The steady-state capture skips past warmup and records 60 seconds of realistic serving — cameras streaming, logger writing, arm executing — and yields the per-stage latency table and the spike census. The injection run is the one people skip and should not: inject a known 25 ms sleep into one stage behind an environment flag, capture again, and verify the delay appears in the right NVTX range, in the robot-side observation-to-command distribution shifted by ~25 ms, and nowhere else. Injection is the end-to-end test of the instrumentation itself: if a known cause fails to show up at the right place and magnitude, no unknown cause will either — and every latency-sensitivity claim in the capstone rests on exactly this kind of controlled injection.

# 1. Warmup capture: cold process, catch autotune, JIT, allocator growth
nsys profile --trace=cuda,nvtx,osrt --sample=none \
    --duration=40 -o capture_warmup \
    python serve_policy.py --config pi0_widowx

# 2. Steady state: skip past warmup, then record 60 s under realistic load
nsys profile --trace=cuda,nvtx,osrt --sample=cpu \
    --delay=90 --duration=60 -o capture_steady \
    python serve_policy.py --config pi0_widowx

# 3. Injection run: a known 25 ms delay inside the preprocess stage
INJECT_PREPROCESS_MS=25 nsys profile --trace=cuda,nvtx,osrt \
    --delay=90 --duration=60 -o capture_inject \
    python serve_policy.py --config pi0_widowx

# Export tables the analysis notebook and Phase 06 scripts can cite
nsys stats --report nvtx_sum,cuda_gpu_kern_sum capture_steady.nsys-rep
nsys export --type sqlite capture_steady.nsys-rep

• Raw captures — the three .nsys-rep files plus sqlite exports, named by date and git hash, never overwritten.
• Anchor record — estimated offset, its δ/2 bound, and measured drift in ppm, at capture start and end.
• Per-stage table — p50/p95/p99 for preprocess, encode, denoise, postprocess, and robot-side observation-to-command, generated by script from the exports.
• Spike census — count, period, worst magnitude, and attributed cause for every periodic anomaly found at steady state.
• Environment fingerprint — git hash, driver and CUDA versions, GPU clocks and power mode, camera settings, and whether the profiler observer-effect check passed.

This packet closes the loop that names the phase. A Phase 06 claim of the form the delay-conditioned scheduler recovers most of the success rate lost at 200 ms of injected latency cites the injection capture as proof the latency was really injected where claimed, and the steady-state table as proof of the baseline. Kernel-level observation to task success, one directory of evidence — and every future regression gets diffed against it.

Where this goes next: the previous lesson, Real-time chunking: asynchronous execution without discontinuity, built the scheduler that hides inference latency behind executing chunks — this lesson built the microscope that shows exactly which milliseconds it must hide. The next lesson, Motion quality: smoothness, jerk, and recovery, moves the measurement to the other end of the wire: encoder streams instead of kernel rows, jerk instead of gap totals. The merged trace built here is what connects the two — a specific allocator stall in the GPU timeline to a specific hitch in the joint trajectory — turning motion-quality metrics from descriptions into diagnoses.