The critical path: tracing observation to actuation

The previous phase ended with a working inference contract: a π₀-class policy behind a server on your RTX workstation, a robot-host client driving the WidowX AI, a schema both sides honor. Which means you now own a distributed system — camera firmware, a driver, two or three OS processes, a GPU, a UDP link into the arm's real-time controller, and a physical arm — and you have not yet traced it. In your serving world this would be unthinkable: nobody optimizes a pipeline they cannot see, and no production stack ships without distributed tracing. This lesson is exactly that discipline, aimed at a robot. The twist is that the trace does not end at an HTTP response. It ends when metal moves — and the last two spans execute on silicon that has no profiler hooks at all.

Foundations: Freshness, Jitter, and the Limits of Little's Law

Before tracing the path, we must define the metrics that determine whether the trace is healthy. In distributed serving, the primary objective is throughput: maximizing the number of requests processed per second. In a robotic control loop, the primary objective is freshness: minimizing the age of the data used to make a decision. We define the Observation Age at any time $t$ as $Age(t) = t_{current} - t_{capture}$, where $t_{capture}$ is the timestamp of the sensor exposure. The control objective is to minimize $Age(t)$ at the moment of actuation, not merely to minimize the latency of the network transfer. A system can have low latency but high age if it buffers data; conversely, a system can have high latency but low age if it discards old data immediately.

A second critical concept is jitter. Jitter is the variance of the inter-arrival time or the variance of the observation age. While mean latency tells you the average delay, jitter tells you the predictability of that delay. In a feedback control system, high jitter is often more destructive than high mean latency because it destabilizes the controller's internal state estimation. We quantify jitter as the standard deviation of the span duration or the age over a sliding window. A healthy system has low mean age and, crucially, low jitter.

Little's Law, $L = \lambda W$, is a powerful tool for queueing analysis, but it has physical constraints that are often ignored in software engineering contexts. $L$ represents the mean occupancy of the queue, $\lambda$ is the throughput (drain rate), and $W$ is the mean wait time. A critical constraint is that for a finite queue of depth $D$, $L \le D$. If the arrival rate exceeds the service rate, the queue saturates ($L \to D$), and the system becomes lossy. In this regime, $\lambda$ is the service rate, not the arrival rate, and $W$ becomes unbounded if the queue is not managed with a discard policy. This is why 'latest-wins' semantics are essential: they cap $L$ at 1, ensuring that $W$ remains bounded by the frame period, regardless of how fast the camera produces data.

Finally, we must correct a common terminological error: the slow oscillation in observation age caused by mismatched clock rates is phase drift, not aliasing. Aliasing is a spectral phenomenon that occurs when a signal is sampled at a rate lower than twice its highest frequency component, causing high-frequency components to fold into the low-frequency spectrum. Phase drift is a temporal phenomenon: two periodic processes with slightly different frequencies will have a relative phase that slides over time. The 'beat frequency' is the rate at which this phase slip occurs. Confusing these two concepts leads to incorrect diagnostic strategies: you cannot fix phase drift by changing the sampling rate; you must synchronize the clocks or trigger the processes based on the other.

Worked Example: Quantifying Phase Drift and Freshness Cost

Consider a system where a camera runs at 30 fps ($T_{cam} = 33.33$ ms) and the inference server runs at 10 Hz ($T_{inf} = 100$ ms). The camera's crystal oscillator has a drift of 100 ppm relative to the host clock. We want to calculate the phase slip per inference tick and the resulting beat period.

The controller rate is $f_{inf}=10$ Hz, so perfect lock would require exactly $Nf_{inf}=3\times10=30$ camera frames per second. The real camera produces 29.997 frames per second. Their difference is the rate at which the relative phase slips, measured in camera frames per second. Equivalently, each 100 ms control tick contains $f_{cam}'/f_{inf}=2.99970$ frames, so the phase falls behind by $0.00030$ frame per tick.

At $0.00030$ frame of slip per tick, one full frame of phase takes about $3333$ ticks, or $333$ seconds. During that interval, the age of the most recent frame at each control tick sweeps from nearly 0 ms to nearly one frame period (33.3 ms), then wraps when the controller samples the next frame. The age is bounded; it does not grow without limit. A 5.6-minute oscillation can easily masquerade as thermal or load-related drift unless you log capture timestamps and recognize the clock-rate mismatch.

From photons to first motion: naming every stage

