From 409e9c4d83dc35faf1bc7ca9a369130bd930b7bc Mon Sep 17 00:00:00 2001 From: Joseph <162703152+josephnef@users.noreply.github.com> Date: Sat, 10 Oct 2026 09:00:04 +0300 Subject: [PATCH 1/2] stream: per-frame air-side timing in addr3 + a hardware-clocked marker Six bytes in every stream frame's addr3 (no receiver read it: every consumer keys on addr2 and slices the body at +24) carry the transmitter's backlog depth, capture->send_packet and its predicted TSF at the send; a periodic probe-response marker (DEVOURER_STREAM_TIMING=N) carries the host<->TSF fit state and the window's stage statistics. rxdemo fits the transmitter's clock from hardware egress pairs only and reports a one-way submit->arrival and capture->arrival latency per frame (rx.frame lat_us / c2a_us, rx.timing per marker). The producer's capture time arrives through the stdin control escape streamtx and duplex now share (opcode 4, CAPTURE_TS); the Python producers emit it with --capture-ts. Measured first (tests/probe_resp_egress_tsf_check.sh): an injected probe response is MAC-stamped with the egress TSF on Jaguar2, Jaguar3 and Kestrel but not on Jaguar1, where the 8821AU writes a counter that is neither TSF port -- hence AdapterCaps::hw_injected_mgmt_txtsf, and the hardware beacon as Jaguar1's clock carrier on a fixed channel. Both fits restart on a >50 ms discontinuity (the beacon arm pulses the TSF; a re-init zeroes it). The TX fit never reads a register on the send path: one ReadTsf per 100 ms. On air (tests/stream_timing_onair.sh, CF-924AC witness): submit->air p50 ~100-150 us on 8812CU / 8832CU / paced 8812EU, ~400 us with depth 2 on the async 8821AU; a 20 ms producer delay on every 10th record is recovered as 20.08 ms on 10% of frames; the clock survives slot hopping; svctx and duplex stamp identically. A producer that outruns the chip (8812EU on 5 GHz, 20 ms bulk-OUT stalls) pins capture->send at its clip -- a true backlog reading, documented with the harness's pacing knob. Co-Authored-By: Claude Fable 5.1 --- CLAUDE.md | 13 + CMakeLists.txt | 7 + README.md | 3 + docs/logging.md | 8 +- docs/stream-timing.md | 150 ++++++++++ examples/common/host_tsf_fit.h | 135 +++++++++ examples/common/stream_stdin.h | 75 +++++ examples/common/stream_stdin_selftest.cpp | 28 ++ examples/common/stream_timing_tx.h | 215 +++++++++++++++ examples/common/tsf_linfit.h | 55 ++++ examples/duplex/main.cpp | 59 ++-- examples/rx/main.cpp | 90 ++++++ examples/streamtx/main.cpp | 40 ++- examples/svctx/main.cpp | 14 + examples/timesync/timesync.h | 48 +--- src/AdapterCaps.h | 18 +- src/RxPacket.h | 6 +- src/StreamTelemetry.h | 319 ++++++++++++++++++++++ src/TxStats.h | 7 + src/UsbTransport.cpp | 2 + src/jaguar1/RtlJaguarDevice.cpp | 4 + src/jaguar2/RtlJaguar2Device.cpp | 1 + src/jaguar3/RtlJaguar3Device.cpp | 1 + src/kestrel/RtlKestrelDevice.cpp | 1 + tests/README.md | 17 ++ tests/probe_resp_egress_tsf_check.sh | 108 ++++++++ tests/probe_resp_egress_tx.cpp | 125 +++++++++ tests/stream_telemetry_selftest.cpp | 137 ++++++++++ tests/stream_timing_analyze.py | 131 +++++++++ tests/stream_timing_onair.sh | 254 +++++++++++++++++ tools/precoder/adaptive_link.py | 12 +- tools/precoder/fused_fec_tx.py | 6 +- tools/precoder/stream.py | 66 +++++ tools/precoder/stream_tx.py | 12 +- tools/precoder/tun_p2p.py | 11 +- 35 files changed, 2091 insertions(+), 87 deletions(-) create mode 100644 docs/stream-timing.md create mode 100644 examples/common/host_tsf_fit.h create mode 100644 examples/common/stream_timing_tx.h create mode 100644 examples/common/tsf_linfit.h create mode 100644 src/StreamTelemetry.h create mode 100755 tests/probe_resp_egress_tsf_check.sh create mode 100644 tests/probe_resp_egress_tx.cpp create mode 100644 tests/stream_telemetry_selftest.cpp create mode 100644 tests/stream_timing_analyze.py create mode 100755 tests/stream_timing_onair.sh diff --git a/CLAUDE.md b/CLAUDE.md index 4212fe58..9da74222 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -451,6 +451,19 @@ temporal layer and injects each at its ladder's rate (RS outer code + corrupt-frame salvage) lives in `tools/precoder/` (`docs/fused-fec.md`). +Per-frame TX-side timing rides every stream frame's addr3 (six bytes no +receiver otherwise reads: backlog depth, capture→send, the transmitter's +predicted TSF) plus a periodic marker (`DEVOURER_STREAM_TIMING=N`), so +`rxdemo` reports a one-way submit→arrival and capture→arrival latency per +frame. The receiver's clock fit takes **hardware egress pairs only**: an +injected probe response is MAC-stamped on Jaguar2/3 and Kestrel but **not on +Jaguar1** (`AdapterCaps::hw_injected_mgmt_txtsf`), where the hardware beacon +carries the clock on a fixed channel and a hopping session gets durations +only. The producer's capture stamp arrives through the stdin control escape +(opcode 4) streamtx and duplex share. Wire format, clock model and the +measured matrix, floor first: `docs/stream-timing.md`; harness +`tests/stream_timing_onair.sh`. + ## Frequency hopping `IRadio::FastRetune(channel)` — lean intra-band, same-bandwidth retune on diff --git a/CMakeLists.txt b/CMakeLists.txt index 4b7dd096..a3c66b10 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -240,6 +240,7 @@ add_library(devourer src/hopset/HopsetState.h src/hopset/HopsetTypes.h src/hopset/HopsetWire.h + src/StreamTelemetry.h src/hopset/HopsetAuthority.h src/hopset/HopsetFollower.h src/hopset/HopsetPolicy.h @@ -1427,6 +1428,12 @@ add_executable(HopsetWireSelftest tests/hopset_wire_selftest.cpp) target_link_libraries(HopsetWireSelftest PRIVATE devourer) add_test(NAME hopset_wire_kat COMMAND HopsetWireSelftest) +# Headless guard for src/StreamTelemetry.h (the addr3 per-frame field + the +# timing marker IE): known-answer bytes, version rejection, TSF unwrap, latency. +add_executable(StreamTelemetrySelftest tests/stream_telemetry_selftest.cpp) +target_link_libraries(StreamTelemetrySelftest PRIVATE devourer) +add_test(NAME stream_telemetry_kat COMMAND StreamTelemetrySelftest) + add_executable(HopsetProtoSelftest tests/hopset_proto_selftest.cpp) target_link_libraries(HopsetProtoSelftest PRIVATE devourer) add_test(NAME hopset_proto_matrix COMMAND HopsetProtoSelftest) diff --git a/README.md b/README.md index a8eb5f31..31bf272c 100644 --- a/README.md +++ b/README.md @@ -301,6 +301,9 @@ per-chip quirks notes at the bottom. controller design, [its validation](docs/adaptive-link-validation.md), and the [building blocks](docs/adaptive-link-building-blocks.md): what each knob (power, rate, bandwidth, hopping) measurably buys. +- [Stream timing](docs/stream-timing.md) — per-frame air-side timing in the + stream link: backlog, capture→send and a hardware-clocked one-way latency + per frame, carried in header bytes no receiver otherwise reads. - [Fused FEC](docs/fused-fec.md) — the cross-layer error-protection stack: per-layer PHY rates, corrupt-frame salvage, outer erasure code. - [Aggregation & hardware ACK](docs/aggregation.md) — USB TX aggregation, diff --git a/docs/logging.md b/docs/logging.md index 82ffcdbf..b0f4ea17 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -88,7 +88,8 @@ Emitters: L = library, RX/TX/... = demo. Optional fields in [brackets]; | ev | emitter | fields | |---|---|---| | `rx.pkt` | RX | n, len (first 10 + every 100th frame) | -| `rx.frame` | RX (`DEVOURER_STREAM_OUT`), duplex | rate, len, crc, icv, rssi[2], evm[2], snr[2], seq, tsfl, bw, stbc, ldpc, sgi, paggr, ppdu, fc1 (FC flags byte; bit3 = 802.11 RETRY), sa hex, body hex; `tx_tsf` (sender's hardware egress TSF) on beacons/probe-responses only. SA gate: canonical-SA with `DEVOURER_RX_AGG_SA` unset; when set, that filter ("canon"/mac/"any") selects the stream instead | +| `rx.frame` | RX (`DEVOURER_STREAM_OUT`), duplex | rate, len, crc, icv, rssi[2], evm[2], snr[2], seq, tsfl, bw, stbc, ldpc, sgi, paggr, ppdu, fc1 (FC flags byte; bit3 = 802.11 RETRY), sa hex, a3 hex (addr3 verbatim), body hex; `tx_tsf` (sender's hardware egress TSF) on beacons/probe-responses only. When addr3 decodes as the stream timing field (`src/StreamTelemetry.h`, RX only): tel=1, depth (frames behind this one on the TX host), c2s_us (capture→send_packet; cap=1 when from the producer's CAPTURE_TS stamp, else from the stdin read), and once the receiver has fitted the transmitter's clock from its egress-stamped frames: lat_us (predicted submit→hardware arrival, one-way) and c2a_us (capture→arrival, cap=1 frames). SA gate: canonical-SA with `DEVOURER_RX_AGG_SA` unset; when set, that filter ("canon"/mac/"any") selects the stream instead | +| `rx.timing` | RX | the transmitter's stream timing marker (probe response, canonical SA) decoded: frames, tq_p50_us, tq_max_us (stdin read→send), tw_p50_us, tw_max_us (send_packet wall time), c2s_p50_us, c2s_max_us, depth_max, captured, tsf_pred, tx_fit_ppm, tx_fit_n, presp_stamped (this part's injected probe responses carry a hardware egress TSF), beacon (a TBTT beacon carries the clock instead), tx_async; plus this receiver's clock fit: tsfl, pairs, rx_fit_ppm, rx_resid_us, rx_resets (a transmitter restart resets its TSF; the fit starts over past 50 ms) | | `rx.body` | RX (`DEVOURER_DUMP_BODY`) | rate, rssi[2], evm[2], snr[2], crc, len, body hex | | `rx.corrupt` | RX (`DEVOURER_RX_DUMP_ALL`) | len, crc, icv, rate, bw, stbc, ldpc, sgi, rssi[2], evm[2], snr[2] | | `rx.txhit` | RX, TX | hits, total_rx, len, seq, paggr, ppdu, rate, bw, stbc, ldpc, ppdu_type — canonical-SA (57:42:75:05:d6:00) matcher; rate/ldpc prove what encoding was decoded (8814A reports ldpc=0 always — no HW indicator); ppdu_type is the AX RXD format nibble (7=HE_SU, 8=HE_ERSU; 255 on pre-AX chips) | @@ -185,8 +186,9 @@ Emitters: L = library, RX/TX/... = demo. Optional fields in [brackets]; ### Stream demos / misc | ev | emitter | fields | |---|---|---| -| `stream.rx` / `stream.ctl` / `stream.eof` / `stream.tx` | duplex (stdout), streamtx (stderr) | hits / op, len / tx_count, [bytes] / n, ok, psdu, [total] | -| `stream.done` | streamtx (stderr) | sent | +| `stream.rx` / `stream.ctl` / `stream.eof` / `stream.tx` | duplex (stdout), streamtx (stderr) | hits / op, len, [applied 0 — streamtx reports the live-knob opcodes it does not apply; op 4 CAPTURE_TS is consumed silently by both] / tx_count, [bytes] / n, ok, psdu, [total] | +| `stream.timing` | streamtx, svctx, duplex (`DEVOURER_STREAM_TIMING=N`, every N data frames) | ok (the marker frame's send), frames, tq_p50_us, tq_max_us, tw_p50_us, tw_max_us, c2s_p50_us, c2s_max_us, depth_max, captured, tsf_pred, fit_ppm, fit_n, fit_resid_us, fit_resets (the host↔TSF fit, one ReadTsf per 100 ms; a reset = the chip's TSF jumped under it), presp_stamped, beacon, tx_async — the same window the marker carries on air (`examples/common/stream_timing_tx.h`) | +| `stream.done` | streamtx (stderr) | sent, capture_dropped (CAPTURE_TS stamps that no record followed) | | `svc.stats` | svctx | frames, crit, t0, t1, t2, t3plus | | `doctor.verdict` | doctor | verdict, reasons "0x…", efuse_reads, efuse_mismatch, efuse_bad_id, efuse_id, fw_attempted, fw_ready, rx_ok, rx_crc, init | diff --git a/docs/stream-timing.md b/docs/stream-timing.md new file mode 100644 index 00000000..e8adc107 --- /dev/null +++ b/docs/stream-timing.md @@ -0,0 +1,150 @@ +# Per-frame air-side timing in the stream link + +What the transmitter knew about a frame when it sent it — how long the frame +waited on the host, how deep the backlog behind it was, when the producer +captured it — travels with the frame, in header bytes no receiver otherwise +reads, so the ground station can show a measured latency per frame and per +stage instead of an estimate. The idea is kestrel-air's slice-header +telemetry; the clock underneath is devourer's own: the MAC TSF. + +## What travels, and where + +**Every stream frame** (`streamtx`, `svctx`, `duplex`) carries six bytes in +the 802.11 header's addr3 — the BSSID field of a probe request, which the +stream demos used to fill with the source address and which no consumer reads +(every one keys on addr2 and slices the body at +24). The FEC bodies are +byte-for-byte untouched and the MTU is unchanged: + +| bytes | field | +|---|---| +| 0 | version and flags: capture stamp present, TSF present, depth present, async TX | +| 1 | depth: frames handed to the transport whose completion has not been reaped | +| 2–3 | the transmitter's predicted TSF at `send_packet`, low 16 bits in 10 µs units | +| 4–5 | capture → `send_packet`, 10 µs units, clipped at 655 ms | + +The version is chosen so the old addr3 contents (the canonical SA) decode as +"no telemetry" rather than as garbage values. + +**A periodic marker** (`DEVOURER_STREAM_TIMING=N`, every N data frames, its +own frame like the hop sync marker) carries the absolute pair (predicted TSF, +host clock), the state of the transmitter's host↔TSF fit, and the window since +the previous marker: p50/max of stdin-read→send, of the `send_packet` wall +time (kestrel-air's T_WRITE), of capture→send, the deepest backlog, and how +many frames had a producer stamp. The marker is a probe response with the +canonical SA, and on the parts whose MAC stamps an injected probe response +with its egress TSF, the marker's own timestamp field is the hardware pair +the receiver's clock fit needs. + +**The producer's capture time** arrives through the stdin control escape +shared with the duplex demo's live knobs: a length word with its top bit set +introduces ``; opcode 4 is `CAPTURE_TS ` +and applies to the next record. The Python producers emit it with +`--capture-ts` (and `--capture-delay N:MS` for the check below). A stamp taken +at record emission is a proxy; a real encoder stamps at capture. + +## The clock, and why the marker must be hardware-stamped + +The transmitter never reads a register per frame (the standing send-path +rule: a control transfer is ~200–340 µs on USB). A poller samples `ReadTsf()` +once per 100 ms against the host's monotonic clock and a least-squares line +predicts the TSF at every `send_packet` call. Its residual is the read-latency +jitter, tens of µs. A sample more than 50 ms off the line means the chip's TSF +was reset under the fit (arming the Jaguar1 beacon pulses it; a re-init zeroes +it), and the fit starts over rather than averaging across the jump: a fit +that averages across the beacon arm reads a 62 ms "latency" that decays over +the session as the poisoned intercept washes out (measured on the 8821AU, +which is why the beacon is armed before the fit samples). + +The receiver maps each frame's hardware arrival (`tsfl`) onto the +transmitter's TSF with a fit of its own, and that fit is fed **only from +hardware egress pairs**: frames whose timestamp field the transmitter's MAC +wrote at the instant of transmission. A pair built from a software stamp would +fold the mean one-way latency into the fit's offset and leave only jitter. +Which frames qualify was measured, not assumed +(`tests/probe_resp_egress_tsf_check.sh`, a constant in the field and an +independent witness reading it back): + +| transmitter | injected probe response / beacon | hardware TBTT beacon | +|---|---|---| +| Jaguar2 8812BU | stamped, 34 µs spread | stamped | +| Jaguar3 8812CU, 8812EU | stamped, 38–41 µs spread | stamped | +| Kestrel 8832CU | stamped, 35 µs spread | stamped | +| Jaguar1 8821AU | **not a TSF**: a counter that is neither TSF port, held ~7 frames at a time | stamped, 3.2 µs spread | + +So on Jaguar2, Jaguar3 and Kestrel the marker frame itself is the pair, on +any channel, hopping included. On Jaguar1 the marker's flags say its stamp is +not to be trusted and, on a fixed channel, the transmitter arms the hardware +beacon with the same SA as the clock carrier (`AdapterCaps::hw_injected_mgmt_txtsf` +is the per-part fact). A hopping Jaguar1 session has no egress pair the +beacon can follow and reports stage durations without an absolute latency; +the 8812AU and 8814AU are unmeasured and treated as the 8821AU. The receiver +also restarts its fit when a pair lands more than 50 ms off the line: a +transmitter that restarts resets its TSF. + +The per-frame one-way latency is then arrival − unwrapped predicted submit +TSF: host jitter on the transmit side only, hardware on the receive side. + +## Measured + +`tests/stream_timing_onair.sh`, one CF-924AC (8822BU) witness, 20 s runs, +producer paced at 2 ms. The floor is measured first: identical runs, +repeated, so a later difference has something to be judged against. + +| transmitter | runs | submit→air p50 (µs) | run-to-run sd | capture→air p50 | capture→send p50 | depth max | fit residual | +|---|---|---|---|---|---|---|---| +| Jaguar3 8812CU, ch6 | 5 | 98–146 | 3–16 | 148–172 | 30 | 0 | < 1 µs | +| Kestrel 8832CU, ch6 | 2 | 90 | 0 | 126 | 30 | 0 | < 1 µs | +| Jaguar1 8821AU, ch6 (beacon clock) | 3 | 358–434 | 34 | 436 | 30–40 | 2 | < 1 µs | +| Jaguar3 8812EU, ch36, producer at 15 ms | 2 | 109–122 | 6 | 150 | 30 | 0 | < 1 µs | +| Jaguar3 8812CU, `svctx` (no producer stamp) | 1 | 155 | — | — | — | 0 | < 1 µs | +| Jaguar3 8812CU, `duplex` (TX+RX on one chip) | 1 | 124 | — | 150 | 30 | 0 | < 1 µs | + +The checks every cell passes or fails on: + +- **The producer delay is recovered.** With `--capture-delay 10:20` the + producer sleeps 20 ms between the stamp and every 10th record: the receiver + sees 10.2% (Jaguar3) and 9.8% (Kestrel) of stamped frames standing 20.08 + and 20.09 ms above the rest. The field tracks the producer, not the pipe. +- **Hopping survives.** A slot-hopping Jaguar3 transmitter (1/6/11 at 50 ms) + keeps the marker and the clock through retunes — 4837 frames with an + absolute latency in 20 s — and the window's stdin-read→send maximum, 5.3 ms, + is the retune showing up where it should. +- **Corrupted frames never feed the clock.** With the witness keeping + CRC-failed frames the fit's residual stays below 1 µs. + +The adversarial readings, in the same breath: + +- **The depth field is honest about the transport.** Jaguar1's asynchronous + bulk-OUT shows a backlog of 2 and a 400 µs one-way figure where the + synchronous families show 0 and ~100 µs. That is the transport's shape, not + a defect the telemetry found. +- **A producer that outruns the chip pins capture→send at its clip.** The + 8812EU on 5 GHz stalls its synchronous send for the full 20 ms bulk-OUT + timeout now and then (the window's send-time maximum reads 20.99 ms, the + known 5 GHz flood behaviour of that module, `docs/8822e-quirks.md`); at a + 2 ms producer pace the stdin pipe fills and every capture→send reads + 655 ms — a true reading of the backlog, and useless as a steady-state + number (that run's submit→air median was 206–235 µs, with a 10 ms p99 from + frames queued behind the stalls). The harness runs that part at a 15 ms + pace (`PACE_US`), where it reads like the 8812CU. +- **A record pushed during bring-up wedges the duplex TXDMA.** The duplex + demo spawns its TX thread before the chip is up; a feeder that writes at + once gets every send timed out for the whole run, marker or no marker. The + harness's feeder idles 12 s as the ARQ harness's does, and the timing fit + arms itself on the first record rather than at thread start, so no + register read or beacon arm lands inside a bring-up on any demo. +- **The first seconds are the pipe, not the link.** The producer fills the + stdin pipe while the chip is brought up, so the first ~1000 records arrive + with stamps seconds old. The analyzer drops a 4 s warm-up for that reason. +- **svctx has no producer stamp.** It pre-reads and replays a clip, so its + capture→send is each NAL's loop iteration; a live stdin mode is a follow-up. + +## Reading it + +`rxdemo` with `DEVOURER_STREAM_OUT=1`: every `rx.frame` carries `a3` and, +when it decodes, `tel`, `depth`, `c2s_us`, `cap`, and — once the receiver has +the transmitter's clock — `lat_us` and `c2a_us`. Each marker is an `rx.timing` +event with the transmitter's window and this receiver's fit state; the +transmitter logs the same window as `stream.timing`. Schema: `docs/logging.md`. +`tests/stream_timing_analyze.py` turns one capture into a summary line and the +checks above. diff --git a/examples/common/host_tsf_fit.h b/examples/common/host_tsf_fit.h new file mode 100644 index 00000000..585e2f77 --- /dev/null +++ b/examples/common/host_tsf_fit.h @@ -0,0 +1,135 @@ +// HostTsfFit — predict the chip's TSF for any host instant without reading a +// register per frame. +// +// The stream-timing field (src/StreamTelemetry.h) wants the transmitter's TSF +// at every send_packet call, and the standing rule is that nothing reads a +// register on the send path (a control transfer is ~200-340 µs on USB and +// serialises against the bulk pipe). So a poller thread samples +// IRadio::ReadTsf() once per period against std::chrono::steady_clock, and a +// least-squares line maps host ns -> TSF µs; predict() is pure arithmetic. +// The residual is the host's read-latency jitter, tens of µs on USB +// (docs/timing-accuracy.md), which is far below the millisecond-scale +// latencies the field reports. +// +// A read that throws (USB failure, or the race with a heavy RX bulk-IN load +// the IRadio contract warns about) or returns 0 is dropped. A part whose +// ReadTsf is not ported returns 0 every time (the RTL8733B): after +// kGiveUpZeros consecutive zeros the fit declares itself unsupported and the +// caller marks its frames has_tsf=0. ready() follows LinFit's 16-sample floor: +// 1.6 s at the default 100 ms period, the timesync-master cadence. +#pragma once + +#include +#include +#include +#include +#include + +#include "IRadio.h" +#include "tsf_linfit.h" + +class HostTsfFit { + public: + static constexpr int kGiveUpZeros = 5; + + explicit HostTsfFit(IRadio &dev, int period_ms = 100) + : _dev(dev), _period_ms(period_ms) {} + ~HostTsfFit() { stop(); } + HostTsfFit(const HostTsfFit &) = delete; + HostTsfFit &operator=(const HostTsfFit &) = delete; + + void start() { + if (_thread.joinable()) return; + _stop.store(false); + _thread = std::thread([this] { run(); }); + } + void stop() { + _stop.store(true); + if (_thread.joinable()) _thread.join(); + } + + static uint64_t host_ns() { + return static_cast( + std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count()); + } + + bool unsupported() const { return _unsupported.load(); } + bool ready() const { + std::lock_guard lk(_mu); + return _fit.ready(); + } + // Predicted TSF (µs) at the given host instant; 0 before ready(). + uint64_t predict(uint64_t host_ns_at) const { + std::lock_guard lk(_mu); + if (!_fit.ready()) return 0; + const double tsf = _fit.at(static_cast(host_ns_at) / 1000.0); + return tsf < 0 ? 0 : static_cast(tsf); + } + // Host-clock vs TSF rate in ppm (0.0 before ready()). + double ppm() const { + std::lock_guard lk(_mu); + return _fit.ready() ? _fit.ppm() : 0.0; + } + int samples() const { + std::lock_guard lk(_mu); + return static_cast(_fit.n); + } + // Residual of the latest sample against the fit built before it (µs); a + // live quality figure for the stream.timing event. + double last_resid_us() const { return _last_resid.load(); } + // Times the fit started over because a sample landed more than + // kDiscontinuityUs off the line: the chip's TSF was reset under us (the + // Jaguar1 beacon arm pulses DUAL_TSF_RST; a re-init zeroes it). + int resets() const { return _resets.load(); } + static constexpr double kDiscontinuityUs = 50000.0; + + private: + void run() { + int zeros = 0; + while (!_stop.load()) { + const uint64_t t0 = host_ns(); + uint64_t tsf = 0; + try { + tsf = _dev.ReadTsf(); + } catch (...) { + tsf = 0; + } + const uint64_t t1 = host_ns(); + if (tsf == 0) { + if (++zeros >= kGiveUpZeros && samples() == 0) { + _unsupported.store(true); + return; + } + } else { + zeros = 0; + // The read's midpoint is the best host estimate of when the chip + // latched the value; half the round trip is the irreducible error. + const double x = static_cast(t0 / 2 + t1 / 2) / 1000.0; + std::lock_guard lk(_mu); + if (_fit.ready()) { + const double r = static_cast(tsf) - _fit.at(x); + _last_resid.store(r); + if (r > kDiscontinuityUs || r < -kDiscontinuityUs) { + _fit = tsffit::LinFit{}; + _resets.fetch_add(1); + } + } + _fit.add(x, static_cast(tsf)); + } + for (int i = 0; i < _period_ms && !_stop.load(); ++i) + std::this_thread::sleep_for(std::chrono::milliseconds(1)); + } + } + + IRadio &_dev; + const int _period_ms; + mutable std::mutex _mu; + tsffit::LinFit _fit; + std::atomic _stop{false}; + std::atomic _unsupported{false}; + std::atomic _last_resid{0.0}; + std::atomic _resets{0}; + std::thread _thread; +}; diff --git a/examples/common/stream_stdin.h b/examples/common/stream_stdin.h index a5aea3d5..ade54aa7 100644 --- a/examples/common/stream_stdin.h +++ b/examples/common/stream_stdin.h @@ -104,6 +104,36 @@ inline ReadResult read_body(std::FILE *f, std::vector &out, return n ? read_exact(f, out.data(), n) : ReadResult::Ok; } +/* ---- the control escape ------------------------------------------------- + * + * A length word with its top bit set is not a PSDU: the body is a control + * TLV, , bounded at kCtlMax rather than at the PSDU maximum. + * The duplex demo introduced it for the adaptive link's live knobs; streamtx + * honours it too. Opcodes are one namespace across the demos; a demo that + * does not implement one ignores it (and says so in its stream.ctl event). */ +constexpr uint32_t kCtlFlag = 0x80000000u; +constexpr size_t kCtlMax = 256; +enum CtlOp : uint8_t { + kCtlSetPwr = 1, /* flat TXAGC override */ + kCtlSetRate = 2, /* live TX rate */ + kCtlSetChan = 3, /* SetMonitorChannel */ + kCtlCaptureTs = 4, /* the producer's capture time of the NEXT + * data record, CLOCK_MONOTONIC ns on the same host. The + * TX measures capture->send_packet from it and carries + * that in the frame (src/StreamTelemetry.h). A stamp + * followed by another stamp, or by EOF, is dropped. */ +}; + +/* Decode a kCtlCaptureTs body. False unless it is exactly op 4 + 8 bytes. */ +inline bool parse_capture_ts(const std::vector &ctl, + std::uint64_t &ns) { + if (ctl.size() != 9 || ctl[0] != kCtlCaptureTs) return false; + ns = 0; + for (int i = 0; i < 8; ++i) + ns |= static_cast(ctl[1 + i]) << (8 * i); + return true; +} + enum class RecordResult { Ok, // a complete record is in `out` Eof, // clean close: nothing at all where a record would have started @@ -111,6 +141,7 @@ enum class RecordResult { EofMidBody, // the length word arrived, then the stream closed before a byte // of its body — one record lost, cleanly BadLength, // zero, or larger than the caller's bound + Control, // read_item only: a control TLV is in `ctl`, not a record }; // Read one whole record. `max` bounds the body. When @@ -143,4 +174,48 @@ inline RecordResult read_record(std::FILE *f, std::vector &out, return RecordResult::Short; // unreachable; keeps every toolchain quiet } +/* Read one stdin item: a data record (RecordResult::Ok, body in `out`) or a + * control TLV (RecordResult::Control, in `ctl`). Every other state + * is read_record's. A control body outside [1, kCtlMax] is BadLength with the + * raw length word in `raw_len`, so the caller can say which it was. */ +inline RecordResult read_item(std::FILE *f, std::vector &out, + std::vector &ctl, std::size_t max, + std::uint32_t *raw_len = nullptr) { + std::uint32_t len = 0; + switch (read_length(f, len)) { + case ReadResult::Eof: + return RecordResult::Eof; + case ReadResult::Short: + return RecordResult::Short; + case ReadResult::Ok: + break; + } + if (raw_len) + *raw_len = len; + if (len & kCtlFlag) { + const std::uint32_t clen = len & ~kCtlFlag; + if (clen == 0 || clen > kCtlMax) + return RecordResult::BadLength; + switch (read_body(f, ctl, clen)) { + case ReadResult::Ok: + return RecordResult::Control; + case ReadResult::Eof: + return RecordResult::EofMidBody; + case ReadResult::Short: + return RecordResult::Short; + } + } + if (len == 0 || len > max) + return RecordResult::BadLength; + switch (read_body(f, out, len)) { + case ReadResult::Ok: + return RecordResult::Ok; + case ReadResult::Eof: + return RecordResult::EofMidBody; + case ReadResult::Short: + return RecordResult::Short; + } + return RecordResult::Short; +} + } // namespace stream_stdin diff --git a/examples/common/stream_stdin_selftest.cpp b/examples/common/stream_stdin_selftest.cpp index 07224b2d..f6083fc8 100644 --- a/examples/common/stream_stdin_selftest.cpp +++ b/examples/common/stream_stdin_selftest.cpp @@ -218,6 +218,34 @@ static int do_states() { return 7; } } + /* read_item: a CAPTURE_TS control TLV (op 4 + u64) followed by a record. */ + { + std::vector bytes(4); + put_u32_le(bytes.data(), stream_stdin::kCtlFlag | 9u); + bytes.push_back(stream_stdin::kCtlCaptureTs); + const uint64_t ns = 0x0102030405060708ull; + for (int i = 0; i < 8; ++i) bytes.push_back(uint8_t(ns >> (8 * i))); + std::vector r = rec(2, 2); // length word 2, two body bytes + bytes.insert(bytes.end(), r.begin(), r.end()); + std::FILE *f = std::tmpfile(); + if (!f) return 7; + std::fwrite(bytes.data(), 1, bytes.size(), f); + std::rewind(f); + std::vector body, ctl; + uint64_t got = 0; + const bool ok = + stream_stdin::read_item(f, body, ctl, 16) == stream_stdin::RecordResult::Control && + stream_stdin::parse_capture_ts(ctl, got) && got == ns && + stream_stdin::read_item(f, body, ctl, 16) == stream_stdin::RecordResult::Ok && + body.size() == 2 && + stream_stdin::read_item(f, body, ctl, 16) == stream_stdin::RecordResult::Eof; + std::fclose(f); + if (!ok) { + std::fprintf(stderr, "stream_stdin_selftest: FAIL — read_item did not " + "deliver CAPTURE_TS then the record\n"); + return 7; + } + } std::fprintf(stdout, "stream_stdin_selftest: %zu record states OK\n", cases.size()); return 0; diff --git a/examples/common/stream_timing_tx.h b/examples/common/stream_timing_tx.h new file mode 100644 index 00000000..154dfeac --- /dev/null +++ b/examples/common/stream_timing_tx.h @@ -0,0 +1,215 @@ +// StreamTimingTx — the TX side of the per-frame timing telemetry +// (src/StreamTelemetry.h), shared by streamtx, svctx and duplex so the three +// demos stamp identically. +// +// DEVOURER_STREAM_TIMING=N air a timing marker every N data frames and run +// the host<->TSF fit (one ReadTsf per 100 ms, off +// the send path). Unset or 0: no marker, no fit — +// the addr3 field still carries depth and +// capture->send on every frame, at zero cost. +// +// Per frame the demo calls stamp() right before send_packet (fills the six +// addr3 bytes) and sent() right after it; maybe_marker() before each data +// frame airs the marker when due. On a part whose MAC does not stamp an +// injected probe response (AdapterCaps::hw_injected_mgmt_txtsf == false, +// Jaguar1) and a fixed channel, start() arms the hardware TBTT beacon with the +// same SA so the receiver still gets hardware egress pairs; the marker's flags +// tell the receiver which frames to trust. A hopping session on such a part +// gets no absolute latency and says so. +#pragma once + +#include +#include +#include +#include +#include +#include + +#include "AdapterCaps.h" +#include "Event.h" +#include "IRadio.h" +#include "StreamTelemetry.h" +#include "TxStats.h" +#include "host_tsf_fit.h" +#include "logger.h" + +class StreamTimingTx { + public: + using FrameTiming = devourer::stream_timing::FrameTiming; + using TimingMarker = devourer::stream_timing::TimingMarker; + + StreamTimingTx(IRadio &dev, devourer::EventSink &ev, Logger &log, + const uint8_t sa[6], bool hopping) + : _dev(dev), _ev(ev), _log(log), _hopping(hopping) { + std::memcpy(_sa, sa, 6); + } + ~StreamTimingTx() { stop(); } + + static uint64_t now_ns() { return HostTsfFit::host_ns(); } + + // Reads DEVOURER_STREAM_TIMING. The fit thread and the beacon fallback are + // armed on the first record (ensure_started), not here: the duplex demo + // spawns its TX thread before the chip is brought up, and a ReadTsf or a + // StartBeacon landing inside bring-up is not something to find out about + // on air. By the first record the chip is up on every demo. + void start() { + if (const char *e = std::getenv("DEVOURER_STREAM_TIMING")) { + _marker_every = std::atol(e); + if (_marker_every < 0) _marker_every = 0; + } + } + void ensure_started() { + if (_started) return; + _started = true; + const auto caps = _dev.GetAdapterCaps(); + _tx_async = caps.generation == devourer::ChipGeneration::Jaguar1; + _presp_stamped = caps.hw_injected_mgmt_txtsf; + if (_marker_every == 0) return; + /* The beacon first: arming it pulses the TSF on Jaguar1, and the fit + * must not sample across that (it would restart anyway). */ + if (!_presp_stamped && caps.hw_beacon_txtsf && !_hopping) { + std::vector bcn; + devourer::stream_timing::append_beacon_mpdu(bcn, _sa, _channel); + _beacon = _dev.StartBeacon(bcn.data(), bcn.size(), 100); + _log.info("stream timing: injected frames are not egress-stamped on this " + "part — hardware beacon {} as the clock carrier", + _beacon ? "armed" : "REFUSED (no absolute latency)"); + } else if (!_presp_stamped) { + _log.warn("stream timing: no egress-stamped frame on this part while " + "hopping — the receiver gets stage durations, not absolute latency"); + } + _fit = std::make_unique(_dev); + _fit->start(); + _log.info("stream timing: marker every {} frames, fit {}", _marker_every, + _fit->unsupported() ? "unsupported" : "running"); + } + void stop() { + if (_beacon) { + _dev.StopBeacon(); + _beacon = false; + } + if (_fit) _fit->stop(); + } + + // The marker and the beacon name the channel in their DS parameter set. + void set_channel(uint8_t ch) { _channel = ch; } + + // Right before send_packet. `read_ns` = when the record came off stdin, + // `capture_ns` = the producer's stamp (has_capture) or read_ns. Fills the six + // addr3 bytes; remembers the instants for sent(). + void stamp(uint8_t *addr3, uint64_t read_ns, uint64_t capture_ns, bool has_capture) { + ensure_started(); + _t0 = now_ns(); + _read_ns = read_ns; + _capture_ns = capture_ns; + _has_capture = has_capture; + const auto st = _dev.GetTxStats(); + _depth = st.inflight; + FrameTiming t; + t.has_capture = has_capture; + t.has_depth = true; + t.tx_async = _tx_async; + t.depth = static_cast(_depth > 255 ? 255 : _depth); + const uint64_t c2s = _t0 > capture_ns ? (_t0 - capture_ns) / 1000 : 0; + t.c2s10 = devourer::stream_timing::clip10(c2s); + if (_fit && _fit->ready()) { + const uint64_t tsf = _fit->predict(_t0); + t.has_tsf = tsf != 0; + t.tsf10_lo = static_cast((tsf / 10) & 0xffff); + } + t.encode(addr3); + } + // Right after send_packet returned. + void sent() { + const uint64_t t1 = now_ns(); + const uint64_t tq = _t0 > _read_ns ? (_t0 - _read_ns) / 1000 : 0; + const uint64_t tw = (t1 - _t0) / 1000; + const uint64_t c2s = _t0 > _capture_ns ? (_t0 - _capture_ns) / 1000 : 0; + _window.add(tq, tw, c2s, _has_capture, _depth); + ++_frames; + } + + // Before each data frame: air the marker when due. `radiotap` is the stream + // radiotap header. Returns true when a marker was sent. + bool maybe_marker(const std::vector &radiotap) { + if (_marker_every == 0 || (_frames % static_cast(_marker_every)) != 0 || + _frames == _last_marker_frame) + return false; + _last_marker_frame = _frames; + TimingMarker m; + if (_presp_stamped) m.flags |= devourer::stream_timing::kMkPrespStamped; + if (_beacon) m.flags |= devourer::stream_timing::kMkBeaconRunning; + if (_tx_async) m.flags |= devourer::stream_timing::kMkTxAsync; + if (_capture_seen) m.flags |= devourer::stream_timing::kMkCaptureSource; + const uint64_t hn = now_ns(); + m.host_ns = hn; + if (_fit && _fit->ready()) { + m.flags |= devourer::stream_timing::kMkFitReady; + m.tsf_pred_us = _fit->predict(hn); + m.fit_ppm_x100 = static_cast(_fit->ppm() * 100.0); + } + m.fit_n = static_cast(_fit ? (_fit->samples() > 0xffff ? 0xffff : _fit->samples()) : 0); + _window.drain_into(m); + _buf.clear(); + _buf.insert(_buf.end(), radiotap.begin(), radiotap.end()); + devourer::stream_timing::append_marker_mpdu(_buf, _sa, _channel, m); + const bool ok = _dev.send_packet(_buf.data(), _buf.size()); + devourer::Ev(_ev, "stream.timing") + .f("ok", ok ? 1 : 0) + .f("frames", m.frames) + .f("tq_p50_us", m.t_queue_p50_10 * 10) + .f("tq_max_us", m.t_queue_max_10 * 10) + .f("tw_p50_us", m.t_write_p50_10 * 10) + .f("tw_max_us", m.t_write_max_10 * 10) + .f("c2s_p50_us", m.c2s_p50_10 * 10) + .f("c2s_max_us", m.c2s_max_10 * 10) + .f("depth_max", m.depth_max) + .f("captured", m.captured) + .f("tsf_pred", (unsigned long long)m.tsf_pred_us) + .f("fit_ppm", _fit && _fit->ready() ? _fit->ppm() : 0.0) + .f("fit_n", m.fit_n) + .f("fit_resid_us", _fit ? _fit->last_resid_us() : 0.0) + .f("fit_resets", _fit ? _fit->resets() : 0) + .f("presp_stamped", _presp_stamped ? 1 : 0) + .f("beacon", _beacon ? 1 : 0) + .f("tx_async", _tx_async ? 1 : 0); + return true; + } + + // A producer capture stamp arrived (kCtlCaptureTs): remembered for the next + // data record. A second stamp before a record replaces the first (counted). + void capture_stamp(uint64_t ns) { + if (_pending_capture) ++_capture_dropped; + _pending_capture = true; + _pending_capture_ns = ns; + _capture_seen = true; + } + // Take the pending stamp for the record read at `read_ns` (or fall back to it). + uint64_t take_capture(uint64_t read_ns, bool &has_capture) { + ensure_started(); + has_capture = _pending_capture; + _pending_capture = false; + return has_capture ? _pending_capture_ns : read_ns; + } + uint64_t capture_dropped() const { return _capture_dropped; } + + private: + IRadio &_dev; + devourer::EventSink &_ev; + Logger &_log; + const bool _hopping; + uint8_t _sa[6]; + uint8_t _channel = 0; + long _marker_every = 0; + bool _started = false; + bool _tx_async = false, _presp_stamped = false, _beacon = false; + std::unique_ptr _fit; + devourer::stream_timing::TimingWindow _window; + std::vector _buf; + uint64_t _frames = 0, _last_marker_frame = UINT64_MAX; + uint64_t _t0 = 0, _read_ns = 0, _capture_ns = 0; + bool _has_capture = false; + uint32_t _depth = 0; + bool _pending_capture = false, _capture_seen = false; + uint64_t _pending_capture_ns = 0, _capture_dropped = 0; +}; diff --git a/examples/common/tsf_linfit.h b/examples/common/tsf_linfit.h new file mode 100644 index 00000000..388a60df --- /dev/null +++ b/examples/common/tsf_linfit.h @@ -0,0 +1,55 @@ +// Shared by timesync, tdma-style schedulers and the stream-timing TX fit: a +// 32->64-bit TSF reconstruction and an offset-normalised incremental +// least-squares line. Header-only, no device dependency. examples/timesync +// re-exports both under its own namespace. +#pragma once + +#include + +namespace tsffit { + +// 32→64-bit TSF reconstruction (the MAC latches only the low 32 bits per frame; +// it wraps every ~71 min). One per clock source. +struct Recon { + int64_t hi = 0; + uint32_t plo = 0; + bool init = false; + int64_t operator()(uint32_t lo) { + if (init && lo < plo) hi += (1LL << 32); + plo = lo; + init = true; + return hi + lo; + } +}; + +// Incremental ordinary-least-squares fit y = a·x + b, offset-normalized to the +// first sample so the sums stay well within double precision over a long run. +struct LinFit { + bool init = false; + double x0 = 0, y0 = 0; + long long n = 0; + double sx = 0, sy = 0, sxx = 0, sxy = 0; + + void add(double x, double y) { + if (!init) { x0 = x; y0 = y; init = true; } + double xi = x - x0, yi = y - y0; + ++n; sx += xi; sy += yi; sxx += xi * xi; sxy += xi * yi; + } + bool ready() const { return n >= 16; } + double slope() const { + double den = (double)n * sxx - sx * sx; + return den == 0 ? 1.0 : ((double)n * sxy - sx * sy) / den; + } + double intercept() const { return (sy - slope() * sx) / (double)n; } + // Predicted y at x. + double at(double x) const { return y0 + slope() * (x - x0) + intercept(); } + // Inverse: the x that yields a given y (for scheduling in the fitted domain). + double inverse(double y) const { + double a = slope(); + return x0 + (a == 0 ? 0 : (y - y0 - intercept()) / a); + } + // Fitted rate offset in ppm (slope = dy/dx, for same-unit clocks). + double ppm() const { return (slope() - 1.0) * 1e6; } +}; + +} // namespace tsffit diff --git a/examples/duplex/main.cpp b/examples/duplex/main.cpp index 23f560fb..501bd7d2 100644 --- a/examples/duplex/main.cpp +++ b/examples/duplex/main.cpp @@ -74,6 +74,7 @@ #include "env_config.h" #include "logger.h" #include "stream_stdin.h" +#include "stream_timing_tx.h" #define USB_VENDOR_ID 0x0bda @@ -301,6 +302,7 @@ struct TxArgs { size_t max_psdu; std::atomic *should_stop; std::shared_ptr logger; + int channel; // named in the timing marker's DS parameter set }; static void tx_thread(TxArgs args) { @@ -308,28 +310,35 @@ static void tx_thread(TxArgs args) { std::vector tx_buf; tx_buf.reserve(g_radiotap.size() + dot11.size() + args.max_psdu); long tx_count = 0; + /* Per-frame timing telemetry in addr3 + the DEVOURER_STREAM_TIMING marker + * (examples/common/stream_timing_tx.h). The marker rides this thread's + * send lock like every other frame. */ + StreamTimingTx timing(*args.rtl, *g_ev, *args.logger, kCanonicalSa, + /*hopping=*/false); + timing.set_channel(static_cast(args.channel)); + timing.start(); + std::vector ctl; while (!args.should_stop->load()) { - // This demo reads the length itself rather than using read_record: its top - // bit escapes to a control TLV with its own, much smaller bound, so the - // length has to be inspected before the body may be read. + // The stdin control escape (stream_stdin.h): a length word with its top + // bit set is a control TLV — the adaptive link's live + // knobs and the producer's capture stamp — not a PSDU. uint32_t len = 0; - if (stream_stdin::read_length(stdin, len) != stream_stdin::ReadResult::Ok) { + std::vector psdu; + const auto r = stream_stdin::read_item(stdin, psdu, ctl, args.max_psdu, &len); + if (r == stream_stdin::RecordResult::Eof || r == stream_stdin::RecordResult::Short) { // Clean EOF or short read — TX side done. RX keeps running. devourer::Ev(*g_ev, "stream.eof").f("tx_count", tx_count); break; } - - // Control-opcode escape: top bit set -> the body is a control TLV (the - // adaptive link's live knobs), not a PSDU. . - if (len & 0x80000000u) { - uint32_t clen = len & 0x7fffffffu; - if (clen == 0 || clen > 256) break; - std::vector ctl; - if (stream_stdin::read_body(stdin, ctl, clen) != - stream_stdin::ReadResult::Ok) - break; + if (r == stream_stdin::RecordResult::Control) { + const uint32_t clen = static_cast(ctl.size()); uint8_t op = ctl[0]; + uint64_t cap_ns = 0; + if (stream_stdin::parse_capture_ts(ctl, cap_ns)) { + timing.capture_stamp(cap_ns); + continue; + } if (op == 1 && clen >= 2) { // SET_PWR /* Flat TXAGC override via the generation-agnostic runtime TX-power * API (previously Jaguar1-only): applies live on every family. */ @@ -347,30 +356,38 @@ static void tx_thread(TxArgs args) { devourer::Ev(*g_ev, "stream.ctl").f("op", op).f("len", clen); continue; } - - if (len == 0 || len > args.max_psdu) { - args.logger->error("tx PSDU len {} out of range (max {})", len, + if (r == stream_stdin::RecordResult::BadLength) { + args.logger->error("tx PSDU len {:#x} out of range (max {})", len, args.max_psdu); break; } - std::vector psdu; - if (stream_stdin::read_body(stdin, psdu, len) != - stream_stdin::ReadResult::Ok) { + if (r == stream_stdin::RecordResult::EofMidBody) { /* EOF mid-PSDU: `bytes` = the expected PSDU length that was cut short. */ devourer::Ev(*g_ev, "stream.eof").f("tx_count", tx_count).f("bytes", len); break; } + const uint64_t read_ns = StreamTimingTx::now_ns(); + bool has_capture = false; + const uint64_t capture_ns = timing.take_capture(read_ns, has_capture); tx_buf.clear(); + size_t addr3_off = 0; { std::lock_guard lk(g_rt_mu); // live rate may be rewritten tx_buf.insert(tx_buf.end(), g_radiotap.begin(), g_radiotap.end()); + addr3_off = g_radiotap.size() + 16; } tx_buf.insert(tx_buf.end(), dot11.begin(), dot11.end()); tx_buf.insert(tx_buf.end(), psdu.begin(), psdu.end()); bool ok; { std::lock_guard lk(g_send_mu); + { + std::lock_guard lr(g_rt_mu); + timing.maybe_marker(g_radiotap); + } + timing.stamp(tx_buf.data() + addr3_off, read_ns, capture_ns, has_capture); ok = args.rtl->send_packet(tx_buf.data(), tx_buf.size()); + timing.sent(); } ++tx_count; if (tx_count <= 5 || tx_count % 500 == 0) { @@ -506,7 +523,7 @@ int main(int argc, char **argv) { // Spawn TX thread first; it'll block on stdin until our peer pushes a // length-prefixed PSDU. Then drop into Init() (the RX loop) in the main // thread. - TxArgs txa{rtlDevice, interval_ms, max_psdu, &should_stop, logger}; + TxArgs txa{rtlDevice, interval_ms, max_psdu, &should_stop, logger, channel}; std::thread tx{tx_thread, std::move(txa)}; /* Receipt emitter (DEVOURER_RX_RECEIPT_MS): every tick, encode the current diff --git a/examples/rx/main.cpp b/examples/rx/main.cpp index cc16bd45..06278e6c 100644 --- a/examples/rx/main.cpp +++ b/examples/rx/main.cpp @@ -1,6 +1,7 @@ #include #include #include +#include #include #include #include @@ -27,7 +28,9 @@ #include "RadiotapBuilder.h" #include "LinkHealth.h" #include "RxPacket.h" +#include "StreamTelemetry.h" #include "SweepSpec.h" +#include "tsf_linfit.h" #include "TriggerParse.h" #include "caps_event.h" #include "station_arm_env.h" @@ -650,6 +653,22 @@ static RxAgg g_rxagg; * rx.txhit matcher and the "canon" aggregate filter below. */ static const uint8_t kTxSa[6] = {0x57, 0x42, 0x75, 0x05, 0xd6, 0x00}; +/* Stream timing (src/StreamTelemetry.h): the transmitter's clock, fitted from + * hardware egress pairs only — its TBTT beacons (FC 0x80) always, its injected + * probe-response markers (FC 0x50) once a marker has said this part stamps + * them. local = this receiver's reconstructed 64-bit tsfl of canonical-SA + * frames; remote = the transmitter's TSF. Never fed from a software stamp + * (that would fold the mean latency into the offset). */ +static tsffit::Recon g_rt_recon; +static tsffit::LinFit g_rt_fit; +static bool g_rt_presp_stamped = false; +static uint64_t g_rt_pairs = 0, g_rt_resets = 0; +static double g_rt_resid_us = 0; +/* A transmitter that restarts resets its TSF (InitWrite zeroes it): the next + * egress pair lands seconds off the line. Anything past this is a new clock, + * not jitter (a marker's own spread is tens of µs), so the fit starts over. */ +static constexpr double kRtDiscontinuityUs = 50000.0; + /* DEVOURER_RX_AGG_SA: restrict the per-frame aggregate to frames whose SA * matches — the active-sounding filter, so ambient traffic doesn't pollute the * per-bin link stats (a sweep dwell hears everything on the bin; H(f) wants @@ -1119,6 +1138,55 @@ static void packetProcessor(const Packet &packet) { static const bool keep_corrupted = std::getenv("DEVOURER_RX_KEEP_CORRUPTED") != nullptr; const bool corrupted = packet.RxAtrib.crc_err || packet.RxAtrib.icv_err; + /* Stream timing: the transmitter's clock from its egress-stamped frames, + * and its periodic marker as an event of its own. */ + int64_t rt_local = 0; + if (sa_canon && !corrupted && packet.Data.size() >= 24) { + rt_local = g_rt_recon(packet.RxAtrib.tsfl); + const uint8_t fc0 = packet.Data[0]; + devourer::stream_timing::TimingMarker mk; + if (fc0 == 0x50 && + devourer::stream_timing::TimingMarker::decode( + packet.Data.data() + 24, packet.Data.size() - 24, mk)) { + g_rt_presp_stamped = mk.flags & devourer::stream_timing::kMkPrespStamped; + devourer::Ev(*g_ev, "rx.timing") + .f("frames", mk.frames) + .f("tq_p50_us", mk.t_queue_p50_10 * 10) + .f("tq_max_us", mk.t_queue_max_10 * 10) + .f("tw_p50_us", mk.t_write_p50_10 * 10) + .f("tw_max_us", mk.t_write_max_10 * 10) + .f("c2s_p50_us", mk.c2s_p50_10 * 10) + .f("c2s_max_us", mk.c2s_max_10 * 10) + .f("depth_max", mk.depth_max) + .f("captured", mk.captured) + .f("tsf_pred", (unsigned long long)mk.tsf_pred_us) + .f("tx_fit_ppm", mk.fit_ppm_x100 / 100.0) + .f("tx_fit_n", mk.fit_n) + .f("presp_stamped", g_rt_presp_stamped ? 1 : 0) + .f("beacon", (mk.flags & devourer::stream_timing::kMkBeaconRunning) ? 1 : 0) + .f("tx_async", (mk.flags & devourer::stream_timing::kMkTxAsync) ? 1 : 0) + .f("tsfl", packet.RxAtrib.tsfl) + .f("pairs", (unsigned long long)g_rt_pairs) + .f("rx_fit_ppm", g_rt_fit.ready() ? g_rt_fit.ppm() : 0.0) + .f("rx_resid_us", g_rt_resid_us) + .f("rx_resets", (unsigned long long)g_rt_resets); + } + if (fc0 == 0x80 || (fc0 == 0x50 && g_rt_presp_stamped)) { + if (auto tx = packet.TxEgressTsf()) { + if (g_rt_fit.ready()) { + g_rt_resid_us = static_cast(*tx) - + g_rt_fit.at(static_cast(rt_local)); + if (std::fabs(g_rt_resid_us) > kRtDiscontinuityUs) { + g_rt_fit = tsffit::LinFit{}; + g_rt_pairs = 0; + ++g_rt_resets; + } + } + g_rt_fit.add(static_cast(rt_local), static_cast(*tx)); + ++g_rt_pairs; + } + } + } if (sa_canon) { const int hits = ++g_txhits; if (hits <= 10 || hits % 100 == 0) { @@ -1280,6 +1348,28 @@ static void packetProcessor(const Packet &packet) { /* sa: the transmitter address the stream gate matched on — lets a * multi-source consumer attribute frames when the gate is "any". */ ev.hex("sa", packet.Data.data() + 10, 6); + /* a3: addr3 verbatim, and its decode when it is the per-frame timing + * field (src/StreamTelemetry.h): depth behind the frame on the TX host, + * capture->send (cap=1: from the producer's stamp, else from the stdin + * read), and — once this receiver has the transmitter's clock — + * lat_us = submit->arrival one-way, c2a_us = capture->arrival. */ + ev.hex("a3", packet.Data.data() + 16, 6); + { + devourer::stream_timing::FrameTiming ft; + if (devourer::stream_timing::FrameTiming::decode(packet.Data.data() + 16, ft)) { + ev.f("tel", 1) + .f("depth", ft.depth) + .f("c2s_us", ft.c2s10 * 10) + .f("cap", ft.has_capture ? 1 : 0); + devourer::stream_timing::FrameLatency fl; + if (sa_canon && !corrupted && g_rt_fit.ready() && + devourer::stream_timing::latency( + ft, static_cast(g_rt_fit.at(static_cast(rt_local))), fl)) { + ev.f("lat_us", (long long)fl.submit_to_air_us); + if (fl.has_capture) ev.f("c2a_us", (long long)fl.capture_to_air_us); + } + } + } /* tx_tsf: the sender's hardware TX-egress TSF (beacons / probe responses * only). Pair with tsfl — the local hardware RX timestamp above — for * one-way hardware time sync with no host-clock jitter on either end. */ diff --git a/examples/streamtx/main.cpp b/examples/streamtx/main.cpp index 278ef3c9..6a53f31e 100644 --- a/examples/streamtx/main.cpp +++ b/examples/streamtx/main.cpp @@ -80,6 +80,7 @@ #include "env_config.h" #include "logger.h" #include "stream_stdin.h" +#include "stream_timing_tx.h" #define USB_VENDOR_ID 0x0bda @@ -350,6 +351,14 @@ int main(int argc, char **argv) { std::vector tx_buf; tx_buf.reserve(kStreamRadiotap.size() + dot11.size() + max_psdu); + /* Per-frame timing telemetry in addr3 + the DEVOURER_STREAM_TIMING marker + * (examples/common/stream_timing_tx.h). */ + StreamTimingTx timing(*rtlDevice, logger->events(), *logger, kCanonicalSa, + !hop_channels.empty()); + timing.set_channel(static_cast(channel)); + timing.start(); + const size_t addr3_off = kStreamRadiotap.size() + 16; + logger->info( "stream TX ready (legacy 6M OFDM, ch {}); reading length-prefixed PSDUs " "from stdin", channel); @@ -362,18 +371,31 @@ int main(int argc, char **argv) { const uint32_t hop_epoch = static_cast( std::chrono::high_resolution_clock::now().time_since_epoch().count()); std::vector sync_buf; + std::vector ctl; while (true) { std::vector psdu; uint32_t len = 0; { - const auto r = stream_stdin::read_record(stdin, psdu, max_psdu, &len); + const auto r = stream_stdin::read_item(stdin, psdu, ctl, max_psdu, &len); if (r == stream_stdin::RecordResult::Eof) break; // clean stdin close + if (r == stream_stdin::RecordResult::Control) { + /* The stdin control escape (stream_stdin.h). This demo takes the + * producer's capture stamp; the live-knob opcodes are the duplex + * demo's and are reported, not applied. */ + uint64_t ns = 0; + const bool applied = stream_stdin::parse_capture_ts(ctl, ns); + if (applied) timing.capture_stamp(ns); + else + devourer::Ev(logger->events(), "stream.ctl") + .f("op", ctl[0]).f("len", ctl.size()).f("applied", 0); + continue; + } if (r == stream_stdin::RecordResult::EofMidBody) { logger->warn("EOF mid-PSDU (expected {} bytes)", len); break; } if (r == stream_stdin::RecordResult::BadLength) { - logger->error("PSDU length {} out of range (max {}); stopping", len, + logger->error("PSDU length {:#x} out of range (max {}); stopping", len, max_psdu); break; } @@ -383,6 +405,9 @@ int main(int argc, char **argv) { std::exit(2); } } + const uint64_t read_ns = StreamTimingTx::now_ns(); + bool has_capture = false; + const uint64_t capture_ns = timing.take_capture(read_ns, has_capture); /* Retune to this PSDU's hop channel before sending. FastRetune/fast_retune * is a cheap no-op when the channel is unchanged within a dwell, so calling @@ -399,6 +424,7 @@ int main(int argc, char **argv) { int ch = hop_schedule ? hop_schedule->channel(slot, hop_channels) : hop_channels[slot % hop_channels.size()]; const bool slot_changed = (slot != last_hop_slot); + timing.set_channel(static_cast(ch)); if (slot_changed) { auto ev = devourer::Ev(logger->events(), "hop.dwell"); ev.f("slot", (unsigned long long)slot) @@ -455,12 +481,17 @@ int main(int argc, char **argv) { } } + timing.maybe_marker(kStreamRadiotap); + tx_buf.clear(); tx_buf.insert(tx_buf.end(), kStreamRadiotap.begin(), kStreamRadiotap.end()); tx_buf.insert(tx_buf.end(), dot11.begin(), dot11.end()); tx_buf.insert(tx_buf.end(), psdu.begin(), psdu.end()); + /* addr3 is the per-frame telemetry field (the body is untouched). */ + timing.stamp(tx_buf.data() + addr3_off, read_ns, capture_ns, has_capture); bool ok = rtlDevice->send_packet(tx_buf.data(), tx_buf.size()); + timing.sent(); ++tx_count; // TX progress marker (event stream rides stderr in this demo, keeping // stdout clean for downstream callers that may chain this binary). @@ -476,7 +507,10 @@ int main(int argc, char **argv) { } } - devourer::Ev(logger->events(), "stream.done").f("sent", tx_count); + timing.stop(); + devourer::Ev(logger->events(), "stream.done") + .f("sent", tx_count) + .f("capture_dropped", (unsigned long long)timing.capture_dropped()); /* Device, then interface, handle and context (DeviceSession.h). Explicit * only because the process has nothing left to do here — the destructor * does exactly the same on every other exit path. */ diff --git a/examples/svctx/main.cpp b/examples/svctx/main.cpp index 13fc947d..2afb5722 100644 --- a/examples/svctx/main.cpp +++ b/examples/svctx/main.cpp @@ -67,6 +67,7 @@ #include "env_config.h" #include "logger.h" #include "stream_stdin.h" +#include "stream_timing_tx.h" #include "svc_tx.h" #define USB_VENDOR_ID 0x0bda @@ -203,6 +204,15 @@ int main(int argc, char** argv) { const auto dot11 = build_dot11_probe_req(); + /* Per-frame timing telemetry in addr3 + the DEVOURER_STREAM_TIMING marker. + * svctx pre-reads and replays a clip, so "capture" is each NAL's loop + * iteration and has_capture stays 0; the depth, queue and write stages and + * the TSF stamp are real. */ + StreamTimingTx timing(*rtlDevice, logger->events(), *logger, kCanonicalSa, + /*hopping=*/false); + timing.set_channel(static_cast(channel)); + timing.start(); + // Read all length-prefixed NALs up front. std::vector> nals; while (true) { @@ -223,6 +233,7 @@ int main(int argc, char** argv) { long frames = 0; while (true) { for (const auto& nal : nals) { + const uint64_t nal_ns = StreamTimingTx::now_ns(); svc::NalInfo info = svc::parse_hevc_nal(nal.data(), nal.size()); const std::vector& rt = info.critical ? rt_crit @@ -237,7 +248,10 @@ int main(int argc, char** argv) { frame.insert(frame.end(), rt.begin(), rt.end()); frame.insert(frame.end(), dot11.begin(), dot11.end()); frame.insert(frame.end(), nal.begin() + off, nal.begin() + off + n); + timing.maybe_marker(rt); + timing.stamp(frame.data() + rt.size() + 16, nal_ns, nal_ns, false); rtlDevice->send_packet(frame.data(), frame.size()); + timing.sent(); if (gap_us > 0) std::this_thread::sleep_for(std::chrono::microseconds(gap_us)); } diff --git a/examples/timesync/timesync.h b/examples/timesync/timesync.h index 3b6c8734..64c64a23 100644 --- a/examples/timesync/timesync.h +++ b/examples/timesync/timesync.h @@ -24,53 +24,15 @@ #include "RadiotapBuilder.h" // devourer::TxMode / parse_tx_mode_str #include "tdma.h" // tdma::build_frame / parse_frame / kSa / Class +#include "tsf_linfit.h" // tsffit::Recon / LinFit namespace timesync { -// 32→64-bit TSF reconstruction (the MAC latches only the low 32 bits per frame; -// it wraps every ~71 min). One per clock source. -struct Recon { - int64_t hi = 0; - uint32_t plo = 0; - bool init = false; - int64_t operator()(uint32_t lo) { - if (init && lo < plo) hi += (1LL << 32); - plo = lo; - init = true; - return hi + lo; - } -}; - -// Incremental ordinary-least-squares fit y = a·x + b, offset-normalized to the -// first sample so the sums stay well within double precision over a long run. +// Recon / LinFit live in examples/common/tsf_linfit.h (shared with the +// stream-timing TX fit); re-exported here so the fit sites read unchanged. // Here x = the slave's local TSF (µs), y = the master's broadcast TSF (µs). -struct LinFit { - bool init = false; - double x0 = 0, y0 = 0; - long long n = 0; - double sx = 0, sy = 0, sxx = 0, sxy = 0; - - void add(double x, double y) { - if (!init) { x0 = x; y0 = y; init = true; } - double xi = x - x0, yi = y - y0; - ++n; sx += xi; sy += yi; sxx += xi * xi; sxy += xi * yi; - } - bool ready() const { return n >= 16; } - double slope() const { - double den = (double)n * sxx - sx * sx; - return den == 0 ? 1.0 : ((double)n * sxy - sx * sy) / den; - } - double intercept() const { return (sy - slope() * sx) / (double)n; } - // Predicted y at x. - double at(double x) const { return y0 + slope() * (x - x0) + intercept(); } - // Inverse: the x that yields a given y (for scheduling in the fitted domain). - double inverse(double y) const { - double a = slope(); - return x0 + (a == 0 ? 0 : (y - y0 - intercept()) / a); - } - // Fitted crystal offset in ppm (slope = dy/dx). - double ppm() const { return (slope() - 1.0) * 1e6; } -}; +using tsffit::Recon; +using tsffit::LinFit; // Uplink extends the downlink beacon with two more TD-tag class codes (reusing // tdma::build_frame; parse_frame round-trips any class value, so tdma.h is diff --git a/src/AdapterCaps.h b/src/AdapterCaps.h index 334abc38..08fad851 100644 --- a/src/AdapterCaps.h +++ b/src/AdapterCaps.h @@ -426,9 +426,25 @@ struct AdapterCaps { * Jaguar2/3, whose TBTT is deaf to a TSF write (measured — use * PinBeaconTbtt there), and left false on Jaguar1: its TBTT is recorded as * TSF-locked from the PinBeaconTbtt bench, but not measured through - * WriteTsf. */ + * WriteTsf. + * + * hw_injected_mgmt_txtsf: the MAC ALSO overwrites the timestamp field of a + * management frame the HOST injects through send_packet (a probe response or + * a beacon-shaped frame) with its live egress TSF, so a caller can air an + * egress-stamped frame on any channel at any time without the hardware + * beacon function. Measured with a constant in the field and an independent + * witness reading it back (tests/probe_resp_egress_tsf_check.sh): true on + * Jaguar2 (8812BU), Jaguar3 (8812CU, 8812EU) and Kestrel (8832CU), both FC + * 0x50 and 0x80, arrival−egress spread 34–41 µs over 15 s. FALSE on Jaguar1: + * the 8821AU rewrites the field, but with a free-running counter that is + * neither TSF port (both read live during the run) and repeats for ~7 + * frames at a time; its hardware TBTT beacon IS stamped (3.2 µs spread), so + * on this family the egress pair rides StartBeacon. The 8812AU/8814AU are + * unmeasured and inherit false. False on the RTL8733B (no TSF read, no + * beacon) and the MT7612U (unmeasured). */ bool hw_rx_timestamp = false; bool hw_beacon_txtsf = false; + bool hw_injected_mgmt_txtsf = false; bool tsf_write_ok = false; bool tbtt_follows_tsf = false; /* 802.11ax scheduled UL (Kestrel/RTL8852 only). trigger_ul_ok: the adapter diff --git a/src/RxPacket.h b/src/RxPacket.h index 09ad8ffa..4bec1a0c 100644 --- a/src/RxPacket.h +++ b/src/RxPacket.h @@ -146,7 +146,11 @@ struct Packet * For the frames the 802.11 MAC regenerates itself — beacons and probe * responses — the sender's MAC overwrites the 8-byte timestamp field (MPDU * bytes 24-31) with its live TSF at the instant the frame is clocked onto - * the air. That is a genuine hardware TX-egress timestamp, latched below the + * the air. For a HARDWARE beacon (StartBeacon) that holds on every + * generation; for a frame the host injects it holds only where + * AdapterCaps::hw_injected_mgmt_txtsf says so — a Jaguar1 transmitter puts + * a counter that is not a TSF there, which this accessor cannot tell from + * a real stamp. That is a genuine hardware TX-egress timestamp, latched below the * CSMA/queueing layer (bench-measured sub-µs against an independent * receiver, vs ~100+ µs for any host-side "read the clock after send" * approximation). Paired with RxAtrib.tsfl (this receiver's hardware RX diff --git a/src/StreamTelemetry.h b/src/StreamTelemetry.h new file mode 100644 index 00000000..00b024c6 --- /dev/null +++ b/src/StreamTelemetry.h @@ -0,0 +1,319 @@ +/* StreamTelemetry — per-frame TX-side timing for the stream link, in bytes the + * receiver never otherwise reads. + * + * Two carriers, both pure wire codecs here (no device dependency): + * + * 1. FrameTiming — six bytes in the 802.11 header's addr3 (BSSID) of every + * stream frame. The stream demos fill addr3 with the canonical SA today and + * no receiver reads it (every consumer keys on addr2 and slices the body at + * +24), so the FEC bodies stay byte-for-byte untouched and the MTU is + * unchanged. It carries what kestrel-air puts in its slice header: the + * backlog depth, the time from the producer's capture stamp (or the stdin + * read) to send_packet, and the low 16 bits of the transmitter's PREDICTED + * TSF at the send call in 10 µs units, so a receiver that knows the + * transmitter's clock (TsfSync fed from egress-stamped frames) gets the + * one-way submit→arrival latency per frame, host jitter on the TX side + * only. The TX never reads a register per frame: the TSF is predicted from + * a slow host-clock↔TSF fit (examples/common/host_tsf_fit.h). + * + * 2. TimingMarker — a vendor IE (221 / OUI 57:42:75 / type 0x49; 0x48 is the + * hop sync marker) on its own periodic frame, a probe response with the + * canonical SA. It carries the absolute (predicted TSF, host ns) pair, the + * fit state, and windowed stage statistics since the previous marker: + * stdin-read→send (t_queue), the previous frame's send_packet wall time + * (t_write, kestrel-air's T_WRITE), capture→send, depth. On the dies whose + * MAC stamps an injected probe response with its egress TSF (measured: + * Jaguar2, Jaguar3, Kestrel — tests/probe_resp_egress_tsf_check.sh) the + * marker frame's own timestamp field is the hardware egress pair the RX + * fit needs; where it is not (Jaguar1: the 8821AU rewrites the field with + * a counter that is not either TSF port), the flags say so and the clock + * pair rides the hardware TBTT beacon instead. A software-stamped pair must + * never feed the fit: it folds the mean latency into the offset. + * + * Versioned with backward rejection (the HopSyncMarker convention). The + * FrameTiming version lives in addr3 byte 0 bits 7..5 and is chosen so the + * canonical SA's first byte (0x57 → version 2) decodes as "no telemetry": a + * frame from a demo that never wrote the field is rejected, not misread. */ +#ifndef DEVOURER_STREAM_TELEMETRY_H +#define DEVOURER_STREAM_TELEMETRY_H + +#include +#include +#include +#include +#include +#include + +namespace devourer { +namespace stream_timing { + +/* ---- units ----------------------------------------------------------- */ + +/* Stage times travel as u16 in 10 µs units (655.35 ms range), clipped. */ +inline uint16_t clip10(uint64_t us) { + const uint64_t t = us / 10; + return t > 0xffff ? 0xffff : static_cast(t); +} + +/* The TSF travels as the low 16 bits of (tsf_us / 10): a 655.36 ms wrap. + * Unwrap against a nearby absolute (the receiver's mapped arrival): the fit + * error is tens of µs, so the nearest congruent value is the right one as long + * as |arrival − submit| < 327 ms, which any live stream satisfies. */ +inline constexpr int64_t kTsf10WrapUs = 655360; +inline int64_t unwrap_tsf10(uint16_t lo16, int64_t near_us) { + const int64_t base = near_us - (((near_us % kTsf10WrapUs) + kTsf10WrapUs) % kTsf10WrapUs) + + static_cast(lo16) * 10; + int64_t best = base; + for (int64_t cand : {base - kTsf10WrapUs, base + kTsf10WrapUs}) + if (std::llabs(cand - near_us) < std::llabs(best - near_us)) best = cand; + return best; +} + +/* ---- per-frame field: addr3 ------------------------------------------ */ + +inline constexpr uint8_t kFrameVersion = 1; /* byte 0 bits 7..5 */ +inline constexpr uint8_t kFrameHasCapture = 0x01; /* c2s measured from a producer capture stamp */ +inline constexpr uint8_t kFrameHasTsf = 0x02; /* tsf10_lo is from a ready fit */ +inline constexpr uint8_t kFrameHasDepth = 0x04; /* depth is a real in-flight count */ +inline constexpr uint8_t kFrameTxAsync = 0x08; /* async TX: t_write describes the submit, not the air */ + +struct FrameTiming { + bool has_capture = false, has_tsf = false, has_depth = false, tx_async = false; + uint8_t depth = 0; /* frames in flight behind this one, clipped 255 */ + uint16_t tsf10_lo = 0; /* predicted TX TSF at send_packet, (us/10) & 0xffff */ + uint16_t c2s10 = 0; /* capture (or stdin read) → send_packet, 10 µs, clipped */ + + static constexpr size_t kSize = 6; + + void encode(uint8_t out[kSize]) const { + uint8_t f = 0; + if (has_capture) f |= kFrameHasCapture; + if (has_tsf) f |= kFrameHasTsf; + if (has_depth) f |= kFrameHasDepth; + if (tx_async) f |= kFrameTxAsync; + out[0] = static_cast((kFrameVersion << 5) | (f & 0x1f)); + out[1] = depth; + out[2] = static_cast(tsf10_lo); + out[3] = static_cast(tsf10_lo >> 8); + out[4] = static_cast(c2s10); + out[5] = static_cast(c2s10 >> 8); + } + /* False for any other version — including the canonical SA left in addr3 + * by a demo that does not write telemetry (0x57 >> 5 == 2). */ + static bool decode(const uint8_t in[kSize], FrameTiming &t) { + if ((in[0] >> 5) != kFrameVersion) return false; + t.has_capture = in[0] & kFrameHasCapture; + t.has_tsf = in[0] & kFrameHasTsf; + t.has_depth = in[0] & kFrameHasDepth; + t.tx_async = in[0] & kFrameTxAsync; + t.depth = in[1]; + t.tsf10_lo = static_cast(in[2] | (in[3] << 8)); + t.c2s10 = static_cast(in[4] | (in[5] << 8)); + return true; + } +}; + +/* Per-frame latency on the receiver. `remote_arrival_us` is this frame's + * hardware arrival (tsfl) mapped onto the transmitter's TSF by the receiver's + * fit. Returns false when the frame carries no TSF. On success `submit_to_air` + * is arrival − predicted submit (µs; negative only by the fit error) and, when + * the frame has a capture stamp, `capture_to_air` adds the TX-side c2s. */ +struct FrameLatency { + int64_t submit_to_air_us = 0; + int64_t capture_to_air_us = 0; + bool has_capture = false; +}; +inline bool latency(const FrameTiming &t, int64_t remote_arrival_us, FrameLatency &out) { + if (!t.has_tsf) return false; + const int64_t submit = unwrap_tsf10(t.tsf10_lo, remote_arrival_us); + out.submit_to_air_us = remote_arrival_us - submit; + out.has_capture = t.has_capture; + out.capture_to_air_us = out.submit_to_air_us + static_cast(t.c2s10) * 10; + return true; +} + +/* ---- periodic marker IE ----------------------------------------------- */ + +inline constexpr uint8_t kMarkerIeType = 0x49; +inline constexpr uint8_t kMarkerVersion = 1; +inline constexpr uint8_t kMkPrespStamped = 0x01; /* this frame's timestamp field is a hardware egress TSF */ +inline constexpr uint8_t kMkBeaconRunning = 0x02; /* a hardware TBTT beacon with the same SA carries the clock */ +inline constexpr uint8_t kMkFitReady = 0x04; /* tsf_pred_us comes from a ready host↔TSF fit */ +inline constexpr uint8_t kMkTxAsync = 0x08; +inline constexpr uint8_t kMkCaptureSource = 0x10; /* the producer supplies capture stamps */ + +struct TimingMarker { + uint8_t flags = 0; + uint64_t tsf_pred_us = 0; /* predicted TX TSF when the marker was built */ + uint64_t host_ns = 0; /* TX steady_clock at the same instant */ + int32_t fit_ppm_x100 = 0; /* host-clock vs TSF rate, 0.01 ppm */ + uint16_t fit_n = 0; /* ReadTsf samples in the fit */ + uint32_t frames = 0; /* data frames in the window since the previous marker */ + uint16_t t_queue_p50_10 = 0, t_queue_max_10 = 0; /* stdin read → send_packet */ + uint16_t t_write_p50_10 = 0, t_write_max_10 = 0; /* send_packet wall time */ + uint16_t c2s_p50_10 = 0, c2s_max_10 = 0; /* capture → send_packet */ + uint8_t depth_max = 0; + uint16_t captured = 0; /* frames in the window that had a producer stamp */ + + static constexpr size_t kSize = 51; /* IE hdr 2 + OUI 3 + type 1 + ver 1 + body 42 + tail 2 */ + + static std::array encode(const TimingMarker &m) { + std::array b{{221, kSize - 2, 0x57, 0x42, 0x75, kMarkerIeType, kMarkerVersion}}; + size_t o = 7; + b[o++] = m.flags; + put64(b.data() + o, m.tsf_pred_us); o += 8; + put64(b.data() + o, m.host_ns); o += 8; + put32(b.data() + o, static_cast(m.fit_ppm_x100)); o += 4; + put16(b.data() + o, m.fit_n); o += 2; + put32(b.data() + o, m.frames); o += 4; + put16(b.data() + o, m.t_queue_p50_10); o += 2; + put16(b.data() + o, m.t_queue_max_10); o += 2; + put16(b.data() + o, m.t_write_p50_10); o += 2; + put16(b.data() + o, m.t_write_max_10); o += 2; + put16(b.data() + o, m.c2s_p50_10); o += 2; + put16(b.data() + o, m.c2s_max_10); o += 2; + b[o++] = m.depth_max; + put16(b.data() + o, m.captured); o += 2; + b[o++] = 0xd7; + b[o++] = 0x3b; + return b; + } + /* Scans the buffer (a whole MPDU is fine — the signature cannot start inside + * the 802.11 header: the byte after a 0xdd in addr1/addr2/addr3 is never the + * length 49 followed by the OUI). Rejects every other version. */ + static bool decode(const uint8_t *p, size_t n, TimingMarker &m) { + for (size_t i = 0; i + kSize <= n; ++i) { + if (p[i] != 221 || p[i + 1] != kSize - 2 || p[i + 2] != 0x57 || p[i + 3] != 0x42 || + p[i + 4] != 0x75 || p[i + 5] != kMarkerIeType || p[i + 6] != kMarkerVersion || + p[i + kSize - 2] != 0xd7 || p[i + kSize - 1] != 0x3b) + continue; + size_t o = i + 7; + m.flags = p[o++]; + m.tsf_pred_us = get64(p + o); o += 8; + m.host_ns = get64(p + o); o += 8; + m.fit_ppm_x100 = static_cast(get32(p + o)); o += 4; + m.fit_n = get16(p + o); o += 2; + m.frames = get32(p + o); o += 4; + m.t_queue_p50_10 = get16(p + o); o += 2; + m.t_queue_max_10 = get16(p + o); o += 2; + m.t_write_p50_10 = get16(p + o); o += 2; + m.t_write_max_10 = get16(p + o); o += 2; + m.c2s_p50_10 = get16(p + o); o += 2; + m.c2s_max_10 = get16(p + o); o += 2; + m.depth_max = p[o++]; + m.captured = get16(p + o); + return true; + } + return false; + } + + private: + static void put16(uint8_t *p, uint16_t v) { p[0] = uint8_t(v); p[1] = uint8_t(v >> 8); } + static void put32(uint8_t *p, uint32_t v) { + for (int i = 0; i < 4; ++i) p[i] = uint8_t(v >> (8 * i)); + } + static void put64(uint8_t *p, uint64_t v) { + for (int i = 0; i < 8; ++i) p[i] = uint8_t(v >> (8 * i)); + } + static uint16_t get16(const uint8_t *p) { return uint16_t(p[0] | (p[1] << 8)); } + static uint32_t get32(const uint8_t *p) { + uint32_t v = 0; + for (int i = 0; i < 4; ++i) v |= uint32_t(p[i]) << (8 * i); + return v; + } + static uint64_t get64(const uint8_t *p) { + uint64_t v = 0; + for (int i = 0; i < 8; ++i) v |= uint64_t(p[i]) << (8 * i); + return v; + } +}; + +/* The marker's own frame: a probe response (FC 0x50) to the broadcast DA with + * the given SA as addr2 and addr3, the 8-byte timestamp field zero (the MAC + * overwrites it on the dies that stamp — the flag says which), beacon interval + * and capability as a plain open BSS, an SSID IE naming the stream, the DS + * parameter set for the channel, then the marker IE. Appended after the + * caller's radiotap header. */ +inline void append_mgmt_mpdu(std::vector &out, uint8_t fc0, const uint8_t sa[6], + uint8_t channel, const TimingMarker *m) { + const uint8_t hdr[24] = {fc0, 0x00, 0x00, 0x00, + 0xff, 0xff, 0xff, 0xff, 0xff, 0xff, + sa[0], sa[1], sa[2], sa[3], sa[4], sa[5], + sa[0], sa[1], sa[2], sa[3], sa[4], sa[5], + 0x00, 0x00}; + out.insert(out.end(), hdr, hdr + 24); + out.insert(out.end(), 8, 0); /* timestamp */ + out.push_back(0x64); out.push_back(0x00); /* interval 100 TU */ + out.push_back(0x21); out.push_back(0x04); /* ESS + short preamble */ + static const char ssid[] = "devourer-stream"; + out.push_back(0x00); out.push_back(sizeof(ssid) - 1); + out.insert(out.end(), ssid, ssid + sizeof(ssid) - 1); + out.push_back(0x03); out.push_back(0x01); out.push_back(channel); + if (m) { + const auto ie = TimingMarker::encode(*m); + out.insert(out.end(), ie.begin(), ie.end()); + } +} +inline void append_marker_mpdu(std::vector &out, const uint8_t sa[6], + uint8_t channel, const TimingMarker &m) { + append_mgmt_mpdu(out, 0x50, sa, channel, &m); +} +/* The Jaguar1 fallback: the same shape as a beacon (FC 0x80) for StartBeacon, + * whose MAC-stamped timestamp is the egress pair on that family. */ +inline void append_beacon_mpdu(std::vector &out, const uint8_t sa[6], uint8_t channel) { + append_mgmt_mpdu(out, 0x80, sa, channel, nullptr); +} + +/* ---- TX-side window accumulator -------------------------------------- */ + +/* What a TX demo feeds per frame and drains into a marker. Samples are kept + * (bounded) for the p50; counts and maxima are exact for the whole window. */ +class TimingWindow { + public: + static constexpr size_t kMaxSamples = 8192; + + void add(uint64_t t_queue_us, uint64_t t_write_us, uint64_t c2s_us, bool captured, + unsigned depth) { + ++_frames; + if (captured) ++_captured; + if (depth > _depth_max) _depth_max = depth; + push(_q, t_queue_us, _q_max); + push(_w, t_write_us, _w_max); + push(_c, c2s_us, _c_max); + } + uint32_t frames() const { return _frames; } + + /* Fill the window fields of `m` and reset for the next window. */ + void drain_into(TimingMarker &m) { + m.frames = _frames; + m.captured = static_cast(std::min(_captured, 0xffff)); + m.depth_max = static_cast(std::min(_depth_max, 255)); + m.t_queue_p50_10 = clip10(p50(_q)); m.t_queue_max_10 = clip10(_q_max); + m.t_write_p50_10 = clip10(p50(_w)); m.t_write_max_10 = clip10(_w_max); + m.c2s_p50_10 = clip10(p50(_c)); m.c2s_max_10 = clip10(_c_max); + _frames = _captured = 0; _depth_max = 0; + _q.clear(); _w.clear(); _c.clear(); + _q_max = _w_max = _c_max = 0; + } + + private: + static void push(std::vector &v, uint64_t x, uint64_t &mx) { + if (x > mx) mx = x; + if (v.size() < kMaxSamples) v.push_back(x); + } + static uint64_t p50(std::vector &v) { + if (v.empty()) return 0; + auto mid = v.begin() + static_cast(v.size() / 2); + std::nth_element(v.begin(), mid, v.end()); + return *mid; + } + uint32_t _frames = 0, _captured = 0; + unsigned _depth_max = 0; + std::vector _q, _w, _c; + uint64_t _q_max = 0, _w_max = 0, _c_max = 0; +}; + +} // namespace stream_timing +} // namespace devourer + +#endif /* DEVOURER_STREAM_TELEMETRY_H */ diff --git a/src/TxStats.h b/src/TxStats.h index 9a09b919..56bc7610 100644 --- a/src/TxStats.h +++ b/src/TxStats.h @@ -30,6 +30,13 @@ constexpr int kTxShortWriteRc = -1000; struct TxStats { uint64_t submitted = 0; uint64_t failed = 0; + /* Frames handed to the transport whose completion has not been reaped — + * the backlog depth behind the next send. Live only on the asynchronous + * bulk-OUT path (Jaguar1), where it is the in-flight URB count the sender + * blocks on at its cap; a synchronous transport has nothing outstanding + * between calls and reports 0. A per-frame telemetry field, not a health + * signal: it is what the receiver sees as "depth". */ + uint32_t inflight = 0; int last_error_rc = 0; /* raw libusb rc / negated transfer status / * kTxShortWriteRc */ bool last_was_timeout = false; diff --git a/src/UsbTransport.cpp b/src/UsbTransport.cpp index 2ac2658f..dd4b9aff 100644 --- a/src/UsbTransport.cpp +++ b/src/UsbTransport.cpp @@ -1425,6 +1425,8 @@ TxStats UsbTransport::tx_stats() const { s.failed = _tx_failed.load(std::memory_order_relaxed); s.last_error_rc = _tx_last_rc.load(std::memory_order_relaxed); s.last_was_timeout = _tx_last_timeout.load(std::memory_order_relaxed); + const int inflight = _tx_inflight.load(std::memory_order_relaxed); + s.inflight = inflight > 0 ? static_cast(inflight) : 0; return s; } diff --git a/src/jaguar1/RtlJaguarDevice.cpp b/src/jaguar1/RtlJaguarDevice.cpp index b0e05df3..271df27d 100644 --- a/src/jaguar1/RtlJaguarDevice.cpp +++ b/src/jaguar1/RtlJaguarDevice.cpp @@ -2311,6 +2311,10 @@ devourer::AdapterCaps RtlJaguarDevice::GetAdapterCaps() { c.hw_beacon_txtsf = true; /* StartBeacon: MAC inserts the egress TSF into * beacons (bench: 8821AU + 8814AU body-TS steps * live at the beacon interval) */ + c.hw_injected_mgmt_txtsf = false; /* measured on the 8821AU: an injected + * probe response / beacon gets a counter that is + * not a TSF (AdapterCaps.h) — the hardware beacon + * above is this family's egress-stamped frame */ c.tsf_write_ok = true; /* WriteTsf: bare REG_TSFTR (8821AU readback) */ c.xtal_cap_max = 0x3f; /* 6-bit AFE crystal-cap trim (0x2C) */ c.xtal_cap_default = _eepromManager->crystal_cap & 0x3f; diff --git a/src/jaguar2/RtlJaguar2Device.cpp b/src/jaguar2/RtlJaguar2Device.cpp index 6dd48472..7c799580 100644 --- a/src/jaguar2/RtlJaguar2Device.cpp +++ b/src/jaguar2/RtlJaguar2Device.cpp @@ -1356,6 +1356,7 @@ devourer::AdapterCaps RtlJaguar2Device::GetAdapterCaps() { c.station_mode_ok = _variant == jaguar2::ChipVariant::C8822B; c.hw_rx_timestamp = true; /* FrameParserJaguar2 fills RxAtrib.tsfl */ c.hw_beacon_txtsf = true; /* StartBeacon: MAC inserts the egress TSF into beacons */ + c.hw_injected_mgmt_txtsf = true; /* bench 8812BU: injected 0x50/0x80 stamped, 34 µs spread */ c.tsf_write_ok = true; /* WriteTsf: REG_TSFTR (8822B readback) */ c.xtal_cap_max = 0x3f; /* 6-bit AFE crystal-cap trim (0x24/0x28) */ c.xtal_cap_default = _hal.efuse_logical_byte(0xB9) == 0xFF diff --git a/src/jaguar3/RtlJaguar3Device.cpp b/src/jaguar3/RtlJaguar3Device.cpp index 1f880965..81307b93 100644 --- a/src/jaguar3/RtlJaguar3Device.cpp +++ b/src/jaguar3/RtlJaguar3Device.cpp @@ -1933,6 +1933,7 @@ devourer::AdapterCaps RtlJaguar3Device::GetAdapterCaps() { c.narrowband_ok = true; /* 5/10 MHz baseband re-clock — Jaguar3 only */ c.hw_rx_timestamp = true; /* FrameParserJaguar3 fills RxAtrib.tsfl */ c.hw_beacon_txtsf = true; /* StartBeacon: MAC inserts the egress TSF into beacons */ + c.hw_injected_mgmt_txtsf = true; /* bench 8812CU + 8812EU: injected 0x50/0x80 stamped, 38–41 µs spread */ c.tsf_write_ok = true; /* WriteTsf: REG_TSFTR (8822C readback) */ c.xtal_cap_max = 0x7f; /* 7-bit AFE crystal-cap trim (0x1040) */ c.xtal_cap_default = 0x20; diff --git a/src/kestrel/RtlKestrelDevice.cpp b/src/kestrel/RtlKestrelDevice.cpp index 941717bd..53a1948c 100644 --- a/src/kestrel/RtlKestrelDevice.cpp +++ b/src/kestrel/RtlKestrelDevice.cpp @@ -979,6 +979,7 @@ devourer::AdapterCaps RtlKestrelDevice::GetAdapterCaps() { /* The AX beacon engine (StartBeacon) airs a HW-timed beacon with the live TSF * inserted by the MAC at TX — on-air validated on the 8852BU. */ c.hw_beacon_txtsf = true; + c.hw_injected_mgmt_txtsf = true; /* bench 8832CU: injected 0x50/0x80 stamped, 35 µs spread */ /* WriteTsf: the bare port-0 TSF pair is writable over PCIe (bench, RTL8852CE: * a read-add-write moved TSF vs FREERUN by the requested step to within the * read latency). USB is unmeasured, so it stays refused there. */ diff --git a/tests/README.md b/tests/README.md index 50732879..cc3d092a 100644 --- a/tests/README.md +++ b/tests/README.md @@ -588,6 +588,23 @@ frame size. It exists to put a number under the hardware-crypto question (`docs/mt7612u-ap-mode.md`); compare it with a transport's per-frame send cost, not with another CPU. +### `stream_timing_onair.sh`: per-frame timing telemetry on air + +Two adapters: a stream transmitter (`streamtx`, or `svctx` / `duplex` as +phases) stamping the addr3 timing field and airing the +`DEVOURER_STREAM_TIMING` marker, and a witness `rxdemo` fitting the +transmitter's clock from its egress-stamped frames. Phases: `floor` (REPS +identical runs, the run-to-run sd of the median latency reported before any +claim), `delay` (the producer sleeps 20 ms between its capture stamp and +every 10th record; the receiver must see that step on ~10% of frames), `hop` +(slot hopping; the clock survives retunes where the part stamps injected +frames), `corrupt` (CRC-failed frames kept and never fed to the fit), `svctx`, +`duplex`. `tests/stream_timing_analyze.py` is the per-capture summary and the +checks; `PACE_US` slows the producer for a part that cannot take 500 fps (the +8812EU on 5 GHz). Which parts stamp an injected probe response is measured by +`tests/probe_resp_egress_tsf_check.sh` (`HWBEACON=1` for the hardware +beacon). Numbers and the adversarial readings: `docs/stream-timing.md`. + ### `mt7612u_tsf_wrap.sh`: the MT7612U TSF read across the low-word wrap Wraps `bringup tsfwrap`, which is where the "two TSF halves are not latched" diff --git a/tests/probe_resp_egress_tsf_check.sh b/tests/probe_resp_egress_tsf_check.sh new file mode 100755 index 00000000..54980b21 --- /dev/null +++ b/tests/probe_resp_egress_tsf_check.sh @@ -0,0 +1,108 @@ +#!/usr/bin/env bash +# probe_resp_egress_tsf_check.sh — Phase-0 gate for the stream-timing marker. +# Does the MAC stamp a HOST-INJECTED probe response (FC 0x50) / beacon (0x80) +# with its live TSF at egress, or does the frame air with the timestamp bytes +# the host wrote? One TX adapter injects both kinds with a constant timestamp +# (tests/probe_resp_egress_tx.cpp); a witness rxdemo reports rx.frame tx_tsf +# (src/RxPacket.h TxEgressTsf) + its own hardware tsfl. Verdict per kind: +# STAMPED — tx_tsf is live (distinct per frame, tsfl−tx_tsf constant to <1 ms) +# CONSTANT — tx_tsf == the host's constant: the MAC does not touch it +# NONE — no such frames decoded (link problem, not an answer) +# +# sudo -v && tests/probe_resp_egress_tsf_check.sh +# TX_VID=0x2357 TX_PID=0x0120 tests/probe_resp_egress_tsf_check.sh # 8821AU (Jaguar1) +# HWBEACON=1 TX_VID=0x2357 TX_PID=0x0120 tests/probe_resp_egress_tsf_check.sh +# — the fallback: air the hardware TBTT beacon (timesync master, +# StartBeacon) instead of injecting; reported under the "beacon 0x80" +# row (its body carries no SSID tag, so it is classed by FC alone). +# PR0_REGS=1 ... the injector also samples both TSF ports (0x560/0x568) and +# beacon control every 500 ms as pr0.regs events (test-only +# second RtlAdapter on the handle), to tell a stamp apart +# from either timer. +# Exit: 0 = verdicts produced, 3 = preflight failed, 77 = adapter missing. +set -u +ROOT="$(cd "$(dirname "$0")/.." && pwd)"; cd "$ROOT" +TX_VID="${TX_VID:-0x0bda}"; TX_PID="${TX_PID:-0xc812}" # RTL8812CU (Jaguar3) +RX_VID="${RX_VID:-0x0bda}"; RX_PID="${RX_PID:-0xb812}" # CF-924AC (8822BU) witness +CH="${CH:-6}"; SECS="${SECS:-15}" +OUT="${OUT:-/tmp/devourer-pr0}" + +plugged() { lsusb -d "$(printf '%04x:%04x' "$1" "$2")" >/dev/null 2>&1; } +plugged "$TX_VID" "$TX_PID" || { echo "SKIP: TX $TX_VID:$TX_PID not plugged"; exit 77; } +plugged "$RX_VID" "$RX_PID" || { echo "SKIP: RX $RX_VID:$RX_PID not plugged"; exit 77; } + +HWBEACON="${HWBEACON:-}" +cleanup() { + sudo pkill -INT -x timesync 2>/dev/null || true + sudo pkill -INT -x probe_resp_egress_tx 2>/dev/null || true + sudo pkill -INT -x rxdemo 2>/dev/null || true + sleep 1 + sudo pkill -x timesync 2>/dev/null || true + sudo pkill -x probe_resp_egress_tx 2>/dev/null || true + sudo pkill -x rxdemo 2>/dev/null || true +} +trap cleanup EXIT INT TERM + +echo "== build ==" +cmake --build build -j --target rxdemo timesync devourer >/dev/null || exit 1 +if [ ! -x build/probe_resp_egress_tx ] || [ tests/probe_resp_egress_tx.cpp -nt build/probe_resp_egress_tx ]; then + g++ -std=c++20 -O2 -Isrc -Iexamples/common tests/probe_resp_egress_tx.cpp \ + examples/common/env_config.cpp build/libdevourer.a \ + $(pkg-config --cflags --libs libusb-1.0) -lpthread -o build/probe_resp_egress_tx || exit 1 +fi +mkdir -p "$OUT"; rm -f "${OUT:?}"/*.log "${OUT:?}"/*.jsonl + +tag="$(printf '%04x' "$TX_PID")" +echo "== witness $RX_VID:$RX_PID on ch$CH ==" +sudo env DEVOURER_VID="$RX_VID" DEVOURER_PID="$RX_PID" DEVOURER_CHANNEL="$CH" \ + DEVOURER_STREAM_OUT=1 DEVOURER_LOG_LEVEL=warn DEVOURER_EVENTS=stdout \ + timeout $((SECS + 20)) ./build/rxdemo >"$OUT/rx_$tag.jsonl" 2>"$OUT/rx_$tag.log" & +sleep 6 +# Preflight: the witness must be alive and decoding before the TX starts. +if ! grep -q -F '"ev":"rx.frame"' "$OUT/rx_$tag.jsonl" && ! grep -q -F 'first_rx_frame' "$OUT/rx_$tag.jsonl"; then + if ! pgrep -x rxdemo >/dev/null; then echo "PREFLIGHT FAILED: witness died ($OUT/rx_$tag.log)"; exit 3; fi +fi +echo "== TX $TX_VID:$TX_PID, ${SECS}s ==" +if [ -n "$HWBEACON" ]; then + sudo env DEVOURER_VID="$TX_VID" DEVOURER_PID="$TX_PID" DEVOURER_CHANNEL="$CH" \ + DEVOURER_TSYNC_ROLE=master DEVOURER_TSYNC_HWBEACON=1 DEVOURER_LOG_LEVEL=warn \ + timeout "$SECS" ./build/timesync >"$OUT/tx_$tag.jsonl" 2>"$OUT/tx_$tag.log" + rc=$?; [ $rc -eq 124 ] && rc=0 # timeout ends the master; that is the plan +else + sudo env DEVOURER_VID="$TX_VID" DEVOURER_PID="$TX_PID" DEVOURER_CHANNEL="$CH" \ + PR0_REGS="${PR0_REGS:-}" DEVOURER_LOG_LEVEL=warn ./build/probe_resp_egress_tx "$SECS" >"$OUT/tx_$tag.jsonl" 2>"$OUT/tx_$tag.log" + rc=$? +fi +sleep 2; cleanup +[ $rc -eq 0 ] || { echo "PREFLIGHT FAILED: TX exited $rc ($OUT/tx_$tag.log)"; exit 3; } + +python3 - "$OUT/rx_$tag.jsonl" "$OUT/tx_$tag.jsonl" <<'PY' +import json, statistics, sys +sys.path.insert(0, "tests") +from devourer_events import iter_events +CONST = 0x1122334455667788 +rx = list(iter_events(open(sys.argv[1]), ev="rx.frame")) +tx_tsf = [e["tsf"] for e in iter_events(open(sys.argv[2]), ev="pr0.tsf") if e.get("tsf")] +by = {"P": [], "B": []} +for e in rx: + if e.get("sa") != "57427505d600" or "tx_tsf" not in e: continue + body = bytes.fromhex(e["body"]) + k = "P" if b"devourer-tP" in body else "B" if b"devourer-tB" in body else None + if k is None and e.get("fc1") is not None and len(body) >= 12 and b"devourer" not in body: + k = "B" # HWBEACON mode: the timesync beacon, classed by being the only other stamped frame + if k: by[k].append((int(e["tx_tsf"]), int(e["tsfl"]))) +lo, hi = (min(tx_tsf), max(tx_tsf)) if tx_tsf else (0, 0) +print(f"TX ReadTsf span: {lo}..{hi} us ({len(tx_tsf)} reads)") +for k, name in (("P", "probe response 0x50"), ("B", "beacon 0x80")): + v = by[k] + if not v: print(f"{name}: NONE (0 frames decoded)"); continue + n = len(v); nconst = sum(1 for t, _ in v if t == CONST); distinct = len({t for t, _ in v}) + d = [((l - (t & 0xffffffff)) & 0xffffffff) for t, l in v if t != CONST] + sd = statistics.pstdev(d) if len(d) > 1 else float("nan") + inspan = sum(1 for t, _ in v if lo - 2_000_000 <= t <= hi + 2_000_000) if tx_tsf else 0 + if nconst / n > 0.9: verdict = "CONSTANT" + elif nconst == 0 and distinct > n // 2 and sd < 1000: verdict = "STAMPED" + else: verdict = "MIXED" + print(f"{name}: {verdict} n={n} const={nconst} distinct={distinct} " + f"sd(tsfl-tx_tsf)={sd:.1f}us in_tx_span={inspan}") +PY diff --git a/tests/probe_resp_egress_tx.cpp b/tests/probe_resp_egress_tx.cpp new file mode 100644 index 00000000..a45b543d --- /dev/null +++ b/tests/probe_resp_egress_tx.cpp @@ -0,0 +1,125 @@ +// probe_resp_egress_tx.cpp — Phase-0 gate for the stream-timing marker: does +// the MAC overwrite the 8-byte timestamp field of a HOST-INJECTED management +// frame with its live TSF at egress? src/RxPacket.h:TxEgressTsf() reads that +// field for beacons (FC 0x80) and probe responses (FC 0x50); the beacon case is +// bench-proven for the hardware TBTT beacon (StartBeacon), never for a frame +// pushed through send_packet. This program alternates injected probe responses +// and injected beacons whose timestamp field is a CONSTANT; the witness +// (rxdemo, rx.frame tx_tsf) shows either that constant (not stamped) or a live +// TSF. Once a second it also logs ReadTsf() so the analyzer can tell a live +// stamp from garbage. Driven by tests/probe_resp_egress_tsf_check.sh. +// +// Build: see tests/dl_departure_matrix.sh build_local (same recipe). +// Run: sudo DEVOURER_PID=0xc812 DEVOURER_CHANNEL=6 build/probe_resp_egress_tx [secs] +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +#include "RadiotapBuilder.h" +#include "RtlAdapter.h" +#include "SelectedChannel.h" +#include "UsbOpen.h" +#include "WiFiDriver.h" +#include "env_config.h" +#include "logger.h" + +static const uint8_t kSa[6] = {0x57, 0x42, 0x75, 0x05, 0xd6, 0x00}; +static constexpr uint64_t kConstTs = 0x1122334455667788ull; + +static std::vector build(const std::vector& rt, uint8_t fc0, + uint16_t seq) { + std::vector f(rt); + const uint8_t hdr[24] = {fc0, 0x00, 0x00, 0x00, + 0xff, 0xff, 0xff, 0xff, 0xff, 0xff, + kSa[0], kSa[1], kSa[2], kSa[3], kSa[4], kSa[5], + kSa[0], kSa[1], kSa[2], kSa[3], kSa[4], kSa[5], + (uint8_t)(seq << 4), (uint8_t)(seq >> 4)}; + f.insert(f.end(), hdr, hdr + 24); + for (int i = 0; i < 8; ++i) f.push_back((uint8_t)(kConstTs >> (8 * i))); + f.push_back(0x64); f.push_back(0x00); // beacon interval 100 TU + f.push_back(0x21); f.push_back(0x04); // cap: ESS + short preamble + static const char ssid[] = "devourer-ts"; + f.push_back(0x00); f.push_back((uint8_t)(sizeof(ssid) - 1)); + f.insert(f.end(), ssid, ssid + sizeof(ssid) - 1); + f.back() = fc0 == 0x50 ? 'P' : 'B'; // "devourer-tP"/"-tB": the witness tells the two apart by SSID + f.push_back(0x01); f.push_back(0x01); f.push_back(0x8c); // rates: 6M basic + f.push_back(0x03); f.push_back(0x01); f.push_back(0x00); // DS param, patched below + return f; +} + +int main(int argc, char** argv) { + int secs = argc > 1 ? atoi(argv[1]) : 15; + int gap_us = 10000; + if (const char* g = std::getenv("GAP_US")) gap_us = atoi(g); + uint16_t vid = 0x0bda, pid = 0xc812; + if (const char* p = std::getenv("DEVOURER_PID")) pid = (uint16_t)strtoul(p, 0, 0); + if (const char* v = std::getenv("DEVOURER_VID")) vid = (uint16_t)strtoul(v, 0, 0); + uint8_t ch = 6; + if (const char* c = std::getenv("DEVOURER_CHANNEL")) ch = atoi(c); + + auto logger = std::make_shared(); + libusb_context* ctx = nullptr; + libusb_init(&ctx); + libusb_set_option(ctx, LIBUSB_OPTION_LOG_LEVEL, LIBUSB_LOG_LEVEL_WARNING); + auto* h = libusb_open_device_with_vid_pid(ctx, vid, pid); + if (!h) { fprintf(stderr, "open fail %04x:%04x\n", vid, pid); return 1; } + std::shared_ptr lk; + if (devourer::claim_interface_then_reset(h, devourer::find_wifi_interface(h), logger, true, lk) != 0) return 1; + WiFiDriver wifi(logger); + auto dev = wifi.CreateRadio(h, ctx, lk, devourer_config_from_env()); + if (!dev) return 1; + + dev->InitWrite(SelectedChannel{ch, 0, CHANNEL_WIDTH_20}); + std::this_thread::sleep_for(std::chrono::seconds(2)); + + // PR0_REGS=1: a second RtlAdapter on the same handle reads the two TSF + // ports + beacon control every 500 ms (test-only; never on a send path). + std::unique_ptr regs; + if (std::getenv("PR0_REGS")) regs = std::make_unique(h, logger, ctx, lk); + const auto rt = devourer::build_stream_radiotap(devourer::parse_tx_mode_str("6M")); + auto presp = build(rt, 0x50, 0); + auto bcn = build(rt, 0x80, 0); + presp.back() = ch; bcn.back() = ch; + + uint32_t n = 0; + auto deadline = std::chrono::steady_clock::now() + std::chrono::seconds(secs); + auto next_tsf = std::chrono::steady_clock::now(); + while (std::chrono::steady_clock::now() < deadline) { + if (std::chrono::steady_clock::now() >= next_tsf) { + uint64_t tsf = 0; + try { tsf = dev->ReadTsf(); } catch (...) { tsf = 0; } + // JSONL on stdout so the analyzer can bracket the witness's tx_tsf. + printf("{\"ev\":\"pr0.tsf\",\"tsf\":%llu,\"sent\":%u}\n", + (unsigned long long)tsf, n); + fflush(stdout); + next_tsf += std::chrono::seconds(1); + } + static auto next_regs = std::chrono::steady_clock::now(); + if (regs && std::chrono::steady_clock::now() >= next_regs) { + try { + uint64_t t0 = regs->rtw_read32(0x0560) | ((uint64_t)regs->rtw_read32(0x0564) << 32); + uint64_t t1 = regs->rtw_read32(0x0568) | ((uint64_t)regs->rtw_read32(0x056c) << 32); + printf("{\"ev\":\"pr0.regs\",\"tsftr\":%llu,\"tsftr1\":%llu,\"bcn_ctrl\":\"0x%04x\",\"dual_rst\":\"0x%02x\",\"sent\":%u}\n", + (unsigned long long)t0, (unsigned long long)t1, + regs->rtw_read16(0x0550), regs->rtw_read8(0x0553), n); + fflush(stdout); + } catch (...) {} + next_regs += std::chrono::milliseconds(500); + } + auto& f = (n & 1) ? bcn : presp; + dev->send_packet(f.data(), f.size()); + ++n; + std::this_thread::sleep_for(std::chrono::microseconds(gap_us)); + } + dev->Stop(); + fprintf(stderr, "probe_resp_egress_tx: %u frames (half 0x50, half 0x80) on ch%d (%04x:%04x)\n", + n, ch, vid, pid); + return 0; +} diff --git a/tests/stream_telemetry_selftest.cpp b/tests/stream_telemetry_selftest.cpp new file mode 100644 index 00000000..036d7b91 --- /dev/null +++ b/tests/stream_telemetry_selftest.cpp @@ -0,0 +1,137 @@ +// Headless guard for src/StreamTelemetry.h: known-answer bytes for the addr3 +// field and the marker IE, the canonical-SA-in-addr3 rejection, clipping, the +// 655.36 ms TSF unwrap on both sides of a wrap, marker tamper/truncation/version +// rejection, the latency arithmetic and the window accumulator's p50/max. +#include +#include +#include +#include + +#include "StreamTelemetry.h" + +using namespace devourer::stream_timing; + +static int fails = 0; +#define CHECK(cond, msg) \ + do { \ + if (!(cond)) { \ + std::fprintf(stderr, "FAIL %s:%d: %s\n", __FILE__, __LINE__, msg); \ + ++fails; \ + } \ + } while (0) + +int main() { + // ---- FrameTiming KAT ------------------------------------------------ + { + FrameTiming t; + t.has_capture = true; t.has_tsf = true; t.has_depth = true; t.tx_async = false; + t.depth = 3; t.tsf10_lo = 0xbeef; t.c2s10 = 0x0102; + uint8_t b[6]; + t.encode(b); + const uint8_t want[6] = {0x27, 0x03, 0xef, 0xbe, 0x02, 0x01}; + CHECK(std::memcmp(b, want, 6) == 0, "FrameTiming KAT bytes"); + FrameTiming d; + CHECK(FrameTiming::decode(b, d), "FrameTiming decodes"); + CHECK(d.has_capture && d.has_tsf && d.has_depth && !d.tx_async, "flags round-trip"); + CHECK(d.depth == 3 && d.tsf10_lo == 0xbeef && d.c2s10 == 0x0102, "fields round-trip"); + } + // The canonical SA left in addr3 by a demo that writes no telemetry. + { + const uint8_t sa[6] = {0x57, 0x42, 0x75, 0x05, 0xd6, 0x00}; + FrameTiming d; + CHECK(!FrameTiming::decode(sa, d), "canonical SA in addr3 is not telemetry"); + uint8_t v0[6] = {0x00, 0, 0, 0, 0, 0}; + CHECK(!FrameTiming::decode(v0, d), "version 0 rejected"); + uint8_t v2[6] = {0x40, 0, 0, 0, 0, 0}; + CHECK(!FrameTiming::decode(v2, d), "version 2 rejected"); + } + // ---- units ---------------------------------------------------------- + CHECK(clip10(0) == 0 && clip10(9) == 0 && clip10(10) == 1, "clip10 floor"); + CHECK(clip10(655350) == 0xffff && clip10(10000000) == 0xffff, "clip10 clips"); + { + // Submit at 1,000,000 us -> lo16 of 100000 = 0x86a0. Arrival 200 us later. + const uint16_t lo = static_cast((1000000 / 10) & 0xffff); + CHECK(unwrap_tsf10(lo, 1000200) == 1000000, "unwrap, no wrap"); + // Across the wrap: submit just below a 655360 boundary, arrival just above. + const int64_t sub = 5 * kTsf10WrapUs - 100; + const uint16_t lo2 = static_cast((sub / 10) & 0xffff); + CHECK(unwrap_tsf10(lo2, 5 * kTsf10WrapUs + 300) == sub, "unwrap across wrap up"); + // Arrival slightly BEFORE submit (fit error): still the nearest congruent. + const int64_t sub3 = 7 * kTsf10WrapUs + 50; + const uint16_t lo3 = static_cast((sub3 / 10) & 0xffff); + CHECK(unwrap_tsf10(lo3, 7 * kTsf10WrapUs - 20) == sub3, "unwrap across wrap down"); + } + // ---- latency ---------------------------------------------------------- + { + FrameTiming t; + t.has_tsf = true; t.has_capture = true; + t.tsf10_lo = static_cast((123456780 / 10) & 0xffff); + t.c2s10 = 250; // 2.5 ms + FrameLatency l; + CHECK(latency(t, 123456780 + 1500, l), "latency computes"); + CHECK(l.submit_to_air_us == 1500, "submit->air"); + CHECK(l.has_capture && l.capture_to_air_us == 1500 + 2500, "capture->air"); + FrameTiming notsf; + CHECK(!latency(notsf, 0, l), "no tsf -> no latency"); + } + // ---- marker KAT / tamper / truncation / version ------------------------ + { + TimingMarker m; + m.flags = kMkPrespStamped | kMkFitReady; + m.tsf_pred_us = 0x0102030405060708ull; + m.host_ns = 0x1112131415161718ull; + m.fit_ppm_x100 = -1234; + m.fit_n = 42; + m.frames = 1000; + m.t_queue_p50_10 = 1; m.t_queue_max_10 = 2; + m.t_write_p50_10 = 3; m.t_write_max_10 = 4; + m.c2s_p50_10 = 5; m.c2s_max_10 = 6; + m.depth_max = 7; m.captured = 8; + auto b = TimingMarker::encode(m); + CHECK(b.size() == 51, "marker size"); + const uint8_t head[7] = {221, 49, 0x57, 0x42, 0x75, 0x49, 1}; + CHECK(std::memcmp(b.data(), head, 7) == 0, "marker header KAT"); + CHECK(b[49] == 0xd7 && b[50] == 0x3b, "marker tail KAT"); + TimingMarker d; + CHECK(TimingMarker::decode(b.data(), b.size(), d), "marker decodes"); + CHECK(d.flags == m.flags && d.tsf_pred_us == m.tsf_pred_us && d.host_ns == m.host_ns && + d.fit_ppm_x100 == -1234 && d.fit_n == 42 && d.frames == 1000 && + d.t_queue_p50_10 == 1 && d.t_queue_max_10 == 2 && d.t_write_p50_10 == 3 && + d.t_write_max_10 == 4 && d.c2s_p50_10 == 5 && d.c2s_max_10 == 6 && + d.depth_max == 7 && d.captured == 8, + "marker fields round-trip"); + // Embedded in a whole MPDU (header + fixed fields + IEs) it is still found. + std::vector mpdu; + const uint8_t sa[6] = {0x57, 0x42, 0x75, 0x05, 0xd6, 0x00}; + append_marker_mpdu(mpdu, sa, 36, m); + CHECK(mpdu[0] == 0x50 && mpdu.size() == 24 + 8 + 2 + 2 + 2 + 15 + 3 + 51, "marker mpdu shape"); + CHECK(TimingMarker::decode(mpdu.data(), mpdu.size(), d) && d.frames == 1000, "marker found in mpdu"); + // Truncated: not found. + CHECK(!TimingMarker::decode(b.data(), b.size() - 1, d), "truncated marker rejected"); + // Tail tamper: not found. + auto t = b; t[50] ^= 1; + CHECK(!TimingMarker::decode(t.data(), t.size(), d), "tail-tampered marker rejected"); + // Other version: not found. + auto v = b; v[6] = 2; + CHECK(!TimingMarker::decode(v.data(), v.size(), d), "other marker version rejected"); + // The hop sync marker's type byte (0x48) is not ours. + auto h = b; h[5] = 0x48; + CHECK(!TimingMarker::decode(h.data(), h.size(), d), "hop marker type rejected"); + } + // ---- window ------------------------------------------------------------ + { + TimingWindow w; + for (unsigned i = 1; i <= 101; ++i) w.add(i * 10, 1000, 20000, i % 2 == 0, i % 5); + CHECK(w.frames() == 101, "window frame count"); + TimingMarker m; + w.drain_into(m); + CHECK(m.frames == 101 && m.captured == 50 && m.depth_max == 4, "window counts"); + CHECK(m.t_queue_p50_10 == 51 && m.t_queue_max_10 == 101, "window queue p50/max"); + CHECK(m.t_write_p50_10 == 100 && m.c2s_max_10 == 2000, "window write/c2s"); + w.drain_into(m); + CHECK(m.frames == 0 && m.t_queue_max_10 == 0, "window reset after drain"); + } + + if (fails == 0) std::printf("stream_telemetry selftest OK\n"); + return fails == 0 ? 0 : 1; +} diff --git a/tests/stream_timing_analyze.py b/tests/stream_timing_analyze.py new file mode 100644 index 00000000..6c0613be --- /dev/null +++ b/tests/stream_timing_analyze.py @@ -0,0 +1,131 @@ +#!/usr/bin/env python3 +"""stream_timing_analyze.py — summarize one rxdemo JSONL capture of the stream +timing telemetry (src/StreamTelemetry.h): per-frame rx.frame fields `tel`, +`depth`, `c2s_us`, `cap`, `lat_us`, `c2a_us`, and the per-marker `rx.timing`. + + python3 tests/stream_timing_analyze.py rx.jsonl # summary line (JSON) + python3 tests/stream_timing_analyze.py rx.jsonl --expect-delay 10:20 + # the producer slept 20 ms between CAPTURE_TS and every 10th record: + # those frames' c2s must stand 20 ms (+-TOL) above the others' median, + # and about 1 in 10 frames must be such a frame. + --min-lat-frames N require at least N frames carrying lat_us (default 100) + --tol-ms MS tolerance for --expect-delay (default 6) + --no-abs do not require lat_us (a part/mode with no egress pairs) + --warmup-s S drop the first S seconds of telemetry frames (default 4): + the producer fills the stdin pipe while streamtx brings the + chip up, so the first ~1000 records carry stale stamps — a + true backlog reading, but not the steady state under test + +Exit 0 = every check passed, 1 = a check failed, 3 = too little data. The +summary is one JSON object on stdout (ev = stream_timing.summary) so a script +can grep it like any other event line. +""" +import argparse +import json +import statistics +import sys +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parent)) +from devourer_events import iter_events # noqa: E402 + + +def pct(v, q): + if not v: + return None + s = sorted(v) + i = min(len(s) - 1, max(0, int(round(q * (len(s) - 1))))) + return s[i] + + +def main(argv=None) -> int: + ap = argparse.ArgumentParser(description=__doc__, + formatter_class=argparse.RawDescriptionHelpFormatter) + ap.add_argument("rx_jsonl") + ap.add_argument("--expect-delay", default=None, metavar="N:MS") + ap.add_argument("--tol-ms", type=float, default=6.0) + ap.add_argument("--min-lat-frames", type=int, default=100) + ap.add_argument("--no-abs", action="store_true") + ap.add_argument("--warmup-s", type=float, default=4.0) + args = ap.parse_args(argv) + + frames, markers = [], [] + with open(args.rx_jsonl, "rb") as f: + for e in iter_events(f): + ev = e.get("ev") + if ev == "rx.frame" and e.get("sa") == "57427505d600": + frames.append(e) + elif ev == "rx.timing": + markers.append(e) + + tel = [e for e in frames if e.get("tel") == 1] + warm = 0 + if tel and args.warmup_s > 0: + t0 = tel[0]["tsfl"] + keep = [e for e in tel if ((e["tsfl"] - t0) & 0xffffffff) >= args.warmup_s * 1e6] + warm = len(tel) - len(keep) + tel = keep + lat = [e["lat_us"] for e in tel if "lat_us" in e] + c2a = [e["c2a_us"] for e in tel if "c2a_us" in e] + c2s = [e["c2s_us"] for e in tel] + cap = [e["c2s_us"] for e in tel if e.get("cap") == 1] + depth = [e.get("depth", 0) for e in tel] + out = { + "ev": "stream_timing.summary", + "frames": len(frames), "tel": len(tel), "warmup_dropped": warm, "lat_frames": len(lat), + "cap_frames": len(cap), "markers": len(markers), + "lat_p50_us": pct(lat, 0.5), "lat_p99_us": pct(lat, 0.99), + "lat_max_us": max(lat) if lat else None, + "lat_min_us": min(lat) if lat else None, + "c2s_p50_us": pct(c2s, 0.5), "c2s_p99_us": pct(c2s, 0.99), + "c2a_p50_us": pct(c2a, 0.5), "c2a_p99_us": pct(c2a, 0.99), + "depth_max": max(depth) if depth else None, + "pairs": markers[-1].get("pairs") if markers else None, + "rx_resid_us": markers[-1].get("rx_resid_us") if markers else None, + "presp_stamped": markers[-1].get("presp_stamped") if markers else None, + "beacon": markers[-1].get("beacon") if markers else None, + "tx_async": markers[-1].get("tx_async") if markers else None, + "tw_p50_us": pct([m["tw_p50_us"] for m in markers], 0.5) if markers else None, + "tw_max_us": max((m["tw_max_us"] for m in markers), default=None), + "tq_max_us": max((m["tq_max_us"] for m in markers), default=None), + "checks": {}, + } + + ok = True + if len(tel) < args.min_lat_frames: + print(json.dumps(out)); print(f"TOO LITTLE DATA: {len(tel)} telemetry frames", file=sys.stderr) + return 3 + if not args.no_abs: + c = len(lat) >= args.min_lat_frames + out["checks"]["abs_latency_present"] = c + ok &= c + if lat: + # Submit->air can only be negative by the fit error; a tail of + # large negatives means the clock mapping is wrong. + c = pct(lat, 0.01) > -2000 + out["checks"]["no_negative_tail"] = c + ok &= c + if args.expect_delay: + n, ms = args.expect_delay.split(":") + n, ms = int(n), float(ms) + if not cap: + out["checks"]["delay_step"] = False + ok = False + else: + base = pct(cap, 0.5) + hi = [v for v in cap if v - base > (ms * 1000) / 2] + frac = len(hi) / len(cap) + step = (statistics.median(hi) - base) / 1000.0 if hi else None + out["delay_frac"] = frac + out["delay_step_ms"] = step + c_frac = abs(frac - 1.0 / n) < 0.5 / n + c_step = step is not None and abs(step - ms) <= args.tol_ms + out["checks"]["delay_fraction"] = c_frac + out["checks"]["delay_step"] = c_step + ok &= c_frac and c_step + print(json.dumps(out)) + return 0 if ok else 1 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tests/stream_timing_onair.sh b/tests/stream_timing_onair.sh new file mode 100755 index 00000000..14f1a25e --- /dev/null +++ b/tests/stream_timing_onair.sh @@ -0,0 +1,254 @@ +#!/usr/bin/env bash +# stream_timing_onair.sh — on-air validation of the per-frame stream timing +# telemetry (src/StreamTelemetry.h): streamtx stamps addr3 + airs the +# DEVOURER_STREAM_TIMING marker; a witness rxdemo fits the transmitter's clock +# from the egress-stamped frames and emits lat_us / c2a_us per frame. +# +# Phases (each a fresh TX run against one long-lived witness): +# floor REPS identical runs: the run-to-run sd of median lat_us / c2a_us — +# measured FIRST, so later differences are judged against it. +# delay the producer sleeps DELAY_MS between CAPTURE_TS and every DELAY_Nth +# record: those frames' capture->send must stand DELAY_MS above the +# rest, and be ~1/N of the stamped frames (the field tracks the +# producer, not the pipe). +# hop slot-hopping TX (DEVOURER_HOP_CHANNELS): the marker and the clock +# fit must survive retunes — lat_us still present after the first +# hops, tq_max in the markers shows the retune cost. +# corrupt witness with DEVOURER_RX_KEEP_CORRUPTED=1: corrupted frames are +# decoded for what they are and never feed the clock fit. +# svctx the SVC demo as the transmitter (synthetic NALs, per-layer rates): +# the same addr3 field and marker from a second TX demo. +# duplex the duplex demo as the transmitter (TX+RX on one chip): same again, +# with the capture stamp through its control escape. +# +# PACE_US is the producer's record period (default 2000 = 500 fps). A part that +# cannot sustain that (the 8812EU on 5 GHz stalls 20 ms at a time) fills the +# stdin pipe, and capture->send pins at its 655 ms clip — a truthful reading of +# the backlog, not a steady state: run such a part with PACE_US=15000. +# +# sudo -v && tests/stream_timing_onair.sh +# TX_VID=0x2357 TX_PID=0x0120 tests/stream_timing_onair.sh # Jaguar1: beacon fallback +# PHASES="floor delay" REPS=5 SECS=30 tests/stream_timing_onair.sh +# CH=36 PACE_US=15000 TX_PID=0xa81a tests/stream_timing_onair.sh # 8812EU +# Exit: 0 all checks passed, 1 a check failed, 3 preflight failed, +# 77 an adapter is missing. Logs under $OUT. +set -u +ROOT="$(cd "$(dirname "$0")/.." && pwd)"; cd "$ROOT" +TX_VID="${TX_VID:-0x0bda}"; TX_PID="${TX_PID:-0xc812}" # RTL8812CU (Jaguar3) +RX_VID="${RX_VID:-0x0bda}"; RX_PID="${RX_PID:-0xb812}" # CF-924AC (8822BU) witness +CH="${CH:-6}"; SECS="${SECS:-20}"; REPS="${REPS:-3}" +MARKER_EVERY="${MARKER_EVERY:-50}" +PACE_US="${PACE_US:-2000}" +DELAY_N="${DELAY_N:-10}"; DELAY_MS="${DELAY_MS:-20}" +HOP_CHANNELS="${HOP_CHANNELS:-1,6,11}"; HOP_SLOT_MS="${HOP_SLOT_MS:-50}" +PHASES="${PHASES:-floor delay hop corrupt}" +OUT="${OUT:-/tmp/devourer-stream-timing}" +PY="${PY:-python3}" +UVRUN=(uv run --quiet --project tools/precoder python) + +plugged() { lsusb -d "$(printf '%04x:%04x' "$1" "$2")" >/dev/null 2>&1; } +plugged "$TX_VID" "$TX_PID" || { echo "SKIP: TX $TX_VID:$TX_PID not plugged"; exit 77; } +plugged "$RX_VID" "$RX_PID" || { echo "SKIP: RX $RX_VID:$RX_PID not plugged"; exit 77; } +[ "$(id -u)" -eq 0 ] || sudo -n true 2>/dev/null || { echo "needs sudo"; exit 3; } + +WIT_PID="" +cleanup() { + sudo pkill -INT -x streamtx 2>/dev/null || true + sudo pkill -INT -x svctx 2>/dev/null || true + sudo pkill -INT -x duplex 2>/dev/null || true + [ -n "$WIT_PID" ] && sudo kill -INT "$WIT_PID" 2>/dev/null || true + sleep 1 + sudo pkill -x streamtx 2>/dev/null || true + sudo pkill -x svctx 2>/dev/null || true + sudo pkill -x duplex 2>/dev/null || true + sudo pkill -x rxdemo 2>/dev/null || true +} +trap cleanup EXIT INT TERM + +echo "== build ==" +cmake --build build -j --target rxdemo streamtx svctx duplex >/dev/null || exit 1 +mkdir -p "$OUT"; rm -f "${OUT:?}"/*.log "${OUT:?}"/*.jsonl "${OUT:?}"/*.bin +head -c 200000 /dev/urandom >"$OUT/src.bin" + +fails=0 +pass() { echo "PASS: $*"; } +fail() { echo "FAIL: $*"; fails=$((fails + 1)); } + +start_witness() { # $1 = tag, $2.. = extra env + local tag="$1"; shift + sudo env DEVOURER_VID="$RX_VID" DEVOURER_PID="$RX_PID" DEVOURER_CHANNEL="$CH" \ + DEVOURER_STREAM_OUT=1 DEVOURER_LOG_LEVEL=warn DEVOURER_EVENTS=stdout "$@" \ + ./build/rxdemo >"$OUT/rx_$tag.jsonl" 2>"$OUT/rx_$tag.log" & + WIT_PID=$! + sleep 6 + if ! kill -0 "$WIT_PID" 2>/dev/null; then + echo "PREFLIGHT FAILED: witness died ($OUT/rx_$tag.log)"; exit 3 + fi +} +stop_witness() { sudo kill -INT "$WIT_PID" 2>/dev/null || true; wait "$WIT_PID" 2>/dev/null; WIT_PID=""; } + +# One TX run: $1 = tag, $2 = producer args (string), rest = extra TX env. +run_tx() { + local tag="$1" prod="$2"; shift 2 + # The producer paces at ~2 ms per record (500 fps); the clip repeats so a + # run of SECS seconds never runs out of records. + "${UVRUN[@]}" tools/precoder/stream_tx.py --input "$OUT/src.bin" --repeat 2000 \ + --pace-us "$PACE_US" $prod 2>"$OUT/prod_$tag.log" | + sudo env DEVOURER_VID="$TX_VID" DEVOURER_PID="$TX_PID" DEVOURER_CHANNEL="$CH" \ + DEVOURER_STREAM_TIMING="$MARKER_EVERY" DEVOURER_LOG_LEVEL=info "$@" \ + timeout "$SECS" ./build/streamtx --interval-ms 0 >"$OUT/tx_$tag.out" 2>"$OUT/tx_$tag.log" + sudo pkill -INT -x streamtx 2>/dev/null || true + sleep 1 +} +# Slice the witness log written during the last run: byte offset bookkeeping. +mark() { stat -c %s "$OUT/rx_$1.jsonl"; } +slice() { tail -c +"$(( $2 + 1 ))" "$OUT/rx_$1.jsonl" >"$OUT/run_$3.jsonl"; } + +# ---- preflight: 15 s of liveness before anything long ------------------------- +echo "== preflight (TX $TX_VID:$TX_PID -> RX $RX_VID:$RX_PID, ch$CH) ==" +start_witness pre +off=$(mark pre) +SECS_SAVE=$SECS; SECS=15 +run_tx pre "--capture-ts" +SECS=$SECS_SAVE +slice pre "$off" pre +ntel=$(grep -c -F '"tel":1' "$OUT/run_pre.jsonl") +nmk=$(grep -c -F '"ev":"rx.timing"' "$OUT/run_pre.jsonl") +nlat=$(grep -c -F '"lat_us"' "$OUT/run_pre.jsonl") +echo "preflight: tel=$ntel markers=$nmk lat=$nlat" +if [ "$ntel" -lt 100 ] || { [ "$MARKER_EVERY" -gt 0 ] && [ "$nmk" -lt 2 ]; }; then + stop_witness + echo "PREFLIGHT FAILED: tel=$ntel markers=$nmk (tx log: $OUT/tx_pre.log)"; exit 3 +fi +grep -E "stream timing:" "$OUT/tx_pre.log" | head -3 + +# ---- floor --------------------------------------------------------------- +if [[ " $PHASES " == *" floor "* ]]; then + echo "== floor: $REPS identical ${SECS}s runs ==" + : >"$OUT/floor.tsv" + for r in $(seq 1 "$REPS"); do + off=$(mark pre) + run_tx "floor$r" "--capture-ts" + slice pre "$off" "floor$r" + $PY tests/stream_timing_analyze.py "$OUT/run_floor$r.jsonl" >"$OUT/sum_floor$r.json"; rc=$? + $PY - "$OUT/sum_floor$r.json" "$r" "$rc" <<'PY' >>"$OUT/floor.tsv" +import json, sys +s = json.load(open(sys.argv[1])) +print(sys.argv[2], sys.argv[3], s["tel"], s["lat_frames"], s["lat_p50_us"], s["lat_p99_us"], + s["c2a_p50_us"], s["c2s_p50_us"], s["depth_max"], s["rx_resid_us"], sep="\t") +PY + tail -1 "$OUT/floor.tsv" + done + $PY - "$OUT/floor.tsv" <<'PY' +import statistics, sys +rows = [l.split("\t") for l in open(sys.argv[1]) if l.strip()] +ok = all(r[1] == "0" for r in rows) +def col(i): + v = [float(r[i]) for r in rows if r[i] not in ("None", "")] + return v +for name, i in (("lat_p50_us", 4), ("c2a_p50_us", 6), ("c2s_p50_us", 7)): + v = col(i) + if len(v) >= 2: + print(f"floor {name}: mean {statistics.mean(v):.0f} sd {statistics.pstdev(v):.0f} " + f"range {min(v):.0f}..{max(v):.0f} (n={len(v)}) — effects under 2 sd are not detectable") + elif v: + print(f"floor {name}: {v[0]:.0f} (one run — no sd)") +sys.exit(0 if ok else 1) +PY + if [ $? -eq 0 ]; then pass "floor: every run carried absolute latency"; else fail "floor: a run failed its checks ($OUT/sum_floor*.json)"; fi +fi + +# ---- delay --------------------------------------------------------------- +if [[ " $PHASES " == *" delay "* ]]; then + echo "== delay: ${DELAY_MS} ms producer delay on every ${DELAY_N}th record ==" + off=$(mark pre) + run_tx delay "--capture-ts --capture-delay $DELAY_N:$DELAY_MS" + slice pre "$off" delay + if $PY tests/stream_timing_analyze.py "$OUT/run_delay.jsonl" --expect-delay "$DELAY_N:$DELAY_MS" >"$OUT/sum_delay.json"; then + pass "delay: $(tr -d '\n' <"$OUT/sum_delay.json" | grep -o '"delay_step_ms": [0-9.]*\|"delay_frac": [0-9.]*' | tr '\n' ' ')" + else + fail "delay: $(cat "$OUT/sum_delay.json")" + fi +fi +stop_witness + +# ---- hop ----------------------------------------------------------------- +if [[ " $PHASES " == *" hop "* ]]; then + echo "== hop: slot hopping over $HOP_CHANNELS at ${HOP_SLOT_MS} ms ==" + start_witness hop DEVOURER_HOP_CHANNELS="$HOP_CHANNELS" DEVOURER_HOP_SLOT_MS="$HOP_SLOT_MS" DEVOURER_HOP_SEED=c0ffeef00dc0ffeef00dc0ffeef00d01 + off=$(mark hop) + run_tx hop "--capture-ts" DEVOURER_HOP_CHANNELS="$HOP_CHANNELS" DEVOURER_HOP_SLOT_MS="$HOP_SLOT_MS" DEVOURER_HOP_SEED=c0ffeef00dc0ffeef00dc0ffeef00d01 DEVOURER_HOP_FAST=1 + slice hop "$off" hop + stop_witness + # On a part without an egress-stamped injected frame there is no clock while + # hopping (the beacon cannot follow the hops): durations only. + noabs="" + grep -q -F '"presp_stamped":0' "$OUT/run_hop.jsonl" && noabs="--no-abs" + if $PY tests/stream_timing_analyze.py "$OUT/run_hop.jsonl" $noabs --min-lat-frames 50 >"$OUT/sum_hop.json"; then + pass "hop: $(grep -o '"lat_frames": [0-9]*\|"tq_max_us": [0-9]*\|"markers": [0-9]*' "$OUT/sum_hop.json" | tr '\n' ' ') ${noabs:+(durations only on this part)}" + else + fail "hop: $(cat "$OUT/sum_hop.json")" + fi +fi + +# ---- corrupt ------------------------------------------------------------- +if [[ " $PHASES " == *" corrupt "* ]]; then + echo "== corrupt: witness keeps CRC-failed frames ==" + start_witness corrupt DEVOURER_RX_KEEP_CORRUPTED=1 + off=$(mark corrupt) + run_tx corrupt "--capture-ts" + slice corrupt "$off" corrupt + stop_witness + ncrc=$(grep -F '"ev":"rx.frame"' "$OUT/run_corrupt.jsonl" | grep -c -F '"crc":1') + if $PY tests/stream_timing_analyze.py "$OUT/run_corrupt.jsonl" >"$OUT/sum_corrupt.json"; then + pass "corrupt: $ncrc CRC-failed frames surfaced, clock fit intact ($(grep -o '"rx_resid_us": [-0-9.e]*' "$OUT/sum_corrupt.json"))" + else + fail "corrupt: $(cat "$OUT/sum_corrupt.json")" + fi +fi + +# ---- svctx --------------------------------------------------------------- +if [[ " $PHASES " == *" svctx "* ]]; then + echo "== svctx: synthetic SVC NALs at the per-layer ladder ==" + start_witness svctx + off=$(mark svctx) + $PY tests/gen_svc_nals.py 40 2>/dev/null | + sudo env DEVOURER_VID="$TX_VID" DEVOURER_PID="$TX_PID" DEVOURER_CHANNEL="$CH" \ + DEVOURER_STREAM_TIMING="$MARKER_EVERY" DEVOURER_LOG_LEVEL=info \ + timeout "$SECS" ./build/svctx --gap-us "$PACE_US" >"$OUT/tx_svctx.out" 2>"$OUT/tx_svctx.log" + sudo pkill -INT -x svctx 2>/dev/null || true; sleep 1 + slice svctx "$off" svctx + stop_witness + if $PY tests/stream_timing_analyze.py "$OUT/run_svctx.jsonl" >"$OUT/sum_svctx.json"; then + pass "svctx: $(grep -o '"lat_frames": [0-9]*\|"lat_p50_us": [0-9]*\|"markers": [0-9]*' "$OUT/sum_svctx.json" | tr '\n' ' ')" + else + fail "svctx: $(cat "$OUT/sum_svctx.json")" + fi +fi + +# ---- duplex -------------------------------------------------------------- +if [[ " $PHASES " == *" duplex "* ]]; then + echo "== duplex: TX+RX on the transmitter chip, capture stamp via the control escape ==" + start_witness duplex + off=$(mark duplex) + # duplex spawns its TX thread before the chip is up and sends whatever + # stdin offers; a record pushed during bring-up wedges the TXDMA. The + # feeder idles through bring-up, as tests/arq_e2e_delivery.sh's does. + DUPLEX_LEAD_S="${DUPLEX_LEAD_S:-12}" + ( sleep "$DUPLEX_LEAD_S"; "${UVRUN[@]}" tools/precoder/stream_tx.py --input "$OUT/src.bin" --repeat 2000 \ + --pace-us "$PACE_US" --capture-ts 2>"$OUT/prod_duplex.log" ) | + sudo env DEVOURER_VID="$TX_VID" DEVOURER_PID="$TX_PID" DEVOURER_CHANNEL="$CH" \ + DEVOURER_STREAM_TIMING="$MARKER_EVERY" DEVOURER_LOG_LEVEL=info DEVOURER_TX_WITH_RX=thread \ + timeout $((SECS + DUPLEX_LEAD_S)) ./build/duplex --interval-ms 0 >"$OUT/tx_duplex.out" 2>"$OUT/tx_duplex.log" + sudo pkill -INT -x duplex 2>/dev/null || true; sleep 1 + slice duplex "$off" duplex + stop_witness + if $PY tests/stream_timing_analyze.py "$OUT/run_duplex.jsonl" >"$OUT/sum_duplex.json"; then + pass "duplex: $(grep -o '"lat_frames": [0-9]*\|"lat_p50_us": [0-9]*\|"c2a_p50_us": [0-9]*\|"markers": [0-9]*' "$OUT/sum_duplex.json" | tr '\n' ' ')" + else + fail "duplex: $(cat "$OUT/sum_duplex.json")" + fi +fi + +echo "== done: $fails failure(s); logs in $OUT ==" +exit "$fails" diff --git a/tools/precoder/adaptive_link.py b/tools/precoder/adaptive_link.py index 20c1c576..38f90d12 100644 --- a/tools/precoder/adaptive_link.py +++ b/tools/precoder/adaptive_link.py @@ -353,17 +353,7 @@ def selftest(verbose: bool = False): from devourer_events import parse_event, desc_rate_to_mcs # noqa: E402 -def ctl_frame(op: int, payload: bytes = b"") -> bytes: - """Encode a stdin control TLV for the duplex binary's SET_* opcodes.""" - body = bytes([op]) + payload - return struct.pack(" bytes: - return struct.pack(" dict[int, float]: diff --git a/tools/precoder/fused_fec_tx.py b/tools/precoder/fused_fec_tx.py index 5660f270..98afe929 100644 --- a/tools/precoder/fused_fec_tx.py +++ b/tools/precoder/fused_fec_tx.py @@ -23,6 +23,8 @@ if _HERE not in sys.path: sys.path.insert(0, _HERE) +import stream # noqa: E402 + from fused_fec_link import FusedFecSender # noqa: E402 from stream_fec import FecConfig # noqa: E402 @@ -40,6 +42,7 @@ def main(argv=None) -> int: ap = argparse.ArgumentParser( description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) ap.add_argument("--input", default=None, help="read bytes from file (else stdin)") + stream.add_capture_args(ap) ap.add_argument("--repeat", type=int, default=1, help="emit each body this many times (combats RX warmup loss)") add_fec_args(ap) @@ -57,10 +60,11 @@ def main(argv=None) -> int: bodies = snd.add_bytes(data) + snd.flush() out = sys.stdout.buffer nbytes = 0 + stamper = stream.capture_stamper_from_args(args) for body in bodies: chunk = struct.pack(" Iterator[tuple[int, bytes]]: delivered += 1 if total_target and delivered >= total_target: return + + +# ---- stdin control TLVs (examples/common/stream_stdin.h) --------------------- +# A length word with the top bit set is a control TLV , not a +# PSDU. SET_* drive the duplex binary's live knobs; CAPTURE_TS tells streamtx +# / duplex the producer's capture time of the NEXT record (CLOCK_MONOTONIC ns, +# same host), which the TX turns into the per-frame capture->send field. +CTL_FLAG = 0x80000000 +SET_PWR, SET_RATE, SET_CHAN, CAPTURE_TS = 1, 2, 3, 4 + + +def ctl_frame(op: int, payload: bytes = b"") -> bytes: + body = bytes([op]) + payload + return struct.pack(" bytes: + return struct.pack(" bytes: + """CAPTURE_TS for the next record; ns defaults to time.monotonic_ns().""" + if ns is None: + ns = time.monotonic_ns() + return ctl_frame(CAPTURE_TS, struct.pack("send field + tracks the producer, not the pipe (tests/stream_timing_onair.sh).""" + + def __init__(self, enabled: bool, delay_every: int = 0, delay_ms: float = 0.0): + self.enabled = enabled + self.delay_every = max(0, delay_every) + self.delay_ms = delay_ms + self.n = 0 + + def prefix(self) -> bytes: + if not self.enabled: + return b"" + self.n += 1 + out = capture_ts_frame() + if self.delay_every and self.n % self.delay_every == 0 and self.delay_ms > 0: + time.sleep(self.delay_ms / 1000.0) + return out + + +def add_capture_args(ap) -> None: + ap.add_argument("--capture-ts", action="store_true", + help="prefix every record with a CAPTURE_TS control TLV " + "(stamped at emission; a real encoder stamps at capture)") + ap.add_argument("--capture-delay", default=None, metavar="N:MS", + help="with --capture-ts: sleep MS ms between stamp and record " + "on every Nth record (validation of the TX-side c2s field)") + + +def capture_stamper_from_args(args) -> "CaptureStamper": + every, ms = 0, 0.0 + if getattr(args, "capture_delay", None): + n, m = args.capture_delay.split(":") + every, ms = int(n), float(m) + return CaptureStamper(bool(getattr(args, "capture_ts", False)), every, ms) diff --git a/tools/precoder/stream_tx.py b/tools/precoder/stream_tx.py index 2f12d68b..bca2376a 100644 --- a/tools/precoder/stream_tx.py +++ b/tools/precoder/stream_tx.py @@ -38,6 +38,7 @@ import os import struct import sys +import time from typing import Optional # Allow running both via `uv run python tools/precoder/stream_tx.py` @@ -105,6 +106,11 @@ def main(argv: Optional[list[str]] = None) -> int: help="override DEVOURER_STREAM_ENTRY_STATE") ap.add_argument("--seq-start", type=int, default=None, help="override DEVOURER_STREAM_SEQ_START") + stream.add_capture_args(ap) + ap.add_argument("--pace-us", type=int, default=0, + help="sleep this long between records and flush each one, so " + "the pipe stays shallow and a CAPTURE_TS stamp measures the " + "producer->air path rather than the pipe backlog") ap.add_argument("--repeat", type=int, default=1, help="emit each encoded body this many times in sequence " "(RX dedups by seq). Combats early-frame loss during " @@ -145,6 +151,7 @@ def main(argv: Optional[list[str]] = None) -> int: dump = open(args.dump_bodies, "wb") if args.dump_bodies else None repeat = max(1, args.repeat) + stamper = stream.capture_stamper_from_args(args) total_bytes = 0 for f in frames: body, layout = stream.encode_body( @@ -153,8 +160,11 @@ def main(argv: Optional[list[str]] = None) -> int: ) chunk = struct.pack(" 0: + out.flush() + time.sleep(args.pace_us / 1e6) if dump is not None: dump.write(body) diff --git a/tools/precoder/tun_p2p.py b/tools/precoder/tun_p2p.py index 5d659cba..80667fd3 100644 --- a/tools/precoder/tun_p2p.py +++ b/tools/precoder/tun_p2p.py @@ -107,6 +107,10 @@ # users running on a python without the wheel installed don't get # blindsided at startup. We only need the module when --fec-k > 0. stream_fec = None # type: ignore[assignment] +# The CAPTURE_TS prefix for every record, set from --capture-ts in main(). +_stamper = stream.CaptureStamper(False) + + def _import_stream_fec(): # noqa: E302 global stream_fec if stream_fec is None: @@ -269,7 +273,7 @@ def tx_thread(stop: StopBit, tun_fd: int, tx_stdin, body_bytes: int, chunk = struct.pack(" int: ap.add_argument("--duplex-bin", default=str(repo / "build" / "duplex")) ap.add_argument("--interval-ms", type=int, default=2) + stream.add_capture_args(ap) ap.add_argument("--repeat", type=int, default=1, help="blind per-frame replication (combine with the " "default --dedup to collapse the fan-out at RX so " @@ -535,6 +540,8 @@ def main(argv: Optional[list[str]] = None) -> int: "4). Higher = denser coefficient vectors → better " "recovery, more CPU.") args = ap.parse_args(argv) + global _stamper + _stamper = stream.capture_stamper_from_args(args) do_tx = args.mode in ("duplex", "duplex-split", "tx-only") do_rx = args.mode in ("duplex", "duplex-split", "rx-only") From 5bfaacf86c05c125501f5dfdc61f0a959c3f1824 Mon Sep 17 00:00:00 2001 From: Joseph <162703152+josephnef@users.noreply.github.com> Date: Sat, 10 Oct 2026 09:27:28 +0300 Subject: [PATCH 2/2] =?UTF-8?q?stream=20timing:=20review=20round=20?= =?UTF-8?q?=E2=80=94=20measured-only=20caps,=20receiver=20guards,=20clean?= =?UTF-8?q?=20stops?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - hw_injected_mgmt_txtsf only on the dies measured (8822B, 8852C); the 8821C and 8852B stay false until a cell exists. - rxdemo: no clock fit or latency on a receiver without a hardware RX stamp (hw_rx_timestamp false); addr3 read and decoded only on frames >= 24 bytes; a TSF discontinuity is caught from the second pair on, not only once the fit is ready (the TX fit likewise); beacon pairs are taken only when the live marker says a beacon carries the clock -- a Jaguar1 hardware beacon outlived its killed transmitter and poisoned the next run's fit. - streamtx/svctx/duplex: SIGINT/SIGTERM end the loop through the ordinary exit path (device stopped, timing beacon disarmed; verified zero stray beacons after a timeout-ended Jaguar1 run); no marker before the first data frame went out; the fit log no longer claims a state it cannot know, and stream.timing carries fit_unsupported. - duplex: a live SET_CHAN updates the marker's DS channel. - TimingWindow: a uniform reservoir, so a window longer than 8192 frames reports the whole window's median (selftest: 40000-frame ramp). - rx.frame gains fc0 (rxdemo + duplex); adaptive_link counts only 0x40 data frames as video, so markers and beacons never enter its sequence ledger. - The stdin control TLVs move to tools/precoder/stdin_ctl.py (stdlib only); stream.py re-exports them, adaptive_link stays numpy-free. - CLAUDE.md keeps a pointer, not a copy, of the wire details. Re-validated on air: 8812CU floor/delay/hop/corrupt/duplex, 8821AU floor (beacon clock, fit_resets 0), 8832CU floor, all PASS. Co-Authored-By: Claude Fable 5.1 --- CLAUDE.md | 15 ++---- docs/logging.md | 4 +- docs/stream-timing.md | 27 ++++++++--- examples/common/host_tsf_fit.h | 20 ++++++-- examples/common/stream_timing_tx.h | 23 ++++++--- examples/duplex/main.cpp | 16 ++++++- examples/rx/main.cpp | 59 ++++++++++++++++++----- examples/streamtx/main.cpp | 10 +++- examples/svctx/main.cpp | 10 ++-- src/AdapterCaps.h | 6 ++- src/StreamTelemetry.h | 23 ++++++--- src/jaguar2/RtlJaguar2Device.cpp | 4 +- src/kestrel/RtlKestrelDevice.cpp | 4 +- tests/stream_telemetry_selftest.cpp | 10 ++++ tools/precoder/adaptive_link.py | 7 ++- tools/precoder/stdin_ctl.py | 73 +++++++++++++++++++++++++++++ tools/precoder/stream.py | 69 +++------------------------ 17 files changed, 259 insertions(+), 121 deletions(-) create mode 100644 tools/precoder/stdin_ctl.py diff --git a/CLAUDE.md b/CLAUDE.md index 9da74222..627b8f56 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -451,17 +451,10 @@ temporal layer and injects each at its ladder's rate (RS outer code + corrupt-frame salvage) lives in `tools/precoder/` (`docs/fused-fec.md`). -Per-frame TX-side timing rides every stream frame's addr3 (six bytes no -receiver otherwise reads: backlog depth, capture→send, the transmitter's -predicted TSF) plus a periodic marker (`DEVOURER_STREAM_TIMING=N`), so -`rxdemo` reports a one-way submit→arrival and capture→arrival latency per -frame. The receiver's clock fit takes **hardware egress pairs only**: an -injected probe response is MAC-stamped on Jaguar2/3 and Kestrel but **not on -Jaguar1** (`AdapterCaps::hw_injected_mgmt_txtsf`), where the hardware beacon -carries the clock on a fixed channel and a hopping session gets durations -only. The producer's capture stamp arrives through the stdin control escape -(opcode 4) streamtx and duplex share. Wire format, clock model and the -measured matrix, floor first: `docs/stream-timing.md`; harness +Per-frame TX-side timing for the stream link (`src/StreamTelemetry.h`, +`examples/common/stream_timing_tx.h`): what each frame carries, which parts +MAC-stamp an injected frame (`AdapterCaps::hw_injected_mgmt_txtsf`) and the +measured matrix are in `docs/stream-timing.md`; harness `tests/stream_timing_onair.sh`. ## Frequency hopping diff --git a/docs/logging.md b/docs/logging.md index b0f4ea17..60926ed6 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -88,7 +88,7 @@ Emitters: L = library, RX/TX/... = demo. Optional fields in [brackets]; | ev | emitter | fields | |---|---|---| | `rx.pkt` | RX | n, len (first 10 + every 100th frame) | -| `rx.frame` | RX (`DEVOURER_STREAM_OUT`), duplex | rate, len, crc, icv, rssi[2], evm[2], snr[2], seq, tsfl, bw, stbc, ldpc, sgi, paggr, ppdu, fc1 (FC flags byte; bit3 = 802.11 RETRY), sa hex, a3 hex (addr3 verbatim), body hex; `tx_tsf` (sender's hardware egress TSF) on beacons/probe-responses only. When addr3 decodes as the stream timing field (`src/StreamTelemetry.h`, RX only): tel=1, depth (frames behind this one on the TX host), c2s_us (capture→send_packet; cap=1 when from the producer's CAPTURE_TS stamp, else from the stdin read), and once the receiver has fitted the transmitter's clock from its egress-stamped frames: lat_us (predicted submit→hardware arrival, one-way) and c2a_us (capture→arrival, cap=1 frames). SA gate: canonical-SA with `DEVOURER_RX_AGG_SA` unset; when set, that filter ("canon"/mac/"any") selects the stream instead | +| `rx.frame` | RX (`DEVOURER_STREAM_OUT`), duplex | rate, len, crc, icv, rssi[2], evm[2], snr[2], seq, tsfl, bw, stbc, ldpc, sgi, paggr, ppdu, fc1 (FC flags byte; bit3 = 802.11 RETRY), sa hex, fc0 (frame-control type/subtype byte: 0x40 stream data, 0x50 timing marker, 0x80 beacon), a3 hex (addr3 verbatim, frames ≥ 24 bytes), body hex; `tx_tsf` (sender's hardware egress TSF) on beacons/probe-responses only. When addr3 decodes as the stream timing field (`src/StreamTelemetry.h`, RX only): tel=1, depth (frames behind this one on the TX host), c2s_us (capture→send_packet; cap=1 when from the producer's CAPTURE_TS stamp, else from the stdin read), and once the receiver has fitted the transmitter's clock from its egress-stamped frames: lat_us (predicted submit→hardware arrival, one-way) and c2a_us (capture→arrival, cap=1 frames). SA gate: canonical-SA with `DEVOURER_RX_AGG_SA` unset; when set, that filter ("canon"/mac/"any") selects the stream instead | | `rx.timing` | RX | the transmitter's stream timing marker (probe response, canonical SA) decoded: frames, tq_p50_us, tq_max_us (stdin read→send), tw_p50_us, tw_max_us (send_packet wall time), c2s_p50_us, c2s_max_us, depth_max, captured, tsf_pred, tx_fit_ppm, tx_fit_n, presp_stamped (this part's injected probe responses carry a hardware egress TSF), beacon (a TBTT beacon carries the clock instead), tx_async; plus this receiver's clock fit: tsfl, pairs, rx_fit_ppm, rx_resid_us, rx_resets (a transmitter restart resets its TSF; the fit starts over past 50 ms) | | `rx.body` | RX (`DEVOURER_DUMP_BODY`) | rate, rssi[2], evm[2], snr[2], crc, len, body hex | | `rx.corrupt` | RX (`DEVOURER_RX_DUMP_ALL`) | len, crc, icv, rate, bw, stbc, ldpc, sgi, rssi[2], evm[2], snr[2] | @@ -187,7 +187,7 @@ Emitters: L = library, RX/TX/... = demo. Optional fields in [brackets]; | ev | emitter | fields | |---|---|---| | `stream.rx` / `stream.ctl` / `stream.eof` / `stream.tx` | duplex (stdout), streamtx (stderr) | hits / op, len, [applied 0 — streamtx reports the live-knob opcodes it does not apply; op 4 CAPTURE_TS is consumed silently by both] / tx_count, [bytes] / n, ok, psdu, [total] | -| `stream.timing` | streamtx, svctx, duplex (`DEVOURER_STREAM_TIMING=N`, every N data frames) | ok (the marker frame's send), frames, tq_p50_us, tq_max_us, tw_p50_us, tw_max_us, c2s_p50_us, c2s_max_us, depth_max, captured, tsf_pred, fit_ppm, fit_n, fit_resid_us, fit_resets (the host↔TSF fit, one ReadTsf per 100 ms; a reset = the chip's TSF jumped under it), presp_stamped, beacon, tx_async — the same window the marker carries on air (`examples/common/stream_timing_tx.h`) | +| `stream.timing` | streamtx, svctx, duplex (`DEVOURER_STREAM_TIMING=N`, every N data frames) | ok (the marker frame's send), frames, tq_p50_us, tq_max_us, tw_p50_us, tw_max_us, c2s_p50_us, c2s_max_us, depth_max, captured, tsf_pred, fit_ppm, fit_n, fit_resid_us, fit_resets, fit_unsupported (the host↔TSF fit, one ReadTsf per 100 ms; a reset = the chip's TSF jumped under it; unsupported = ReadTsf returns 0 on this part), presp_stamped, beacon, tx_async — the same window the marker carries on air (`examples/common/stream_timing_tx.h`) | | `stream.done` | streamtx (stderr) | sent, capture_dropped (CAPTURE_TS stamps that no record followed) | | `svc.stats` | svctx | frames, crit, t0, t1, t2, t3plus | | `doctor.verdict` | doctor | verdict, reasons "0x…", efuse_reads, efuse_mismatch, efuse_bad_id, efuse_id, fw_attempted, fw_ready, rx_ok, rx_crc, init | diff --git a/docs/stream-timing.md b/docs/stream-timing.md index e8adc107..c99c15fb 100644 --- a/docs/stream-timing.md +++ b/docs/stream-timing.md @@ -94,7 +94,7 @@ repeated, so a later difference has something to be judged against. |---|---|---|---|---|---|---|---| | Jaguar3 8812CU, ch6 | 5 | 98–146 | 3–16 | 148–172 | 30 | 0 | < 1 µs | | Kestrel 8832CU, ch6 | 2 | 90 | 0 | 126 | 30 | 0 | < 1 µs | -| Jaguar1 8821AU, ch6 (beacon clock) | 3 | 358–434 | 34 | 436 | 30–40 | 2 | < 1 µs | +| Jaguar1 8821AU, ch6 (beacon clock) | 5 | 358–1337 | 34 (first three) | 436–1373 | 30–40 | 2–19 | < 1 µs | | Jaguar3 8812EU, ch36, producer at 15 ms | 2 | 109–122 | 6 | 150 | 30 | 0 | < 1 µs | | Jaguar3 8812CU, `svctx` (no producer stamp) | 1 | 155 | — | — | — | 0 | < 1 µs | | Jaguar3 8812CU, `duplex` (TX+RX on one chip) | 1 | 124 | — | 150 | 30 | 0 | < 1 µs | @@ -115,9 +115,18 @@ The checks every cell passes or fails on: The adversarial readings, in the same breath: - **The depth field is honest about the transport.** Jaguar1's asynchronous - bulk-OUT shows a backlog of 2 and a 400 µs one-way figure where the - synchronous families show 0 and ~100 µs. That is the transport's shape, not - a defect the telemetry found. + bulk-OUT shows a backlog of 2 to 19 URBs and a 400 µs to 1.3 ms one-way + figure, run to run, where the synchronous families show 0 and ~100 µs. That + is the transport's shape (the async path blocks only at 256 in flight), not + a defect the telemetry found — and the reason the field exists. +- **A hardware beacon outlives the process that armed it.** On Jaguar1 the + timing clock rides `StartBeacon`, and a transmitter killed by SIGTERM left + its beacon airing at 100 TU with the canonical SA; the next transmitter's + witness then saw two clock sources and its fit reset on every pair. The TX + demos now end on SIGINT/SIGTERM through their ordinary exit path (beacon + disarmed, device stopped — verified: zero canonical-SA beacons on the air + after a timeout-ended run), and the receiver takes beacon pairs only when + the live marker says a beacon carries the clock. - **A producer that outruns the chip pins capture→send at its clip.** The 8812EU on 5 GHz stalls its synchronous send for the full 20 ms bulk-OUT timeout now and then (the window's send-time maximum reads 20.99 ms, the @@ -141,9 +150,13 @@ The adversarial readings, in the same breath: ## Reading it -`rxdemo` with `DEVOURER_STREAM_OUT=1`: every `rx.frame` carries `a3` and, -when it decodes, `tel`, `depth`, `c2s_us`, `cap`, and — once the receiver has -the transmitter's clock — `lat_us` and `c2a_us`. Each marker is an `rx.timing` +`rxdemo` with `DEVOURER_STREAM_OUT=1`: every `rx.frame` carries `fc0` (so a +consumer can keep the marker and a Jaguar1 beacon out of its video +accounting: only `0x40` frames carry the stream envelope) and `a3`, and when +addr3 decodes, `tel`, `depth`, `c2s_us`, `cap`, and — once the receiver has +the transmitter's clock — `lat_us` and `c2a_us`. A receiver without a +hardware RX stamp (`hw_rx_timestamp` false, the MT7612U) decodes the field +and the marker but never fits a clock or reports a latency. Each marker is an `rx.timing` event with the transmitter's window and this receiver's fit state; the transmitter logs the same window as `stream.timing`. Schema: `docs/logging.md`. `tests/stream_timing_analyze.py` turns one capture into a summary line and the diff --git a/examples/common/host_tsf_fit.h b/examples/common/host_tsf_fit.h index 585e2f77..d6144a02 100644 --- a/examples/common/host_tsf_fit.h +++ b/examples/common/host_tsf_fit.h @@ -108,15 +108,25 @@ class HostTsfFit { // latched the value; half the round trip is the irreducible error. const double x = static_cast(t0 / 2 + t1 / 2) / 1000.0; std::lock_guard lk(_mu); + bool jump = false; if (_fit.ready()) { const double r = static_cast(tsf) - _fit.at(x); _last_resid.store(r); - if (r > kDiscontinuityUs || r < -kDiscontinuityUs) { - _fit = tsffit::LinFit{}; - _resets.fetch_add(1); - } + jump = r > kDiscontinuityUs || r < -kDiscontinuityUs; + } else if (_have_last) { + // Before the line is ready, two consecutive samples whose TSF and + // host deltas disagree by more than the bound saw a TSF reset. + const double d = (static_cast(tsf) - _last_tsf) - (x - _last_x); + jump = d > kDiscontinuityUs || d < -kDiscontinuityUs; + } + if (jump) { + _fit = tsffit::LinFit{}; + _resets.fetch_add(1); } _fit.add(x, static_cast(tsf)); + _last_tsf = static_cast(tsf); + _last_x = x; + _have_last = true; } for (int i = 0; i < _period_ms && !_stop.load(); ++i) std::this_thread::sleep_for(std::chrono::milliseconds(1)); @@ -127,6 +137,8 @@ class HostTsfFit { const int _period_ms; mutable std::mutex _mu; tsffit::LinFit _fit; + bool _have_last = false; + double _last_tsf = 0, _last_x = 0; std::atomic _stop{false}; std::atomic _unsupported{false}; std::atomic _last_resid{0.0}; diff --git a/examples/common/stream_timing_tx.h b/examples/common/stream_timing_tx.h index 154dfeac..d5545a49 100644 --- a/examples/common/stream_timing_tx.h +++ b/examples/common/stream_timing_tx.h @@ -80,8 +80,8 @@ class StreamTimingTx { } _fit = std::make_unique(_dev); _fit->start(); - _log.info("stream timing: marker every {} frames, fit {}", _marker_every, - _fit->unsupported() ? "unsupported" : "running"); + _log.info("stream timing: marker every {} frames; host<->TSF fit started " + "(one ReadTsf per 100 ms)", _marker_every); } void stop() { if (_beacon) { @@ -119,8 +119,12 @@ class StreamTimingTx { } t.encode(addr3); } - // Right after send_packet returned. - void sent() { + // Right after send_packet returned (`ok` = its result). No marker is aired + // before the first data frame went out: the duplex demo's TX thread can run + // ahead of its chip's bring-up, and the marker must not be the frame that + // finds out. + void sent(bool ok = true) { + if (ok) _data_sent_ok = true; const uint64_t t1 = now_ns(); const uint64_t tq = _t0 > _read_ns ? (_t0 - _read_ns) / 1000 : 0; const uint64_t tw = (t1 - _t0) / 1000; @@ -132,10 +136,16 @@ class StreamTimingTx { // Before each data frame: air the marker when due. `radiotap` is the stream // radiotap header. Returns true when a marker was sent. bool maybe_marker(const std::vector &radiotap) { - if (_marker_every == 0 || (_frames % static_cast(_marker_every)) != 0 || + if (_marker_every == 0 || !_data_sent_ok || + (_frames % static_cast(_marker_every)) != 0 || _frames == _last_marker_frame) return false; _last_marker_frame = _frames; + if (_fit && _fit->unsupported() && !_warned_unsupported) { + _warned_unsupported = true; + _log.warn("stream timing: ReadTsf returns 0 on this part — frames carry " + "stage durations only, no TSF (has_tsf=0)"); + } TimingMarker m; if (_presp_stamped) m.flags |= devourer::stream_timing::kMkPrespStamped; if (_beacon) m.flags |= devourer::stream_timing::kMkBeaconRunning; @@ -170,6 +180,7 @@ class StreamTimingTx { .f("fit_n", m.fit_n) .f("fit_resid_us", _fit ? _fit->last_resid_us() : 0.0) .f("fit_resets", _fit ? _fit->resets() : 0) + .f("fit_unsupported", _fit && _fit->unsupported() ? 1 : 0) .f("presp_stamped", _presp_stamped ? 1 : 0) .f("beacon", _beacon ? 1 : 0) .f("tx_async", _tx_async ? 1 : 0); @@ -201,7 +212,7 @@ class StreamTimingTx { uint8_t _sa[6]; uint8_t _channel = 0; long _marker_every = 0; - bool _started = false; + bool _started = false, _data_sent_ok = false, _warned_unsupported = false; bool _tx_async = false, _presp_stamped = false, _beacon = false; std::unique_ptr _fit; devourer::stream_timing::TimingWindow _window; diff --git a/examples/duplex/main.cpp b/examples/duplex/main.cpp index 501bd7d2..faab2634 100644 --- a/examples/duplex/main.cpp +++ b/examples/duplex/main.cpp @@ -73,6 +73,7 @@ #include "WiFiDriver.h" #include "env_config.h" #include "logger.h" +#include "SignalStop.h" #include "stream_stdin.h" #include "stream_timing_tx.h" @@ -288,6 +289,10 @@ static void packet_processor(const Packet &packet) { .f("stbc", packet.RxAtrib.stbc) .f("ldpc", packet.RxAtrib.ldpc) .f("sgi", packet.RxAtrib.sgi) + /* fc0: the frame-control type/subtype byte, so a consumer can tell + * the stream's data frames (0x40) from the timing marker (0x50) and + * a Jaguar1 beacon (0x80) that share the canonical SA. */ + .f("fc0", packet.Data[0]) .hex("body", packet.Data.data() + 24, body_len); } if (hits <= 5 || hits % 500 == 0) { @@ -319,13 +324,14 @@ static void tx_thread(TxArgs args) { timing.start(); std::vector ctl; - while (!args.should_stop->load()) { + while (!args.should_stop->load() && !g_devourer_should_stop) { // The stdin control escape (stream_stdin.h): a length word with its top // bit set is a control TLV — the adaptive link's live // knobs and the producer's capture stamp — not a PSDU. uint32_t len = 0; std::vector psdu; const auto r = stream_stdin::read_item(stdin, psdu, ctl, args.max_psdu, &len); + if (g_devourer_should_stop) break; // signal: the RX loop is ending too if (r == stream_stdin::RecordResult::Eof || r == stream_stdin::RecordResult::Short) { // Clean EOF or short read — TX side done. RX keeps running. devourer::Ev(*g_ev, "stream.eof").f("tx_count", tx_count); @@ -352,6 +358,7 @@ static void tx_thread(TxArgs args) { args.rtl->SetMonitorChannel(SelectedChannel{ .Channel = ctl[1], .ChannelOffset = ctl[2], .ChannelWidth = static_cast(ctl[3])}); + timing.set_channel(ctl[1]); // the marker's DS parameter set follows } devourer::Ev(*g_ev, "stream.ctl").f("op", op).f("len", clen); continue; @@ -387,7 +394,7 @@ static void tx_thread(TxArgs args) { } timing.stamp(tx_buf.data() + addr3_off, read_ns, capture_ns, has_capture); ok = args.rtl->send_packet(tx_buf.data(), tx_buf.size()); - timing.sent(); + timing.sent(ok); } ++tx_count; if (tx_count <= 5 || tx_count % 500 == 0) { @@ -519,6 +526,11 @@ int main(int argc, char **argv) { rtlDevice->SetTxPower(static_cast(std::atoi(p))); std::atomic should_stop{false}; + /* SIGINT/SIGTERM: every generation's RX loop returns on the shared flag, so + * Init() comes back, the TX thread's blocking read returns short (no + * SA_RESTART) and sees the flag, and the ordinary exit path runs — the + * device stopped, a Jaguar1 timing beacon disarmed. */ + install_devourer_signal_handlers(); // Spawn TX thread first; it'll block on stdin until our peer pushes a // length-prefixed PSDU. Then drop into Init() (the RX loop) in the main diff --git a/examples/rx/main.cpp b/examples/rx/main.cpp index 06278e6c..326ef66e 100644 --- a/examples/rx/main.cpp +++ b/examples/rx/main.cpp @@ -662,8 +662,24 @@ static const uint8_t kTxSa[6] = {0x57, 0x42, 0x75, 0x05, 0xd6, 0x00}; static tsffit::Recon g_rt_recon; static tsffit::LinFit g_rt_fit; static bool g_rt_presp_stamped = false; +/* Which frames are the clock, as the transmitter's marker declares: its + * probe responses when it says they are stamped, a beacon only when it says + * one carries the clock. Before any marker both are taken. A beacon with the + * canonical SA is not proof of anything by itself — another devourer + * transmitter's hardware beacon can outlive the process that armed it. */ +static bool g_rt_marker_seen = false, g_rt_beacon_ok = true; static uint64_t g_rt_pairs = 0, g_rt_resets = 0; static double g_rt_resid_us = 0; +/* The receiver's side of the fit is its hardware RX stamp; a part that does + * not fill tsfl (AdapterCaps::hw_rx_timestamp false — the MT7612U) has no + * local clock and must not fit, let alone report a latency. Set from the + * caps in main before the RX loop starts. */ +static bool g_rt_hw_tsfl = false; +/* The previous pair, so a TSF jump is caught from the second pair on, not + * only once the fit is ready: with Δremote ≠ Δlocal by more than the + * discontinuity bound the transmitter's clock restarted between them. */ +static bool g_rt_have_last = false; +static int64_t g_rt_last_remote = 0, g_rt_last_local = 0; /* A transmitter that restarts resets its TSF (InitWrite zeroes it): the next * egress pair lands seconds off the line. Anything past this is a new clock, * not jitter (a marker's own spread is tens of µs), so the fit starts over. */ @@ -1142,13 +1158,15 @@ static void packetProcessor(const Packet &packet) { * and its periodic marker as an event of its own. */ int64_t rt_local = 0; if (sa_canon && !corrupted && packet.Data.size() >= 24) { - rt_local = g_rt_recon(packet.RxAtrib.tsfl); + if (g_rt_hw_tsfl) rt_local = g_rt_recon(packet.RxAtrib.tsfl); const uint8_t fc0 = packet.Data[0]; devourer::stream_timing::TimingMarker mk; if (fc0 == 0x50 && devourer::stream_timing::TimingMarker::decode( packet.Data.data() + 24, packet.Data.size() - 24, mk)) { g_rt_presp_stamped = mk.flags & devourer::stream_timing::kMkPrespStamped; + g_rt_beacon_ok = mk.flags & devourer::stream_timing::kMkBeaconRunning; + g_rt_marker_seen = true; devourer::Ev(*g_ev, "rx.timing") .f("frames", mk.frames) .f("tq_p50_us", mk.t_queue_p50_10 * 10) @@ -1171,19 +1189,32 @@ static void packetProcessor(const Packet &packet) { .f("rx_resid_us", g_rt_resid_us) .f("rx_resets", (unsigned long long)g_rt_resets); } - if (fc0 == 0x80 || (fc0 == 0x50 && g_rt_presp_stamped)) { + const bool clock_frame = + fc0 == 0x80 ? (g_rt_beacon_ok || !g_rt_marker_seen) + : (fc0 == 0x50 && g_rt_presp_stamped); + if (g_rt_hw_tsfl && clock_frame) { if (auto tx = packet.TxEgressTsf()) { + const int64_t remote = static_cast(*tx); + bool jump = false; if (g_rt_fit.ready()) { - g_rt_resid_us = static_cast(*tx) - + g_rt_resid_us = static_cast(remote) - g_rt_fit.at(static_cast(rt_local)); - if (std::fabs(g_rt_resid_us) > kRtDiscontinuityUs) { - g_rt_fit = tsffit::LinFit{}; - g_rt_pairs = 0; - ++g_rt_resets; - } + jump = std::fabs(g_rt_resid_us) > kRtDiscontinuityUs; + } else if (g_rt_have_last) { + const double d = static_cast((remote - g_rt_last_remote) - + (rt_local - g_rt_last_local)); + jump = std::fabs(d) > kRtDiscontinuityUs; + } + if (jump) { + g_rt_fit = tsffit::LinFit{}; + g_rt_pairs = 0; + ++g_rt_resets; } - g_rt_fit.add(static_cast(rt_local), static_cast(*tx)); + g_rt_fit.add(static_cast(rt_local), static_cast(remote)); ++g_rt_pairs; + g_rt_last_remote = remote; + g_rt_last_local = rt_local; + g_rt_have_last = true; } } } @@ -1353,8 +1384,9 @@ static void packetProcessor(const Packet &packet) { * capture->send (cap=1: from the producer's stamp, else from the stdin * read), and — once this receiver has the transmitter's clock — * lat_us = submit->arrival one-way, c2a_us = capture->arrival. */ - ev.hex("a3", packet.Data.data() + 16, 6); - { + ev.f("fc0", packet.Data[0]); + if (packet.Data.size() >= 24) { + ev.hex("a3", packet.Data.data() + 16, 6); devourer::stream_timing::FrameTiming ft; if (devourer::stream_timing::FrameTiming::decode(packet.Data.data() + 16, ft)) { ev.f("tel", 1) @@ -1362,7 +1394,7 @@ static void packetProcessor(const Packet &packet) { .f("c2s_us", ft.c2s10 * 10) .f("cap", ft.has_capture ? 1 : 0); devourer::stream_timing::FrameLatency fl; - if (sa_canon && !corrupted && g_rt_fit.ready() && + if (g_rt_hw_tsfl && sa_canon && !corrupted && g_rt_fit.ready() && devourer::stream_timing::latency( ft, static_cast(g_rt_fit.at(static_cast(rt_local))), fl)) { ev.f("lat_us", (long long)fl.submit_to_air_us); @@ -1615,6 +1647,9 @@ int main(int argc, char **argv) { * (and its in-flight TX) dies before libusb does. */ session.adopt_device(std::move(owned_device)); IRadio *const rtlDevice = session.device(); + /* The stream-timing clock fit needs this receiver's hardware RX stamp; set + * once here, ahead of every RX-loop entry point below. */ + g_rt_hw_tsfl = rtlDevice->GetAdapterCaps().hw_rx_timestamp; devourer::Ev(*g_ev, "init.timing") .f("stage", "demo.create_device") .f("ms", ms_since_start()); diff --git a/examples/streamtx/main.cpp b/examples/streamtx/main.cpp index 6a53f31e..fc32a776 100644 --- a/examples/streamtx/main.cpp +++ b/examples/streamtx/main.cpp @@ -79,6 +79,7 @@ #include "WiFiDriver.h" #include "env_config.h" #include "logger.h" +#include "SignalStop.h" #include "stream_stdin.h" #include "stream_timing_tx.h" @@ -113,6 +114,12 @@ int main(int argc, char **argv) { auto logger = std::make_shared(); apply_logging_env(*logger); /* DEVOURER_LOG_LEVEL / DEVOURER_EVENTS / ... */ + /* SIGINT/SIGTERM end the send loop through the ordinary exit path, so the + * device is stopped (and a hardware beacon armed as the Jaguar1 timing + * clock is disarmed) instead of left airing by a killed process. The + * handler is installed without SA_RESTART, so the blocking stdin read + * returns short and the loop sees the flag. */ + install_devourer_signal_handlers(); /* Events ride stderr here (overriding the stdout default): stdout is left * clean for downstream callers that may chain this binary. */ logger->events().configure(stderr); @@ -377,6 +384,7 @@ int main(int argc, char **argv) { uint32_t len = 0; { const auto r = stream_stdin::read_item(stdin, psdu, ctl, max_psdu, &len); + if (g_devourer_should_stop) break; // signal: clean stop if (r == stream_stdin::RecordResult::Eof) break; // clean stdin close if (r == stream_stdin::RecordResult::Control) { /* The stdin control escape (stream_stdin.h). This demo takes the @@ -491,7 +499,7 @@ int main(int argc, char **argv) { /* addr3 is the per-frame telemetry field (the body is untouched). */ timing.stamp(tx_buf.data() + addr3_off, read_ns, capture_ns, has_capture); bool ok = rtlDevice->send_packet(tx_buf.data(), tx_buf.size()); - timing.sent(); + timing.sent(ok); ++tx_count; // TX progress marker (event stream rides stderr in this demo, keeping // stdout clean for downstream callers that may chain this binary). diff --git a/examples/svctx/main.cpp b/examples/svctx/main.cpp index 2afb5722..32087b76 100644 --- a/examples/svctx/main.cpp +++ b/examples/svctx/main.cpp @@ -66,6 +66,7 @@ #include "WiFiDriver.h" #include "env_config.h" #include "logger.h" +#include "SignalStop.h" #include "stream_stdin.h" #include "stream_timing_tx.h" #include "svc_tx.h" @@ -103,6 +104,9 @@ static const char* mode_str(const devourer::TxMode& m) { int main(int argc, char** argv) { auto logger = std::make_shared(); apply_logging_env(*logger); /* DEVOURER_LOG_LEVEL / DEVOURER_EVENTS / ... */ + /* SIGINT/SIGTERM end the replay loop through the ordinary exit path (device + * stopped, a Jaguar1 timing beacon disarmed) instead of a killed process. */ + install_devourer_signal_handlers(); size_t mtu = 1400; long gap_us = 2000; @@ -231,8 +235,9 @@ int main(int argc, char** argv) { long sent[9] = {0}; // [0..7] per TID, [8] = critical long frames = 0; - while (true) { + while (!g_devourer_should_stop) { for (const auto& nal : nals) { + if (g_devourer_should_stop) break; const uint64_t nal_ns = StreamTimingTx::now_ns(); svc::NalInfo info = svc::parse_hevc_nal(nal.data(), nal.size()); const std::vector& rt = @@ -250,8 +255,7 @@ int main(int argc, char** argv) { frame.insert(frame.end(), nal.begin() + off, nal.begin() + off + n); timing.maybe_marker(rt); timing.stamp(frame.data() + rt.size() + 16, nal_ns, nal_ns, false); - rtlDevice->send_packet(frame.data(), frame.size()); - timing.sent(); + timing.sent(rtlDevice->send_packet(frame.data(), frame.size())); if (gap_us > 0) std::this_thread::sleep_for(std::chrono::microseconds(gap_us)); } diff --git a/src/AdapterCaps.h b/src/AdapterCaps.h index 08fad851..c6d14691 100644 --- a/src/AdapterCaps.h +++ b/src/AdapterCaps.h @@ -434,8 +434,10 @@ struct AdapterCaps { * egress-stamped frame on any channel at any time without the hardware * beacon function. Measured with a constant in the field and an independent * witness reading it back (tests/probe_resp_egress_tsf_check.sh): true on - * Jaguar2 (8812BU), Jaguar3 (8812CU, 8812EU) and Kestrel (8832CU), both FC - * 0x50 and 0x80, arrival−egress spread 34–41 µs over 15 s. FALSE on Jaguar1: + * the Jaguar2 8822B die (8812BU), Jaguar3 (8812CU, 8812EU) and the Kestrel + * 8852C die (8832CU), both FC 0x50 and 0x80, arrival−egress spread 34–41 µs + * over 15 s; the 8821C and 8852B dies are unmeasured and stay false. FALSE + * on Jaguar1: * the 8821AU rewrites the field, but with a free-running counter that is * neither TSF port (both read live during the run) and repeats for ~7 * frames at a time; its hardware TBTT beacon IS stamped (3.2 µs spread), so diff --git a/src/StreamTelemetry.h b/src/StreamTelemetry.h index 00b024c6..cde8d102 100644 --- a/src/StreamTelemetry.h +++ b/src/StreamTelemetry.h @@ -266,8 +266,10 @@ inline void append_beacon_mpdu(std::vector &out, const uint8_t sa[6], u /* ---- TX-side window accumulator -------------------------------------- */ -/* What a TX demo feeds per frame and drains into a marker. Samples are kept - * (bounded) for the p50; counts and maxima are exact for the whole window. */ +/* What a TX demo feeds per frame and drains into a marker. Counts and maxima + * are exact for the whole window; the p50 comes from a bounded uniform + * reservoir (Algorithm R over the window's samples), so a window longer than + * the reservoir is still represented end to end. */ class TimingWindow { public: static constexpr size_t kMaxSamples = 8192; @@ -277,9 +279,16 @@ class TimingWindow { ++_frames; if (captured) ++_captured; if (depth > _depth_max) _depth_max = depth; - push(_q, t_queue_us, _q_max); - push(_w, t_write_us, _w_max); - push(_c, c2s_us, _c_max); + /* One slot decision per frame for all three series: the reservoir index + * is uniform over [0, frames) (xorshift64*, seeded per window). */ + size_t slot = kMaxSamples; /* "append" while the reservoir fills */ + if (_frames > kMaxSamples) { + _rng ^= _rng >> 12; _rng ^= _rng << 25; _rng ^= _rng >> 27; + slot = static_cast((_rng * 0x2545F4914F6CDD1DULL) % _frames); + } + push(_q, t_queue_us, _q_max, slot); + push(_w, t_write_us, _w_max, slot); + push(_c, c2s_us, _c_max, slot); } uint32_t frames() const { return _frames; } @@ -297,9 +306,10 @@ class TimingWindow { } private: - static void push(std::vector &v, uint64_t x, uint64_t &mx) { + static void push(std::vector &v, uint64_t x, uint64_t &mx, size_t slot) { if (x > mx) mx = x; if (v.size() < kMaxSamples) v.push_back(x); + else if (slot < kMaxSamples) v[slot] = x; } static uint64_t p50(std::vector &v) { if (v.empty()) return 0; @@ -309,6 +319,7 @@ class TimingWindow { } uint32_t _frames = 0, _captured = 0; unsigned _depth_max = 0; + uint64_t _rng = 0x9E3779B97F4A7C15ULL; std::vector _q, _w, _c; uint64_t _q_max = 0, _w_max = 0, _c_max = 0; }; diff --git a/src/jaguar2/RtlJaguar2Device.cpp b/src/jaguar2/RtlJaguar2Device.cpp index 7c799580..b73061c7 100644 --- a/src/jaguar2/RtlJaguar2Device.cpp +++ b/src/jaguar2/RtlJaguar2Device.cpp @@ -1356,7 +1356,9 @@ devourer::AdapterCaps RtlJaguar2Device::GetAdapterCaps() { c.station_mode_ok = _variant == jaguar2::ChipVariant::C8822B; c.hw_rx_timestamp = true; /* FrameParserJaguar2 fills RxAtrib.tsfl */ c.hw_beacon_txtsf = true; /* StartBeacon: MAC inserts the egress TSF into beacons */ - c.hw_injected_mgmt_txtsf = true; /* bench 8812BU: injected 0x50/0x80 stamped, 34 µs spread */ + /* Measured on the 8822B die only (an 8812BU: injected 0x50/0x80 stamped, + * 34 µs spread); the 8821C runs the same code with no cell. */ + c.hw_injected_mgmt_txtsf = _variant == jaguar2::ChipVariant::C8822B; c.tsf_write_ok = true; /* WriteTsf: REG_TSFTR (8822B readback) */ c.xtal_cap_max = 0x3f; /* 6-bit AFE crystal-cap trim (0x24/0x28) */ c.xtal_cap_default = _hal.efuse_logical_byte(0xB9) == 0xFF diff --git a/src/kestrel/RtlKestrelDevice.cpp b/src/kestrel/RtlKestrelDevice.cpp index 53a1948c..905d8c67 100644 --- a/src/kestrel/RtlKestrelDevice.cpp +++ b/src/kestrel/RtlKestrelDevice.cpp @@ -979,7 +979,9 @@ devourer::AdapterCaps RtlKestrelDevice::GetAdapterCaps() { /* The AX beacon engine (StartBeacon) airs a HW-timed beacon with the live TSF * inserted by the MAC at TX — on-air validated on the 8852BU. */ c.hw_beacon_txtsf = true; - c.hw_injected_mgmt_txtsf = true; /* bench 8832CU: injected 0x50/0x80 stamped, 35 µs spread */ + /* Measured on the 8852C die only (an 8832CU: injected 0x50/0x80 stamped, + * 35 µs spread); the 8852B is unmeasured and stays false. */ + c.hw_injected_mgmt_txtsf = _variant == kestrel::ChipVariant::C8852C; /* WriteTsf: the bare port-0 TSF pair is writable over PCIe (bench, RTL8852CE: * a read-add-write moved TSF vs FREERUN by the requested step to within the * read latency). USB is unmeasured, so it stays refused there. */ diff --git a/tests/stream_telemetry_selftest.cpp b/tests/stream_telemetry_selftest.cpp index 036d7b91..b6a39333 100644 --- a/tests/stream_telemetry_selftest.cpp +++ b/tests/stream_telemetry_selftest.cpp @@ -130,6 +130,16 @@ int main() { CHECK(m.t_write_p50_10 == 100 && m.c2s_max_10 == 2000, "window write/c2s"); w.drain_into(m); CHECK(m.frames == 0 && m.t_queue_max_10 == 0, "window reset after drain"); + // A window longer than the reservoir: a monotonically rising series of + // 40000 frames has its true median at ~20000 us; a reservoir that stopped + // taking samples at 8192 would report ~4096 us. + TimingWindow big; + for (unsigned i = 1; i <= 40000; ++i) big.add(i, 0, 0, false, 0); + big.drain_into(m); + CHECK(m.frames == 40000, "long window frame count"); + CHECK(m.t_queue_p50_10 > 1700 && m.t_queue_p50_10 < 2300, + "long window p50 is the whole window's, not the first 8192 frames'"); + CHECK(m.t_queue_max_10 == 4000, "long window max exact"); } if (fails == 0) std::printf("stream_telemetry selftest OK\n"); diff --git a/tools/precoder/adaptive_link.py b/tools/precoder/adaptive_link.py index 38f90d12..9c7cf3de 100644 --- a/tools/precoder/adaptive_link.py +++ b/tools/precoder/adaptive_link.py @@ -353,7 +353,7 @@ def selftest(verbose: bool = False): from devourer_events import parse_event, desc_rate_to_mcs # noqa: E402 -from stream import ctl_frame, psdu_frame, SET_PWR, SET_RATE, SET_CHAN # noqa: E402 +from stdin_ctl import ctl_frame, psdu_frame, SET_PWR, SET_RATE, SET_CHAN # noqa: E402 def _parse_mcs_bias(spec: str) -> dict[int, float]: @@ -387,6 +387,11 @@ def reader(): ev = parse_event(line, ev="rx.frame") if ev is None: continue + # The timing marker (FC 0x50) and a Jaguar1 clock beacon (0x80) + # share the canonical SA; only the probe-request data frames + # (0x40) carry the stream envelope and its sequence counter. + if ev.get("fc0", 0x40) != 0x40: + continue body = bytes.fromhex(ev.get("body") or "") if rp.frame_type(body) == rp.T_DISC_ACK: vrx.on_disc_ack(body, _now_ms()) diff --git a/tools/precoder/stdin_ctl.py b/tools/precoder/stdin_ctl.py new file mode 100644 index 00000000..db5c61ec --- /dev/null +++ b/tools/precoder/stdin_ctl.py @@ -0,0 +1,73 @@ +"""stdin control TLVs for the stream demos (examples/common/stream_stdin.h). + +Imports only the standard library on purpose: adaptive_link.py and the +on-air orchestrators run under interpreters without numpy, while stream.py +(the body codec) needs it. stream.py re-exports these names for the +producers. +""" +from __future__ import annotations + +import struct +import time + +# A length word with the top bit set is a control TLV , not a +# PSDU. SET_* drive the duplex binary's live knobs; CAPTURE_TS tells streamtx +# / duplex the producer's capture time of the NEXT record (CLOCK_MONOTONIC ns, +# same host), which the TX turns into the per-frame capture->send field. +CTL_FLAG = 0x80000000 +SET_PWR, SET_RATE, SET_CHAN, CAPTURE_TS = 1, 2, 3, 4 + + +def ctl_frame(op: int, payload: bytes = b"") -> bytes: + body = bytes([op]) + payload + return struct.pack(" bytes: + return struct.pack(" bytes: + """CAPTURE_TS for the next record; ns defaults to time.monotonic_ns().""" + if ns is None: + ns = time.monotonic_ns() + return ctl_frame(CAPTURE_TS, struct.pack("send field + tracks the producer, not the pipe (tests/stream_timing_onair.sh).""" + + def __init__(self, enabled: bool, delay_every: int = 0, delay_ms: float = 0.0): + self.enabled = enabled + self.delay_every = max(0, delay_every) + self.delay_ms = delay_ms + self.n = 0 + + def prefix(self) -> bytes: + if not self.enabled: + return b"" + self.n += 1 + out = capture_ts_frame() + if self.delay_every and self.n % self.delay_every == 0 and self.delay_ms > 0: + time.sleep(self.delay_ms / 1000.0) + return out + + +def add_capture_args(ap) -> None: + ap.add_argument("--capture-ts", action="store_true", + help="prefix every record with a CAPTURE_TS control TLV " + "(stamped at emission; a real encoder stamps at capture)") + ap.add_argument("--capture-delay", default=None, metavar="N:MS", + help="with --capture-ts: sleep MS ms between stamp and record " + "on every Nth record (validation of the TX-side c2s field)") + + +def capture_stamper_from_args(args) -> "CaptureStamper": + every, ms = 0, 0.0 + if getattr(args, "capture_delay", None): + n, m = args.capture_delay.split(":") + every, ms = int(n), float(m) + return CaptureStamper(bool(getattr(args, "capture_ts", False)), every, ms) diff --git a/tools/precoder/stream.py b/tools/precoder/stream.py index 291ccb9f..307b9bd0 100644 --- a/tools/precoder/stream.py +++ b/tools/precoder/stream.py @@ -581,65 +581,10 @@ def unpack_stream(frames: Iterable[StreamFrame]) -> Iterator[tuple[int, bytes]]: return -# ---- stdin control TLVs (examples/common/stream_stdin.h) --------------------- -# A length word with the top bit set is a control TLV , not a -# PSDU. SET_* drive the duplex binary's live knobs; CAPTURE_TS tells streamtx -# / duplex the producer's capture time of the NEXT record (CLOCK_MONOTONIC ns, -# same host), which the TX turns into the per-frame capture->send field. -CTL_FLAG = 0x80000000 -SET_PWR, SET_RATE, SET_CHAN, CAPTURE_TS = 1, 2, 3, 4 - - -def ctl_frame(op: int, payload: bytes = b"") -> bytes: - body = bytes([op]) + payload - return struct.pack(" bytes: - return struct.pack(" bytes: - """CAPTURE_TS for the next record; ns defaults to time.monotonic_ns().""" - if ns is None: - ns = time.monotonic_ns() - return ctl_frame(CAPTURE_TS, struct.pack("send field - tracks the producer, not the pipe (tests/stream_timing_onair.sh).""" - - def __init__(self, enabled: bool, delay_every: int = 0, delay_ms: float = 0.0): - self.enabled = enabled - self.delay_every = max(0, delay_every) - self.delay_ms = delay_ms - self.n = 0 - - def prefix(self) -> bytes: - if not self.enabled: - return b"" - self.n += 1 - out = capture_ts_frame() - if self.delay_every and self.n % self.delay_every == 0 and self.delay_ms > 0: - time.sleep(self.delay_ms / 1000.0) - return out - - -def add_capture_args(ap) -> None: - ap.add_argument("--capture-ts", action="store_true", - help="prefix every record with a CAPTURE_TS control TLV " - "(stamped at emission; a real encoder stamps at capture)") - ap.add_argument("--capture-delay", default=None, metavar="N:MS", - help="with --capture-ts: sleep MS ms between stamp and record " - "on every Nth record (validation of the TX-side c2s field)") - - -def capture_stamper_from_args(args) -> "CaptureStamper": - every, ms = 0, 0.0 - if getattr(args, "capture_delay", None): - n, m = args.capture_delay.split(":") - every, ms = int(n), float(m) - return CaptureStamper(bool(getattr(args, "capture_ts", False)), every, ms) +# The stdin control TLVs live in stdin_ctl.py (numpy-free, so adaptive_link +# and the orchestrators can import them without this module's numpy); the +# producers reach them through these names. +from stdin_ctl import ( # noqa: E402,F401 + CTL_FLAG, SET_PWR, SET_RATE, SET_CHAN, CAPTURE_TS, ctl_frame, psdu_frame, + capture_ts_frame, CaptureStamper, add_capture_args, capture_stamper_from_args, +)