Docs/accuracy investigation - #2
Merged
Merged
Conversation
Records the 28.8-day chrony soak and the analysis of Caesium's 0.81 ms offset against internet stratum-1 sources. - HANDOFF.md: current state and next action (time-base validation pulse) - HWTIMESTAMPING.md: conditional design sketch for ISR-boundary stamping - session.md: full narrative record, including corrections Reports stay untracked under the existing *.log ignore, so both docs reproduce every number inline. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Hzy3M4jnzg2r3SuWMAt664
Implements the next action from HANDOFF.md: measure whether Caesium's served time agrees with its own PPS, which is the one thing that distinguishes WAN asymmetry from the device genuinely running slow. Firmware: a 50us pulse on GPIO33, fired one *served* second after the PPS the NTP path is interpolating from, using the same calibrated usPerPps that hwTimeToNtp() uses. Scoped against the real PPS on GPIO16, the edge-to-edge interval is E_c directly. Both edges are generated by the device, so the host clock never enters the result. Guarded by -D TIMEBASE_PULSE (env esp32-poe-iso-timebase); the default build is unchanged. Tooling: saleae_mcp.py talks to the Logic 2 MCP automation server over HTTP; pps_capture.py runs and analyses captures; measure_ntp.py does NTP offset/delay with interface pinning, since Tailscale otherwise captures the route to Caesium and triples the round trip. Findings so far (TIMEBASE.md): - The obvious design — analyzer timestamps vs host NTP — cannot work. Logic 2's absolute timestamps are applied in software at capture start; eight captures of the same PPS scatter across 115.7 ms, ~40x the effect being measured. Recorded so it is not retried. - PPS is clean over 274 s: 0 dropped pulses, 73.1 ns cycle-to-cycle jitter, 10.8 ns pulse-width sd. Eliminates the "PPS is glitching" class of explanation. - Server processing measures 24.0 us here, independently reproducing serv1's 23.7 us on different hardware and a different client. - The Logic 8's own crystal is -9.62 ppm with 9 us of wander over 274 s. Irrelevant to E_c, which is a one-second interval. Not yet run: needs the debug build flashed (no OTA) and GPIO33 wired. Probe interference on the PPS line also needs a ground-lead fix; the capture tool identifies the PPS by pulse width and reports rejected edges so a noisy run cannot be mistaken for a good one. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MCHe2uuhEfTM4rWU6YdgFG
Runs the time-base validation pulse against Caesium's PPS and closes
the accuracy investigation.
Result: E_c = +5.070us median over 600 consecutive seconds, sd 0.246us,
600/600 pulses, 0 dropped PPS edges. A 60s pilot gave +5.080us — the
two runs agree to 10ns.
Caesium's served time tracks its own PPS to five microseconds, which is
160x too small to account for the 0.81ms gap against internet stratum-1
consensus. Hypothesis (b), the device running ~0.78ms slow, required
the served time to disagree with its own PPS and is therefore dead.
Hypothesis (a), shared-segment WAN asymmetry, is the only surviving
mechanism: >=0.56ms of the gap is network.
The sign is the consistency check, not just the magnitude. PPS ISR
latency L makes ppsTimeMicros late, which makes the served time slow by
L and delays the pulse by the same L — so a faithful time base predicts
a positive E_c. HANDOFF.md predicted that before the rig was wired.
A negative or scattered result would have indicted the measurement.
The budget is now bounded by two measured terms rather than one
measured and one assumed:
device packet path <= 0.25 ms (|bias| <= delta/2)
device time base 0.005 ms (measured here)
device total <= 0.255 ms
observed gap 0.81 ms
-> WAN asymmetry >= 0.56 ms
Firmware now drives GPIO33 and GPIO32 together — same output register
bank, one atomic write, no skew — so either pin can be probed. GPIO32
is adjacent to the PPS pin, which makes it a far easier target on a
dense header where GPIO34-39 are input-only and a slip onto one is
indistinguishable from a bad contact.
Also recorded: what this does NOT prove (the PPS is still trusted
against UTC on the NEO-M9N spec; the packet-path term is bounded, not
measured), and why gotcha 3 is now load-bearing — calibrating against
an internet reference would bake >=1.12ms of ISP asymmetry into a
device whose LAN clients never traverse that path.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01MCHe2uuhEfTM4rWU6YdgFG
Keeps every logic-analyzer capture from this session in the repo. The rig was awkward to assemble and these are not cheap to reproduce, so the raw edge lists travel with the conclusions rather than living in temp directories. Index and channel map in data/README.md. Load test, run while the rig was still wired: 180s of E_c capture while flooding the device with NTP from six threads. Robustness result is good. Caesium sustained 838,510 queries at 4711 req/s with zero failures and p99 RTT of 1.406ms, barely above its 1.05ms floor. No dropped requests, no loss of GPS lock. E_c degraded from +5.070us median to +22.900us, max +189.490us. This is mostly instrument, not device, and the writeup says so explicitly: the pulse is emitted from loop() on core 1 and busy-waits to its target, so preemption at that instant delays the edge — while the NTP response is timestamped inline in tcpip_thread the moment the packet arrives, with no loop() scheduling in that path and T2/T3 stamped separately so s_proc cancels. The run therefore bounds pulse emission jitter under load and only indirectly speaks to served accuracy. Some of it could be genuine, since PPS ISR latency may also rise under load, but this measurement cannot separate the two. It does not affect the WAN conclusion: the 28.8-day chrony comparison ran at normal poll intervals, which is the quiet regime, so +5.07us remains the applicable figure. Separating device from instrument would need the pulse emitted from an ISR or hardware timer rather than from loop(). Noted as worth doing only if serving accuracy under sustained load becomes a real question. Firmware left on the timebase build and the probes left in place, per request — no rollback. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MCHe2uuhEfTM4rWU6YdgFG
Merging b7fa5eb surfaced a structural limitation of this measurement worth writing down before it is lost. That commit fixes PVT(n) pairing with PPS(n+1)'s timestamp under Core 1 starvation, publishing a timeState exactly 1.000000s in the past. The validation pulse cannot see it: target becomes ppsTimeMicros(n+1) + usPerPps, so the pulse fires one second after PPS(n+1) and lands on PPS(n+2). Nearest-edge matching then reports a small E_c, exactly as if nothing were wrong. E_c therefore certifies the sub-second phase of the time base and says nothing about epoch labelling. The two checks are complementary. This does not weaken the conclusions: the 0.81ms gap is sub-second, and a 1s error would have been unmissable across 4119 chrony samples at sd 0.103ms. But E_c should not be read as validating the whole time base. Also noted: the load test ran on pre-b7fa5eb firmware, at exactly the request rate that provokes the starvation path, and recorded only RTT rather than offset — so it could not have detected that failure mode either. Re-running the flood on merged firmware while recording offset would close it. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MCHe2uuhEfTM4rWU6YdgFG
Reruns the load test on firmware merged with b7fa5eb, recording NTP offset alongside E_c. The earlier run predated the fix and captured only RTT, so it could not have detected the epoch-labelling failure that commit guards against — E_c is structurally blind to it. The guard holds: 0 whole-second errors in 757,859 queries at 4258 req/s, the exact rate that provokes Core 1 starvation. Served accuracy does not degrade under load. NTP offset held at median +0.359ms with sd 0.084ms across 757,859 samples — tighter than the quiet spot-checks taken earlier. 2 failures (0.0003%). Delay floor 0.419ms, better than the 1.05ms idle figure. This confirms the earlier caveat that the E_c tail is instrument rather than device. If the time base genuinely wandered by 128us under load the offsets would show it; 0.084ms of spread across three quarters of a million samples says it does not. The median also barely moves (5.120 -> 5.980us) while mean and max blow out — the signature of occasional preemption spikes on an otherwise clean distribution, exactly as predicted for an edge emitted from loop(). Quiet E_c is unchanged by the fix (+5.070 -> +5.120us, sd 0.246 -> 0.206), so the guard costs nothing in the normal regime. Also fixes a real bug in pps_capture.py: Logic 2 resolves export and save paths in its own process, so a relative --outdir silently wrote elsewhere and the run then failed on a missing file. Paths are now absolute. Archived captures include a .sal that reopens directly in the Logic 2 GUI; .gitignore keeps *.sal out except under data/. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MCHe2uuhEfTM4rWU6YdgFG
Measurement is done, so the device is back on the default esp32-poe-iso env. Verified on hardware: stratum 1 within ~5s of reset, GPIO32/33 silent on the analyzer, PPS still pulsing. Confirmed rather than assumed that the debug env does not leak into production. Building the default env from this branch and from origin/main yields binaries differing in 69 bytes of 579,136 — the embedded build timestamp and the app-descriptor hash that covers it. The firmware source diff against main is 84 lines added, 0 removed, every one inside #ifdef TIMEBASE_PULSE. Shipping this branch's default build is shipping main's firmware. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MCHe2uuhEfTM4rWU6YdgFG
b7fa5eb's sequence counter only catches a PPS edge that fires after latchUartCycleSequence(). That latch is the first statement in loop(), so if the task is never *scheduled* for a full second — blocked at vTaskDelay(1) while tcpip_thread holds the core — it resumes, latches ppsSequence at its already-incremented value, and the comparison comes out equal while the buffered PVT still predates the edge whose timestamp is held: resume t=1010ms -> latch seq = n+1 (edge already fired) -> parse PVT(n) from FIFO (still unread) -> ppsAge = 10ms (fresh stamp, passes) -> seq n+1 == n+1 (guard passes) -> publish epoch(n) with PPS(n+1)'s timestamp Nothing observable separates the two states — the timestamp is fresh either way, so ppsAge cannot help. The gap between loop iterations is the only remaining evidence. latchUartCycleSequence() now records it and marks the cycle suspect past UART_CYCLE_MAX_GAP_US (500ms). pvtCallback drops such a publish but leaves ppsFlag set: the edge is good, only the PVT is stale, so the next PVT pairs with it correctly one second later rather than waiting two. getDroppedPairingCount() is surfaced on the periodic debug line so a starved device is visible in the field. Validated on hardware in both directions via a new esp32-poe-iso-starvetest env, which stalls loop() 1050ms every ~6s. The 1050ms walks the resume phase forward 50ms each time, sweeping the whole second so the narrow window is hit repeatedly rather than by luck, while leaving clean seconds so normal syncing still runs. Identical injection, identical probe, only the guard differs: pre-fix fixed samples 5990 5988 whole-second errors 1005 (17%) 0 offset sd 373.669ms 0.242ms unsynced (LI=3) 0 0 Every pre-fix error sat at exactly -1.000000s, the predicted signature. LI=3 was never set: the device reported itself synchronised while serving time a full second wrong, one sample in six — the failure mode that matters, because a client cannot detect it. Regression check on the production build with no injection: 4294 samples, 0 failures, 0 unsynced, offset sd 0.191ms, 0 dropped pairings. The guard costs nothing in normal operation. esp32-poe-iso-starvetest is a test fixture and must never be deployed. Under continuous starvation it correctly refuses to publish and the device reports LI=3 — the right failure direction, but not a state to ship into. Device left on the production build and verified. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MCHe2uuhEfTM4rWU6YdgFG
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Random messing