Walk the path concretely for your rig. Your RealSense D405 wrist camera exposes a frame at 30 fps and stamps it on its own ASIC clock. The frame crosses USB3 into a driver ring buffer on the robot host. Your client process — the one running the Phase 01 episode logger — picks the freshest frame, packs it with joint states into a request, and sends it to the policy server. The server resizes to 224×224, normalizes, copies host-to-device, and runs the π₀-class VLA — a ~3B vision-language backbone plus a ~300M action expert integrating roughly ten flow steps — to produce a 50×7 action chunk. The chunk travels back, lands in the robot host's action buffer, and a 50 Hz executor pops actions one at a time, sending goal positions over UDP to the arm's iNerve controller each tick. The iNerve's 500 Hz real-time loop relays each goal over the internal CAN FD bus to the joints' FOC controllers, which chase the latched target, and a dozen or so milliseconds later the ~500 Hz joint-state stream shows velocity rising above the noise floor. That encoder crossing is the end of the story: the moment the world learned what the camera saw.

A trace is this path cut into spans: named intervals, each with a start and end on a known clock, all sharing a trace id. The root span, call it obs_to_motion, opens at the exposure midpoint (the capture-time convention you established in Phase 01) and closes at encoder-confirmed motion. Everything else nests inside it. Here is the span inventory for the full stack — commit these names to your tracing schema now, because every later lesson in this phase reports against them.

Notice what is not in the table: the time between spans. A frame sits in the driver buffer before client.request; a chunk sits in the action buffer before exec.dispatch. Those gaps are queues, and they get their own section, because on a robot they are where latency goes to hide.

Span design: ids and timestamps that survive process boundaries

Root the trace id at the observation, not at the request: camera_serial + frame_number plus the capture timestamp. This choice does real work. Most frames never become traces at all — at 30 fps feeding ~10 Hz inference, two of every three frames are dropped by design, and only sampled frames mint ids. One observation produces at most one inference, but one inference produces fifty actions, so each executed action carries the parent trace id plus a chunk_index attribute. And because a chunk keeps executing while newer observations are already in flight, traces overlap in time — your waterfall will look exactly like a serving dashboard under concurrent load, which is the correct mental picture for everything in the real-time chunking lesson later this phase.

Propagation is the same trick as a traceparent header: the request to the policy server carries trace_id and capture_mono — the exposure-midpoint time already mapped into host monotonic by your Phase 01 logger — as metadata alongside the image tensor. The server never invents time for the observation; it only appends spans stamped on its own clock. The client, which owns the root span, reconciles everything on receipt.

Reconciling requires knowing the offset between client and server clocks. Today both processes live on one workstation and share CLOCK_MONOTONIC, so the offset is zero and correlation is free — verify this once with a loopback handshake rather than assuming it. The moment the server moves to another machine, you are back to the round-trip estimation you met in Phase 01, and here is the payoff of doing tracing properly: every inference request is already a handshake. Four timestamps ride along for free — client send $t_0$, server receive $t_1$, server reply $t_2$, client receive $t_3$ — so you re-estimate the offset continuously at no cost. You need the refresh: a 50 ppm crystal difference drifts 3 ms per minute, which would corrupt your cross-host span alignment within a single episode.

import json
import time

MONO = time.monotonic  # one clock domain per host, per Phase 01

class Tracer:
    def __init__(self, host: str):
        self.host = host
        self.spans = []

    def record(self, trace_id, name, t_start, t_end, **attrs):
        self.spans.append({
            "trace_id": trace_id, "name": name, "host": self.host,
            "t_start": t_start, "t_end": t_end, "attrs": attrs,
        })

    def to_chrome_trace(self, clock_offset_s=0.0):
        # Chrome trace-event format; open the file in Perfetto
        events = []
        for s in self.spans:
            events.append({
                "name": s["name"], "ph": "X",
                "pid": s["host"], "tid": s["trace_id"][:12],
                "ts": (s["t_start"] + clock_offset_s) * 1e6,
                "dur": (s["t_end"] - s["t_start"]) * 1e6,
                "args": s["attrs"],
            })
        return json.dumps({"traceEvents": events})

# --- robot host: root the trace at the observation ---
def make_context(frame):
    trace_id = frame.camera_serial + "-" + str(frame.number)
    return {
        "trace_id": trace_id,
        "capture_mono": frame.capture_mono,  # exposure midpoint
        "t0": MONO(),
    }
    # ctx rides in request metadata, like a traceparent header

# --- policy server: spans on the server clock, echoed back ---
def handle(ctx, obs, policy, tracer):
    t1 = MONO()
    x = preprocess(obs)          # resize, normalize, H2D copy
    t_pre = MONO()
    chunk = policy.infer(x)      # pi0-class forward, ~10 flow steps
    t2 = MONO()
    tracer.record(ctx["trace_id"], "server.preprocess", t1, t_pre)
    tracer.record(ctx["trace_id"], "server.infer", t_pre, t2)
    return chunk, dict(ctx, t1=t1, t2=t2)

