feat: live control-loop rate readout during inference - #85
Conversation
lerobot reports a missed control-loop rate as a warning per missed iteration, buried in the inference log. A run that quietly drops from its 30 Hz target to 10 Hz therefore looks, in the UI, exactly like one that holds — which matters, because a policy behaves differently when it is stepped at a fraction of the rate it was trained at. There was no way to answer "is it actually running at 30 Hz?" without opening a log file after the fact. Measure it instead. `lelab/rollout_metrics.py` is a thin wrapper around lerobot.scripts.lerobot_rollout (the module the inference subprocess now spawns) that counts ThreadSafeRobot.get_observation calls: the rollout control loop makes exactly one per iteration, so counting them over a window is the loop rate, with no lerobot patch and no measurable overhead. A reporter thread prints one [LELAB_FPS] line per second. The server side needs no new plumbing: _pump_stdout already reads every line to find the rollout-start marker, so it also parses the rate samples and lerobot's own "FPS: 30" banner (read rather than assumed, so the display stays honest if the rollout config changes). /inference-status gains current rate, average, worst second, longest stall and a staleness flag; the Inference page already polls it every second and now shows three tiles plus a sparkline against the target. Two details worth flagging for review: - Each window is timed from its own first to its own last tick rather than by the reporter's wall clock. The half-filled window left behind when a run ends would otherwise report a phantom slowdown — a healthy 20 Hz run finishing mid-window read as 10 Hz before this. - The reported rate is not lerobot's warning number. lerobot logs 1/dt for a single slow iteration; one 230 ms hiccup among 29 healthy iterations makes it shout "0.4 Hz" while the second genuinely ran at 24 Hz. Hence the separate longest-stall figure, which is where that shows up. Verified on an SO-101 run: the meter tracks 30 Hz with intermittent stalls, matching what the profiler reports for the same run. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
nicolas-rabault
left a comment
There was a problem hiding this comment.
Two blockers inline. The meter can't currently see a stall: I drove _RateMeter with a 30 Hz stream frozen for 4 seconds of a 10 second run and got avg=30.0 and worst second=30.0. A starved run reading as clean 30 Hz is the one outcome this feature exists to prevent.
And this collides with #75 over the same -m slot, see inline. Both wrappers swallow failures by design, so whichever loses just goes silent rather than erroring. Decide how you want the two to coexist before either lands.
| def drain(self) -> tuple[int, float, float]: | ||
| """(ticks, seconds spanned by those ticks, worst gap).""" | ||
| with self._lock: | ||
| span = (self._newest - self._first) if self.ticks >= 2 else 0.0 | ||
| out = (self.ticks, span, self.max_gap) | ||
| self.ticks = 0 | ||
| self.max_gap = 0.0 | ||
| self._first = None | ||
| self._newest = None | ||
| return out |
There was a problem hiding this comment.
A window timed from its own first tick cannot see a stall: the frozen time falls outside span, so it never reaches avg or fps_min. Feeding this meter a 30 Hz stream frozen from t=3.0 to t=7.0 of a 10 second run gives avg=30.0 and worst second=30.0, on 150 ticks over 10 seconds of wall clock, so 15 Hz actually delivered.
Timing each window from the previous window's last tick fixes it, roughly:
span = (self._newest - prev_last) if self.ticks >= 1 else 0.0with intervals = ticks rather than ticks - 1. Frozen time then lands in the window where the loop resumed. It also measures the trailing partial window at end of run honestly, which is the phantom slowdown you were working around, so the not started skip below can go with it and you get that second of data back.
max_gap needs the same treatment, see the note on the ticks < 2 branch.
| if ticks < 2 or span <= 0: | ||
| continue |
There was a problem hiding this comment.
Second half of the same fix. drain() has already run by the time this continue fires, and it zeroed max_gap, so a gap this window measured is silently discarded.
Same 4 second freeze as in the note above, but resumed 20 ms before a reporter tick so this window drained holding a single tick: longest stall came back 33 ms and every figure read healthy. Whether a freeze is visible at all ends up depending on where it lands against the 1 Hz reporter, and with the current windowing this is the only figure carrying stalls at all.
Accumulate the worst gap for the run's lifetime and read it without clearing, rather than resetting it per drain.
| # Thin wrapper around lerobot.scripts.lerobot_rollout that installs | ||
| # the control-loop rate meter before handing over to it. | ||
| "lelab.rollout_metrics", |
There was a problem hiding this comment.
#75 replaces this same element with "lelab.rollout_frames", its own wrapper for the demo page's camera tee, and that module has the identical shape: main() installs its hooks then calls lerobot.scripts.lerobot_rollout.main. Only one name can occupy this slot.
Git will conflict here, but the conflict is the harmless part. The trap is the resolution: picking one module name leaves the other wrapper never imported, and since both swallow every failure by design, nothing raises. The losing feature just reports nothing, forever, on a run that otherwise looks fine.
Worth deciding now, whichever way you prefer: one wrapper module that installs both sets of hooks, or a chain where one wrapper imports the other's install function. Whoever lands first should probably leave the seam in place for the second.
The problem
There is currently no way to answer a basic question about a running policy: is it actually stepping at 30 Hz?
lerobot does notice when the control loop misses its target, but it reports it as a warning per missed iteration, buried in the inference log:
That number is
1/dtfor a single slow iteration, so it swings wildly and says nothing about the run as a whole. Meanwhile the UI shows the same thing whether the policy is holding 30 Hz or crawling at 8 — a stopwatch and a progress bar. Since a policy behaves differently when it is stepped at a fraction of the rate it was trained at, that gap matters when you are trying to work out whether a disappointing rollout is a bad checkpoint or a starved control loop.What this adds
A live readout of the real control-loop rate, measured rather than assumed.
On the Inference page
Three figures under the timer, plus the last minute of history against the target:
The average is also carried into the completion toast, so a finished run states the rate it actually ran at.
In demo mode
The same measurement, presented for a different audience. Demo mode (#75) is meant to be watched from across a room, so it gets a single colour-coded pill next to the running indicator rather than a panel:
Green while the loop holds its target, amber below 85%, red below 55% — enough to catch a degrading demo at a glance, small enough to stay out of the way.
How it works
The measurement point is
ThreadSafeRobot.get_observation: the rollout control loop calls it exactly once per iteration, so counting those calls over a window is the loop rate. No lerobot patch, no instrumentation inside the loop body.lelab/rollout_metrics.py— a thin wrapper aroundlerobot.scripts.lerobot_rollout(the module the inference subprocess now spawns). It installs the counter, then hands over. Every failure path is swallowed: a run whose meter fails to install simply reports no rate.lelab/rollout.py—_pump_stdoutalready read every output line to find the rollout-start marker, so it now also picks up the rate samples and lerobot's ownRobot: … | FPS: 30 | …banner. The target is read, not assumed fromRolloutConfig's default, so the display stays honest if the config changes./inference-statusonce a second. Nothing new is plumbed; they just render fields that are now in the response.New fields on
/inference-status:target_fps,fps_now,fps_avg,fps_min,fps_worst_gap_ms,fps_ticks,fps_stale.Two details worth a reviewer's eye
Windows are timed by their own ticks, not by the reporter's clock. The obvious implementation — count ticks, divide by one second — reports a phantom slowdown for the half-filled window left behind when a run ends. A healthy 20 Hz run finishing mid-window read as 10 Hz, which would have put a scary "worst second" on every clean run. Each window is now timed from its own first to its own last tick, and a window with fewer than two ticks reports nothing at all. That silence is also what lets the server mark the sample stale (3 s) instead of showing a frozen number as live.
This is not lerobot's warning number. lerobot logs
1/dtfor one slow iteration; a single 230 ms hiccup among 29 healthy iterations makes it shout0.4 Hzwhile the second genuinely ran at 24 Hz. Both are true, they answer different questions. That is exactly why the longest-stall figure is reported separately — it is where a single freeze shows up, instead of being averaged away.Testing
frontend/dist/is intentionally untouched —build_frontend.ymlrebuilds it onmain.