Skip to content

The clock that lied

We added one boring check to the analysis, "are there gaps in the data?", and it unravelled a bug in the machine, not the code. It also proved that an earlier diagnosis of ours was wrong.

A boring check fails

To finish Phase 1, battery_report.py got a data completeness check: no gap longer than 3 s between /battery samples in Elasticsearch. We expected it to pass trivially. It failed on our "good" run from Experiment #1:

| Data completeness (max gap) | <= 3 s | 5.4 s | FAIL |

Follow the data down the stack

Suspect 1: the shipper drops data. We have the ground truth, so we checked the MCAP bag directly (analysis/bag_gaps.py):

header stamp: 546 msgs over 294.0s; top gaps: [3.44, 3.43, 3.43, 3.43, 3.43]

The gaps were in the bag too, so the shipper was innocent. And they were suspiciously identical: 3.43 s, every ~33 s.

Suspect 2: the node stalls. We ran battery_sim alone with a control: a plain Python loop doing sleep(0.5) and timing itself with the monotonic clock. The control never stalled once. The node "stalled" on schedule.

The arithmetic that cracked it: 546 messages at 2 Hz is 273 s of ticks, but the timestamps spanned 294 s. The node wasn't missing ticks. Time itself was jumping forward between them.

Catching the clock in the act

$ python3 scripts/clock_check.py 75
  t+  8.5s  wall clock stepped +2.932s
  t+ 40.8s  wall clock stepped +2.931s
  t+ 73.1s  wall clock stepped +2.930s
wall-vs-monotonic drift over 75s: +8.793s

$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
tsc        # WSL2 normally uses hyperv_clocksource_tsc_page

The WSL update that killed our first session installed kernel 6.18, and it booted with the tsc clocksource. Linux's monotonic clock runs about 9% slow on it. Time sync notices and steps the wall clock forward about 2.9 s every 32 s. ROS timestamps use wall time; timers use the slow monotonic clock.

We had it wrong earlier

In Phase 1 we blamed a 6.7% drain error on "Python timers firing late". We were wrong. The 40 s smoke run contained one clock step (about 3 s out of about 43 s), and that was the error. Measuring dt from the clock was still the right fix, for the wrong reason. The old post now carries a correction.

Making it observable, forever

Where What
make doctor Fails if the clocksource isn't hyperv_clocksource_tsc_page
make clock-check Measures wall-clock steps over 40 s
es_shipper stats Reports clock_offset_s (wall minus monotonic) every 10 s, charted in Kibana
Analysis The completeness check stays: it flags untrustworthy timestamps, which matter as much as missing data

The host fix needs root, so it's left for the human:

# Immediate (until the next WSL restart):
echo hyperv_clocksource_tsc_page | sudo tee /sys/devices/system/clocksource/clocksource0/current_clocksource
# Persistent: in Windows, %UserProfile%\.wslconfig
# [wsl2]
# kernelCommandLine = clocksource=hyperv_clocksource_tsc_page

Update: the clocksource wasn't it

Chris switched to hyperv_clocksource_tsc_page, and the steps continued: still +2.93 s every 32 s. Measured against the Windows clock over 60 s: Windows 65.82 s, Linux wall 66.18 s, Linux monotonic 60.32 s. The kernel's timekeeping runs ~8.4% slow under every clocksource, and systemd-timesyncd (polling at its 32 s minimum) steps the wall clock to compensate. The likely culprit is the new WSL kernel itself. make doctor now measures the clock rate against Windows (scripts/clock_rate.py) instead of trusting the clocksource name. A check that passes while the problem persists is worse than no check.

Lessons learned

  • Keep the raw data. Without the MCAP bag we would have "fixed" the shipper.
  • Run a control. One sleep() loop separated "the node" from "the machine".
  • Do the arithmetic. Message count × period vs. timestamp span exposed the clock.
  • Correct the record. A devlog that hides its wrong turns teaches the wrong lessons.
  • For a robot, time is data. Gazebo will run on simulated time, but anything stamped with wall time inherits the host's clock bugs.