# --- robot host again: every reply is a clock handshake ---
def reconcile(meta):
    t3 = MONO()
    theta = ((meta["t1"] - meta["t0"]) + (meta["t2"] - t3)) / 2.0
    rtt = (t3 - meta["t0"]) - (meta["t2"] - meta["t1"])
    return theta, rtt  # alignment error bounded by rtt / 2

Queues: where latency hides between spans

Spans measure busy time. But subtract the sum of spans from the measured end-to-end and you will find missing milliseconds — sometimes hundreds of them. That difference is wait time, and every wait lives in a queue: the driver's frame ring buffer, the middleware subscription queue if ROS 2 carries your images, the server's request queue, the CUDA submission queue, the action buffer. Queues are where your serving instincts go exactly wrong: in serving, queues protect throughput; here most of them destroy the only thing that matters, freshness.

The tool for reasoning about them is Little's law, and it is worth deriving once because the derivation shows why it applies to any stationary queue regardless of scheduling or distribution. Watch a queue for a long window $T$. Count arrivals $A(T)$, and let $N(t)$ be the occupancy at time $t$. The area under $N(t)$ can be counted two ways: integrate occupancy over time, or sum each item's dwell time $w_i$ — every item contributes its dwell to the area. Setting the two counts equal and dividing by $T$:

Rearranged as $W = L/\lambda$, it becomes a staleness meter. The crucial subtlety: for a full, lossy queue, $\lambda$ is the drain rate, not the arrival rate, because dropped items never transit. A camera pushes 30 fps into a FIFO of depth 4 that your client drains at 10 Hz: the queue sits pinned at 4, throughput through it is 10 per second, so every frame the policy actually sees waited $W = 4/10 = 400$ ms — before a single flop of inference. The fix is not a bigger queue or a faster consumer; it is different semantics: keep the latest, drop the rest. A depth-one, latest-value slot — keep_last(1) in ROS 2 QoS terms — is mandatory everywhere on the observation path. Buffering is only correct where items are commitments about the future: the action buffer (a chunk of upcoming actions is the entire point of chunking — starving it causes stop-and-go motion), and off-critical-path export queues like your trace log writer. The GPU submission queue sits in between: within one inference, deep kernel queuing is fine; across observations, allow at most one inference in flight (two once asynchronous execution adds double-buffering) — pipelining three observations through the server turns a 100 ms model into 300 ms of staleness at full throughput.

The waterfall: reading one trace like an engineer

Here is a single healthy trace from a stack like yours — queues already fixed to latest-wins, policy server on the same workstation, times relative to shutter-open. These numbers are plausible for a RealSense-class camera, a π₀-class policy on an RTX 4090-class GPU, and a WidowX AI arm; yours will differ, and measuring that difference is this lesson's exercise.

First motion happens 154 ms after shutter open; measured from the capture time, the arm begins responding to a world 146 ms gone. Now interrogate the trace, because "what is the bottleneck?" is three different questions. Question one — throughput: can this stack sustain a 10 Hz replan? Server busy time is $6 + 95 = 101$ ms per request, over the 100 ms budget — so no, not synchronously; the loop runs at 9.6 Hz with zero slack, and every jitter excursion drops a tick. This tension, not raw speed, is why the asynchronous chunking lesson exists. Question two — first-action freshness: server.infer is the largest single span at 95 ms, 62% of the path. But halve the model — quantize, distill, cut flow steps — and end-to-end drops only to about 107 ms, because 59 ms of camera, transport, dispatch, and joint response do not care about your kernels — and the last 14 ms sit after every optimization software can ever make. Question three — worst-action freshness: this trace ends at the first action of a 50-step chunk. Executed open-loop at 50 Hz, action 49 lands at $154 + 49 \times 20 = 1{,}134$ ms after capture — the chunk horizon dwarfs every stage in the table. Which bottleneck is "true" depends on which failure you are debugging, and the trace is what lets you have that argument with numbers instead of vibes.

Rates that don't divide: 30 into 10 into 50 into 500

The trace shows one tick. The system is four periodic processes running at once: a camera near 30 fps, inference near 10 Hz, an executor at 50 Hz, and the arm's real-time loop at 500 Hz. They compose by decimation and interpolation. Downward (camera → inference), you keep one frame in three and drop the rest — deliberately; a pipeline that processes every frame is a video system, not a controller. Upward (inference → executor), one chunk fans out to many actions: at 10 Hz replanning you consume 5 of 50 actions before replacing the chunk, and the executor's 20 ms tick quantizes when each command leaves — the uniform 0–20 ms action-buffer wait in the waterfall. Below that, the iNerve's 500 Hz loop resamples your 50 Hz staircase of goals, holding each for ten cycles, and the joints' FOC controllers run faster still.

Because these processes free-run on different oscillators, their relative phase is not constant — it slides, and the slide is visible in your data as a slow oscillation in observation age. This is aliasing in the signal-processing sense: sampling one periodic process with another at a slightly mismatched rate produces a beat at the difference frequency. Derive the beat for the camera–inference pair. Let $T_{\text{cam}}$ be the true frame period, $T_{\text{inf}}$ the inference period, and $N$ the nominal frames per tick. Each tick, the phase between tick time and the latest frame slips by $s$; a full sweep of one frame period takes $T_{\text{cam}}/s$ ticks:

Plug in real numbers. Consumer cameras often run at 29.97 fps, not 30.00: $T_{\text{cam}} = 33.367$ ms, $T_{\text{inf}} = 100$ ms, $N = 3$, so $s = |100 - 100.100| = 0.100$ ms per tick and $T_{\text{beat}} \approx 33$ s. Even with both rates nominally exact, two crystals disagreeing by 100 ppm give $s = 10\,\mu$s and a beat period near 5.6 minutes — slow enough to masquerade as thermal drift if you are not expecting it. The signature is unmistakable once you know it: observation age ramps smoothly across exactly one frame period, snaps back, and repeats. Simulate it before you hunt it in real logs:

import numpy as np

T_CAM = 1.0 / 29.97   # true frame period: 33.367 ms
T_INF = 0.100         # inference timer on the host: 100 ms
T_ACT = 0.020         # 50 Hz executor tick
HORIZON = 120.0       # seconds of simulated operation

frames = np.arange(0.0, HORIZON, T_CAM)      # frame capture times
ticks = np.arange(0.0137, HORIZON, T_INF)    # arbitrary initial phase

# latest-wins: each tick grabs the freshest frame already captured
idx = np.searchsorted(frames, ticks) - 1
age_at_infer = ticks - frames[idx]

# find the sawtooth: age sweeps one frame period, then wraps
wraps = np.where(np.abs(np.diff(age_at_infer)) > 0.5 * T_CAM)[0]
beat_s = float(np.median(np.diff(ticks[wraps])))

print("age at inference: min %.1f ms  max %.1f ms"
      % (age_at_infer.min() * 1e3, age_at_infer.max() * 1e3))
print("sawtooth period: %.1f s (predicted 33.4 s)" % beat_s)

# compose with the executor: action k of each chunk executes
# k * T_ACT after dispatch, so its observation age grows linearly
k = np.arange(5)   # 5 actions consumed per replan at 10 Hz
print("extra age at action k:", np.round(k * T_ACT * 1e3, 1), "ms")

One rate deserves special respect: you cannot see below the iNerve. The driver's joint-state stream arrives at roughly 500 Hz, and each joint's FOC loop runs an order of magnitude faster still — so if your executor samples joint states only at its own 50 Hz tick, transients faster than 25 Hz alias in your encoder logs. That is fine for closing the servo.motion span — first motion is a slow edge — but remember it in the motion-quality lesson, when you start computing jerk from those same logs.

Everything here converges on one deliverable, and it is worth being precise because four later lessons depend on it: delay injection needs its baseline, the chunking scheduler must beat its synchronous numbers, Nsight zooms into its server.infer span, and motion-quality metrics correlate against its waits. Assemble:

• The raw trace log — one JSONL record per span, at least 500 complete obs_to_motion traces captured under realistic load (episode logger writing, visualization on, all cameras streaming), plus the Chrome-trace export rendered once in Perfetto (opens in a new tab) to confirm the waterfall reads correctly.
• The stage-budget table — p50/p95/p99 for every span and every inter-span wait, with the clock-offset estimate and its RTT bound recorded alongside each cross-host pair.
• The rate map — measured, not nominal, rates for camera, inference, executor, and joint-state sampling, plus the observation-age distribution at command-write time (the quantity the whole phase is about).
• The bottleneck memo — a short paragraph separating the throughput bottleneck from the freshness bottleneck, each claim citing a number from the table.

Where this goes next: "Serving a policy: the inference contract" gave you the request path; this lesson gave you eyes on all of it, from photons to first motion. The next lesson, "What delay and jitter do to a control loop," takes the numbers in your stage-budget table and asks the control-theoretic question they raise: how much delay can a feedback loop tolerate before tracking degrades, and why is the variance of your waits often more destructive than their mean? Every experiment for the rest of this phase — delay injection, asynchronous chunking, Nsight profiling, motion-quality metrics — reports its results as a diff against the trace artifact you just built. It is the control condition for everything that follows.