diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml index 789c502..5acba4a 100644 --- a/.github/workflows/release.yml +++ b/.github/workflows/release.yml @@ -37,6 +37,12 @@ jobs: - uses: actions/setup-python@v6 with: python-version: "3.12" + # The same gate the Python workflow applies on every push, repeated here: + # PyPI has no unpublish, so the upload below must not be the first time + # the tests are run against what is being shipped. + - run: pip install -e "python/.[diagram,dev]" + - run: pytest python/tests/ -v + - run: mypy python/src/execution_trace - run: pip install build - run: python -m build python/ - uses: pypa/gh-action-pypi-publish@release/v1 diff --git a/.github/workflows/rust.yml b/.github/workflows/rust.yml index d935ab6..6004cc7 100644 --- a/.github/workflows/rust.yml +++ b/.github/workflows/rust.yml @@ -14,5 +14,5 @@ jobs: - uses: actions/checkout@v6 - run: sudo apt-get install -y protobuf-compiler - run: cargo test --features std - - run: cargo clippy --features std -- -D warnings + - run: cargo clippy --all-targets --features std -- -D warnings - run: cargo fmt --check diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 0000000..e646602 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,128 @@ +# Changelog + +All notable changes to the `execution-trace` crate are documented in this file. + +The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/). + +The Python decoder ships from this repository as +[`embedded-etrace`](python/CHANGELOG.md) and is released from the same tag, so the two +version numbers move together. + +## [0.2.0] - 2026-09-19 + +**A breaking release.** The wire format is v2 and is not compatible with the v1 format +0.1.x produced: a firmware built on 0.2.0 needs `embedded-etrace` 0.2.0 on the host, and +a recording made with either version must be decoded by its own. A v2 stream is +recognised by the `TRACE_START` frame at its head. + +### Wire format + +- Every frame class now travels in one flat `TraceFrame` message discriminated by + `event_type`, rather than a `oneof` envelope. proto3 omits unset fields, so an event + pays nothing for the dictionary fields it does not use, where an envelope taxes each + one with a tag and a length. Field numbers stay at or below 15 so every tag is a + single byte. +- Names are interned. A `NAME_REGISTERED` frame carries the name once and assigns a + dictionary id, along with everything else the name fixes — source type, priority and + relative deadline — and per-occurrence events carry only the id. +- Timestamps are deltas against the previous sequenced frame. `TRACE_START` and + `NAME_REGISTERED` carry an absolute timestamp and re-establish the origin. +- `timestamp_ticks` is `sint64`, not unsigned. An event is stamped when recorded rather + than when queued, so an ISR preempting a task between those points legitimately + produces a negative delta; clamping it to zero drifted the host's reconstructed clock + permanently ahead of the device's, at milliseconds per second on a real trace. Zigzag + costs nothing at these magnitudes. +- Sequence numbers wrap at 16 384 (`SEQUENCE_MODULUS`). The counter exists only to make + gaps visible, and a gap is read modulo the wrap, so a full 32-bit counter would spend + up to five varint bytes to buy nothing. Because a wrapped restart only looks backwards + from the low half of the range, `TRACE_START` — not the sequence — is now the reliable + reset signal. +- A new `TRACE_START` header declares the timebase (nanoseconds, or core cycles with + `core_frequency_hz`) and the source-group mask the build was compiled with, so a host + can tell a masked group from one whose frames were lost without hard-coding the mask. + +Measured steady state is 11–12 bytes per event over the delta range the reference +firmware produces, against 27 for v1. + +### Added + +- `TraceEncoder`, holding the three pieces of per-stream state the format needs: the + name dictionary, the delta base, and the sequence counter. Built for its clock with + `TraceEncoder::new()` (nanoseconds) or `TraceEncoder::with_cycle_counter(hz)`. +- `TraceEncoder::encode_dictionary_entry`, for walking the dictionary and re-emitting it + periodically. Without this, a host attaching mid-run receives no dictionary at all and + can resolve nothing — names are registered in the first control cycles after boot, and + the device cannot observe an attach over a one-way transport. +- `TraceEncoder::encode_trace_start`, `registered_names`, and the `Encoded` result, whose + `name_registry_full` flag reports that an event went out under `UNKNOWN_NAME_ID` + because the dictionary was full. +- `RawTraceFrame`, `FrameKind` and `TimeBase`, the decoded form of a single frame. +- `next_sequence()`, the process-global producer-side counter. +- `MAX_TRACE_BURST_SIZE`, `NAME_REGISTRY_CAPACITY`, `SEQUENCE_MODULUS`, `UNKNOWN_NAME_ID`. +- `TraceSink::ticks_per_us`, `tick_mask` and `ticks_since`, so that code measuring an + interval works in whichever timebase the sink reports. All three default to the + nanosecond case, so existing implementations need no change. + +### Changed + +- **`TraceSink::get_elapsed_nanoseconds` is now `now_ticks`.** The unit is whatever the + encoder for the stream declares, so the old name would be a lie on a cycle-counter + sink. A sink may return a free-running 32-bit counter widened to `u64`: the encoder + extends it, so reading the clock can be a single volatile load with no critical + section. +- **`decode_trace_frame` returns `RawTraceFrame`, not `TraceEvent`.** In v2 an event is + not recoverable from one frame — its name is a dictionary id and its timestamp is a + delta — so name resolution and delta accumulation belong to the host decoder, which + holds the per-stream state. +- **Frames are numbered at the producer**, by the recording layer immediately before it + hands the event to the transport, and by the encoder for the header and dictionary + frames it originates itself. Loss at the producer queue used to happen before any + number existed, so the host saw a contiguous stream with events simply absent; it now + leaves a hole. Nothing on the wire changed — only who fills the field. + - The cost is that arrival order is no longer numeric order: a dictionary frame is + written ahead of the event that triggered it but numbered after it, inverting a pair + on every first sight of a name. Hosts must tolerate a reorder window. +- `NAME_REGISTRY_CAPACITY` is 40, down from 64. This array is the largest thing the + format puts in RAM, and under flip-link every byte of `.bss` is a byte the stack does + not get. 40 is half again as many entries as the reference firmware registers, and + overshooting degrades the trace rather than breaking it. +- Interning is keyed on name content rather than on the `&'static str` pointer. By the + time an event reaches the encoder the literal's pointer is gone — `TraceEvent` carries + an inline copy. The scan is linear over at most `NAME_REGISTRY_CAPACITY` entries, with + a length check before any byte comparison, in the task that owns the wire. + +### Removed + +- `SequenceEncoder`, replaced by `TraceEncoder`. Sequencing moved to the producer and the + encoder now owns the dictionary and the delta base as well, so the old wrapper no + longer describes anything. + +### Fixed + +- A name first seen on a `SPAN_END` — its `SPAN_START` dropped upstream under load — is + backfilled when a `SPAN_START` for it arrives, so a dictionary refresh cannot re-send a + bare entry and lose that name's priority for the rest of the run. +- A marker value of `0` is written to the wire instead of being dropped as falsy. + +## [0.1.6] - 2026-05-28 + +### Added + +- The `enabled` feature flag. With it off, the recording API compiles to no-ops with + default implementations, needing neither a clock nor a transport, and the protobuf + codegen is skipped entirely. + +### Changed + +- README: dropped a Cargo.toml example that showed a less clean way to disable tracing. + +## [0.1.5] - 2026-05-25 + +### Changed + +- Improved the crate and Python READMEs. + +## [0.1.4] - 2026-05-24 + +Releases up to and including this one predate this file; see the git history for +0.1.0–0.1.4. diff --git a/Cargo.toml b/Cargo.toml index f27553b..1588148 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -9,7 +9,7 @@ license = "MIT OR Apache-2.0" repository = "https://github.com/erl987/execution-trace" keywords = ["embedded", "tracing", "no_std", "profiling", "rtos"] categories = ["development-tools::profiling", "embedded", "no-std"] -include = ["/src/**", "/proto/**", "/build.rs", "/examples/simulate.rs", "/README.md", "/LICENSE-MIT", "/LICENSE-APACHE"] +include = ["/src/**", "/proto/**", "/build.rs", "/examples/simulate.rs", "/README.md", "/CHANGELOG.md", "/LICENSE-MIT", "/LICENSE-APACHE"] [lints.clippy] unwrap_used = "deny" @@ -23,7 +23,7 @@ enabled = ["dep:heapless", "dep:micropb"] std = [] [dependencies] -heapless = { version = "0.9.2", optional = true } +heapless = { version = "0.9.3", optional = true } micropb = { version = "0.6.0", default-features = false, features = ["encode", "decode", "container-heapless-0-9", "enable-64bit"], optional = true } [build-dependencies] diff --git a/README.md b/README.md index 1b22fef..300aa77 100644 --- a/README.md +++ b/README.md @@ -36,7 +36,7 @@ impl TraceTransport for MyRttSink { } impl TraceSink for MyRttSink { - fn get_elapsed_nanoseconds(&self) -> u64 { + fn now_ticks(&self) -> u64 { 0 // replace with your hardware timer } } @@ -61,50 +61,97 @@ fn ukf_step(sink: &mut impl TraceSink) { } ``` -### 3. Encode with sequence tracking +### 3. Encode with `TraceEncoder` -Use [`SequenceEncoder`] when encoding events manually so the host can detect dropped frames: +[`TraceEncoder`] holds the three pieces of per-stream state the wire format needs: the name +dictionary, the timestamp base the deltas are taken against, and the sequence counter that +lets the host detect dropped frames. Emit the stream header once, then encode events: ```rust -use execution_trace::{SequenceEncoder, SourceType, TraceEvent, encode::MAX_TRACE_FRAME_SIZE}; +use execution_trace::{SourceType, TraceEncoder, TraceEvent}; +use execution_trace::encode::MAX_TRACE_BURST_SIZE; + +// `new()` reads timestamps as 64-bit nanoseconds. For a sink returning a raw +// core cycle counter use `TraceEncoder::with_cycle_counter(72_000_000)`: the +// encoder then extends the 32-bit counter itself, so reading it costs the +// caller one volatile load. +let mut enc = TraceEncoder::new(); +let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + +// Once, at startup: declares the tick unit and the active source mask. +if let Ok(n) = enc.encode_trace_start(0, 0x1F, &mut buf) { + let _ = &buf[..n]; +} let mut name = heapless::String::<32>::new(); name.push_str("my_task").unwrap(); let event = TraceEvent::SpanStart { - timestamp_ns: 0, + timestamp_ns: 1_000, name, source_type: SourceType::Task, sequence: 0, priority: 4, relative_deadline_ms: None, }; -let mut enc = SequenceEncoder::new(); -let mut buf = [0u8; MAX_TRACE_FRAME_SIZE]; -if let Ok(n) = enc.encode(&event, &mut buf) { - // forward buf[..n] over your transport (RTT, UART, USB, etc.) - let _ = &buf[..n]; +if let Ok(encoded) = enc.encode(&event, &mut buf) { + if encoded.name_registry_full { + // The dictionary is full: the event went out with the reserved "unknown" + // id. Count it — the stream stays decodable, but this name is lost. + } + // forward buf[..encoded.len] over your transport (RTT, UART, USB, etc.) + let _ = &buf[..encoded.len]; } ``` +The first sight of a name writes **two** frames — the dictionary entry, then the event — which +is why the buffer is [`encode::MAX_TRACE_BURST_SIZE`] rather than one frame. + ### 4. Decode on the host +A frame is not self-contained: its name is a dictionary id and its timestamp is a delta against +the previous frame. [`encode::decode_trace_frame`] therefore returns a [`RawTraceFrame`], and the reader +resolves both from state it carries across the stream: + ```rust,ignore -use execution_trace::encode::decode_trace_frame; +use execution_trace::{FrameKind, encode::decode_trace_frame}; // raw_bytes arrives from your transport (RTT, UART, file, etc.) -let (event, consumed) = decode_trace_frame(raw_bytes).unwrap(); +let (frame, consumed) = decode_trace_frame(raw_bytes).unwrap(); + +// A dictionary entry or the stream header carries an absolute timestamp and +// re-establishes the origin; every other frame is a delta against it. +clock = match frame.kind { + FrameKind::NameRegistered | FrameKind::TraceStart => frame.timestamp_ticks, + _ => clock + frame.timestamp_ticks, +}; +if frame.kind == FrameKind::NameRegistered { + names.insert(frame.name_id, frame.name); +} ``` +`examples/simulate.rs` carries a complete worked reader; the `execution-trace` Python package +does the same job and renders a timing diagram from it. + ## Wire format Each frame is a standard protobuf length-delimited record: ```text -[ varint: payload byte count ][ protobuf-encoded TraceEvent ] +[ varint: payload byte count ][ protobuf-encoded TraceFrame ] ``` -Maximum frame size is [`encode::MAX_TRACE_FRAME_SIZE`] (128 bytes). Name strings are capped at 32 bytes; -longer names cause `record_*` to return [`TracingError::MessageDropped`] before sending. +One flat message carries every frame class, discriminated by its `event_type`: the three +per-occurrence events, the dictionary entry that assigns a name its id, and the stream header. +proto3 omits unset fields, so an event pays nothing for the dictionary fields it does not use. + +A steady-state event costs **11-13 bytes** — the name, the priority and the deadline are sent +once per name rather than on every occurrence, and the timestamp is a delta. + +Maximum frame size is [`encode::MAX_TRACE_FRAME_SIZE`] (128 bytes), and one `encode` call writes +at most [`encode::MAX_TRACE_BURST_SIZE`]. Name strings are capped at 32 bytes; longer names cause +`record_*` to return [`TracingError::MessageDropped`] before sending. The dictionary holds +[`encode::NAME_REGISTRY_CAPACITY`] distinct names, after which events fall back to a reserved +"unknown" id rather than to a wrong decode. ## Host-side tooling diff --git a/build.rs b/build.rs index 10aeefb..eb8a70e 100644 --- a/build.rs +++ b/build.rs @@ -19,8 +19,9 @@ fn main() { generator.add_protoc_arg("-Iproto"); // name carries the name of the source task/ISR (for spans) or the marker label. + // It appears only on NAME_REGISTERED frames, once per distinct name (§5.5). generator.configure( - ".tracing.TraceEvent.name", + ".tracing.TraceFrame.name", micropb_gen::Config::new() .string_type("heapless::String<$N>") .max_bytes(32), diff --git a/docs/screenshot_python_app_1.png b/docs/screenshot_python_app_1.png index ad375fe..a936254 100644 Binary files a/docs/screenshot_python_app_1.png and b/docs/screenshot_python_app_1.png differ diff --git a/examples/simulate.rs b/examples/simulate.rs index 8f69b44..f993e3e 100644 --- a/examples/simulate.rs +++ b/examples/simulate.rs @@ -7,26 +7,40 @@ // diagram from it, run the companion Python script: // python examples/visualize.py -use execution_trace::encode::{MAX_TRACE_FRAME_SIZE, decode_trace_frame}; +use execution_trace::encode::{MAX_TRACE_BURST_SIZE, decode_trace_frame}; use execution_trace::{ - SequenceEncoder, SourceType, TraceEvent, TraceSink, TraceTransport, TracingError, + FrameKind, SourceType, TraceEncoder, TraceEvent, TraceSink, TraceTransport, TracingError, }; +use std::collections::HashMap; // A sink that encodes each event into a byte buffer that can be written to a file or // forwarded over a transport (RTT, UART, USB). On real hardware this would wrap the // transport driver; here it wraps a Vec so we can write the bytes to disk. struct FileSink { buf: Vec, - encoder: SequenceEncoder, + encoder: TraceEncoder, pub tick_ns: u64, + pub registry_full_events: u32, } impl FileSink { fn new() -> Self { Self { buf: Vec::new(), - encoder: SequenceEncoder::new(), + encoder: TraceEncoder::new(), tick_ns: 0, + registry_full_events: 0, + } + } + + // Emits the stream header. On real hardware this runs once, from `init`. + fn write_header(&mut self, source_mask: u32) { + let mut frame = [0u8; MAX_TRACE_BURST_SIZE]; + if let Ok(n) = self + .encoder + .encode_trace_start(self.tick_ns, source_mask, &mut frame) + { + self.buf.extend_from_slice(&frame[..n]); } } @@ -37,24 +51,33 @@ impl FileSink { impl TraceTransport for FileSink { fn write_event(&mut self, event: TraceEvent) -> Result<(), TracingError> { - let mut frame = [0u8; MAX_TRACE_FRAME_SIZE]; - let n = self + // One call can write two frames: a first-sight name emits its dictionary + // entry ahead of the event, so the buffer is sized for the burst. + let mut frame = [0u8; MAX_TRACE_BURST_SIZE]; + let encoded = self .encoder .encode(&event, &mut frame) .map_err(|_| TracingError::MessageDropped)?; - self.buf.extend_from_slice(&frame[..n]); + if encoded.name_registry_full { + // On hardware this increments the `TracingNameRegistryFull` fault: + // the stream stays decodable, but this event's name is lost. + self.registry_full_events += 1; + } + self.buf.extend_from_slice(&frame[..encoded.len]); Ok(()) } } impl TraceSink for FileSink { - fn get_elapsed_nanoseconds(&self) -> u64 { + fn now_ticks(&self) -> u64 { self.tick_ns } } fn main() -> std::io::Result<()> { let mut sink = FileSink::new(); + // Every group enabled; a real build passes the mask it was compiled with. + sink.write_header(0x1F); // --- Simulated timeline (nanosecond timestamps, two control-loop iterations) --- // @@ -133,82 +156,101 @@ fn main() -> std::io::Result<()> { ); // --- Decode and print each event (round-trip verification) --- + // + // v2 frames are not self-contained: a name is a dictionary id and a timestamp + // is a delta, so the reader carries the two pieces of per-stream state that + // resolve them. This is the same job the Python decoder does. println!("\nDecoded events:"); println!( - "{:<6} {:<14} {:<12} {:<10} {:<8} {}", - "seq", "name", "type", "source", "ts_ms", "extras" + "{:<6} {:<14} {:<12} {:<10} {:<8} extras", + "seq", "name", "type", "source", "ts_ms" ); println!("{}", "-".repeat(72)); + + let mut names: HashMap)> = HashMap::new(); + // Signed: a frame's delta is negative when an event was recorded before the + // one encoded ahead of it. + let mut clock_ns = 0i64; let mut pos = 0; while pos < bytes.len() { match decode_trace_frame(&bytes[pos..]) { - Ok((event, consumed)) => { - match &event { - TraceEvent::SpanStart { - sequence, - name, - source_type, - timestamp_ns, - relative_deadline_ms, - .. - } => { - let ts_ms = *timestamp_ns as f64 / 1_000_000.0; - let source = match source_type { - SourceType::Isr => "ISR", - SourceType::Task => "Task", - }; - let mut extras = String::new(); - if let Some(dl) = relative_deadline_ms { - extras.push_str(&format!("rel_deadline={dl:.1}ms ")); - } + Ok((frame, consumed)) => { + pos += consumed; + + // A dictionary entry and the header carry an absolute timestamp + // and re-establish the origin; everything else is a delta. + clock_ns = match frame.kind { + FrameKind::NameRegistered | FrameKind::TraceStart => frame.timestamp_ticks, + _ => clock_ns + frame.timestamp_ticks, + }; + let ts_ms = clock_ns as f64 / 1_000_000.0; + + match frame.kind { + FrameKind::TraceStart => { println!( - "{:<6} {:<14} {:<12} {:<10} {:<8.3} {}", - sequence, - name.as_str(), - "SpanStart", - source, + "{:<6} {:<14} {:<12} {:<10} {:<8.3} mask=0x{:02X} timebase={:?}", + frame.sequence, + "-", + "TraceStart", + "-", ts_ms, - extras, + frame.source_mask, + frame.timebase, ); } - TraceEvent::SpanEnd { - sequence, - name, - timestamp_ns, - } => { - let ts_ms = *timestamp_ns as f64 / 1_000_000.0; + FrameKind::NameRegistered => { + let source = frame.source_type.unwrap_or(SourceType::Task); println!( - "{:<6} {:<14} {:<12} {:<10} {:<8.3}", - sequence, - name.as_str(), - "SpanEnd", - "-", + "{:<6} {:<14} {:<12} {:<10} {:<8.3} id={}", + frame.sequence, + frame.name.as_str(), + "NameReg", + match source { + SourceType::Isr => "ISR", + SourceType::Task => "Task", + }, ts_ms, + frame.name_id, + ); + names.insert( + frame.name_id, + ( + frame.name.as_str().to_string(), + source, + frame.relative_deadline_ms, + ), ); } - TraceEvent::Marker { - sequence, - name, - timestamp_ns, - marker_value, - } => { - let ts_ms = *timestamp_ns as f64 / 1_000_000.0; - let mut extras = String::new(); - if let Some(v) = marker_value { + kind => { + let (name, source, deadline) = match names.get(&frame.name_id) { + Some(entry) => entry.clone(), + // id 0: the registry was full when this was emitted. + None => ("".to_string(), SourceType::Task, None), + }; + let (label, source_label, mut extras) = match kind { + FrameKind::SpanStart => ( + "SpanStart", + match source { + SourceType::Isr => "ISR", + SourceType::Task => "Task", + }, + match deadline { + Some(dl) => format!("rel_deadline={dl:.1}ms "), + None => String::new(), + }, + ), + FrameKind::SpanEnd => ("SpanEnd", "-", String::new()), + _ => ("Marker", "-", String::new()), + }; + if let Some(v) = frame.marker_value { extras.push_str(&format!("value={v}")); } println!( "{:<6} {:<14} {:<12} {:<10} {:<8.3} {}", - sequence, - name.as_str(), - "Marker", - "-", - ts_ms, - extras, + frame.sequence, name, label, source_label, ts_ms, extras, ); } } - pos += consumed; } Err(e) => { eprintln!("decode error at byte {pos}: {e:?}"); diff --git a/proto/tracing.proto b/proto/tracing.proto index 32a31bd..b4e3041 100644 --- a/proto/tracing.proto +++ b/proto/tracing.proto @@ -1,15 +1,60 @@ syntax = "proto3"; package tracing; -message TraceEvent { - uint64 timestamp_ns = 1; - string name = 2; - TraceEventSourceType source_type = 3; - TraceEventType event_type = 4; - uint32 sequence = 5; - uint32 priority = 6; - optional float relative_deadline_ms = 7; - optional uint32 marker_value = 8; +// Execution-trace wire format v2. +// +// Not wire-compatible with v1. A v2 stream is recognised by its leading +// TRACE_START frame; see §6.4. +// +// One flat message carries every frame class, discriminated by `event_type`, +// rather than a `oneof` envelope. proto3 omits unset fields, so a per-occurrence +// event pays nothing for the dictionary fields it does not use, where an +// envelope would tax every event with a tag and a length (§18.1). +// +// Field numbers stay at or below 15 so that every tag costs a single byte. +message TraceFrame { + // Ticks elapsed since the previous sequenced frame, in the timebase declared + // by the TRACE_START frame. Absolute, not a delta, on NAME_REGISTERED and + // TRACE_START frames, which re-establish the time origin (§5.6). + // + // **Signed**, because the delta can be negative: an event is timestamped when + // it is recorded, before it reaches the producer queue, so a high-priority ISR + // preempting a task between those two points puts a later timestamp ahead of + // an earlier one in drain order. Clamping such an inversion to zero would make + // the host's reconstructed clock drift permanently ahead of the device's + // (§19.10). Zigzag encoding costs no extra byte at the magnitudes seen here. + // + // Declared 64-bit so that an idle stream cannot overflow it. + sint64 timestamp_ticks = 1; + + // Dictionary key assigned by NAME_REGISTERED. Id 0 is reserved for "unknown", + // emitted when the registry is full (§5.5, REQ-T11). + uint32 name_id = 2; + + TraceEventType event_type = 3; + + // Wraps at 16384 (see SEQUENCE_MODULUS). The counter exists only to detect + // gaps, which are read modulo the wrap, so a full 32-bit counter would spend + // up to five varint bytes to buy nothing (§18.1). + uint32 sequence = 4; + + // MARKER only. + optional uint32 marker_value = 5; + + // ── NAME_REGISTERED only: the dictionary entry (§6.2) ──────────────────── + string name = 6; + TraceEventSourceType source_type = 7; + uint32 priority = 8; + optional float relative_deadline_ms = 9; + + // ── TRACE_START only (§6.3) ────────────────────────────────────────────── + TimeBase timebase = 10; + // Core clock in Hz, for converting CYCLES ticks to wall time. Unset when the + // timebase is NANOSECONDS. + uint32 core_frequency_hz = 11; + // The source mask active in this build (§5.4), so the host can tell a masked + // group from a silent one without hard-coding the mask (REQ-T05). + uint32 source_mask = 12; } enum TraceEventSourceType { @@ -23,4 +68,17 @@ enum TraceEventType { SPAN_START = 1; SPAN_END = 2; MARKER = 3; + NAME_REGISTERED = 4; + TRACE_START = 5; +} + +// The unit of `timestamp_ticks`, declared once on the TRACE_START frame. +// +// Increment 6 emits NANOSECONDS; increment 7 (§5.8) switches the firmware to a +// raw DWT cycle counter and emits CYCLES with `core_frequency_hz` set. Declaring +// the unit on the wire keeps that a firmware change rather than a second +// incompatible schema. +enum TimeBase { + NANOSECONDS = 0; + CYCLES = 1; } diff --git a/python/CHANGELOG.md b/python/CHANGELOG.md index a762e47..af607b9 100644 --- a/python/CHANGELOG.md +++ b/python/CHANGELOG.md @@ -1,9 +1,107 @@ # Changelog -All notable changes to this project will be documented in this file. +All notable changes to `embedded-etrace` are documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/). +The Rust crate this package decodes for ships from the same repository as +[`execution-trace`](../CHANGELOG.md) and is released from the same tag, so the two +version numbers move together. + +## [0.2.0] - 2026-09-19 + +**A breaking release.** This decodes the v2 wire format and **cannot decode a v1 stream**, +which is what `execution-trace` 0.1.x firmware emits; 0.1.x of this package cannot decode +a v2 one. A v2 stream is recognised by the `TRACE_START` frame at its head. Recordings +made with either version must be decoded by their own. + +### Added + +- `TraceStreamState` — the per-connection decoder state v2 requires. A frame carries a + dictionary id instead of a name and a delta instead of a timestamp, so it is not + self-contained: this holds the name dictionary, the running clock, the timebase the + `TRACE_START` frame declares, and the sequence tracker. One per connection; the device + restarts its dictionary and clock when it restarts. + - `source_mask` exposes the source-group mask the firmware was built with, so a group + that is silent by design can be told from one whose frames were lost. + - `unresolved_events` counts events dropped because their name id never arrived. +- `NameEntry` — one dictionary entry: the name plus everything it fixes (source type, + priority, relative deadline), sent once rather than on every occurrence. +- `GapRecord` and `TraceEventBuffer.gaps` — a stretch the sequence numbers say was lost, + emitted as a row of its own so that missing data looks missing. Written as a `gap` row + by `write_tracing_csv` and drawn as a hatched band across every lane, labelled with the + frame count. +- `TraceEvent.interrupted` and an `interrupted` CSV column — the span was cut short by a + gap rather than closed by its own `SPAN_END`, so its real end is unknown and at least + `end_us`. Such a span is exempt from the deadline check, may be zero-length, and is + given a minimum render width so it stays visible. +- `SequenceTracker` takes `modulus` and `reorder_window`. +- `SEQUENCE_MODULUS` (16 384), the value the v2 counter wraps at. + +### Changed + +- **`decode_tracing_stream(buf, state, event_buffer)` takes a `TraceStreamState` where it + took a `SequenceTracker`.** The tracker is now held inside the state, along with the + rest of what a stateful decode needs. +- **`SequenceTracker` tolerates reordering** when given a `reorder_window` (the trace + stream uses 64, covering the firmware's 48-slot channel). A frame is numbered by its + producer rather than at the wire, so a dictionary frame is written ahead of the event + that triggered it but numbered after it — inverting a pair on every first sight of a + name. A hole is now declared only once something lands more than the window past it; + stragglers close their own hole, and one arriving after its hole was reported is + ignored rather than read as a backwards jump. Single-producer streams keep the window + at zero and get the report immediately. +- A hole is placed in time from the frames either side of it, not from whichever frame + triggered the report — tens of milliseconds apart on a real trace. +- `etrace-decode` writes gap rows. Without them the CSV shows an unexplained hole and + interrupted spans with nothing beside them to say why. +- An unresolvable name id drops the event rather than renaming it to a placeholder. + Attributing distinct unknown ids to one `` lane interleaved unrelated spans, + so a `SPAN_END` could close a `SPAN_START` belonging to another name and produce a + malformed pair. +- The "never registered" warning fires once per id. At 1 300+ events/s the per-event + warning produced thousands of identical lines a second. + +### Fixed + +- `write_tracing_csv` wrote a marker value of `0` as an empty CSV cell, and likewise a + span `deadline_us` or `value` of `0`. The column is meant to be empty only when the + field is absent, but the writer tested the value for truth, and zero is a legitimate + payload — a reason code, a count of nothing, a deadline at the activation instant. + Downstream the empty cell reads as "no value": `diagram.py` renders it as `—`, hiding + exactly the case the marker was emitted to report. The decoder was always correct; + only the writer dropped it. +- A lost frame no longer leaves its span open until the next unrelated `SPAN_END` for + that name, which drew one enormous bar across the gap and past it. Spans open *at the + hole* are closed and marked interrupted, and the first `SPAN_END` arriving for such a + name afterwards is discarded rather than paired with whatever opens next, which would + invent a span that never ran. +- `decode_tracing_stream` no longer clears the byte buffer on a device reset. The stream + is length-prefixed with no sync marker, so discarding bytes mid-frame misaligned + everything after it unrecoverably — the source of the decode-failure bursts that + arrived at the same millisecond as each false reset. The frames after a reset are + intact; only the decoder state is stale. +- The frame that reveals a reset is no longer discarded with it. That frame is the first + of the new run, usually the reboot's own header carrying the timebase and mask. +- A reboot is separated from ordering jitter by a margin rather than a strict backwards + comparison. A reboot drops the clock by the whole uptime and jitter is microseconds; + without the margin, one inverted microsecond blinded the trace for a full refresh + interval. +- A repeated `TRACE_START` on a running stream is a dictionary refresh, not a reset. + Treating it as a reboot cleared the dictionary on every refresh, undoing the thing the + refresh exists to do. A reboot is identified by the device clock going backwards, which + a refresh never does. + +## [0.1.6] - 2026-05-28 + +No changes to this package; released from the same tag as the crate. + +## [0.1.5] - 2026-05-25 + +### Changed + +- Improved the package README. + ## [0.1.4] - 2026-05-24 ### Added diff --git a/python/README.md b/python/README.md index c834aa5..9e4b585 100644 --- a/python/README.md +++ b/python/README.md @@ -32,21 +32,21 @@ Implement a loop that appends raw bytes from your transport (RTT, UART, TCP…) ```python from execution_trace import ( - SequenceTracker, TraceEventBuffer, decode_tracing_stream, write_tracing_csv, + TraceEventBuffer, TraceStreamState, decode_tracing_stream, write_tracing_csv, ) buf = bytearray() -tracker = SequenceTracker("my-device") +state = TraceStreamState("my-device") # one per connection event_buffer = TraceEventBuffer() while True: buf += transport.read() # append whatever arrived - decode_tracing_stream(buf, tracker, event_buffer) + decode_tracing_stream(buf, state, event_buffer) # When the session ends: event_buffer.flush_pending() # warn about open spans csv_path = write_tracing_csv( - event_buffer.records + event_buffer.markers, # type: ignore[operator] + [*event_buffer.records, *event_buffer.markers, *event_buffer.gaps], output_dir="data", ) print(f"Trace written → {csv_path}") @@ -55,6 +55,15 @@ print(f"Trace written → {csv_path}") `decode_tracing_stream` consumes complete frames from `buf` in-place and handles device resets transparently (the sequence number jumps backward on firmware reboot). +`TraceStreamState` is what makes the decode stateful, and it must be the **same object +across every call for one connection**: a frame carries a dictionary id rather than a +name and a delta rather than a timestamp, so the name table and the running clock live +there. Create a fresh one per connection — the device restarts both when it does. + +Pass `event_buffer.gaps` to the CSV writer as above. A gap is a stretch where the +sequence numbers say frames were lost; writing those rows is what keeps missing data +looking missing rather than silently closing up. + ### 2. Decode a recorded binary file Use the `etrace-decode` console script: @@ -92,24 +101,48 @@ print(f"{result.n_events} events, {result.n_lanes} lanes, {result.n_missed} dead | Column | Type | Description | |----------------|---------|--------------------------------------------------| -| `name` | string | Span or marker name | -| `type` | string | `task`, `isr`, or `marker` | -| `start_us` | float | Activation timestamp in µs | -| `end_us` | float | Completion timestamp in µs (= `start_us` for markers) | +| `name` | string | Span or marker name; `trace gap` on a gap row | +| `type` | string | `task`, `isr`, `marker`, or `gap` | +| `start_us` | float | Activation timestamp in µs; for a gap, the last frame before it | +| `end_us` | float | Completion timestamp in µs (= `start_us` for markers); for a gap, the first frame after it | | `priority` | int | Scheduler priority (0 if unknown) | -| `deadline_us` | float | Absolute deadline in µs (optional) | -| `value` | int | Optional u32 marker payload | +| `deadline_us` | float | Absolute deadline in µs (empty when absent) | +| `value` | int | Optional u32 marker payload; frames lost on a gap row | +| `interrupted` | int | `1` when a gap cut the span short, so its real end is unknown and at least `end_us` | + +An empty `deadline_us` or `value` cell means the field was **absent**. A `0` is a real +payload and is written as `0`. ## Wire format Each frame is a standard protobuf length-delimited record: ``` -[ varint: payload_length ][ proto bytes: TraceEvent ] +[ varint: payload_length ][ proto bytes: TraceFrame ] ``` -The protobuf schema lives in :file:`execution-trace/proto/tracing.proto` (sibling -Rust crate in the same repository). +A frame is **not self-contained**, which is why the decoder is stateful. `TraceFrame` is +one flat message discriminated by `event_type`, and the stream carries three kinds: + +- `TRACE_START`, once at the head of the stream, declaring the timebase (nanoseconds or + raw core cycles plus the core frequency) and the source-group mask the firmware was + built with. A group absent from the mask is silent by design — that is what tells it + apart from a group whose frames were lost. +- `NAME_REGISTERED`, once per distinct name, assigning the dictionary id and everything + fixed about that span or marker: its source type, priority and relative deadline. +- `SPAN_START`, `SPAN_END` and `MARKER`, which carry only a dictionary id, a signed + timestamp delta against the previous frame, and a sequence number wrapping at 16384. + +`TRACE_START` and `NAME_REGISTERED` carry an **absolute** timestamp and re-establish the +time origin; every other frame is a delta against it. The delta is signed because an +event is stamped when recorded rather than when queued, so a preempting ISR can put a +later timestamp ahead of an earlier one. + +This is **v2, and it is not compatible with the v1 format** that `embedded-etrace` 0.1.x +decoded. A v2 stream is recognised by its leading `TRACE_START` frame. + +The protobuf schema lives in `proto/tracing.proto` in the +[repository](https://github.com/erl987/execution-trace), alongside the Rust crate. ## Development diff --git a/python/src/execution_trace/__init__.py b/python/src/execution_trace/__init__.py index 55c551c..803ac98 100644 --- a/python/src/execution_trace/__init__.py +++ b/python/src/execution_trace/__init__.py @@ -4,7 +4,7 @@ from execution_trace import ( SequenceTracker, iter_frames, encode_varint, decode_varint, - TraceEvent, MarkerRecord, TraceEventBuffer, + TraceEvent, MarkerRecord, GapRecord, NameEntry, TraceEventBuffer, TraceStreamState, decode_tracing_stream, write_tracing_csv, ) @@ -16,9 +16,13 @@ """ from execution_trace.decode import ( + SEQUENCE_MODULUS, + GapRecord, MarkerRecord, + NameEntry, TraceEvent, TraceEventBuffer, + TraceStreamState, decode_tracing_stream, write_tracing_csv, ) @@ -36,7 +40,11 @@ "decode_varint", "TraceEvent", "MarkerRecord", + "GapRecord", + "NameEntry", "TraceEventBuffer", + "TraceStreamState", + "SEQUENCE_MODULUS", "decode_tracing_stream", "write_tracing_csv", ] diff --git a/python/src/execution_trace/_cli/decode.py b/python/src/execution_trace/_cli/decode.py index 7bb732f..1246bfd 100644 --- a/python/src/execution_trace/_cli/decode.py +++ b/python/src/execution_trace/_cli/decode.py @@ -13,14 +13,17 @@ import argparse import sys from pathlib import Path -from typing import NoReturn +from typing import NoReturn, Union from execution_trace.decode import ( + GapRecord, + MarkerRecord, + TraceEvent, TraceEventBuffer, + TraceStreamState, decode_tracing_stream, write_tracing_csv, ) -from execution_trace.stream import SequenceTracker def _die(msg: str) -> NoReturn: @@ -60,12 +63,18 @@ def main() -> None: output_dir = args.output if args.output is not None else str(binary_path.parent) buf = bytearray(binary_path.read_bytes()) - tracker = SequenceTracker("etrace-decode") + state = TraceStreamState("etrace-decode") event_buffer = TraceEventBuffer() - decode_tracing_stream(buf, tracker, event_buffer) + decode_tracing_stream(buf, state, event_buffer) event_buffer.flush_pending() - records = event_buffer.records + event_buffer.markers + # Gap rows carry the frames the link lost; without them the CSV shows an + # unexplained hole and interrupted spans with no reason beside them. + records: list[Union[TraceEvent, MarkerRecord, GapRecord]] = [ + *event_buffer.records, + *event_buffer.markers, + *event_buffer.gaps, + ] csv_path = write_tracing_csv(records, output_dir=output_dir) if csv_path is None: diff --git a/python/src/execution_trace/_proto/tracing_pb2.py b/python/src/execution_trace/_proto/tracing_pb2.py index 90abce8..9cbc2e2 100644 --- a/python/src/execution_trace/_proto/tracing_pb2.py +++ b/python/src/execution_trace/_proto/tracing_pb2.py @@ -24,17 +24,19 @@ -DESCRIPTOR = _descriptor_pool.Default().AddSerializedFile(b'\n\rtracing.proto\x12\x07tracing\"\x9d\x02\n\nTraceEvent\x12\x14\n\x0ctimestamp_ns\x18\x01 \x01(\x04\x12\x0c\n\x04name\x18\x02 \x01(\t\x12\x32\n\x0bsource_type\x18\x03 \x01(\x0e\x32\x1d.tracing.TraceEventSourceType\x12+\n\nevent_type\x18\x04 \x01(\x0e\x32\x17.tracing.TraceEventType\x12\x10\n\x08sequence\x18\x05 \x01(\r\x12\x10\n\x08priority\x18\x06 \x01(\r\x12!\n\x14relative_deadline_ms\x18\x07 \x01(\x02H\x00\x88\x01\x01\x12\x19\n\x0cmarker_value\x18\x08 \x01(\rH\x01\x88\x01\x01\x42\x17\n\x15_relative_deadline_msB\x0f\n\r_marker_value*R\n\x14TraceEventSourceType\x12\'\n#TRACE_EVENT_SOURCE_TYPE_UNSPECIFIED\x10\x00\x12\x07\n\x03ISR\x10\x01\x12\x08\n\x04TASK\x10\x02*\\\n\x0eTraceEventType\x12 \n\x1cTRACE_EVENT_TYPE_UNSPECIFIED\x10\x00\x12\x0e\n\nSPAN_START\x10\x01\x12\x0c\n\x08SPAN_END\x10\x02\x12\n\n\x06MARKER\x10\x03\x62\x06proto3') +DESCRIPTOR = _descriptor_pool.Default().AddSerializedFile(b'\n\rtracing.proto\x12\x07tracing\"\x86\x03\n\nTraceFrame\x12\x17\n\x0ftimestamp_ticks\x18\x01 \x01(\x12\x12\x0f\n\x07name_id\x18\x02 \x01(\r\x12+\n\nevent_type\x18\x03 \x01(\x0e\x32\x17.tracing.TraceEventType\x12\x10\n\x08sequence\x18\x04 \x01(\r\x12\x19\n\x0cmarker_value\x18\x05 \x01(\rH\x00\x88\x01\x01\x12\x0c\n\x04name\x18\x06 \x01(\t\x12\x32\n\x0bsource_type\x18\x07 \x01(\x0e\x32\x1d.tracing.TraceEventSourceType\x12\x10\n\x08priority\x18\x08 \x01(\r\x12!\n\x14relative_deadline_ms\x18\t \x01(\x02H\x01\x88\x01\x01\x12#\n\x08timebase\x18\n \x01(\x0e\x32\x11.tracing.TimeBase\x12\x19\n\x11\x63ore_frequency_hz\x18\x0b \x01(\r\x12\x13\n\x0bsource_mask\x18\x0c \x01(\rB\x0f\n\r_marker_valueB\x17\n\x15_relative_deadline_ms*R\n\x14TraceEventSourceType\x12\'\n#TRACE_EVENT_SOURCE_TYPE_UNSPECIFIED\x10\x00\x12\x07\n\x03ISR\x10\x01\x12\x08\n\x04TASK\x10\x02*\x82\x01\n\x0eTraceEventType\x12 \n\x1cTRACE_EVENT_TYPE_UNSPECIFIED\x10\x00\x12\x0e\n\nSPAN_START\x10\x01\x12\x0c\n\x08SPAN_END\x10\x02\x12\n\n\x06MARKER\x10\x03\x12\x13\n\x0fNAME_REGISTERED\x10\x04\x12\x0f\n\x0bTRACE_START\x10\x05*\'\n\x08TimeBase\x12\x0f\n\x0bNANOSECONDS\x10\x00\x12\n\n\x06\x43YCLES\x10\x01\x62\x06proto3') _globals = globals() _builder.BuildMessageAndEnumDescriptors(DESCRIPTOR, _globals) _builder.BuildTopDescriptorsAndMessages(DESCRIPTOR, 'tracing_pb2', _globals) if not _descriptor._USE_C_DESCRIPTORS: DESCRIPTOR._loaded_options = None - _globals['_TRACEEVENTSOURCETYPE']._serialized_start=314 - _globals['_TRACEEVENTSOURCETYPE']._serialized_end=396 - _globals['_TRACEEVENTTYPE']._serialized_start=398 - _globals['_TRACEEVENTTYPE']._serialized_end=490 - _globals['_TRACEEVENT']._serialized_start=27 - _globals['_TRACEEVENT']._serialized_end=312 + _globals['_TRACEEVENTSOURCETYPE']._serialized_start=419 + _globals['_TRACEEVENTSOURCETYPE']._serialized_end=501 + _globals['_TRACEEVENTTYPE']._serialized_start=504 + _globals['_TRACEEVENTTYPE']._serialized_end=634 + _globals['_TIMEBASE']._serialized_start=636 + _globals['_TIMEBASE']._serialized_end=675 + _globals['_TRACEFRAME']._serialized_start=27 + _globals['_TRACEFRAME']._serialized_end=417 # @@protoc_insertion_point(module_scope) diff --git a/python/src/execution_trace/_proto/tracing_pb2.pyi b/python/src/execution_trace/_proto/tracing_pb2.pyi index 7cd25dd..d9a1119 100644 --- a/python/src/execution_trace/_proto/tracing_pb2.pyi +++ b/python/src/execution_trace/_proto/tracing_pb2.pyi @@ -17,6 +17,13 @@ class TraceEventType(int, metaclass=_enum_type_wrapper.EnumTypeWrapper): SPAN_START: _ClassVar[TraceEventType] SPAN_END: _ClassVar[TraceEventType] MARKER: _ClassVar[TraceEventType] + NAME_REGISTERED: _ClassVar[TraceEventType] + TRACE_START: _ClassVar[TraceEventType] + +class TimeBase(int, metaclass=_enum_type_wrapper.EnumTypeWrapper): + __slots__ = () + NANOSECONDS: _ClassVar[TimeBase] + CYCLES: _ClassVar[TimeBase] TRACE_EVENT_SOURCE_TYPE_UNSPECIFIED: TraceEventSourceType ISR: TraceEventSourceType TASK: TraceEventSourceType @@ -24,23 +31,35 @@ TRACE_EVENT_TYPE_UNSPECIFIED: TraceEventType SPAN_START: TraceEventType SPAN_END: TraceEventType MARKER: TraceEventType +NAME_REGISTERED: TraceEventType +TRACE_START: TraceEventType +NANOSECONDS: TimeBase +CYCLES: TimeBase -class TraceEvent(_message.Message): - __slots__ = ("timestamp_ns", "name", "source_type", "event_type", "sequence", "priority", "relative_deadline_ms", "marker_value") - TIMESTAMP_NS_FIELD_NUMBER: _ClassVar[int] - NAME_FIELD_NUMBER: _ClassVar[int] - SOURCE_TYPE_FIELD_NUMBER: _ClassVar[int] +class TraceFrame(_message.Message): + __slots__ = ("timestamp_ticks", "name_id", "event_type", "sequence", "marker_value", "name", "source_type", "priority", "relative_deadline_ms", "timebase", "core_frequency_hz", "source_mask") + TIMESTAMP_TICKS_FIELD_NUMBER: _ClassVar[int] + NAME_ID_FIELD_NUMBER: _ClassVar[int] EVENT_TYPE_FIELD_NUMBER: _ClassVar[int] SEQUENCE_FIELD_NUMBER: _ClassVar[int] + MARKER_VALUE_FIELD_NUMBER: _ClassVar[int] + NAME_FIELD_NUMBER: _ClassVar[int] + SOURCE_TYPE_FIELD_NUMBER: _ClassVar[int] PRIORITY_FIELD_NUMBER: _ClassVar[int] RELATIVE_DEADLINE_MS_FIELD_NUMBER: _ClassVar[int] - MARKER_VALUE_FIELD_NUMBER: _ClassVar[int] - timestamp_ns: int - name: str - source_type: TraceEventSourceType + TIMEBASE_FIELD_NUMBER: _ClassVar[int] + CORE_FREQUENCY_HZ_FIELD_NUMBER: _ClassVar[int] + SOURCE_MASK_FIELD_NUMBER: _ClassVar[int] + timestamp_ticks: int + name_id: int event_type: TraceEventType sequence: int + marker_value: int + name: str + source_type: TraceEventSourceType priority: int relative_deadline_ms: float - marker_value: int - def __init__(self, timestamp_ns: _Optional[int] = ..., name: _Optional[str] = ..., source_type: _Optional[_Union[TraceEventSourceType, str]] = ..., event_type: _Optional[_Union[TraceEventType, str]] = ..., sequence: _Optional[int] = ..., priority: _Optional[int] = ..., relative_deadline_ms: _Optional[float] = ..., marker_value: _Optional[int] = ...) -> None: ... + timebase: TimeBase + core_frequency_hz: int + source_mask: int + def __init__(self, timestamp_ticks: _Optional[int] = ..., name_id: _Optional[int] = ..., event_type: _Optional[_Union[TraceEventType, str]] = ..., sequence: _Optional[int] = ..., marker_value: _Optional[int] = ..., name: _Optional[str] = ..., source_type: _Optional[_Union[TraceEventSourceType, str]] = ..., priority: _Optional[int] = ..., relative_deadline_ms: _Optional[float] = ..., timebase: _Optional[_Union[TimeBase, str]] = ..., core_frequency_hz: _Optional[int] = ..., source_mask: _Optional[int] = ...) -> None: ... diff --git a/python/src/execution_trace/decode.py b/python/src/execution_trace/decode.py index e2d7bdf..978388f 100644 --- a/python/src/execution_trace/decode.py +++ b/python/src/execution_trace/decode.py @@ -1,18 +1,24 @@ -"""High-level decoder for execution-trace protobuf streams. +"""High-level decoder for execution-trace protobuf streams (wire format v2). Receives raw bytes from any transport (RTT, UART, TCP, …), parses -length-delimited :class:`TraceEvent` protobuf frames, matches -``SPAN_START`` / ``SPAN_END`` pairs into :class:`TraceEvent` records, -and records :class:`MarkerRecord` annotations directly. +length-delimited :class:`tracing_pb2.TraceFrame` frames, matches +``SPAN_START`` / ``SPAN_END`` pairs into :class:`TraceEvent` records, and +records :class:`MarkerRecord` annotations directly. + +A v2 frame is **not** self-contained: its name is a dictionary id assigned by an +earlier ``NAME_REGISTERED`` frame, and its timestamp is a delta against the +previous frame. Both are resolved here rather than on the device, which is why +:class:`TraceStreamState` carries the dictionary, the running clock and the +sequence tracker across every frame of one connection. Typical usage:: buf = bytearray() - tracker = SequenceTracker("tracing") + state = TraceStreamState("tracing") event_buffer = TraceEventBuffer() # ... fill buf from hardware ... - decode_tracing_stream(buf, tracker, event_buffer) + decode_tracing_stream(buf, state, event_buffer) csv_path = write_tracing_csv( event_buffer.records + event_buffer.markers, @@ -20,9 +26,11 @@ ) """ +import collections import csv import logging import os +from collections.abc import Sequence from dataclasses import dataclass, field from datetime import datetime from typing import Optional, Union @@ -32,6 +40,43 @@ logger = logging.getLogger(__name__) +# The firmware's sequence counter wraps here rather than at 2**32: it exists only +# to detect gaps, a gap is read modulo the wrap, and a full 32-bit counter would +# spend up to five varint bytes per frame to buy nothing. +SEQUENCE_MODULUS: int = 16_384 + +# Reserved dictionary id, emitted when the device's name registry is full. The +# stream stays decodable; the name of that one event is lost. +UNKNOWN_NAME_ID: int = 0 + +UNKNOWN_NAME: str = "" + +# How many recent frames to remember the arrival time of, for placing a hole the +# reorder window only reveals later. Comfortably more than REORDER_WINDOW. +SEEN_HISTORY: int = 512 + +# How far a frame may arrive ahead of a missing one before that one is called +# lost. +# +# Frames are numbered by their producer, before the queue the transport drains, +# so an ISR preempting a task between those two points takes a later number and +# reaches the wire first. The transport's own frames — the header and the +# dictionary — are numbered when written and can overtake events already queued, +# which bounds the reordering by the depth of that queue rather than by the +# preemption window. 64 covers the 48-slot channel with margin; the cost of the +# margin is only that a genuine loss is reported this many frames later. +REORDER_WINDOW: int = 64 + +# How far the device clock must appear to jump *backwards* on a TRACE_START +# before it is read as a reboot rather than as ordering jitter. +# +# A reboot restarts the clock at zero, so it shows up as the whole uptime — many +# seconds. Jitter is microseconds: the header's timestamp is read after the +# producer queue is drained, but an event recorded just before that read can +# still be encoded after it. Treating a microsecond inversion as a reboot would +# throw the dictionary away and blind the trace for a whole refresh interval. +RESET_BACKWARD_MARGIN_US: float = 1_000_000.0 + @dataclass class TraceEvent: @@ -56,6 +101,32 @@ class TraceEvent: priority: int = 0 deadline_us: Optional[float] = None value: Optional[int] = None + #: The span was cut short by a gap rather than closed by its own ``SPAN_END`` + #: — its real end is unknown and at least ``end_us`` (§5.9). + interrupted: bool = False + + +@dataclass +class GapRecord: + """A stretch of the trace where frames were lost. + + Emitted as a row of its own so that missing data *looks* missing. Silent + truncation is what made a 2 % frame-loss rate read as a broken instrument + (§2.5). + + Attributes: + name: Fixed label, so the row reads for itself in the CSV. + type: Always ``"gap"``. + start_us: Timestamp of the last frame received before the hole. + end_us: Timestamp of the first frame received after it. + frames_lost: How many frames the sequence says are missing. + """ + + start_us: float + end_us: float + frames_lost: int + name: str = "trace gap" + type: str = field(default="gap", init=False) @dataclass @@ -77,6 +148,170 @@ class MarkerRecord: value: Optional[int] = None +@dataclass +class NameEntry: + """One dictionary entry: everything fixed by a span or marker name. + + These attributes are sent once, on the ``NAME_REGISTERED`` frame that assigns + the id, rather than repeated on every occurrence of the event. + + Attributes: + name: Task, ISR or marker label. + source_type: ``tracing_pb2.ISR`` or ``tracing_pb2.TASK``. + priority: Scheduler priority; 0 when the name was first seen on a frame + that carries no attributes (a ``SPAN_END`` or ``MARKER``). + relative_deadline_ms: Deadline relative to activation, or ``None``. + """ + + name: str + source_type: int = tracing_pb2.TRACE_EVENT_SOURCE_TYPE_UNSPECIFIED + priority: int = 0 + relative_deadline_ms: Optional[float] = None + + +class TraceStreamState: + """Per-connection decoder state for one v2 trace stream. + + A v2 frame carries a dictionary id instead of a name and a delta instead of a + timestamp, so decoding is stateful: this holds the name dictionary, the + running clock the deltas accumulate into, the timebase declared by the + ``TRACE_START`` frame, and the sequence tracker that detects gaps and resets. + + Create one per connection — the device's dictionary and clock both restart + when it does. + + Args: + label: Human-readable stream name used in log messages. + + Attributes: + source_mask: The source-group mask the firmware was built with, or + ``None`` until a ``TRACE_START`` frame arrives. A group absent from + the mask is silent by design, which is what distinguishes it from a + group whose frames were lost. + """ + + def __init__(self, label: str = "Trace event") -> None: + self.label = label + self.tracker = SequenceTracker( + label, modulus=SEQUENCE_MODULUS, reorder_window=REORDER_WINDOW + ) + self.names: dict[int, NameEntry] = {} + #: Reconstructed device time, in ticks. Signed, because a frame's delta + #: can be negative — see the `timestamp_ticks` field comment in the proto. + self.clock_ticks: int = 0 + self.timebase: int = tracing_pb2.NANOSECONDS + self.core_frequency_hz: int = 0 + self.source_mask: Optional[int] = None + # Ids already reported as unresolvable. At 1300+ events/s an unregistered + # id would otherwise log thousands of identical lines per second. + self._warned_ids: set[int] = set() + #: Events dropped because their name id could not be resolved. + self.unresolved_events: int = 0 + # sequence -> absolute timestamp, for the most recent frames. A hole is + # reported up to REORDER_WINDOW frames after it happened, so locating it + # in time means looking up the numbers either side of it rather than + # using whatever frame happened to trigger the report. + self._seen_at: collections.OrderedDict[int, float] = collections.OrderedDict() + + def reset(self) -> None: + """Discard all per-stream state after a device reset. + + The dictionary must go with it: the device reassigns ids from one on + reboot, so a stale entry would resolve a new id to the wrong name. + """ + self.tracker = SequenceTracker( + self.label, modulus=SEQUENCE_MODULUS, reorder_window=REORDER_WINDOW + ) + self.names.clear() + self._warned_ids.clear() + self.unresolved_events = 0 + self.clock_ticks = 0 + self.timebase = tracing_pb2.NANOSECONDS + self.core_frequency_hz = 0 + self.source_mask = None + + def ticks_to_us(self, ticks: int) -> float: + """Convert a tick count to microseconds using the declared timebase. + + Args: + ticks: A tick count in the unit the ``TRACE_START`` frame declared. + + Returns: + The equivalent duration in microseconds. + """ + if self.timebase == tracing_pb2.CYCLES and self.core_frequency_hz > 0: + return ticks * 1_000_000.0 / self.core_frequency_hz + return ticks / 1_000.0 + + def advance(self, frame: tracing_pb2.TraceFrame) -> float: + """Advance the stream clock by *frame* and return its absolute time in µs. + + ``NAME_REGISTERED`` and ``TRACE_START`` frames carry an absolute + timestamp and re-establish the origin; every other frame carries a delta + against the frame before it. + + Args: + frame: The decoded frame. + + Returns: + The frame's absolute timestamp in microseconds. + """ + if frame.event_type in (tracing_pb2.NAME_REGISTERED, tracing_pb2.TRACE_START): + self.clock_ticks = frame.timestamp_ticks + else: + self.clock_ticks += frame.timestamp_ticks + return self.ticks_to_us(self.clock_ticks) + + def note_seen(self, sequence: int, timestamp_us: float) -> None: + """Remember when a numbered frame arrived, for locating a later-found hole.""" + self._seen_at[sequence] = timestamp_us + while len(self._seen_at) > SEEN_HISTORY: + self._seen_at.popitem(last=False) + + def gap_bounds(self, first_missing: int, count: int) -> Optional[tuple[float, float]]: + """Timestamps bracketing a hole, from the frames either side of it. + + Returns ``None`` when neither neighbour is still in history, which leaves + the gap unplaceable — it is then reported in the log only. + """ + before = self._seen_at.get((first_missing - 1) % SEQUENCE_MODULUS) + after = self._seen_at.get((first_missing + count) % SEQUENCE_MODULUS) + if before is None and after is None: + return None + start = before if before is not None else after + end = after if after is not None else before + assert start is not None and end is not None # noqa: S101 - narrowing for mypy + return (start, max(end, start)) + + def resolve(self, name_id: int) -> Optional[NameEntry]: + """Look up a dictionary id. + + Args: + name_id: The id carried by the frame. + + Returns: + The registered entry, or ``None`` when the id cannot be resolved — + either the reserved "unknown" id, meaning the device's registry was + full, or an id whose ``NAME_REGISTERED`` frame the host never saw + because it attached after the entry was sent. + + Callers must **drop** an unresolvable event rather than attribute it + to a placeholder name: distinct ids would otherwise share one lane, + and their spans would interleave into pairs that never existed. + """ + entry = self.names.get(name_id) + if entry is not None: + return entry + if name_id != UNKNOWN_NAME_ID and name_id not in self._warned_ids: + self._warned_ids.add(name_id) + logger.warning( + "Tracing: name id %d not resolvable yet — dropping its events " + "until the device's next dictionary refresh", name_id, + ) + self.unresolved_events += 1 + return None + + class TraceEventBuffer: """Accumulates :class:`TraceEvent` records by matching ``SPAN_START`` / ``SPAN_END`` pairs. @@ -87,50 +322,114 @@ class TraceEventBuffer: """ def __init__(self) -> None: - # name → (timestamp_ns, source_type, priority, relative_deadline_ms) - self._pending: dict[str, tuple[int, int, int, Optional[float]]] = {} + # name → (start_us, NameEntry) + self._pending: dict[str, tuple[float, NameEntry]] = {} self._records: list[TraceEvent] = [] self._markers: list[MarkerRecord] = [] - - def push(self, msg: tracing_pb2.TraceEvent) -> None: - """Process one decoded :class:`tracing_pb2.TraceEvent`. + self._gaps: list[GapRecord] = [] + # Names whose span a gap cut short. The next SPAN_END for each is the + # other half of a pair whose START is already closed, so it is dropped + # rather than paired with a later, unrelated START (§5.9). + self._orphaned_ends: set[str] = set() + + def push( + self, + frame: tracing_pb2.TraceFrame, + entry: NameEntry, + timestamp_us: float, + ) -> None: + """Process one decoded frame whose name and timestamp are already resolved. Args: - msg: Decoded protobuf message from the firmware. + frame: The decoded frame, for its event type and marker value. + entry: The dictionary entry its ``name_id`` resolves to. + timestamp_us: Its absolute timestamp in microseconds. """ - name = msg.name - if msg.event_type == tracing_pb2.SPAN_START: + name = entry.name + if frame.event_type == tracing_pb2.SPAN_START: if name in self._pending: logger.warning("Tracing: duplicate START for '%s' — discarding previous", name) - relative_deadline_ms = msg.relative_deadline_ms if msg.HasField("relative_deadline_ms") else None - self._pending[name] = (msg.timestamp_ns, msg.source_type, int(msg.priority), relative_deadline_ms) - elif msg.event_type == tracing_pb2.SPAN_END: + self._pending[name] = (timestamp_us, entry) + elif frame.event_type == tracing_pb2.SPAN_END: + if name in self._orphaned_ends: + # Its START was closed by interrupt_open_spans; pairing this with + # whatever opens next would invent a span that never ran. + self._orphaned_ends.discard(name) + return if name not in self._pending: logger.warning("Tracing: END for '%s' with no matching START — discarding", name) return - start_ns, source_type, priority, relative_deadline_ms = self._pending.pop(name) - type_str = "isr" if source_type == tracing_pb2.ISR else "task" - start_us = start_ns / 1_000.0 - deadline_us = start_us + relative_deadline_ms * 1_000.0 if relative_deadline_ms is not None else None + start_us, start_entry = self._pending.pop(name) + type_str = "isr" if start_entry.source_type == tracing_pb2.ISR else "task" + deadline_us = ( + start_us + start_entry.relative_deadline_ms * 1_000.0 + if start_entry.relative_deadline_ms is not None + else None + ) self._records.append( TraceEvent( name=name, type=type_str, start_us=start_us, - end_us=msg.timestamp_ns / 1_000.0, - priority=priority, + end_us=timestamp_us, + priority=start_entry.priority, deadline_us=deadline_us, ) ) - elif msg.event_type == tracing_pb2.MARKER: - value = int(msg.marker_value) if msg.HasField("marker_value") else None + elif frame.event_type == tracing_pb2.MARKER: + value = int(frame.marker_value) if frame.HasField("marker_value") else None self._markers.append( - MarkerRecord( + MarkerRecord(name=name, timestamp_us=timestamp_us, value=value) + ) + + def interrupt_open_spans(self, at_us: float, frames_lost: int, resumed_us: float) -> None: + """Close every span open at a gap, and record the gap itself. + + A span whose ``SPAN_END`` was lost would otherwise stay open until the + next unrelated end for that name, producing one enormous bar across the + hole and well past it — which is the visual damage §2.5 describes. Each + open span is instead cut at the last frame before the gap and marked + interrupted, so the diagram shows a span of unknown length rather than a + wrong one. + + Args: + at_us: Timestamp of the last frame received before the hole. + frames_lost: How many frames the sequence says are missing. + resumed_us: Timestamp of the first frame received after it. + """ + self._gaps.append( + GapRecord(start_us=at_us, end_us=max(resumed_us, at_us), frames_lost=frames_lost) + ) + # Only spans that were already running when the hole happened. The + # reorder window means this is discovered up to 64 frames later, by which + # time other spans have opened — and one that started after the hole + # cannot have been affected by it. + caught = [ + (name, value) for name, value in self._pending.items() if value[0] <= at_us + ] + for name, (start_us, entry) in caught: + self._records.append( + TraceEvent( name=name, - timestamp_us=msg.timestamp_ns / 1_000.0, - value=value, + type="isr" if entry.source_type == tracing_pb2.ISR else "task", + start_us=start_us, + end_us=at_us, + priority=entry.priority, + deadline_us=( + start_us + entry.relative_deadline_ms * 1_000.0 + if entry.relative_deadline_ms is not None + else None + ), + interrupted=True, ) ) + self._orphaned_ends.add(name) + del self._pending[name] + + @property + def gaps(self) -> list[GapRecord]: + """Gap records in arrival order.""" + return list(self._gaps) def flush_pending(self) -> None: """Warn about any unmatched ``SPAN_START`` events and clear pending state. @@ -156,35 +455,113 @@ def markers(self) -> list[MarkerRecord]: def decode_tracing_stream( buf: bytearray, - tracker: SequenceTracker, + state: TraceStreamState, event_buffer: TraceEventBuffer, ) -> None: """Decode all complete frames from *buf* and push events into *event_buffer*. - Consumes *buf* in-place. Stops and clears *buf* if a device reset is detected - (sequence number jumped backward), also calling :meth:`TraceEventBuffer.flush_pending`. + Consumes *buf* in-place. Resolves each frame's dictionary id and delta + timestamp against *state*, which must be the same object across every call + for one connection. + + On a detected device reset, resets *state* and calls + :meth:`TraceEventBuffer.flush_pending`, then carries on parsing. It does + **not** discard *buf*: the stream is length-prefixed with no sync marker, so + dropping bytes mid-frame leaves every following frame misaligned and + unrecoverable. Args: buf: Mutable byte buffer containing raw RTT / transport bytes. - tracker: Sequence number tracker shared across calls for the same stream. + state: Per-connection decoder state, shared across calls for one stream. event_buffer: Accumulator for decoded events. """ for raw in iter_frames(buf): - msg = tracing_pb2.TraceEvent() + frame = tracing_pb2.TraceFrame() try: - msg.ParseFromString(raw) + frame.ParseFromString(raw) except Exception as exc: - logger.warning("Failed to decode TraceEvent: %s", exc) + logger.warning("Failed to decode TraceFrame: %s", exc) continue - if tracker.observe(msg.sequence): - buf.clear() + + # A device reset invalidates everything carried over: the dictionary is + # reassigned from id one and the clock restarts at zero, so a stale entry + # would resolve a new id to an old name. Two things reveal one. + # + # The device re-emits the header periodically so that a host attaching + # mid-run learns the timebase and the mask, so a header alone is not a + # reset — only one whose absolute timestamp has gone *far* backwards, + # which separates a reboot from ordering jitter (RESET_BACKWARD_MARGIN_US). + clock_restarted = ( + frame.event_type == tracing_pb2.TRACE_START + and state.source_mask is not None + and state.ticks_to_us(state.clock_ticks - frame.timestamp_ticks) + > RESET_BACKWARD_MARGIN_US + ) + if clock_restarted or state.tracker.observe(frame.sequence): + if clock_restarted: + logger.warning("Tracing: device clock restarted — device reset") event_buffer.flush_pending() - break - event_buffer.push(msg) + state.reset() + # Seed the fresh tracker from this frame so gap detection is exact + # from the reset onward rather than from the frame after it. + state.tracker.observe(frame.sequence) + # Then fall through and process this frame: it is the first frame of + # the new run — often the reboot's own header, carrying the timebase + # and mask — and skipping it would leave the stream unattributed + # until the next refresh. + # + # Deliberately no `buf.clear()`: the frames after this point are + # intact and correctly delimited, and discarding bytes mid-frame + # would misalign the rest of the stream permanently. + + timestamp_us = state.advance(frame) + state.note_seen(frame.sequence, timestamp_us) + + # A hole the tracker has just become certain of. Close whatever was open + # across it, so a span whose end was lost does not run on for ever, and + # record the gap as a row of its own (§5.9). + if state.tracker.last_gap is not None: + first_missing, lost = state.tracker.last_gap + bounds = state.gap_bounds(first_missing, lost) + if bounds is not None: + event_buffer.interrupt_open_spans(bounds[0], lost, bounds[1]) + + if frame.event_type == tracing_pb2.TRACE_START: + state.timebase = frame.timebase + state.core_frequency_hz = frame.core_frequency_hz + first_header = state.source_mask is None + state.source_mask = frame.source_mask + # The clock was set from the raw ticks before the timebase was known; + # it is a tick count either way, so only the conversion changes. + if first_header: + logger.info( + "Tracing: stream start, timebase=%s core=%d Hz source_mask=0x%02X", + tracing_pb2.TimeBase.Name(frame.timebase), + frame.core_frequency_hz, + frame.source_mask, + ) + elif frame.event_type == tracing_pb2.NAME_REGISTERED: + state._warned_ids.discard(frame.name_id) + state.names[frame.name_id] = NameEntry( + name=frame.name, + source_type=frame.source_type, + priority=int(frame.priority), + relative_deadline_ms=( + frame.relative_deadline_ms + if frame.HasField("relative_deadline_ms") + else None + ), + ) + else: + entry = state.resolve(frame.name_id) + # An unresolvable id is dropped, not bucketed under a placeholder: + # see TraceStreamState.resolve. + if entry is not None: + event_buffer.push(frame, entry, timestamp_us) def write_tracing_csv( - records: list[Union[TraceEvent, MarkerRecord]], + records: Sequence[Union[TraceEvent, MarkerRecord, GapRecord]], output_dir: str = "data", ) -> Optional[str]: """Write span and marker records to a timestamped CSV file. @@ -209,7 +586,10 @@ def write_tracing_csv( +---------------+------------------------------------------+ | ``deadline_us``| absolute deadline in µs, or empty | +---------------+------------------------------------------+ - | ``value`` | optional u32 payload, or empty | + | ``value`` | optional u32 payload; frames lost on a | + | | ``gap`` row, or empty | + +---------------+------------------------------------------+ + | ``interrupted``| ``1`` when a gap cut the span short | +---------------+------------------------------------------+ Args: @@ -230,21 +610,37 @@ def write_tracing_csv( path = os.path.join(output_dir, filename) latest = os.path.join(output_dir, "trace_latest.csv") + # An optional column is empty only when the field is absent. Testing the value for + # truth instead would write 0 as empty, and zero is a legitimate payload: a reason + # code, a count of nothing, a deadline at the activation instant. + def _optional(field: float | int | None) -> float | int | str: + return "" if field is None else field + with open(path, "w", newline="") as f: writer = csv.writer(f) - writer.writerow(["name", "type", "start_us", "end_us", "priority", "deadline_us", "value"]) + writer.writerow([ + "name", "type", "start_us", "end_us", "priority", "deadline_us", "value", + "interrupted", + ]) for r in records: if isinstance(r, MarkerRecord): writer.writerow([ r.name, "marker", r.timestamp_us, r.timestamp_us, - 0, "", r.value or "", + 0, "", _optional(r.value), 0, + ]) + elif isinstance(r, GapRecord): + writer.writerow([ + r.name, "gap", + r.start_us, r.end_us, + 0, "", r.frames_lost, 0, ]) else: writer.writerow([ r.name, r.type, r.start_us, r.end_us, - r.priority, r.deadline_us or "", r.value or "", + r.priority, _optional(r.deadline_us), _optional(r.value), + int(r.interrupted), ]) # Atomically replace the symlink so trace_latest.csv always points to newest. diff --git a/python/src/execution_trace/diagram.py b/python/src/execution_trace/diagram.py index 6174cac..321e43e 100644 --- a/python/src/execution_trace/diagram.py +++ b/python/src/execution_trace/diagram.py @@ -194,9 +194,23 @@ def _coerce_numeric(df: "pd.DataFrame", col: str, *, required: bool = False) -> if len(df) == 0: die("tracing CSV contains no data rows") - # Markers have start_us == end_us == timestamp_us; only validate spans. + if "interrupted" in df.columns: + df["interrupted"] = ( + pd.to_numeric(df["interrupted"], errors="coerce").fillna(0).astype(bool) + ) + else: + df["interrupted"] = False + + # Markers have start_us == end_us == timestamp_us, and a gap row is a band + # rather than an interval that ran; only validate spans. spans = df[df["type"].isin(["task", "isr"])] - bad = spans[spans["end_us"] <= spans["start_us"]] + # An interrupted span is cut at the last frame before a gap, which can be the + # very frame that opened it — so it may be zero-length. Its end is a lower + # bound on when it finished, not a measurement, and zero is a true one. + bad = spans[ + (spans["end_us"] < spans["start_us"]) + | ((spans["end_us"] == spans["start_us"]) & ~spans["interrupted"]) + ] if not bad.empty: csv_row = bad.index[0] + 2 die(f"row {csv_row}: end_us must be > start_us") @@ -210,6 +224,9 @@ def _coerce_numeric(df: "pd.DataFrame", col: str, *, required: bool = False) -> df["missed"] = ( df["effective_deadline_us"].notna() & (df["end_us"] > df["effective_deadline_us"]) + # An interrupted span's end is unknown and only a lower bound, so it + # cannot be said to have overrun (§5.9). + & ~df["interrupted"] ) return df.reset_index(drop=True) @@ -225,7 +242,8 @@ def assign_lanes(df: "pd.DataFrame") -> "tuple[pd.DataFrame, list[str]]": Marker rows are assigned to the lane of the highest-priority span that contains the marker's timestamp. Uncontained markers receive lane ``-1`` - (rendered below all spans). + (rendered below all spans). Gap rows span every lane and are carried through + with lane ``-1`` as well. Args: df: Validated DataFrame from :func:`load_traces` (spans and markers). @@ -237,6 +255,7 @@ def assign_lanes(df: "pd.DataFrame") -> "tuple[pd.DataFrame, list[str]]": """ spans = df[df["type"].isin(["task", "isr"])].copy() markers = df[df["type"] == "marker"].copy() + gaps = df[df["type"] == "gap"].copy() name_type = spans.groupby("name", sort=False)["type"].first() name_priority = spans.groupby("name", sort=False)["priority"].first() @@ -261,13 +280,16 @@ def _infer_lane(ts: float) -> int: if containing.empty: return -1 idx = containing["priority"].idxmax() - lane = cast(SupportsFloat, containing.loc[idx, "lane"]) + lane = cast(SupportsFloat, containing.at[idx, "lane"]) return int(float(lane)) markers = markers.copy() markers["lane"] = markers["start_us"].apply(_infer_lane) - df = pd.concat([spans, markers], ignore_index=True) if not markers.empty else spans + if not gaps.empty: + gaps["lane"] = -1 + parts = [part for part in (spans, markers, gaps) if not part.empty] + df = pd.concat(parts, ignore_index=True) if len(parts) > 1 else parts[0] return df, top_to_bottom @@ -309,10 +331,19 @@ def _fmt_ms(v: float) -> str: return "—" if pd.isna(v) else f"{v / 1_000:,.3f} ms" -def _bar_source(sub: "pd.DataFrame", colors: dict[str, str]) -> ColumnDataSource: +def _bar_source( + sub: "pd.DataFrame", colors: dict[str, str], min_width: float = 0.0 +) -> ColumnDataSource: + # An interrupted span can be zero-length; without a floor it would vanish, + # which is the opposite of what §5.9 is for. + right = sub["end_us"] if min_width <= 0 else ( + sub[["end_us", "start_us"]].max(axis=1).combine( + sub["start_us"] + min_width, max + ) + ) return ColumnDataSource({ "left": sub["start_us"].tolist(), - "right": sub["end_us"].tolist(), + "right": right.tolist(), "top": (sub["lane"] + _HALF_H).tolist(), "bottom": (sub["lane"] - _HALF_H).tolist(), "name": sub["name"].tolist(), @@ -346,6 +377,7 @@ def build_figure( """ spans = df[df["type"].isin(["task", "isr"])] markers = df[df["type"] == "marker"] + gaps = df[df["type"] == "gap"] n = len(lane_names) x_lo = float(spans["start_us"].min()) @@ -373,6 +405,42 @@ def build_figure( fill_alpha=0.55, line_color=None, ) + # Gap bands go down before the bars so the spans either side stay legible on + # top of them. A trace that is missing data has to look like one (§5.9). + if not gaps.empty: + # A gap of zero width would be invisible; give it a hairline so the + # annotation still has something to sit on. + min_w = max((x_hi - x_lo) * 0.0008, 1.0) + widths = (gaps["end_us"] - gaps["start_us"]).clip(lower=min_w) + gap_src = ColumnDataSource({ + "left": gaps["start_us"].tolist(), + "right": (gaps["start_us"] + widths).tolist(), + "bottom": [-0.6] * len(gaps), + "top": [n - 0.4] * len(gaps), + "frames_lost": [ + int(v) if pd.notna(v) else 0 for v in gaps["value"] + ], + "start_us": gaps["start_us"].tolist(), + }) + gap_renderer = p.quad( + left="left", right="right", bottom="bottom", top="top", + source=gap_src, + fill_color="#b71c1c", fill_alpha=0.13, + hatch_pattern="/", hatch_color="#b71c1c", hatch_alpha=0.45, hatch_scale=12, + line_color="#b71c1c", line_width=1.0, line_alpha=0.55, + legend_label="Trace gap", + ) + p.add_tools(HoverTool( + renderers=[gap_renderer], + tooltips=[("trace gap", "@frames_lost frames lost"), ("at", "@start_us{0,0.0} µs")], + )) + labels = LabelSet( + x="start_us", y=n - 0.45, text="frames_lost", + source=gap_src, text_color="#b71c1c", text_font_size="9pt", + x_offset=3, y_offset=-12, + ) + p.add_layout(labels) + span_renderers = [] marker_renderers = [] @@ -382,11 +450,12 @@ def _add_bars( line_color: str, line_width: float, legend_label: str, + min_width: float = 0.0, ) -> None: sub = spans[mask] if sub.empty: return - src = _bar_source(sub, colors) + src = _bar_source(sub, colors, min_width=min_width) hatch_kw = ( dict(hatch_pattern=hatch, hatch_color="white", hatch_alpha=0.40, hatch_scale=9) if hatch is not None else {} @@ -400,14 +469,21 @@ def _add_bars( ) span_renderers.append(r) - _add_bars((spans["type"] == "task") & ~spans["missed"], + cut = spans["interrupted"] + _add_bars((spans["type"] == "task") & ~spans["missed"] & ~cut, None, "#555555", _NORMAL_LW, "Task") - _add_bars((spans["type"] == "isr") & ~spans["missed"], + _add_bars((spans["type"] == "isr") & ~spans["missed"] & ~cut, "/", "#555555", _NORMAL_LW, "ISR") - _add_bars((spans["type"] == "task") & spans["missed"], + _add_bars((spans["type"] == "task") & spans["missed"] & ~cut, None, "crimson", _MISSED_LW, "Missed deadline") - _add_bars((spans["type"] == "isr") & spans["missed"], + _add_bars((spans["type"] == "isr") & spans["missed"] & ~cut, "/", "crimson", _MISSED_LW, "ISR — missed deadline") + # Cut short by a gap: the end is a lower bound, not a measurement, so it is + # drawn open-ended rather than as a span of that length. + _add_bars( + cut, "x", "#b71c1c", _MISSED_LW, "Interrupted by gap", + min_width=max((x_hi - x_lo) * 0.0008, 1.0), + ) dl = spans[spans["effective_deadline_us"].notna()].copy() if not dl.empty: diff --git a/python/src/execution_trace/stream.py b/python/src/execution_trace/stream.py index 58770e9..e525d9e 100644 --- a/python/src/execution_trace/stream.py +++ b/python/src/execution_trace/stream.py @@ -24,64 +24,174 @@ logger = logging.getLogger(__name__) -# A "drop" count exceeding half the u32 range means the sequence went backward — +# The default counter width, for streams that carry a full 32-bit sequence. +DEFAULT_MODULUS: int = 1 << 32 + +# A "drop" count exceeding half the counter range means the sequence went backward — # a device reset rather than actual packet loss. -RESET_THRESHOLD: int = 1 << 31 +RESET_THRESHOLD: int = DEFAULT_MODULUS >> 1 class SequenceTracker: - """Detects device resets by watching for backwards sequence number jumps. + """Tracks a frame sequence, reporting loss and device resets. + + Embedded firmware increments a counter with every frame. A hole in the + numbers is loss; a large backwards jump is the counter starting over, which + means the device reset. + + Reordering: + With a *reorder_window* above zero the tracker tolerates frames arriving + slightly out of order before calling a hole loss. The execution-trace v2 + format needs this: a frame is numbered by its producer, before it reaches + the queue the transport drains, so an ISR that + preempts a task between those two points takes a later number and reaches + the wire first. The transport's own frames — the stream header and the + dictionary — are numbered when written and can likewise overtake events + already queued. - Embedded firmware typically increments a 32-bit sequence counter with every - frame. When the device resets (panic, watchdog, or reflash), the counter - starts over at zero on the same connection. This class distinguishes a reset - (counter jumped backward by more than half the u32 range) from ordinary - packet loss (small forward gap). + A hole is therefore only reported once a number arrives more than + *reorder_window* ahead of it, which bounds how long the report is + delayed. Single-producer streams should leave the window at zero and get + the report immediately. Args: label: Human-readable stream name used in log messages. + modulus: The value the counter wraps at. Defaults to the full 32-bit + range; the execution-trace v2 format wraps far earlier, at + :data:`execution_trace.decode.SEQUENCE_MODULUS`, because the counter + exists only to detect gaps and a gap is read modulo the wrap. + reorder_window: How far ahead a number may arrive before the numbers it + skipped are declared lost. Zero means strictly ordered. + + Attributes: + dropped: Running total of frames reported lost. + last_gap: ``(first_missing, count)`` for the hole the most recent + :meth:`observe` declared, or ``None`` if it declared none. Lets a + caller locate the hole in its own terms — the numbers either side of + it were received, so their timestamps bound it. + + Raises: + ValueError: If *modulus* is not a positive power of two, which the + masking arithmetic below assumes. """ - def __init__(self, label: str = "Frame") -> None: - self._last: int | None = None + def __init__( + self, + label: str = "Frame", + modulus: int = DEFAULT_MODULUS, + reorder_window: int = 0, + ) -> None: + if modulus <= 0 or modulus & (modulus - 1): + raise ValueError(f"modulus must be a positive power of two, got {modulus}") + if not 0 <= reorder_window < modulus // 2: + raise ValueError( + f"reorder_window must be in [0, {modulus // 2}), got {reorder_window}" + ) self._label = label + self._modulus = modulus + self._mask = modulus - 1 + # Half the range: a larger apparent forward jump is really a backward one. + self._reset_threshold = modulus >> 1 + self._window = reorder_window + self._expected: int | None = None + # Numbers seen ahead of _expected, still within the window. + self._pending: set[int] = set() + self.dropped = 0 + self.last_gap: tuple[int, int] | None = None + + @property + def _last(self) -> int | None: + """The last number consumed in order, or ``None`` before the first.""" + return None if self._expected is None else (self._expected - 1) & self._mask def observe(self, sequence: int) -> bool: """Record a sequence number and detect resets or drops. + Sets :attr:`last_gap` to the hole this call declared, if any. + Args: - sequence: The 32-bit sequence number from the received frame. + sequence: The sequence number from the received frame. Returns: - ``True`` if a device reset was detected (sequence jumped backward), - ``False`` for normal sequential frames or ordinary packet drops. - - Note: - After a reset is detected, ``_last`` is cleared so the very next - frame — whatever its sequence number — is accepted silently as the - new baseline. + ``True`` if a device reset was detected (the counter jumped far + backwards), ``False`` otherwise — including for ordinary loss, which + is logged and counted rather than signalled. """ - # Use & 0xFFFFFFFF to emulate unsigned 32-bit counter math in Python - # (mod 2^32), so increment/subtraction behave correctly across counter - # wraparound. - if self._last is not None: - expected = (self._last + 1) & 0xFFFFFFFF - if sequence != expected: - dropped = (sequence - expected) & 0xFFFFFFFF - if dropped > RESET_THRESHOLD: - logger.warning( - "%s: device reset detected, resuming from #%d", - self._label, sequence, - ) - self._last = None - return True - logger.warning( - "%s drop detected: expected #%d, got #%d (%d dropped)", - self._label, expected, sequence, dropped, - ) - self._last = sequence + self.last_gap = None + if self._expected is None: + self._expected = (sequence + 1) & self._mask + return False + expected = self._expected + + # Distance forward from what we expect next, in the counter's own + # arithmetic. Anything past the halfway point is really a step backwards. + ahead = (sequence - expected) & self._mask + + if ahead > self._reset_threshold: + behind = self._modulus - ahead + if behind <= self._window: + # A frame that overtook us earlier and is only now arriving, or a + # duplicate. Either way it fills nothing we have not moved past. + self._pending.discard(sequence) + return False + logger.warning( + "%s: device reset detected, resuming from #%d", self._label, sequence + ) + self._reset_to(sequence) + return True + + if ahead == 0: + self._expected = self._absorb_pending((sequence + 1) & self._mask) + return False + + if ahead <= self._window: + # Early: hold it and wait for the numbers it skipped. + self._pending.add(sequence) + return False + + # Past the window, so whatever is still missing is genuinely lost. + missing = ahead - sum( + 1 for p in self._pending if (p - expected) & self._mask < ahead + ) + if missing > 0: + self.dropped += missing + self.last_gap = (expected, missing) + logger.warning( + "%s drop detected: expected #%d, got #%d (%d dropped)", + self._label, expected, sequence, missing, + ) + resumed = (sequence + 1) & self._mask + self._discard_passed(resumed) + self._expected = self._absorb_pending(resumed) return False + def _reset_to(self, sequence: int) -> None: + """Drop all state so the next frame, whatever its number, is the baseline. + + The resetting frame is not itself taken as the baseline: the counter has + restarted and the first numbers of the new run are as likely to be + reordered as any others, so anchoring on one of them would manufacture a + gap. Callers that want an exact anchor re-observe on a fresh tracker. + """ + del sequence + self._expected = None + self._pending.clear() + + def _absorb_pending(self, expected: int) -> int: + """Advance *expected* past any numbers already held that continue the run.""" + while expected in self._pending: + self._pending.discard(expected) + expected = (expected + 1) & self._mask + return expected + + def _discard_passed(self, expected: int) -> None: + """Forget held numbers that now sit behind *expected*.""" + self._pending = { + p + for p in self._pending + if (p - expected) & self._mask <= self._reset_threshold + } + def iter_frames(buf: bytearray) -> Generator[bytes, None, None]: """Yield raw protobuf bytes for each complete length-delimited frame in *buf*. diff --git a/python/tests/conftest.py b/python/tests/conftest.py index 688556f..81f1c8e 100644 --- a/python/tests/conftest.py +++ b/python/tests/conftest.py @@ -3,27 +3,43 @@ import pytest from execution_trace._proto import tracing_pb2 +from execution_trace.decode import SEQUENCE_MODULUS from execution_trace.stream import encode_varint -def _make_frame( +def make_frame( event_type: int, - source_type: int, - name: str, - timestamp_ns: int, + *, + timestamp_ticks: int = 0, + name_id: int = 0, sequence: int = 0, + name: str = "", + source_type: int = tracing_pb2.TRACE_EVENT_SOURCE_TYPE_UNSPECIFIED, priority: int = 0, relative_deadline_ms: float | None = None, marker_value: int | None = None, + timebase: int = tracing_pb2.NANOSECONDS, + core_frequency_hz: int = 0, + source_mask: int = 0, ) -> bytes: - """Encode a single TraceEvent as a length-delimited protobuf frame.""" - msg = tracing_pb2.TraceEvent() - msg.timestamp_ns = timestamp_ns - msg.name = name - msg.source_type = source_type + """Encode a single v2 TraceFrame as a length-delimited protobuf frame. + + Every field is optional so a test can build exactly the frame class it means: + a per-occurrence event carries only a delta, an id and a sequence; a + NAME_REGISTERED frame carries the dictionary entry; a TRACE_START frame + carries the timebase and mask. + """ + msg = tracing_pb2.TraceFrame() + msg.timestamp_ticks = timestamp_ticks + msg.name_id = name_id msg.event_type = event_type msg.sequence = sequence + msg.name = name + msg.source_type = source_type msg.priority = priority + msg.timebase = timebase + msg.core_frequency_hz = core_frequency_hz + msg.source_mask = source_mask if relative_deadline_ms is not None: msg.relative_deadline_ms = relative_deadline_ms if marker_value is not None: @@ -32,42 +48,139 @@ def _make_frame( return encode_varint(len(raw)) + raw -@pytest.fixture() -def sample_span_start_frame() -> bytes: - """A well-formed SPAN_START frame for a task named 'main_task'.""" - return _make_frame( - event_type=tracing_pb2.SPAN_START, - source_type=tracing_pb2.TASK, - name="main_task", - timestamp_ns=1_000_000, - sequence=0, - priority=4, - ) +class StreamBuilder: + """Builds a v2 byte stream the way the firmware encoder does. + + Mirrors `TraceEncoder`: it assigns dictionary ids on first sight of a name, + delta-encodes timestamps against the previous frame, and advances a sequence + counter that wraps at :data:`SEQUENCE_MODULUS`. Tests describe events in + absolute nanoseconds and by name; this turns them into wire bytes. + """ + + def __init__(self, timebase: int = tracing_pb2.NANOSECONDS, core_frequency_hz: int = 0): + self.buf = bytearray() + self._names: dict[str, int] = {} + self._attrs: dict[str, tuple[int, int, float | None]] = {} + self._last_ticks = 0 + self._sequence = 0 + self._timebase = timebase + self._core_frequency_hz = core_frequency_hz + + def _next_sequence(self) -> int: + seq = self._sequence + self._sequence = (self._sequence + 1) % SEQUENCE_MODULUS + return seq + + def start(self, timestamp_ticks: int = 0, source_mask: int = 0x1F) -> "StreamBuilder": + """Append the TRACE_START header.""" + self.buf += make_frame( + tracing_pb2.TRACE_START, + timestamp_ticks=timestamp_ticks, + sequence=self._next_sequence(), + timebase=self._timebase, + core_frequency_hz=self._core_frequency_hz, + source_mask=source_mask, + ) + self._last_ticks = timestamp_ticks + return self + + def _name_id( + self, + name: str, + ticks: int, + source_type: int, + priority: int, + relative_deadline_ms: float | None, + ) -> int: + if name in self._names: + return self._names[name] + name_id = len(self._names) + 1 + self._names[name] = name_id + self.buf += make_frame( + tracing_pb2.NAME_REGISTERED, + timestamp_ticks=ticks, + name_id=name_id, + sequence=self._next_sequence(), + name=name, + source_type=source_type, + priority=priority, + relative_deadline_ms=relative_deadline_ms, + ) + self._last_ticks = ticks + return name_id + + def event( + self, + event_type: int, + name: str, + ticks: int, + *, + source_type: int = tracing_pb2.TASK, + priority: int = 0, + relative_deadline_ms: float | None = None, + marker_value: int | None = None, + name_id: int | None = None, + ) -> "StreamBuilder": + """Append one per-occurrence event, registering its name if new. + + Pass *name_id* to emit a specific id without registering it — used to + exercise the unknown-id fallback. + """ + if name_id is None: + name_id = self._name_id(name, ticks, source_type, priority, relative_deadline_ms) + delta = ticks - self._last_ticks + self._last_ticks = ticks + self.buf += make_frame( + event_type, + timestamp_ticks=delta, + name_id=name_id, + sequence=self._next_sequence(), + marker_value=marker_value, + ) + return self + + def span( + self, + name: str, + start_ticks: int, + end_ticks: int, + *, + source_type: int = tracing_pb2.TASK, + priority: int = 0, + relative_deadline_ms: float | None = None, + ) -> "StreamBuilder": + """Append a matched SPAN_START / SPAN_END pair.""" + self.event( + tracing_pb2.SPAN_START, name, start_ticks, + source_type=source_type, priority=priority, + relative_deadline_ms=relative_deadline_ms, + ) + return self.event(tracing_pb2.SPAN_END, name, end_ticks) + + def marker(self, name: str, ticks: int, value: int | None = None) -> "StreamBuilder": + """Append a MARKER.""" + return self.event(tracing_pb2.MARKER, name, ticks, marker_value=value) + + def bytes(self) -> bytearray: + """The stream built so far.""" + return bytearray(self.buf) @pytest.fixture() -def sample_span_end_frame() -> bytes: - """A well-formed SPAN_END frame for a task named 'main_task'.""" - return _make_frame( - event_type=tracing_pb2.SPAN_END, - source_type=tracing_pb2.TASK, - name="main_task", - timestamp_ns=2_000_000, - sequence=1, - ) +def builder() -> StreamBuilder: + """A fresh v2 stream builder with the header already written.""" + return StreamBuilder().start() @pytest.fixture() -def sample_marker_frame() -> bytes: - """A well-formed MARKER frame.""" - return _make_frame( - event_type=tracing_pb2.MARKER, - source_type=tracing_pb2.TASK, - name="loop_tick", - timestamp_ns=1_500_000, - sequence=2, - marker_value=42, - ) +def sample_stream(builder: StreamBuilder) -> bytearray: + """A complete stream: one task span, one ISR span and one marker.""" + builder.span("main_task", 1_000_000, 2_000_000, + source_type=tracing_pb2.TASK, priority=4) + builder.span("gyro_isr", 2_100_000, 2_200_000, + source_type=tracing_pb2.ISR, priority=8) + builder.marker("loop_tick", 2_300_000, 42) + return builder.bytes() @pytest.fixture() diff --git a/python/tests/test_decode.py b/python/tests/test_decode.py index 2c4ea80..6522e5b 100644 --- a/python/tests/test_decode.py +++ b/python/tests/test_decode.py @@ -6,44 +6,65 @@ import pytest +from conftest import StreamBuilder, make_frame + from execution_trace._proto import tracing_pb2 from execution_trace.decode import ( + GapRecord, + REORDER_WINDOW, + RESET_BACKWARD_MARGIN_US, + SEQUENCE_MODULUS, + UNKNOWN_NAME, MarkerRecord, + NameEntry, TraceEvent, TraceEventBuffer, + TraceStreamState, decode_tracing_stream, write_tracing_csv, ) -from execution_trace.stream import SequenceTracker, encode_varint # --------------------------------------------------------------------------- # Helpers # --------------------------------------------------------------------------- -def _make_frame( +def _push( + buf: TraceEventBuffer, event_type: int, - source_type: int, name: str, - timestamp_ns: int, - sequence: int = 0, + timestamp_us: float, + *, + source_type: int = tracing_pb2.TASK, priority: int = 0, relative_deadline_ms: float | None = None, marker_value: int | None = None, -) -> bytes: - msg = tracing_pb2.TraceEvent() - msg.timestamp_ns = timestamp_ns - msg.name = name - msg.source_type = source_type - msg.event_type = event_type - msg.sequence = sequence - msg.priority = priority - if relative_deadline_ms is not None: - msg.relative_deadline_ms = relative_deadline_ms +) -> None: + """Push one already-resolved event into *buf*. + + `TraceEventBuffer.push` takes a frame plus the dictionary entry and absolute + timestamp the stream decoder resolved for it, so these unit tests supply + those directly rather than going through a stream. + """ + frame = tracing_pb2.TraceFrame() + frame.event_type = event_type if marker_value is not None: - msg.marker_value = marker_value - raw = msg.SerializeToString() - return encode_varint(len(raw)) + raw + frame.marker_value = marker_value + entry = NameEntry( + name=name, + source_type=source_type, + priority=priority, + relative_deadline_ms=relative_deadline_ms, + ) + buf.push(frame, entry, timestamp_us) + + +def _decode(stream: bytearray) -> tuple[TraceStreamState, TraceEventBuffer]: + """Decode a whole stream and return the resulting state and buffer.""" + state = TraceStreamState("test") + event_buffer = TraceEventBuffer() + decode_tracing_stream(stream, state, event_buffer) + return state, event_buffer # --------------------------------------------------------------------------- @@ -53,19 +74,8 @@ def _make_frame( class TestTraceEventBuffer: def test_matches_start_end_pair(self): buf = TraceEventBuffer() - msg = tracing_pb2.TraceEvent() - msg.name = "task_a" - msg.event_type = tracing_pb2.SPAN_START - msg.source_type = tracing_pb2.TASK - msg.timestamp_ns = 1_000_000 - msg.priority = 4 - buf.push(msg) - - msg2 = tracing_pb2.TraceEvent() - msg2.name = "task_a" - msg2.event_type = tracing_pb2.SPAN_END - msg2.timestamp_ns = 2_000_000 - buf.push(msg2) + _push(buf, tracing_pb2.SPAN_START, "task_a", 1_000.0, priority=4) + _push(buf, tracing_pb2.SPAN_END, "task_a", 2_000.0) records = buf.records assert len(records) == 1 @@ -79,41 +89,30 @@ def test_matches_start_end_pair(self): def test_isr_source_type_sets_type_field(self): buf = TraceEventBuffer() - msg = tracing_pb2.TraceEvent() - msg.name = "gyro_isr" - msg.event_type = tracing_pb2.SPAN_START - msg.source_type = tracing_pb2.ISR - msg.timestamp_ns = 100 - buf.push(msg) - - msg2 = tracing_pb2.TraceEvent() - msg2.name = "gyro_isr" - msg2.event_type = tracing_pb2.SPAN_END - msg2.timestamp_ns = 200 - buf.push(msg2) - + _push(buf, tracing_pb2.SPAN_START, "gyro_isr", 0.1, source_type=tracing_pb2.ISR) + _push(buf, tracing_pb2.SPAN_END, "gyro_isr", 0.2) assert buf.records[0].type == "isr" + def test_span_attributes_come_from_the_start_not_the_end(self): + # In v2 only the dictionary carries priority and deadline, and a SPAN_END + # resolves to the same entry — but the record must be built from the + # entry seen at the START, which is the one the span was opened with. + buf = TraceEventBuffer() + _push(buf, tracing_pb2.SPAN_START, "t", 0.0, priority=7, relative_deadline_ms=1.0) + _push(buf, tracing_pb2.SPAN_END, "t", 500.0) + assert buf.records[0].priority == 7 + assert buf.records[0].deadline_us == pytest.approx(1_000.0) + def test_unmatched_end_discarded_and_logs(self, caplog): buf = TraceEventBuffer() - msg = tracing_pb2.TraceEvent() - msg.name = "ghost" - msg.event_type = tracing_pb2.SPAN_END - msg.timestamp_ns = 999 with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): - buf.push(msg) + _push(buf, tracing_pb2.SPAN_END, "ghost", 999.0) assert buf.records == [] assert "no matching START" in caplog.text def test_marker_recorded_directly(self): buf = TraceEventBuffer() - msg = tracing_pb2.TraceEvent() - msg.name = "loop_tick" - msg.event_type = tracing_pb2.MARKER - msg.source_type = tracing_pb2.TASK - msg.timestamp_ns = 5_000_000 - msg.marker_value = 7 - buf.push(msg) + _push(buf, tracing_pb2.MARKER, "loop_tick", 5_000.0, marker_value=7) assert buf.records == [] markers = buf.markers @@ -127,40 +126,23 @@ def test_marker_recorded_directly(self): def test_marker_without_value_is_none(self): buf = TraceEventBuffer() - msg = tracing_pb2.TraceEvent() - msg.name = "tick" - msg.event_type = tracing_pb2.MARKER - msg.source_type = tracing_pb2.TASK - msg.timestamp_ns = 1_000 - buf.push(msg) + _push(buf, tracing_pb2.MARKER, "tick", 1.0) assert buf.markers[0].value is None - def test_relative_deadline_ms_converted_to_us(self): + def test_marker_value_of_zero_is_kept(self): buf = TraceEventBuffer() - msg = tracing_pb2.TraceEvent() - msg.name = "t" - msg.event_type = tracing_pb2.SPAN_START - msg.source_type = tracing_pb2.TASK - msg.timestamp_ns = 0 - msg.relative_deadline_ms = 2.5 - buf.push(msg) - - msg2 = tracing_pb2.TraceEvent() - msg2.name = "t" - msg2.event_type = tracing_pb2.SPAN_END - msg2.timestamp_ns = 1_000 - buf.push(msg2) + _push(buf, tracing_pb2.MARKER, "tick", 1.0, marker_value=0) + assert buf.markers[0].value == 0 + def test_relative_deadline_ms_converted_to_us(self): + buf = TraceEventBuffer() + _push(buf, tracing_pb2.SPAN_START, "t", 0.0, relative_deadline_ms=2.5) + _push(buf, tracing_pb2.SPAN_END, "t", 1.0) assert buf.records[0].deadline_us == pytest.approx(2_500.0) def test_flush_pending_warns_and_clears(self, caplog): buf = TraceEventBuffer() - msg = tracing_pb2.TraceEvent() - msg.name = "hanging_task" - msg.event_type = tracing_pb2.SPAN_START - msg.source_type = tracing_pb2.TASK - msg.timestamp_ns = 0 - buf.push(msg) + _push(buf, tracing_pb2.SPAN_START, "hanging_task", 0.0) with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): buf.flush_pending() @@ -175,54 +157,380 @@ def test_flush_pending_warns_and_clears(self, caplog): def test_duplicate_start_warns_and_replaces(self, caplog): buf = TraceEventBuffer() - for ts in (100, 200): - msg = tracing_pb2.TraceEvent() - msg.name = "dup" - msg.event_type = tracing_pb2.SPAN_START - msg.source_type = tracing_pb2.TASK - msg.timestamp_ns = ts - with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): - buf.push(msg) - - # The second START replaces the first; final END should use ts=200 - msg = tracing_pb2.TraceEvent() - msg.name = "dup" - msg.event_type = tracing_pb2.SPAN_END - msg.source_type = tracing_pb2.TASK - msg.timestamp_ns = 300 - buf.push(msg) - - assert buf.records[0].start_us == pytest.approx(200.0 / 1_000) + with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): + _push(buf, tracing_pb2.SPAN_START, "dup", 0.1) + _push(buf, tracing_pb2.SPAN_START, "dup", 0.2) + _push(buf, tracing_pb2.SPAN_END, "dup", 0.3) + + assert buf.records[0].start_us == pytest.approx(0.2) assert "duplicate START" in caplog.text +# --------------------------------------------------------------------------- +# TraceStreamState +# --------------------------------------------------------------------------- + +class TestTraceStreamState: + def test_nanosecond_ticks_convert_to_us(self): + state = TraceStreamState() + assert state.ticks_to_us(1_500) == pytest.approx(1.5) + + def test_cycle_ticks_convert_using_the_core_frequency(self): + state = TraceStreamState() + state.timebase = tracing_pb2.CYCLES + state.core_frequency_hz = 72_000_000 + # 72 000 cycles at 72 MHz is exactly 1 ms. + assert state.ticks_to_us(72_000) == pytest.approx(1_000.0) + + def test_cycles_without_a_frequency_fall_back_to_nanoseconds(self): + # Rather than dividing by zero: a header that declares CYCLES but no + # frequency is malformed, and a wrong-but-finite scale is still readable. + state = TraceStreamState() + state.timebase = tracing_pb2.CYCLES + state.core_frequency_hz = 0 + assert state.ticks_to_us(1_000) == pytest.approx(1.0) + + def test_unregistered_id_resolves_to_a_placeholder_and_warns(self, caplog): + state = TraceStreamState() + with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): + entry = state.resolve(7) + assert entry is None + assert "not resolvable yet" in caplog.text + assert state.unresolved_events == 1 + + def test_an_unresolvable_id_warns_only_once(self, caplog): + # At 1300+ events/s a per-event warning buries the log; the run that + # found this produced thousands of identical lines a second. + state = TraceStreamState() + with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): + for _ in range(50): + state.resolve(7) + assert caplog.text.count("not resolvable yet") == 1 + + def test_the_reserved_unknown_id_resolves_silently(self, caplog): + # Id 0 means the device's registry was full. That is reported by a + # firmware fault counter, so the host need not warn per event. + state = TraceStreamState() + with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): + entry = state.resolve(0) + assert entry is None + assert caplog.text == "" + + def test_reset_clears_the_dictionary(self): + # Ids restart at one on reboot, so a stale entry would resolve a new id + # to the wrong name. + state = TraceStreamState() + state.names[1] = NameEntry(name="old_task") + state.clock_ticks = 12345 + state.source_mask = 0x1F + state.reset() + assert state.names == {} + assert state.clock_ticks == 0 + assert state.source_mask is None + + # --------------------------------------------------------------------------- # decode_tracing_stream # --------------------------------------------------------------------------- class TestDecodeTracingStream: - def test_happy_path(self, sample_span_start_frame, sample_span_end_frame): - buf = bytearray(sample_span_start_frame + sample_span_end_frame) - tracker = SequenceTracker("test") + def test_happy_path(self, sample_stream): + state, event_buffer = _decode(sample_stream) + assert len(event_buffer.records) == 2 + assert len(event_buffer.markers) == 1 + assert sample_stream == bytearray() + + def test_header_fields_reach_the_state(self): + stream = StreamBuilder().start(timestamp_ticks=1_000, source_mask=0x17).bytes() + state, _ = _decode(stream) + assert state.source_mask == 0x17 + assert state.timebase == tracing_pb2.NANOSECONDS + + def test_a_cycles_header_rescales_every_timestamp(self): + builder = StreamBuilder(timebase=tracing_pb2.CYCLES, core_frequency_hz=72_000_000) + builder.start(timestamp_ticks=0) + builder.span("t", 0, 72_000) # 72 000 cycles at 72 MHz = 1 ms + state, event_buffer = _decode(builder.bytes()) + assert state.core_frequency_hz == 72_000_000 + assert event_buffer.records[0].end_us == pytest.approx(1_000.0) + + def test_names_resolve_through_the_dictionary(self, sample_stream): + state, event_buffer = _decode(sample_stream) + assert {e.name for e in state.names.values()} == {"main_task", "gyro_isr", "loop_tick"} + assert [r.name for r in event_buffer.records] == ["main_task", "gyro_isr"] + assert event_buffer.markers[0].name == "loop_tick" + + def test_a_name_is_registered_once_and_reused(self, builder): + builder.span("t", 0, 1_000) + builder.span("t", 2_000, 3_000) + state, event_buffer = _decode(builder.bytes()) + assert len(state.names) == 1 + assert len(event_buffer.records) == 2 + + def test_deltas_accumulate_into_absolute_timestamps(self, builder): + builder.span("main_task", 1_000_000, 2_000_000, priority=4) + builder.span("main_task", 5_000_000, 5_500_000) + _, event_buffer = _decode(builder.bytes()) + spans = [(r.start_us, r.end_us) for r in event_buffer.records] + assert spans == [ + pytest.approx((1_000.0, 2_000.0)), + pytest.approx((5_000.0, 5_500.0)), + ] + + def test_attributes_are_carried_by_the_dictionary_not_the_event(self, builder): + builder.span( + "gyro_isr", 0, 400_000, + source_type=tracing_pb2.ISR, priority=8, relative_deadline_ms=1.0, + ) + _, event_buffer = _decode(builder.bytes()) + r = event_buffer.records[0] + assert r.type == "isr" + assert r.priority == 8 + assert r.deadline_us == pytest.approx(1_000.0) + + def test_an_event_with_the_reserved_unknown_id_is_dropped(self, builder, caplog): + # What the firmware emits when its name registry is full. The event is + # real, but nothing can say what it was, and attributing it to a shared + # placeholder would interleave unrelated spans into one lane. The + # firmware's TracingNameRegistryFull counter is what reports the loss. + builder.event(tracing_pb2.MARKER, "", 1_000, marker_value=5, name_id=0) + with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): + state, event_buffer = _decode(builder.bytes()) + assert event_buffer.markers == [], "an unattributable event is dropped" + assert state.unresolved_events == 1 + + def test_partial_frame_is_left_in_the_buffer(self, builder): + builder.span("t", 0, 1_000) + stream = builder.bytes() + head, tail = stream[:-2], stream[-2:] + state = TraceStreamState("test") event_buffer = TraceEventBuffer() - decode_tracing_stream(buf, tracker, event_buffer) + decode_tracing_stream(head, state, event_buffer) + assert len(head) > 0, "the incomplete frame must be kept for the next read" + assert event_buffer.records == [] + # Feeding the rest completes the span. + head.extend(tail) + decode_tracing_stream(head, state, event_buffer) assert len(event_buffer.records) == 1 - assert buf == bytearray() + assert head == bytearray() + + def test_a_frame_lost_at_the_producer_queue_is_reported(self, caplog): + """AC 7: a frame dropped before the transport still shows as a gap. + + The number is taken when the event is recorded, upstream of the queue the + transport drains, so a drop there burns a number and leaves a hole + (§5.7). Before increment 5 the transport numbered frames itself and this + loss was invisible — the host saw a contiguous stream with events simply + absent (§2.6). + """ + state = TraceStreamState("test") + event_buffer = TraceEventBuffer() + state.names[1] = NameEntry(name="main_task") + + stream = bytearray() + seq = 0 + for i in range(REORDER_WINDOW + 4): + if i == 1: + seq += 1 # this one never reached the transport + continue + stream += make_frame(tracing_pb2.MARKER, name_id=1, sequence=seq) + seq += 1 + + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + decode_tracing_stream(stream, state, event_buffer) + + assert "drop detected" in caplog.text + assert "1 dropped" in caplog.text + assert state.tracker.dropped == 1 + + def test_reordered_frames_are_not_reported_as_loss(self, caplog): + # Producer-side numbering means an ISR can take a later number and reach + # the wire first. That is not loss and must not be reported as any. + state = TraceStreamState("test") + event_buffer = TraceEventBuffer() + state.names[1] = NameEntry(name="main_task") + + stream = bytearray() + for seq in (0, 2, 1, 3, 5, 4, 6): + stream += make_frame(tracing_pb2.MARKER, name_id=1, sequence=seq) + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + decode_tracing_stream(stream, state, event_buffer) - def test_reset_detected_clears_buffer(self): - # Frame with sequence 1000 followed by sequence 0 (reset) - frame_high = _make_frame(tracing_pb2.SPAN_START, tracing_pb2.TASK, "t", 0, sequence=1000) - frame_reset = _make_frame(tracing_pb2.SPAN_START, tracing_pb2.TASK, "t", 0, sequence=0) - buf = bytearray(frame_high + frame_reset + b"\xaa\xbb") # trailing garbage - tracker = SequenceTracker("test") - tracker.observe(999) # pretend we've seen up to 999 + assert caplog.text == "" + assert state.tracker.dropped == 0 + assert len(event_buffer.markers) == 7, "every frame is still delivered" + + def test_sequence_wraps_at_the_modulus_without_a_false_reset(self, caplog): + state = TraceStreamState("test") event_buffer = TraceEventBuffer() + # Walk the tracker up to the last sequence before the wrap, then feed the + # wrapped frame. A u32 tracker would read 0 after 16383 as a huge jump. + state.names[1] = NameEntry(name="tick") + state.tracker.observe(SEQUENCE_MODULUS - 1) + stream = bytearray(make_frame(tracing_pb2.MARKER, name_id=1, sequence=0)) + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + decode_tracing_stream(stream, state, event_buffer) + assert caplog.text == "" + assert len(event_buffer.markers) == 1 - decode_tracing_stream(buf, tracker, event_buffer) + def test_backwards_sequence_is_a_reset_that_clears_the_dictionary(self): + state = TraceStreamState("test") + event_buffer = TraceEventBuffer() + state.tracker.observe(1_000) + state.names[1] = NameEntry(name="stale") + # Restarting at 0 from 1000 is an apparent forward jump of 15 383, more + # than half the modulus, so it reads as a backwards step: a reset. + stream = bytearray(make_frame(tracing_pb2.MARKER, name_id=1, sequence=0)) + decode_tracing_stream(stream, state, event_buffer) + assert state.names == {}, "a stale entry would resolve new ids to old names" + + def test_a_reset_does_not_discard_the_byte_buffer(self): + # The stream is length-prefixed with no sync marker, so dropping bytes + # mid-frame misaligns everything after it permanently — which showed up + # on hardware as a burst of "Failed to decode TraceFrame" immediately + # after every reset (§19.10). + state = TraceStreamState("test") + event_buffer = TraceEventBuffer() + state.tracker.observe(1_000) + state.names[1] = NameEntry(name="stale") + + stream = bytearray(make_frame(tracing_pb2.MARKER, name_id=1, sequence=0)) + # A complete, well-formed frame arriving after the reset point. + stream += make_frame( + tracing_pb2.NAME_REGISTERED, name_id=1, sequence=1, name="fresh", + source_type=tracing_pb2.TASK, + ) + stream += make_frame(tracing_pb2.MARKER, name_id=1, sequence=2, marker_value=9) + decode_tracing_stream(stream, state, event_buffer) + + assert stream == bytearray(), "every complete frame is still consumed" + assert state.names[1].name == "fresh", "frames after the reset still parse" + assert [m.value for m in event_buffer.markers] == [9] + + def test_a_reset_from_high_in_the_range_is_not_visible_in_the_sequence(self, caplog): + # A consequence of wrapping at 16 384 rather than 2**32: restarting at 0 + # only looks backwards when the pre-reset counter was below half the + # modulus. From 9 000 it reads as an ordinary 7 383-frame gap, and the + # stale dictionary survives. This is why TRACE_START, not the sequence, + # is the reliable reset signal — see the test below. + state = TraceStreamState("test") + event_buffer = TraceEventBuffer() + state.tracker.observe(9_000) + state.names[1] = NameEntry(name="stale") + stream = bytearray(make_frame(tracing_pb2.MARKER, name_id=1, sequence=0)) + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + decode_tracing_stream(stream, state, event_buffer) + assert "drop detected" in caplog.text + assert "reset" not in caplog.text + assert state.names == {1: NameEntry(name="stale")} + + def test_a_dictionary_refresh_resolves_events_seen_before_it(self, builder): + # What a host attaching mid-run sees: events for ids it never saw + # registered, then the device's periodic re-emission of the dictionary. + state = TraceStreamState("test") + event_buffer = TraceEventBuffer() - # buf is cleared on reset detection + # Events arrive with an id the host has no entry for. + orphan = bytearray() + orphan += make_frame(tracing_pb2.SPAN_START, name_id=1, sequence=0) + orphan += make_frame(tracing_pb2.SPAN_END, timestamp_ticks=500, name_id=1, sequence=1) + decode_tracing_stream(orphan, state, event_buffer) + assert event_buffer.records == [], "unresolvable events are dropped" + assert state.unresolved_events == 2 + + # The refresh arrives: the entry is now known, and later events resolve. + refresh = bytearray() + refresh += make_frame( + tracing_pb2.NAME_REGISTERED, + timestamp_ticks=10_000, + name_id=1, + sequence=2, + name="main_task", + source_type=tracing_pb2.TASK, + priority=4, + ) + refresh += make_frame(tracing_pb2.SPAN_START, name_id=1, sequence=3) + refresh += make_frame(tracing_pb2.SPAN_END, timestamp_ticks=500, name_id=1, sequence=4) + decode_tracing_stream(refresh, state, event_buffer) + + assert [r.name for r in event_buffer.records] == ["main_task"] + assert event_buffer.records[0].priority == 4 + + def test_a_repeated_header_is_not_a_reset(self, caplog): + # The device re-emits the header periodically so a late host learns the + # timebase and mask. Treating that as a reset would clear the dictionary + # every refresh and undo the very thing the refresh exists to fix. + builder = StreamBuilder().start(timestamp_ticks=1_000) + builder.span("t", 2_000, 3_000) + state, event_buffer = _decode(builder.bytes()) + assert len(state.names) == 1 + + later = bytearray( + make_frame( + tracing_pb2.TRACE_START, + timestamp_ticks=9_000, + sequence=state.tracker._last + 1, + source_mask=0x1F, + ) + ) + with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): + decode_tracing_stream(later, state, event_buffer) + assert "reset" not in caplog.text + assert len(state.names) == 1, "the dictionary must survive a refresh" + + def test_a_header_slightly_behind_the_clock_is_not_a_reset(self, caplog): + # The header's timestamp is read after the producer queue is drained, but + # an event recorded just before that read can still be encoded after it, + # putting the header microseconds behind the reconstructed clock. Reading + # that as a reboot would discard the dictionary every refresh (§19.10). + builder = StreamBuilder().start(timestamp_ticks=1_000) + builder.span("t", 2_000_000, 3_000_000) + state, event_buffer = _decode(builder.bytes()) + assert len(state.names) == 1 + + behind = bytearray( + make_frame( + tracing_pb2.TRACE_START, + timestamp_ticks=state.clock_ticks - 300_000, # 300 µs behind + sequence=state.tracker._last + 1, + source_mask=0x1F, + ) + ) + with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): + decode_tracing_stream(behind, state, event_buffer) + assert "reset" not in caplog.text + assert len(state.names) == 1 + + def test_a_second_header_is_treated_as_a_device_reset(self, caplog): + # A real device has been up for seconds before it reboots, so the clock + # drops by its whole uptime — far past RESET_BACKWARD_MARGIN_US. + builder = StreamBuilder().start(timestamp_ticks=30_000_000_000) + builder.span("t", 30_001_000_000, 30_002_000_000) + stream = builder.bytes() + state, event_buffer = _decode(stream) + assert len(state.names) == 1 + + reboot = StreamBuilder().start(timestamp_ticks=0, source_mask=0x1F) + reboot.span("t", 0, 500) + buf = reboot.bytes() + with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): + decode_tracing_stream(buf, state, event_buffer) + assert "device reset" in caplog.text + # The pre-reboot dictionary is gone, and the reboot's own frames — which + # follow in the same buffer — are parsed rather than thrown away. + assert state.names[1].name == "t" + assert state.source_mask == 0x1F assert buf == bytearray() + def test_malformed_payload_is_skipped_without_killing_the_stream(self, caplog): + stream = StreamBuilder().start().bytes() + # A frame whose length prefix is right but whose payload is not a + # TraceFrame: field 1 declared as a length-delimited string. + stream += bytes([3, 0x0A, 0x7F, 0x7F]) + with caplog.at_level(logging.WARNING, logger="execution_trace.decode"): + _decode(stream) + assert stream == bytearray(), "the bad frame is consumed, not left to jam the buffer" + # --------------------------------------------------------------------------- # write_tracing_csv @@ -256,6 +564,50 @@ def test_marker_row_start_eq_end(self, tmp_path): assert rows[0]["start_us"] == rows[0]["end_us"] assert rows[0]["type"] == "marker" + def test_marker_value_of_zero_is_written(self, tmp_path): + # Zero is a legitimate payload — a reason code, or a count of nothing — and a + # truth test on the value would write it as empty, which reads downstream as + # "no value" and hides exactly the case the marker was emitted to report. + records = [MarkerRecord(name="ctl_skip", timestamp_us=1500.0, value=0)] + path = write_tracing_csv(records, output_dir=str(tmp_path)) + assert path is not None + with open(path) as f: + row = list(csv.DictReader(f))[0] + assert row["value"] == "0" + + def test_marker_without_value_is_written_empty(self, tmp_path): + records = [MarkerRecord(name="tick", timestamp_us=1500.0, value=None)] + path = write_tracing_csv(records, output_dir=str(tmp_path)) + assert path is not None + with open(path) as f: + row = list(csv.DictReader(f))[0] + assert row["value"] == "" + + def test_span_deadline_and_value_of_zero_are_written(self, tmp_path): + records = [ + TraceEvent( + name="t", type="task", start_us=0.0, end_us=1.0, + priority=1, deadline_us=0.0, value=0, + ), + ] + path = write_tracing_csv(records, output_dir=str(tmp_path)) + assert path is not None + with open(path) as f: + row = list(csv.DictReader(f))[0] + assert float(row["deadline_us"]) == pytest.approx(0.0) + assert row["value"] == "0" + + def test_span_without_deadline_or_value_is_written_empty(self, tmp_path): + records = [ + TraceEvent(name="t", type="task", start_us=0.0, end_us=1.0, priority=1), + ] + path = write_tracing_csv(records, output_dir=str(tmp_path)) + assert path is not None + with open(path) as f: + row = list(csv.DictReader(f))[0] + assert row["deadline_us"] == "" + assert row["value"] == "" + def test_symlink_updated(self, tmp_path): records = [ TraceEvent(name="t", type="task", start_us=0.0, end_us=1.0, priority=1), @@ -291,3 +643,100 @@ def test_span_row_values(self, tmp_path): assert float(row["end_us"]) == pytest.approx(2000.0) assert row["priority"] == "4" assert float(row["deadline_us"]) == pytest.approx(5000.0) + + +# --------------------------------------------------------------------------- +# Gap handling (§5.9) +# --------------------------------------------------------------------------- + +class TestGapHandling: + """AC 8: a stream with an injected gap renders every span open at the gap as + interrupted, and the gap as an annotated band.""" + + def _stream_with_lost_span_end(self) -> tuple[TraceStreamState, TraceEventBuffer]: + b = StreamBuilder().start(timestamp_ticks=0) + t = 1_000_000 + for _ in range(5): + b.span("main_task", t, t + 400_000, priority=4) + t += 1_000_000 + # A cycle whose SPAN_END never reached the transport: its number is + # burned, which is what makes the loss visible at all (§5.7). + b.event(tracing_pb2.SPAN_START, "main_task", t, priority=4) + b._next_sequence() + t += 1_000_000 + # Enough traffic afterwards to carry past the reorder window. + for _ in range(REORDER_WINDOW + 4): + b.span("gyro_isr", t, t + 40_000, source_type=tracing_pb2.ISR, priority=8) + t += 1_000_000 + state, event_buffer = TraceStreamState("gap"), TraceEventBuffer() + decode_tracing_stream(b.bytes(), state, event_buffer) + return state, event_buffer + + def test_a_gap_is_recorded_with_its_frame_count(self): + state, eb = self._stream_with_lost_span_end() + assert state.tracker.dropped == 1 + assert len(eb.gaps) == 1 + gap = eb.gaps[0] + assert isinstance(gap, GapRecord) + assert gap.frames_lost == 1 + assert gap.type == "gap" + assert gap.end_us >= gap.start_us + + def test_the_gap_is_placed_between_the_frames_either_side_of_it(self): + # Not where the reorder window happened to notice: that is up to 64 + # frames later, which on this trace would be tens of milliseconds off. + state, eb = self._stream_with_lost_span_end() + gap = eb.gaps[0] + assert gap.start_us == pytest.approx(6_000.0), "the lost END's own SPAN_START" + assert gap.end_us == pytest.approx(7_000.0), "the next frame that did arrive" + + def test_the_span_open_at_the_gap_is_interrupted(self): + state, eb = self._stream_with_lost_span_end() + cut = [r for r in eb.records if r.interrupted] + assert len(cut) == 1 + assert cut[0].name == "main_task" + assert cut[0].start_us == pytest.approx(6_000.0) + assert cut[0].end_us == pytest.approx(6_000.0), "cut at the last good frame" + + def test_an_uninterrupted_span_is_untouched(self): + state, eb = self._stream_with_lost_span_end() + whole = [r for r in eb.records if not r.interrupted and r.name == "main_task"] + assert len(whole) == 5 + assert all(r.end_us - r.start_us == pytest.approx(400.0) for r in whole) + + def test_the_first_end_after_the_gap_is_discarded_not_paired(self): + # Otherwise it closes whatever START opens next and invents a span that + # never ran — the damage §5.9 exists to prevent. + b = StreamBuilder().start(timestamp_ticks=0) + b.event(tracing_pb2.SPAN_START, "main_task", 1_000_000, priority=4) + b._next_sequence() # a frame lost at the queue + for i in range(REORDER_WINDOW + 4): + b.span("gyro_isr", 2_000_000 + i * 1_000_000, + 2_040_000 + i * 1_000_000, + source_type=tracing_pb2.ISR, priority=8) + # main_task's END finally arrives, long after its START was closed. + b.event(tracing_pb2.SPAN_END, "main_task", 90_000_000) + state, eb = TraceStreamState("gap"), TraceEventBuffer() + decode_tracing_stream(b.bytes(), state, eb) + + main = [r for r in eb.records if r.name == "main_task"] + assert len(main) == 1, "the orphaned END must not produce a second span" + assert main[0].interrupted + assert main[0].end_us == pytest.approx(1_000.0) + + def test_a_clean_stream_records_no_gap(self, builder): + builder.span("t", 0, 1_000) + builder.span("t", 2_000, 3_000) + _, eb = _decode(builder.bytes()) + assert eb.gaps == [] + assert not any(r.interrupted for r in eb.records) + + def test_gap_rows_reach_the_csv(self, tmp_path): + _, eb = self._stream_with_lost_span_end() + path = write_tracing_csv(eb.records + eb.markers + eb.gaps, output_dir=str(tmp_path)) + assert path is not None + rows = list(csv.DictReader(open(path))) + gaps = [r for r in rows if r["type"] == "gap"] + assert len(gaps) == 1 + assert gaps[0]["value"] == "1", "frames lost travels in the value column" + assert any(r["interrupted"] == "1" for r in rows) diff --git a/python/tests/test_diagram.py b/python/tests/test_diagram.py index 7715930..b995472 100644 --- a/python/tests/test_diagram.py +++ b/python/tests/test_diagram.py @@ -179,3 +179,91 @@ def test_raises_diagram_error_on_missing_csv(self, tmp_path): out = tmp_path / "diagram.html" with pytest.raises(DiagramError): generate_diagram(csv_path=tmp_path / "nosuch.csv", output_path=out) + + +# --------------------------------------------------------------------------- +# Gap rendering (§5.9, AC 8) +# --------------------------------------------------------------------------- + +HEADER = "name,type,start_us,end_us,priority,deadline_us,value,interrupted\n" + + +def _gap_csv(tmp_path: Path) -> Path: + p = tmp_path / "gap.csv" + p.write_text( + HEADER + + "main_task,task,1000.0,1400.0,4,,,0\n" + + "main_task,task,2000.0,2000.0,4,,,1\n" # interrupted by the gap + + "trace gap,gap,2000.0,3000.0,0,,7,0\n" + + "main_task,task,3000.0,3400.0,4,,,0\n" + + "gyro_isr,isr,3100.0,3140.0,8,,,0\n" + ) + return p + + +class TestGapRendering: + def test_a_gap_row_loads_without_being_treated_as_a_span(self, tmp_path): + pytest.importorskip("pandas") + from execution_trace.diagram import load_traces + + df = load_traces(_gap_csv(tmp_path)) + gaps = df[df["type"] == "gap"] + assert len(gaps) == 1 + assert gaps.iloc[0]["value"] == 7 + + def test_a_zero_length_interrupted_span_is_accepted(self, tmp_path): + # Its end is a lower bound on when it finished, not a measurement, and a + # span cut at the frame that opened it is genuinely zero-length. + pytest.importorskip("pandas") + from execution_trace.diagram import load_traces + + df = load_traces(_gap_csv(tmp_path)) + cut = df[df["interrupted"]] + assert len(cut) == 1 + assert cut.iloc[0]["start_us"] == cut.iloc[0]["end_us"] + + def test_a_zero_length_span_that_is_not_interrupted_is_still_rejected(self, tmp_path): + pytest.importorskip("pandas") + from execution_trace.diagram import DiagramError, load_traces + + p = tmp_path / "bad.csv" + p.write_text(HEADER + "main_task,task,1000.0,1000.0,4,,,0\n") + with pytest.raises(DiagramError, match="end_us must be"): + load_traces(p) + + def test_an_interrupted_span_cannot_miss_its_deadline(self, tmp_path): + # Its end is unknown, so calling it an overrun would be an invention. + pytest.importorskip("pandas") + from execution_trace.diagram import load_traces + + p = tmp_path / "dl.csv" + p.write_text( + HEADER + + "main_task,task,1000.0,1200.0,4,1100.0,,1\n" + + "main_task,task,2000.0,2200.0,4,2100.0,,0\n" + ) + df = load_traces(p) + assert list(df["missed"]) == [False, True] + + def test_gaps_keep_their_own_lane_slot(self, tmp_path): + pytest.importorskip("pandas") + from execution_trace.diagram import assign_lanes, load_traces + + df, lanes = assign_lanes(load_traces(_gap_csv(tmp_path))) + assert set(lanes) == {"main_task", "gyro_isr"} + gaps = df[df["type"] == "gap"] + assert len(gaps) == 1, "the gap row survives lane assignment" + assert gaps.iloc[0]["lane"] == -1, "it spans every lane, so it owns none" + + def test_the_diagram_renders_the_band_and_the_interrupted_span(self, tmp_path): + pytest.importorskip("bokeh") + pytest.importorskip("pandas") + from execution_trace.diagram import generate_diagram + + out = tmp_path / "gap.html" + result = generate_diagram(_gap_csv(tmp_path), output_path=out) + assert result.output_path == out + html = out.read_text() + assert "Trace gap" in html, "the band needs a legend entry" + assert "Interrupted by gap" in html + assert "frames lost" in html, "the band is annotated with the count" diff --git a/python/tests/test_stream.py b/python/tests/test_stream.py index 94c3ad4..9ce97da 100644 --- a/python/tests/test_stream.py +++ b/python/tests/test_stream.py @@ -210,3 +210,82 @@ def test_frame_with_empty_payload(self): frames = list(iter_frames(buf)) assert frames == [b""] assert buf == bytearray() + + +class TestSequenceTrackerReordering: + """The v2 trace stream numbers frames at their producer, so they can arrive + slightly out of order; see SequenceTracker's Reordering note.""" + + def _tracker(self, window: int = 4) -> SequenceTracker: + return SequenceTracker("Test", modulus=64, reorder_window=window) + + def test_a_swapped_pair_is_not_reported_as_loss(self, caplog): + t = self._tracker() + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + for s in (10, 12, 11, 13): # 12 overtook 11 + assert t.observe(s) is False + assert caplog.text == "" + assert t.dropped == 0 + + def test_a_frame_arriving_late_within_the_window_closes_its_hole(self, caplog): + t = self._tracker() + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + for s in (10, 14, 13, 12, 11, 15): + t.observe(s) + assert caplog.text == "" + assert t.dropped == 0 + + def test_a_real_hole_is_reported_once_the_window_is_passed(self, caplog): + # 12 never arrives. Nothing is said until a frame lands more than the + # window past it, which bounds how late the report can be. + t = self._tracker(window=4) + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + for s in (10, 11, 13, 14, 15, 16): + t.observe(s) + assert t.dropped == 0, "still inside the window" + t.observe(17) + assert t.dropped == 1 + assert "1 dropped" in caplog.text + + def test_the_count_is_right_when_several_are_missing(self, caplog): + t = self._tracker(window=2) + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + t.observe(10) + t.observe(20) # 11..19 missing, far past the window + assert t.dropped == 9 + + def test_a_window_does_not_hide_a_device_reset(self, caplog): + # Detectable only when the pre-reset counter was low in the range: from + # high in it a restart at zero is indistinguishable from a forward gap, + # which is why the trace decoder leans on TRACE_START instead. + t = self._tracker() + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + t.observe(10) + assert t.observe(0) is True + assert "device reset" in caplog.text + + def test_a_late_arrival_after_its_hole_was_reported_is_ignored(self, caplog): + # The window has already passed the hole and called it lost; the straggler + # must not then be read as a backwards jump. + t = self._tracker(window=2) + t.observe(10) + t.observe(15) # 11..14 declared lost + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + assert t.observe(14) is False + assert "reset" not in caplog.text + + def test_zero_window_reports_immediately(self, caplog): + # Single-producer streams — attitude, status — keep strict ordering and + # should not have their gap reports delayed. + t = SequenceTracker("Strict", modulus=64, reorder_window=0) + with caplog.at_level(logging.WARNING, logger="execution_trace.stream"): + t.observe(10) + t.observe(12) + assert t.dropped == 1 + assert "1 dropped" in caplog.text + + def test_window_must_be_sane(self): + with pytest.raises(ValueError): + SequenceTracker("Test", modulus=64, reorder_window=32) + with pytest.raises(ValueError): + SequenceTracker("Test", modulus=64, reorder_window=-1) diff --git a/src/encode.rs b/src/encode.rs index 3e6f493..548717b 100644 --- a/src/encode.rs +++ b/src/encode.rs @@ -1,38 +1,554 @@ -use crate::TraceEvent; +//! Wire encoding for the v2 trace format. +//! +//! Every frame is `[varint: byte length][protobuf-encoded TraceFrame]`, and every +//! frame class — the three per-occurrence events, the dictionary entry and the +//! stream header — shares one flat message discriminated by `event_type` (§18.1). +//! +//! [`TraceEncoder`] owns the three pieces of per-stream state the format needs: +//! the name dictionary (§5.5), the timestamp base the deltas are taken against +//! (§5.6) and the sequence counter (§5.7). It runs in the task that owns the +//! transport, off the control path. + +use crate::types::{SourceType, TraceEvent}; use micropb::{MessageDecode, MessageEncode, PbDecoder, PbEncoder}; +/// Upper bound on one encoded frame, length prefix included. pub const MAX_TRACE_FRAME_SIZE: usize = 128; -/// Errors returned by [`encode_trace_frame`] and [`SequenceEncoder::encode`]. +/// Upper bound on one [`TraceEncoder::encode`] call, which emits a dictionary +/// frame ahead of the event when a name is seen for the first time. +pub const MAX_TRACE_BURST_SIZE: usize = 2 * MAX_TRACE_FRAME_SIZE; + +/// Distinct names the dictionary holds +pub const NAME_REGISTRY_CAPACITY: usize = 40; + +/// The reserved "unknown" name id, emitted when the registry is full (REQ-T11). +pub const UNKNOWN_NAME_ID: u32 = 0; + +/// Sequence numbers wrap here rather than at 2³². +/// +/// The counter exists only to detect gaps, a gap is read modulo the wrap, and the +/// largest burst ever observed was 103 frames. A full 32-bit counter costs five +/// varint bytes once past 2²⁸; this costs at most two (§18.1). +pub const SEQUENCE_MODULUS: u32 = 16_384; + +/// The unit of the `timestamp_ticks` field, declared once on the stream header. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Default)] +pub enum TimeBase { + /// Ticks are nanoseconds; `core_frequency_hz` is unused. + #[default] + Nanoseconds, + /// Ticks are core clock cycles, converted by `core_frequency_hz` (§5.8). + Cycles, +} + +/// Errors returned by the encoding entry points. #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub enum TracingEncodeError { /// The output buffer is too small or the encoded message exceeds [`MAX_TRACE_FRAME_SIZE`]. BufferFull, } -/// Encodes a [`TraceEvent`] as a length-delimited protobuf frame into `out`. +/// Result of one [`TraceEncoder::encode`] call. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct Encoded { + /// Bytes written to the output buffer. + pub len: usize, + /// The name was unknown and the dictionary was full, so the event went out + /// with [`UNKNOWN_NAME_ID`]. The caller should count this as a fault: the + /// stream stays decodable, but the name is lost. + pub name_registry_full: bool, +} + +/// The frame classes the wire carries. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum FrameKind { + SpanStart, + SpanEnd, + Marker, + /// A dictionary entry: `name_id` now resolves to `name` (§6.2). + NameRegistered, + /// The stream header, carrying the timebase and the source mask (§6.3). + TraceStart, +} + +/// One decoded frame, mirroring the wire message field for field. +/// +/// Decoding deliberately stops here rather than returning a [`TraceEvent`]: in v2 +/// an event is not recoverable from a single frame, because its name is a +/// dictionary id and its timestamp is a delta. Resolving both needs per-stream +/// state, which belongs in the host decoder (§18.3). +#[derive(Debug, Clone, PartialEq)] +pub struct RawTraceFrame { + /// A delta against the previous sequenced frame, except on + /// [`FrameKind::NameRegistered`] and [`FrameKind::TraceStart`], where it is + /// absolute and re-establishes the time origin. + /// + /// Signed: the delta is negative whenever an event was recorded before the + /// one encoded ahead of it, which happens whenever an ISR preempts a task + /// between its timestamp being taken and its being queued (§19.10). + pub timestamp_ticks: i64, + pub name_id: u32, + pub kind: FrameKind, + pub sequence: u32, + /// [`FrameKind::Marker`] only. + pub marker_value: Option, + /// [`FrameKind::NameRegistered`] only. + pub name: heapless::String<32>, + /// [`FrameKind::NameRegistered`] only. + pub source_type: Option, + /// [`FrameKind::NameRegistered`] only. + pub priority: u32, + /// [`FrameKind::NameRegistered`] only. + pub relative_deadline_ms: Option, + /// [`FrameKind::TraceStart`] only. + pub timebase: TimeBase, + /// [`FrameKind::TraceStart`] only; zero when the timebase is nanoseconds. + pub core_frequency_hz: u32, + /// [`FrameKind::TraceStart`] only. + pub source_mask: u32, +} + +impl RawTraceFrame { + fn new(kind: FrameKind, timestamp_ticks: i64, sequence: u32, name_id: u32) -> Self { + Self { + timestamp_ticks, + name_id, + kind, + sequence, + marker_value: None, + name: heapless::String::new(), + source_type: None, + priority: 0, + relative_deadline_ms: None, + timebase: TimeBase::Nanoseconds, + core_frequency_hz: 0, + source_mask: 0, + } + } +} + +/// Encodes [`TraceEvent`]s into the v2 wire format, holding the per-stream state +/// the format needs. +/// +/// # Name interning +/// +/// The dictionary is keyed on the name's **content**, not on the `&'static str` +/// pointer §5.5 proposed. By the time an event reaches this layer the literal's +/// pointer is gone — [`TraceEvent`] carries an inline copy that has been moved +/// through a channel — so pointer keying is only available to a registry in the +/// recording layer, which would mean a process-global with atomics and a changed +/// [`TraceSink`] API (§18.2). The scan is linear over at most +/// [`NAME_REGISTRY_CAPACITY`] entries with a length check before any byte +/// comparison, and it runs off the control path. +/// +/// [`TraceSink`]: crate::TraceSink +pub struct TraceEncoder { + names: heapless::Vec, + clock: TickClock, + /// Extended tick count of the frame emitted most recently, which the next + /// frame's delta is taken against. + last_emitted: i64, + sequence: u32, +} + +/// Turns the readings a sink produces into the monotonic tick count the wire +/// carries. +/// +/// The distinction exists because a raw hardware cycle counter is 32 bits and +/// free-running. Extending it to 64 is bookkeeping, and §5.8's whole point is +/// that the ISR recording an event must not pay for it — so it happens here, in +/// the task that owns the transport, off the control path. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +enum TickWidth { + /// Readings are already a 64-bit monotonic count and are used as given. + Monotonic64, + /// Readings are a free-running 32-bit counter that wraps. + Wrapping32, +} + +#[derive(Debug, Clone, Copy)] +struct TickClock { + width: TickWidth, + timebase: TimeBase, + core_frequency_hz: u32, + last_raw: u64, + absolute: i64, + started: bool, +} + +impl TickClock { + /// Folds a raw reading into the extended, absolute tick count. + /// + /// For a wrapping source the step is taken in the counter's own 32-bit + /// arithmetic and read as signed, which handles both the wrap — every + /// 59.65 s at 72 MHz — and the small backwards steps that ISR preemption + /// produces (§19.10), without telling them apart or needing to. The only + /// assumption is that consecutive readings are less than half a wrap apart; + /// the dictionary refresh reads the clock every 2 s, so nothing else has to + /// guarantee it. + fn extend(&mut self, raw: u64) -> i64 { + match self.width { + TickWidth::Monotonic64 => self.absolute = i64::try_from(raw).unwrap_or(i64::MAX), + TickWidth::Wrapping32 if self.started => { + #[allow(clippy::cast_possible_truncation, clippy::cast_possible_wrap)] + let step = i64::from((raw as u32).wrapping_sub(self.last_raw as u32) as i32); + self.absolute = self.absolute.wrapping_add(step); + } + TickWidth::Wrapping32 => self.absolute = i64::try_from(raw).unwrap_or(i64::MAX), + } + self.last_raw = raw; + self.started = true; + self.absolute + } +} + +/// One dictionary entry: a name and everything fixed by it. /// -/// Frame format: `[varint: byte length][protobuf-encoded TraceEvent]`. +/// The attributes are kept, not just the name, so that the dictionary can be +/// **re-emitted** in full ([`TraceEncoder::encode_dictionary_entry`]). A host +/// that attaches after startup never saw the original frames, and without a +/// re-emission every id it receives resolves to nothing. +#[derive(Debug, Clone, PartialEq)] +struct DictionaryEntry { + name: heapless::String<32>, + source_type: Option, + priority: u32, + relative_deadline_ms: Option, +} + +impl TraceEncoder { + /// Creates an encoder for a sink whose readings are 64-bit monotonic + /// nanoseconds. + pub const fn new() -> Self { + Self::with_clock(TickWidth::Monotonic64, TimeBase::Nanoseconds, 0) + } + + /// Creates an encoder for a sink whose readings are a free-running 32-bit + /// core cycle counter (§5.8). + /// + /// The counter wraps every `2³² / core_frequency_hz` seconds — 59.65 s at + /// 72 MHz — and this encoder extends it, so a reading costs the sink one + /// volatile load with no critical section and no division. The frequency is + /// put on the stream header so the host can convert to wall time without + /// hard-coding it. + pub const fn with_cycle_counter(core_frequency_hz: u32) -> Self { + Self::with_clock(TickWidth::Wrapping32, TimeBase::Cycles, core_frequency_hz) + } + + const fn with_clock(width: TickWidth, timebase: TimeBase, core_frequency_hz: u32) -> Self { + Self { + names: heapless::Vec::new(), + clock: TickClock { + width, + timebase, + core_frequency_hz, + last_raw: 0, + absolute: 0, + started: false, + }, + last_emitted: 0, + sequence: 0, + } + } + + /// Returns the sequence number this encoder last took for a frame of its own + /// (the stream header or a dictionary entry). + /// + /// Recorded events are numbered by the producer, not here, so this does not + /// track them; see [`next_sequence`](crate::next_sequence). + pub fn sequence(&self) -> u32 { + self.sequence + } + + /// Returns the number of names currently held in the dictionary. + pub fn registered_names(&self) -> usize { + self.names.len() + } + + /// Encodes the stream header (§6.3) into `out`, returning the bytes written. + /// + /// The header gives the host the tick unit and the active source mask without + /// either being hard-coded in the decoder, and it is what marks the stream as + /// v2 (§6.4). Emit it once at init, before any event. + /// + /// Its timestamp is absolute and becomes the base the following deltas are + /// taken against. + /// + /// # Errors + /// Returns [`TracingEncodeError::BufferFull`] if `out` is too small. + pub fn encode_trace_start( + &mut self, + timestamp_ticks: u64, + source_mask: u32, + out: &mut [u8], + ) -> Result { + let now = self.clock.extend(timestamp_ticks); + let mut frame = RawTraceFrame::new( + FrameKind::TraceStart, + now, + self.next_sequence(), + UNKNOWN_NAME_ID, + ); + frame.timebase = self.clock.timebase; + frame.core_frequency_hz = self.clock.core_frequency_hz; + frame.source_mask = source_mask; + self.last_emitted = now; + encode_trace_frame(&frame, out) + } + + /// Encodes `event` into `out`, interning its name, delta-encoding its + /// timestamp and assigning its sequence number. + /// + /// When the name is seen for the first time this writes **two** frames: the + /// dictionary entry, carrying the name and its fixed attributes, followed by + /// the event itself. `out` must therefore be at least + /// [`MAX_TRACE_BURST_SIZE`] bytes. + /// + /// # Errors + /// Returns [`TracingEncodeError::BufferFull`] if `out` is too small. + pub fn encode( + &mut self, + event: &TraceEvent, + out: &mut [u8], + ) -> Result { + let (name, timestamp_ns) = match event { + TraceEvent::SpanStart { + name, timestamp_ns, .. + } + | TraceEvent::SpanEnd { + name, timestamp_ns, .. + } + | TraceEvent::Marker { + name, timestamp_ns, .. + } => (name, *timestamp_ns), + }; + + let mut written = 0usize; + let mut name_registry_full = false; + + let name_id = match self.lookup(name) { + Some(id) => { + self.backfill(id, event); + id + } + None => match self.register(event, timestamp_ns, out) { + Ok((id, n)) => { + written += n; + id + } + Err(RegisterError::Full) => { + name_registry_full = true; + UNKNOWN_NAME_ID + } + Err(RegisterError::Encode(e)) => return Err(e), + }, + }; + + // Signed: a negative delta is an event that was recorded before the one + // encoded ahead of it. Clamping it to zero while still moving the base + // backwards would leave the host's clock permanently ahead (§19.10). + let now = self.clock.extend(timestamp_ns); + let delta = now - self.last_emitted; + self.last_emitted = now; + // Forwarded, not assigned: the number was taken when the event was + // recorded, upstream of the producer queue, so a frame lost there still + // leaves a gap on the wire (§5.7). + let sequence = event.sequence(); + + let mut frame = match event { + TraceEvent::SpanStart { .. } => { + RawTraceFrame::new(FrameKind::SpanStart, delta, sequence, name_id) + } + TraceEvent::SpanEnd { .. } => { + RawTraceFrame::new(FrameKind::SpanEnd, delta, sequence, name_id) + } + TraceEvent::Marker { marker_value, .. } => { + let mut f = RawTraceFrame::new(FrameKind::Marker, delta, sequence, name_id); + f.marker_value = *marker_value; + f + } + }; + // proto3 omits a zero-valued scalar, so a delta of zero costs nothing. + frame.timestamp_ticks = delta; + + let out_tail = out + .get_mut(written..) + .ok_or(TracingEncodeError::BufferFull)?; + written += encode_trace_frame(&frame, out_tail)?; + + Ok(Encoded { + len: written, + name_registry_full, + }) + } + + /// Linear scan keyed on content, length checked before any byte comparison. + fn lookup(&self, name: &heapless::String<32>) -> Option { + let needle = name.as_bytes(); + self.names + .iter() + .position(|candidate| { + candidate.name.len() == needle.len() && candidate.name.as_bytes() == needle + }) + // Ids are one-based: zero is reserved for "unknown". + .and_then(|index| u32::try_from(index + 1).ok()) + } + + /// Fills in the attributes of an entry that was first registered without them. + /// + /// A name is normally first seen on its `SpanStart`, which carries the + /// attributes. It is seen first on a `SpanEnd` only when the `SpanStart` was + /// dropped upstream of the encoder — at the producer queue, under load — and + /// without this the priority and deadline for that name would stay lost for + /// the rest of the run. + fn backfill(&mut self, name_id: u32, event: &TraceEvent) { + let TraceEvent::SpanStart { + source_type, + priority, + relative_deadline_ms, + .. + } = event + else { + return; + }; + let Some(index) = usize::try_from(name_id) + .ok() + .and_then(|id| id.checked_sub(1)) + else { + return; + }; + let Some(entry) = self.names.get_mut(index) else { + return; + }; + if entry.source_type.is_none() { + entry.source_type = Some(*source_type); + entry.priority = *priority; + entry.relative_deadline_ms = *relative_deadline_ms; + } + } + + /// Re-encodes the dictionary entry at `index` as a `NAME_REGISTERED` frame. + /// + /// Each entry is otherwise sent once, when its name is first seen, so a host + /// that attaches later resolves every id to nothing. Re-emitting the whole + /// dictionary periodically is what makes a mid-run attach decodable: the + /// frames are identical to the originals apart from their timestamp and + /// sequence, and a host that already holds an entry overwrites it with the + /// same value. + /// + /// Returns `None` once `index` is past the end, so a caller can walk from + /// zero until it stops. + /// + /// # Errors + /// Returns [`TracingEncodeError::BufferFull`] if `out` is too small. + pub fn encode_dictionary_entry( + &mut self, + index: usize, + timestamp_ticks: u64, + out: &mut [u8], + ) -> Option> { + let entry = self.names.get(index)?.clone(); + let name_id = u32::try_from(index + 1).ok()?; + let now = self.clock.extend(timestamp_ticks); + let sequence = self.next_sequence(); + let mut frame = RawTraceFrame::new(FrameKind::NameRegistered, now, sequence, name_id); + frame.name = entry.name; + frame.source_type = entry.source_type; + frame.priority = entry.priority; + frame.relative_deadline_ms = entry.relative_deadline_ms; + self.last_emitted = now; + Some(encode_trace_frame(&frame, out)) + } + + /// Assigns the next id and writes the dictionary frame, whose timestamp is + /// absolute so a host attaching mid-run can re-establish the time origin. + fn register( + &mut self, + event: &TraceEvent, + timestamp_ns: u64, + out: &mut [u8], + ) -> Result<(u32, usize), RegisterError> { + let (name, source_type, priority, relative_deadline_ms) = match event { + TraceEvent::SpanStart { + name, + source_type, + priority, + relative_deadline_ms, + .. + } => (name, Some(*source_type), *priority, *relative_deadline_ms), + // A SpanEnd or Marker reaching registration before its SpanStart + // carries no attributes to register; the name alone is the entry. + TraceEvent::SpanEnd { name, .. } | TraceEvent::Marker { name, .. } => { + (name, None, 0, None) + } + }; + + self.names + .push(DictionaryEntry { + name: name.clone(), + source_type, + priority, + relative_deadline_ms, + }) + .map_err(|_| RegisterError::Full)?; + let id = u32::try_from(self.names.len()).map_err(|_| RegisterError::Full)?; + + let now = self.clock.extend(timestamp_ns); + let sequence = self.next_sequence(); + let mut frame = RawTraceFrame::new(FrameKind::NameRegistered, now, sequence, id); + frame.name = name.clone(); + frame.source_type = source_type; + frame.priority = priority; + frame.relative_deadline_ms = relative_deadline_ms; + self.last_emitted = now; + + let n = encode_trace_frame(&frame, out).map_err(RegisterError::Encode)?; + Ok((id, n)) + } + + /// Takes a number for a frame the encoder generates itself — the stream + /// header and the dictionary entries, which were never "recorded" and so + /// have no producer-side number of their own. + /// + /// Drawn from the same global counter as recorded events: one sequence space + /// is what makes a gap mean anything. + fn next_sequence(&mut self) -> u32 { + let taken = crate::next_sequence(); + self.sequence = taken; + taken + } +} + +impl Default for TraceEncoder { + fn default() -> Self { + Self::new() + } +} + +enum RegisterError { + Full, + Encode(TracingEncodeError), +} + +/// Encodes one [`RawTraceFrame`] as a length-delimited protobuf frame into `out`. /// -/// The `sequence` parameter **overwrites** the `sequence` field already present in -/// `msg`. [`TraceSink`] always produces events with `sequence = 0`; use -/// [`SequenceEncoder`] or manage the counter manually here to enable drop detection -/// on the host. +/// Frame format: `[varint: byte length][protobuf-encoded TraceFrame]`. Returns the +/// number of bytes written. /// -/// Returns the number of bytes written on success. +/// This is the stateless half: it writes exactly the fields the frame carries and +/// applies no interning, delta or sequencing. Use [`TraceEncoder`] to produce +/// frames from [`TraceEvent`]s. /// /// # Errors /// Returns [`TracingEncodeError::BufferFull`] if `out` is too small or the message /// exceeds [`MAX_TRACE_FRAME_SIZE`]. -/// -/// [`TraceSink`]: crate::TraceSink #[allow(clippy::indexing_slicing)] // bounds-checked: n <= vec.len() <= MAX_TRACE_FRAME_SIZE <= out.len() pub fn encode_trace_frame( - msg: &TraceEvent, - sequence: u32, + frame: &RawTraceFrame, out: &mut [u8], ) -> Result { - let proto_msg = to_proto(msg, sequence); + let proto_msg = to_proto(frame); let mut vec: heapless::Vec = heapless::Vec::new(); let mut encoder = PbEncoder::new(vec); @@ -60,74 +576,33 @@ pub enum TracingDecodeError { DecodeError, } -/// Decodes one length-delimited protobuf frame produced by [`encode_trace_frame`]. +/// Decodes one length-delimited frame produced by [`encode_trace_frame`]. /// -/// `frame` must begin with a varint-encoded byte count followed by that many bytes -/// of protobuf-encoded [`TraceEvent`]. Returns the decoded event and the total number -/// of bytes consumed (varint header + payload). Useful for host-side tooling. +/// Returns the raw frame and the total number of bytes consumed (varint header + +/// payload). The frame's name is a dictionary id and its timestamp is usually a +/// delta; resolving either needs the per-stream state the host decoder holds +/// (§18.3). /// /// # Errors -/// Returns [`TracingDecodeError`] if the frame is truncated, the varint is malformed, -/// or the protobuf payload cannot be decoded. -pub fn decode_trace_frame(frame: &[u8]) -> Result<(TraceEvent, usize), TracingDecodeError> { +/// Returns [`TracingDecodeError`] if the frame is truncated, the varint is +/// malformed, or the protobuf payload cannot be decoded. +pub fn decode_trace_frame(frame: &[u8]) -> Result<(RawTraceFrame, usize), TracingDecodeError> { let (payload_len, header_len) = decode_varint(frame).ok_or(TracingDecodeError::MalformedVarint)?; let total = header_len + payload_len; if frame.len() < total { return Err(TracingDecodeError::Truncated); } - let payload = &frame[header_len..total]; + let payload = frame + .get(header_len..total) + .ok_or(TracingDecodeError::Truncated)?; let mut decoder = PbDecoder::new(payload); - let mut proto_event = crate::proto::tracing_::TraceEvent::default(); - proto_event + let mut proto_frame = crate::proto::tracing_::TraceFrame::default(); + proto_frame .decode(&mut decoder, payload_len) .map_err(|_| TracingDecodeError::DecodeError)?; - let event = from_proto(proto_event).ok_or(TracingDecodeError::DecodeError)?; - Ok((event, total)) -} - -/// Encodes [`TraceEvent`]s into a byte buffer while tracking the sequence counter. -/// -/// [`TraceSink`] does not manage sequence numbers — that is the responsibility of the -/// transport layer (the code that owns the wire). Use `SequenceEncoder` when encoding -/// events manually so that the host-side decoder can detect dropped frames. -/// -/// [`TraceSink`]: crate::TraceSink -pub struct SequenceEncoder { - sequence: u32, -} - -impl SequenceEncoder { - /// Creates a new encoder with the sequence counter initialised to zero. - pub const fn new() -> Self { - Self { sequence: 0 } - } - - /// Encodes `event` into `out`, injecting the current sequence number and - /// advancing the counter. Returns the number of bytes written. - /// - /// # Errors - /// Returns [`TracingEncodeError::BufferFull`] if `out` is too small. - pub fn encode( - &mut self, - event: &TraceEvent, - out: &mut [u8], - ) -> Result { - let n = encode_trace_frame(event, self.sequence, out)?; - self.sequence = self.sequence.wrapping_add(1); - Ok(n) - } - - /// Returns the current sequence counter value (the number of the *next* frame). - pub fn sequence(&self) -> u32 { - self.sequence - } -} - -impl Default for SequenceEncoder { - fn default() -> Self { - Self::new() - } + let decoded = from_proto(proto_frame).ok_or(TracingDecodeError::DecodeError)?; + Ok((decoded, total)) } /// Returns `(value, bytes_consumed)` for a varint at the start of `buf`, @@ -148,448 +623,850 @@ fn decode_varint(buf: &[u8]) -> Option<(usize, usize)> { None } -fn to_proto(event: &TraceEvent, sequence: u32) -> crate::proto::tracing_::TraceEvent { +fn to_proto(frame: &RawTraceFrame) -> crate::proto::tracing_::TraceFrame { use crate::proto::tracing_ as pb; - use crate::types::SourceType; - match event { - TraceEvent::SpanStart { - timestamp_ns, - name, - source_type, - priority, - relative_deadline_ms, - .. - } => { - let pb_source = match source_type { - SourceType::Isr => pb::TraceEventSourceType::Isr, - SourceType::Task => pb::TraceEventSourceType::Task, - }; - let mut msg = pb::TraceEvent { - timestamp_ns: *timestamp_ns, - name: name.clone(), - source_type: pb_source, - event_type: pb::TraceEventType::SpanStart, - sequence, - priority: *priority, - ..Default::default() - }; - if let Some(dl) = relative_deadline_ms { - msg.set_relative_deadline_ms(*dl); - } - msg - } - TraceEvent::SpanEnd { - timestamp_ns, name, .. - } => pb::TraceEvent { - timestamp_ns: *timestamp_ns, - name: name.clone(), - event_type: pb::TraceEventType::SpanEnd, - sequence, - ..Default::default() + let mut msg = pb::TraceFrame { + timestamp_ticks: frame.timestamp_ticks, + name_id: frame.name_id, + event_type: match frame.kind { + FrameKind::SpanStart => pb::TraceEventType::SpanStart, + FrameKind::SpanEnd => pb::TraceEventType::SpanEnd, + FrameKind::Marker => pb::TraceEventType::Marker, + FrameKind::NameRegistered => pb::TraceEventType::NameRegistered, + FrameKind::TraceStart => pb::TraceEventType::TraceStart, }, - TraceEvent::Marker { - timestamp_ns, - name, - marker_value, - .. - } => { - let mut msg = pb::TraceEvent { - timestamp_ns: *timestamp_ns, - name: name.clone(), - event_type: pb::TraceEventType::Marker, - sequence, - ..Default::default() - }; - if let Some(v) = marker_value { - msg.set_marker_value(*v); - } - msg - } + sequence: frame.sequence, + name: frame.name.clone(), + source_type: match frame.source_type { + Some(SourceType::Isr) => pb::TraceEventSourceType::Isr, + Some(SourceType::Task) => pb::TraceEventSourceType::Task, + None => pb::TraceEventSourceType::Unspecified, + }, + priority: frame.priority, + timebase: match frame.timebase { + TimeBase::Nanoseconds => pb::TimeBase::Nanoseconds, + TimeBase::Cycles => pb::TimeBase::Cycles, + }, + core_frequency_hz: frame.core_frequency_hz, + source_mask: frame.source_mask, + ..Default::default() + }; + if let Some(v) = frame.marker_value { + msg.set_marker_value(v); } + if let Some(dl) = frame.relative_deadline_ms { + msg.set_relative_deadline_ms(dl); + } + msg } -fn from_proto(p: crate::proto::tracing_::TraceEvent) -> Option { +fn from_proto(p: crate::proto::tracing_::TraceFrame) -> Option { use crate::proto::tracing_ as pb; - use crate::types::SourceType; - - let et = p.event_type; - if et == pb::TraceEventType::SpanStart { - let source_type = if p.source_type == pb::TraceEventSourceType::Isr { - SourceType::Isr - } else if p.source_type == pb::TraceEventSourceType::Task { - SourceType::Task - } else { - return None; - }; - let relative_deadline_ms = p.relative_deadline_ms().copied(); - Some(TraceEvent::SpanStart { - timestamp_ns: p.timestamp_ns, - source_type, - sequence: p.sequence, - priority: p.priority, - relative_deadline_ms, - name: p.name, - }) - } else if et == pb::TraceEventType::SpanEnd { - Some(TraceEvent::SpanEnd { - timestamp_ns: p.timestamp_ns, - sequence: p.sequence, - name: p.name, - }) - } else if et == pb::TraceEventType::Marker { - let marker_value = p.marker_value().copied(); - Some(TraceEvent::Marker { - timestamp_ns: p.timestamp_ns, - sequence: p.sequence, - marker_value, - name: p.name, - }) + + let kind = if p.event_type == pb::TraceEventType::SpanStart { + FrameKind::SpanStart + } else if p.event_type == pb::TraceEventType::SpanEnd { + FrameKind::SpanEnd + } else if p.event_type == pb::TraceEventType::Marker { + FrameKind::Marker + } else if p.event_type == pb::TraceEventType::NameRegistered { + FrameKind::NameRegistered + } else if p.event_type == pb::TraceEventType::TraceStart { + FrameKind::TraceStart + } else { + return None; + }; + + let source_type = if p.source_type == pb::TraceEventSourceType::Isr { + Some(SourceType::Isr) + } else if p.source_type == pb::TraceEventSourceType::Task { + Some(SourceType::Task) } else { None - } + }; + + let timebase = if p.timebase == pb::TimeBase::Cycles { + TimeBase::Cycles + } else { + TimeBase::Nanoseconds + }; + + Some(RawTraceFrame { + timestamp_ticks: p.timestamp_ticks, + name_id: p.name_id, + kind, + sequence: p.sequence, + marker_value: p.marker_value().copied(), + source_type, + priority: p.priority, + relative_deadline_ms: p.relative_deadline_ms().copied(), + timebase, + core_frequency_hz: p.core_frequency_hz, + source_mask: p.source_mask, + name: p.name, + }) } +// `unwrap` and `panic!` are how a test asserts. The crate denies both because a +// firmware panic is a hard fault, which is not a risk a test harness runs. #[cfg(all(test, feature = "std", feature = "enabled"))] +#[allow(clippy::unwrap_used, clippy::panic)] mod tests { use super::*; - use crate::SourceType; use heapless::String; use insta::assert_debug_snapshot; - fn make_span_start() -> TraceEvent { - let mut name: String<32> = String::new(); - name.push_str("led_task").unwrap(); + fn name(v: &str) -> String<32> { + let mut n: String<32> = String::new(); + n.push_str(v).unwrap(); + n + } + + /// Builds an event the way the recording layer does, including taking its + /// producer-side sequence number (§5.7). + fn span_start(n: &str, ts: u64) -> TraceEvent { TraceEvent::SpanStart { - timestamp_ns: 1_000_000, - name, + timestamp_ns: ts, + name: name(n), source_type: SourceType::Task, - sequence: 0, + sequence: crate::next_sequence(), priority: 2, relative_deadline_ms: None, } } - fn make_span_start_with_deadline() -> TraceEvent { - let mut name: String<32> = String::new(); - name.push_str("led_task").unwrap(); + fn span_start_with_deadline(n: &str, ts: u64) -> TraceEvent { TraceEvent::SpanStart { - timestamp_ns: 1_000_000, - name, - source_type: SourceType::Task, - sequence: 0, - priority: 2, + timestamp_ns: ts, + name: name(n), + source_type: SourceType::Isr, + sequence: crate::next_sequence(), + priority: 8, relative_deadline_ms: Some(0.5), } } - fn make_span_end() -> TraceEvent { - let mut name: String<32> = String::new(); - name.push_str("gyro_isr").unwrap(); + fn span_end(n: &str, ts: u64) -> TraceEvent { TraceEvent::SpanEnd { - timestamp_ns: 2_000_000, - name, - sequence: 0, + timestamp_ns: ts, + name: name(n), + sequence: crate::next_sequence(), } } - fn make_marker() -> TraceEvent { - let mut name: String<32> = String::new(); - name.push_str("ukf_predict").unwrap(); + fn marker(n: &str, ts: u64, value: Option) -> TraceEvent { TraceEvent::Marker { - timestamp_ns: 1_500_000, - name, - sequence: 0, - marker_value: None, + timestamp_ns: ts, + name: name(n), + sequence: crate::next_sequence(), + marker_value: value, } } - fn make_marker_with_value() -> TraceEvent { - let mut name: String<32> = String::new(); - name.push_str("ukf_predict").unwrap(); - TraceEvent::Marker { - timestamp_ns: 1_500_000, - name, - sequence: 0, - marker_value: Some(42), - } + /// Encodes into a fresh buffer and returns the bytes actually written. + fn encode_one(enc: &mut TraceEncoder, event: &TraceEvent) -> (Vec, Encoded) { + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + let outcome = enc.encode(event, &mut buf).unwrap(); + (buf[..outcome.len].to_vec(), outcome) } - fn encode(msg: &TraceEvent, seq: u32) -> ([u8; MAX_TRACE_FRAME_SIZE], usize) { - let mut buf = [0u8; MAX_TRACE_FRAME_SIZE]; - let n = encode_trace_frame(msg, seq, &mut buf).unwrap(); - (buf, n) - } - - fn check_frame_length(frame: &[u8]) { - let mut value: u64 = 0; - let mut shift = 0u32; - for (i, &byte) in frame.iter().enumerate() { - value |= ((byte & 0x7F) as u64) << shift; - if byte & 0x80 == 0 { - let header_bytes = i + 1; - assert_eq!( - header_bytes + value as usize, - frame.len(), - "varint length prefix does not match frame length" - ); - return; - } - shift += 7; + /// Decodes every frame in `bytes`, asserting the buffer is consumed exactly. + fn decode_all(bytes: &[u8]) -> Vec { + let mut frames = Vec::new(); + let mut offset = 0; + while offset < bytes.len() { + let (frame, consumed) = decode_trace_frame(&bytes[offset..]).unwrap(); + frames.push(frame); + offset += consumed; } - panic!("incomplete varint in frame"); + assert_eq!(offset, bytes.len(), "frames did not tile the buffer"); + frames } - fn contains_bytes(frame: &[u8], needle: &[u8]) -> bool { - frame.windows(needle.len()).any(|w| w == needle) + /// An encoder whose dictionary already holds `names`, so that following + /// encodes are steady-state rather than cold. + fn warmed(names: &[&str]) -> TraceEncoder { + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + for n in names { + enc.encode(&span_start(n, 0), &mut buf).unwrap(); + } + enc } + // ── Frame structure ─────────────────────────────────────────────────────── + #[test] - fn span_start_encodes_without_error() { - let (buf, n) = encode(&make_span_start(), 0); - assert!(n > 0 && n <= MAX_TRACE_FRAME_SIZE); - check_frame_length(&buf[..n]); + fn first_sight_of_a_name_emits_a_dictionary_frame_then_the_event() { + let mut enc = TraceEncoder::new(); + let (bytes, outcome) = encode_one(&mut enc, &span_start_with_deadline("gyro_isr", 5_000)); + assert!(!outcome.name_registry_full); + + let frames = decode_all(&bytes); + assert_eq!(frames.len(), 2, "expected dictionary frame + event"); + + assert_eq!(frames[0].kind, FrameKind::NameRegistered); + assert_eq!(frames[0].name.as_str(), "gyro_isr"); + assert_eq!(frames[0].name_id, 1); + assert_eq!(frames[0].source_type, Some(SourceType::Isr)); + assert_eq!(frames[0].priority, 8); + assert_eq!(frames[0].relative_deadline_ms, Some(0.5)); + + assert_eq!(frames[1].kind, FrameKind::SpanStart); + assert_eq!(frames[1].name_id, 1); + assert!(frames[1].name.is_empty(), "event must not carry the name"); } #[test] - fn span_start_with_deadline_encodes_without_error() { - let (buf, n) = encode(&make_span_start_with_deadline(), 0); - assert!(n > 0 && n <= MAX_TRACE_FRAME_SIZE); - check_frame_length(&buf[..n]); + fn dictionary_frame_timestamp_is_absolute() { + let mut enc = TraceEncoder::new(); + let (bytes, _) = encode_one(&mut enc, &span_start("main_task", 7_000_000)); + let frames = decode_all(&bytes); + assert_eq!(frames[0].timestamp_ticks, 7_000_000); } #[test] - fn span_end_encodes_without_error() { - let (buf, n) = encode(&make_span_end(), 0); - assert!(n > 0 && n <= MAX_TRACE_FRAME_SIZE); - check_frame_length(&buf[..n]); + fn second_sight_of_a_name_emits_the_event_alone() { + let mut enc = warmed(&["main_task"]); + let (bytes, _) = encode_one(&mut enc, &span_end("main_task", 1_000)); + let frames = decode_all(&bytes); + assert_eq!(frames.len(), 1); + assert_eq!(frames[0].kind, FrameKind::SpanEnd); + assert_eq!(frames[0].name_id, 1); } #[test] - fn marker_encodes_without_error() { - let (buf, n) = encode(&make_marker(), 0); - assert!(n > 0 && n <= MAX_TRACE_FRAME_SIZE); - check_frame_length(&buf[..n]); + fn distinct_names_get_distinct_ids() { + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + for (i, n) in ["a", "b", "c"].iter().enumerate() { + let outcome = enc.encode(&span_start(n, 0), &mut buf).unwrap(); + let frames = decode_all(&buf[..outcome.len]); + assert_eq!(frames[0].name_id, u32::try_from(i + 1).unwrap()); + assert_eq!(frames[1].name_id, u32::try_from(i + 1).unwrap()); + } + assert_eq!(enc.registered_names(), 3); } #[test] - fn marker_with_value_encodes_without_error() { - let (buf, n) = encode(&make_marker_with_value(), 0); - assert!(n > 0 && n <= MAX_TRACE_FRAME_SIZE); - check_frame_length(&buf[..n]); + fn name_ids_are_one_based_so_zero_stays_reserved() { + let mut enc = TraceEncoder::new(); + let (bytes, _) = encode_one(&mut enc, &span_start("first", 0)); + assert_eq!(decode_all(&bytes)[0].name_id, 1); + assert_ne!(decode_all(&bytes)[0].name_id, UNKNOWN_NAME_ID); } #[test] - fn span_start_fits_in_max_buffer() { - let (_, n) = encode(&make_span_start_with_deadline(), u32::MAX); - assert!(n <= MAX_TRACE_FRAME_SIZE); + fn interning_is_keyed_on_content_not_on_pointer() { + // Two separately constructed names with equal content must share an id — + // this is the property §18.2 chose content keying to get. + let mut enc = warmed(&["main_task"]); + let mut owned = std::string::String::from("main_"); + owned.push_str("task"); + let (bytes, _) = encode_one(&mut enc, &span_end(&owned, 10)); + let frames = decode_all(&bytes); + assert_eq!(frames.len(), 1, "equal content must not re-register"); + assert_eq!(frames[0].name_id, 1); } #[test] - fn span_end_fits_in_max_buffer() { - let (_, n) = encode(&make_span_end(), u32::MAX); - assert!(n <= MAX_TRACE_FRAME_SIZE); + fn names_sharing_a_prefix_are_distinct_entries() { + let mut enc = warmed(&["main", "main_task"]); + assert_eq!(enc.registered_names(), 2); + let (bytes, _) = encode_one(&mut enc, &span_end("main", 0)); + assert_eq!(decode_all(&bytes)[0].name_id, 1); + let (bytes, _) = encode_one(&mut enc, &span_end("main_task", 0)); + assert_eq!(decode_all(&bytes)[0].name_id, 2); } + // ── Dictionary refresh ──────────────────────────────────────────────────── + #[test] - fn marker_fits_in_max_buffer() { - let (_, n) = encode(&make_marker_with_value(), u32::MAX); - assert!(n <= MAX_TRACE_FRAME_SIZE); + fn the_dictionary_can_be_re_emitted_in_full() { + // What makes a mid-run host attach decodable: the device re-sends every + // entry, so ids it never saw registered become resolvable. + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + enc.encode(&span_start_with_deadline("gyro_isr", 0), &mut buf) + .unwrap(); + enc.encode(&marker("ukf_predict", 0, None), &mut buf) + .unwrap(); + + let mut wire = Vec::new(); + let mut index = 0; + while let Some(result) = enc.encode_dictionary_entry(index, 5_000, &mut buf) { + wire.extend_from_slice(&buf[..result.unwrap()]); + index += 1; + } + assert_eq!(index, 2, "one frame per entry, then it stops"); + + let frames = decode_all(&wire); + assert!(frames.iter().all(|f| f.kind == FrameKind::NameRegistered)); + assert_eq!(frames[0].name_id, 1); + assert_eq!(frames[0].name.as_str(), "gyro_isr"); + assert_eq!(frames[0].source_type, Some(SourceType::Isr)); + assert_eq!(frames[0].priority, 8); + assert_eq!(frames[0].relative_deadline_ms, Some(0.5)); + assert_eq!(frames[1].name_id, 2); + assert_eq!(frames[1].name.as_str(), "ukf_predict"); } #[test] - fn name_present_in_output() { - let (buf, n) = encode(&make_span_start(), 0); - assert!(contains_bytes(&buf[..n], b"led_task")); + fn a_refresh_keeps_the_ids_it_originally_assigned() { + let mut enc = warmed(&["a", "b", "c"]); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + for index in 0..3 { + let n = enc + .encode_dictionary_entry(index, 0, &mut buf) + .unwrap() + .unwrap(); + let frame = decode_all(&buf[..n]).remove(0); + assert_eq!(frame.name_id, u32::try_from(index + 1).unwrap()); + } + // Following events still resolve to the same ids. + let (bytes, _) = encode_one(&mut enc, &span_end("b", 0)); + assert_eq!(decode_all(&bytes)[0].name_id, 2); } #[test] - fn marker_label_present_in_output() { - let (buf, n) = encode(&make_marker(), 0); - assert!(contains_bytes(&buf[..n], b"ukf_predict")); + fn a_refresh_is_sequenced_so_it_cannot_look_like_a_gap() { + let mut enc = warmed(&["a"]); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + let before = enc.sequence(); + enc.encode_dictionary_entry(0, 0, &mut buf) + .unwrap() + .unwrap(); + assert_eq!(enc.sequence(), before + 1); } #[test] - fn deadline_present_in_span_start_output() { - let (buf, n) = encode(&make_span_start_with_deadline(), 0); - assert!(contains_bytes(&buf[..n], &0.5_f32.to_le_bytes())); + fn a_name_first_seen_on_a_span_end_gains_its_attributes_later() { + // The SpanStart was dropped upstream of the encoder, so the entry is + // registered bare. When a later SpanStart for that name arrives the + // attributes must be filled in, or the refresh re-sends a bare entry + // and the priority is lost for the rest of the run. + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + enc.encode(&span_end("gyro_isr", 0), &mut buf).unwrap(); + enc.encode(&span_start_with_deadline("gyro_isr", 0), &mut buf) + .unwrap(); + + let n = enc + .encode_dictionary_entry(0, 0, &mut buf) + .unwrap() + .unwrap(); + let frame = decode_all(&buf[..n]).remove(0); + assert_eq!(frame.source_type, Some(SourceType::Isr)); + assert_eq!(frame.priority, 8); + assert_eq!(frame.relative_deadline_ms, Some(0.5)); } + // ── Delta timestamps (§5.6) ─────────────────────────────────────────────── + #[test] - fn span_start_with_deadline_larger_than_span_end() { - let (_, n_start) = encode(&make_span_start_with_deadline(), 0); - let (_, n_end) = encode(&make_span_end(), 0); - assert!(n_start > n_end); + fn event_timestamps_are_deltas_against_the_previous_frame() { + let mut enc = warmed(&["main_task"]); + let (bytes, _) = encode_one(&mut enc, &span_start("main_task", 1_000)); + assert_eq!(decode_all(&bytes)[0].timestamp_ticks, 1_000); + let (bytes, _) = encode_one(&mut enc, &span_end("main_task", 1_700)); + assert_eq!(decode_all(&bytes)[0].timestamp_ticks, 700); } #[test] - fn sequence_included_in_output() { - let msg = make_span_start(); - let (buf0, n0) = encode(&msg, 0); - let (buf1, n1) = encode(&msg, 99); - assert_ne!(&buf0[..n0], &buf1[..n1]); + fn the_event_following_its_own_dictionary_frame_has_a_zero_delta() { + let mut enc = TraceEncoder::new(); + let (bytes, _) = encode_one(&mut enc, &span_start("main_task", 9_999)); + let frames = decode_all(&bytes); + assert_eq!( + frames[0].timestamp_ticks, 9_999, + "dictionary frame absolute" + ); + assert_eq!(frames[1].timestamp_ticks, 0, "event delta against it"); } #[test] - fn sequence_wraps_at_max() { - let (buf, n) = encode(&make_span_start(), u32::MAX); - check_frame_length(&buf[..n]); + fn accumulated_deltas_reconstruct_the_original_timestamps() { + let mut enc = warmed(&["a"]); + let stamps = [1_000u64, 1_001, 250_000, 250_003, 9_000_000]; + let mut bytes = Vec::new(); + for ts in stamps { + let (b, _) = encode_one(&mut enc, &span_end("a", ts)); + bytes.extend_from_slice(&b); + } + let mut clock = 0i64; + let reconstructed: Vec = decode_all(&bytes) + .iter() + .map(|f| { + clock += f.timestamp_ticks; + u64::try_from(clock).unwrap() + }) + .collect(); + assert_eq!(reconstructed, stamps); } #[test] - fn timestamp_ns_present_in_output() { - // varint(1_000_000) = [0xC0, 0x84, 0x3D] - let (buf, n) = encode(&make_span_start(), 0); - assert!(contains_bytes(&buf[..n], &[0xC0u8, 0x84, 0x3D])); + fn a_backwards_timestamp_is_encoded_as_a_negative_delta() { + // An event recorded before the one encoded ahead of it: the timestamp is + // taken before the event reaches the producer queue, so an ISR preempting + // a task in between reorders them. The delta has to carry the inversion, + // not clamp it (§19.10). + let mut enc = warmed(&["a"]); + encode_one(&mut enc, &span_end("a", 10_000)); + let (bytes, _) = encode_one(&mut enc, &span_end("a", 9_000)); + assert_eq!(decode_all(&bytes)[0].timestamp_ticks, -1_000); } #[test] - fn buffer_too_small_returns_error() { - let mut buf = [0u8; 4]; + fn out_of_order_timestamps_do_not_drift_the_reconstructed_clock() { + // The recording layer timestamps an event before it reaches the queue, so + // a priority-8 ISR preempting a task between those two points puts a + // *later* timestamp ahead of an earlier one in drain order. The + // reconstructed clock must still track the device, or it runs ahead and a + // later absolute timestamp looks like the device clock went backwards. + let mut enc = warmed(&["a"]); + let mut wire = Vec::new(); + // 100, then an inverted 90, then 110 — one preemption. + for ts in [100_000u64, 90_000, 110_000] { + let (bytes, _) = encode_one(&mut enc, &span_end("a", ts)); + wire.extend_from_slice(&bytes); + } + let mut clock = 0i64; + for frame in decode_all(&wire) { + clock += frame.timestamp_ticks; + } assert_eq!( - encode_trace_frame(&make_span_start(), 0, &mut buf), - Err(TracingEncodeError::BufferFull) + clock, 110_000, + "the reconstructed clock must land on the last timestamp, not past it" ); } + // ── Sequencing (§18.1) ──────────────────────────────────────────────────── + + /// Serialises the tests that assert on absolute sequence numbers. The + /// counter is process-global by design (§5.7), so the test harness running + /// them on separate threads would otherwise make them depend on each other. + static SEQUENCE_LOCK: std::sync::Mutex<()> = std::sync::Mutex::new(()); + + fn with_fresh_sequence(body: impl FnOnce() -> T) -> T { + let guard = SEQUENCE_LOCK.lock().unwrap_or_else(|e| e.into_inner()); + crate::reset_sequence(); + let out = body(); + drop(guard); + out + } + #[test] - fn marker_value_preserved_after_encode_decode() { - let (buf, n) = encode(&make_marker_with_value(), 0); - assert!(n > 0); - // The value 42 as varint is just 0x2A; verify it appears in the frame - assert!(contains_bytes(&buf[..n], &[0x2A])); + fn the_encoder_forwards_the_number_the_event_was_recorded_with() { + // The whole point of §5.7: the transport does not number events, so an + // event lost before it reaches the transport still burned a number. + let mut enc = warmed(&["a"]); + let mut event = span_end("a", 0); + event.set_sequence(4_321); + let (bytes, _) = encode_one(&mut enc, &event); + assert_eq!(decode_all(&bytes)[0].sequence, 4_321); } #[test] - fn span_start_wire_format_snapshot() { - let (buf, n) = encode(&make_span_start_with_deadline(), 1); - assert_debug_snapshot!(&buf[..n]); + fn a_gap_in_recorded_numbers_survives_to_the_wire() { + // A frame dropped at the producer queue: the encoder never sees it, and + // the numbers either side of it must still show the hole (AC 7). + let mut enc = warmed(&["a"]); + let mut wire = Vec::new(); + for seq in [10u32, 11, /* 12 dropped at the queue */ 13] { + let mut event = span_end("a", 0); + event.set_sequence(seq); + let (bytes, _) = encode_one(&mut enc, &event); + wire.extend_from_slice(&bytes); + } + let seen: Vec = decode_all(&wire).iter().map(|f| f.sequence).collect(); + assert_eq!(seen, vec![10, 11, 13]); } - // ── SequenceEncoder tests ───────────────────────────────────────────────── + #[test] + fn recorded_numbers_are_consecutive_and_wrap_at_the_modulus() { + with_fresh_sequence(|| { + let drawn: Vec = (0..SEQUENCE_MODULUS + 3) + .map(|_| crate::next_sequence()) + .collect(); + assert_eq!(drawn[0], 0); + assert_eq!(drawn[SEQUENCE_MODULUS as usize - 1], SEQUENCE_MODULUS - 1); + assert_eq!( + drawn[SEQUENCE_MODULUS as usize], 0, + "wraps to zero, not to 16384" + ); + assert_eq!(drawn[SEQUENCE_MODULUS as usize + 1], 1); + }); + } #[test] - fn sequence_encoder_starts_at_zero() { - assert_eq!(SequenceEncoder::new().sequence(), 0); + fn recorded_numbers_never_exceed_the_modulus() { + for _ in 0..(SEQUENCE_MODULUS * 2) { + assert!(crate::next_sequence() < SEQUENCE_MODULUS); + } } + // ── Registry exhaustion (REQ-T11) ───────────────────────────────────────── + #[test] - fn sequence_encoder_advances_on_each_encode() { - let mut enc = SequenceEncoder::new(); + fn registry_exhaustion_falls_back_to_the_unknown_id_and_reports_it() { + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + for i in 0..NAME_REGISTRY_CAPACITY { + let outcome = enc + .encode(&span_start(&format!("n{i}"), 0), &mut buf) + .unwrap(); + assert!(!outcome.name_registry_full); + } + assert_eq!(enc.registered_names(), NAME_REGISTRY_CAPACITY); + + let (bytes, outcome) = encode_one(&mut enc, &span_start("one_too_many", 0)); + assert!(outcome.name_registry_full); + let frames = decode_all(&bytes); + assert_eq!(frames.len(), 1, "no dictionary frame is emitted"); + assert_eq!(frames[0].name_id, UNKNOWN_NAME_ID); + assert_eq!(frames[0].kind, FrameKind::SpanStart); + } + + #[test] + fn a_registered_name_still_resolves_after_the_registry_fills() { + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + for i in 0..NAME_REGISTRY_CAPACITY { + enc.encode(&span_start(&format!("n{i}"), 0), &mut buf) + .unwrap(); + } + enc.encode(&span_start("overflow", 0), &mut buf).unwrap(); + let (bytes, outcome) = encode_one(&mut enc, &span_end("n0", 0)); + assert!(!outcome.name_registry_full); + assert_eq!(decode_all(&bytes)[0].name_id, 1); + } + + // ── Stream header (§6.3) ────────────────────────────────────────────────── + + #[test] + fn trace_start_carries_the_timebase_frequency_and_mask() { + crate::reset_sequence(); + let mut enc = TraceEncoder::with_cycle_counter(72_000_000); let mut buf = [0u8; MAX_TRACE_FRAME_SIZE]; - enc.encode(&make_span_start(), &mut buf).unwrap(); - assert_eq!(enc.sequence(), 1); - enc.encode(&make_span_end(), &mut buf).unwrap(); - assert_eq!(enc.sequence(), 2); + let n = enc.encode_trace_start(1_234, 0b10111, &mut buf).unwrap(); + let frames = decode_all(&buf[..n]); + assert_eq!(frames.len(), 1); + assert_eq!(frames[0].kind, FrameKind::TraceStart); + assert_eq!(frames[0].timestamp_ticks, 1_234, "absolute, not a delta"); + assert_eq!(frames[0].timebase, TimeBase::Cycles); + assert_eq!(frames[0].core_frequency_hz, 72_000_000); + assert_eq!(frames[0].source_mask, 0b10111); + assert_eq!(frames[0].sequence, 0, "the header is the first frame"); } #[test] - fn sequence_encoder_injects_sequence_into_frame() { - let mut enc = SequenceEncoder::new(); + fn a_nanosecond_encoder_declares_nanoseconds_and_no_frequency() { + let mut enc = TraceEncoder::new(); let mut buf = [0u8; MAX_TRACE_FRAME_SIZE]; - let n = enc.encode(&make_span_start(), &mut buf).unwrap(); - let (decoded, _) = decode_trace_frame(&buf[..n]).unwrap(); - let TraceEvent::SpanStart { sequence, .. } = decoded else { - panic!("expected SpanStart"); - }; - assert_eq!(sequence, 0); - let n = enc.encode(&make_span_start(), &mut buf).unwrap(); - let (decoded, _) = decode_trace_frame(&buf[..n]).unwrap(); - let TraceEvent::SpanStart { sequence, .. } = decoded else { - panic!("expected SpanStart"); - }; - assert_eq!(sequence, 1); + let n = enc.encode_trace_start(1_234, 0x1F, &mut buf).unwrap(); + let frame = decode_all(&buf[..n]).remove(0); + assert_eq!(frame.timebase, TimeBase::Nanoseconds); + assert_eq!(frame.core_frequency_hz, 0); } + // ── A wrapping 32-bit cycle source (§5.8) ──────────────────────────────── + #[test] - fn sequence_encoder_wraps_at_max() { - let mut enc = SequenceEncoder { sequence: u32::MAX }; + fn a_cycle_counter_wrap_is_an_ordinary_small_delta() { + // The counter rolls over every 59.65 s at 72 MHz. The encoder extends + // it, so the wire never sees the discontinuity. + let mut enc = TraceEncoder::with_cycle_counter(72_000_000); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + enc.encode(&span_end("a", u64::from(u32::MAX - 1_000)), &mut buf) + .unwrap(); + // 2 001 cycles later — 1 001 to roll past u32::MAX, then 1 000 more. + let (bytes, _) = encode_one(&mut enc, &span_end("a", 1_000)); + assert_eq!(decode_all(&bytes)[0].timestamp_ticks, 2_001); + } + + #[test] + fn a_wrapped_absolute_timestamp_keeps_climbing() { + // A dictionary refresh after a wrap must not send the host's clock + // backwards: the extension, not the raw counter, goes on the wire. + let mut enc = TraceEncoder::with_cycle_counter(72_000_000); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + enc.encode(&span_end("a", u64::from(u32::MAX - 1_000)), &mut buf) + .unwrap(); + let n = enc.encode_trace_start(1_000, 0x1F, &mut buf).unwrap(); + let header = decode_all(&buf[..n]).remove(0); + assert!( + header.timestamp_ticks > i64::from(u32::MAX - 1_000), + "extended past the wrap, got {}", + header.timestamp_ticks + ); + } + + #[test] + fn a_cycle_source_still_carries_backwards_steps_exactly() { + // ISR preemption inverts a pair (§19.10). Against a wrapping source that + // is a small negative step, and must stay one rather than being read as + // a nearly-complete wrap forward. + let mut enc = TraceEncoder::with_cycle_counter(72_000_000); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + enc.encode(&span_end("a", 500_000), &mut buf).unwrap(); + let (bytes, _) = encode_one(&mut enc, &span_end("a", 499_000)); + assert_eq!(decode_all(&bytes)[0].timestamp_ticks, -1_000); + } + + #[test] + fn cycle_deltas_reconstruct_the_elapsed_time_across_a_wrap() { + let mut enc = TraceEncoder::with_cycle_counter(72_000_000); + let mut wire = Vec::new(); + // 100 steps of 1 000 000 cycles, starting just before the rollover. + let mut raw = u32::MAX - 50_000_000; + for _ in 0..100 { + raw = raw.wrapping_add(1_000_000); + let (bytes, _) = encode_one(&mut enc, &span_end("a", u64::from(raw))); + wire.extend_from_slice(&bytes); + } + let elapsed: i64 = decode_all(&wire).iter().map(|f| f.timestamp_ticks).sum(); + assert_eq!( + elapsed - i64::from(u32::MAX - 50_000_000), + 100_000_000, + "100 steps of a million cycles, wrap included" + ); + } + + #[test] + fn trace_start_sets_the_base_for_the_following_delta() { + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + enc.encode_trace_start(1_000, 0x1F, &mut buf).unwrap(); + let (bytes, _) = encode_one(&mut enc, &span_start("a", 1_500)); + let frames = decode_all(&bytes); + assert_eq!(frames[0].timestamp_ticks, 1_500, "dictionary absolute"); + assert_eq!(frames[1].timestamp_ticks, 0); + } + + #[test] + fn a_nanosecond_timebase_is_the_default_and_costs_no_bytes() { + // proto3 omits zero-valued scalars, so NANOSECONDS and an unset core + // frequency are free on the header. + let mut enc = TraceEncoder::new(); let mut buf = [0u8; MAX_TRACE_FRAME_SIZE]; - enc.encode(&make_span_start(), &mut buf).unwrap(); - assert_eq!(enc.sequence(), 0); + let ns = enc.encode_trace_start(0, 0, &mut buf).unwrap(); + let mut enc = TraceEncoder::with_cycle_counter(72_000_000); + let cycles = enc.encode_trace_start(0, 0, &mut buf).unwrap(); + assert!(cycles > ns); } - // ── decode_trace_frame round-trip tests ─────────────────────────────────── + // ── Marker payloads ─────────────────────────────────────────────────────── - fn round_trip(msg: &TraceEvent, seq: u32) -> TraceEvent { - let (buf, n) = encode(msg, seq); - let (decoded, consumed) = decode_trace_frame(&buf[..n]).unwrap(); - assert_eq!(consumed, n); - decoded + #[test] + fn marker_value_round_trips() { + let mut enc = warmed(&["ukf_predict"]); + let (bytes, _) = encode_one(&mut enc, &marker("ukf_predict", 0, Some(42))); + assert_eq!(decode_all(&bytes)[0].marker_value, Some(42)); } #[test] - fn round_trip_span_start_preserves_fields() { - let decoded = round_trip(&make_span_start(), 7); - let TraceEvent::SpanStart { - name, - source_type, - timestamp_ns, - priority, - sequence, - relative_deadline_ms, - } = decoded - else { - panic!("expected SpanStart"); - }; - assert_eq!(name.as_str(), "led_task"); - assert_eq!(source_type, SourceType::Task); - assert_eq!(timestamp_ns, 1_000_000); - assert_eq!(priority, 2); - assert_eq!(sequence, 7); - assert_eq!(relative_deadline_ms, None); + fn a_bare_marker_carries_no_value() { + let mut enc = warmed(&["ukf_predict"]); + let (bytes, _) = encode_one(&mut enc, &marker("ukf_predict", 0, None)); + assert_eq!(decode_all(&bytes)[0].marker_value, None); } #[test] - fn round_trip_span_start_with_deadline_preserves_deadline() { - let decoded = round_trip(&make_span_start_with_deadline(), 0); - let TraceEvent::SpanStart { - relative_deadline_ms, - .. - } = decoded - else { - panic!("expected SpanStart"); - }; - assert_eq!(relative_deadline_ms, Some(0.5_f32)); + fn a_marker_value_of_zero_survives_as_zero_not_as_absent() { + // proto3 would drop a plain zero field; `marker_value` is optional so the + // presence bit distinguishes them. Regression guard for f3ccb25. + let mut enc = warmed(&["m"]); + let (bytes, _) = encode_one(&mut enc, &marker("m", 0, Some(0))); + assert_eq!(decode_all(&bytes)[0].marker_value, Some(0)); } + // ── Per-occurrence frames carry no fixed field (REQ-T06) ────────────────── + #[test] - fn round_trip_span_end_preserves_fields() { - let decoded = round_trip(&make_span_end(), 3); - let TraceEvent::SpanEnd { name, sequence, .. } = decoded else { - panic!("expected SpanEnd"); - }; - assert_eq!(name.as_str(), "gyro_isr"); - assert_eq!(sequence, 3); + fn events_carry_no_name_bytes_once_registered() { + let mut enc = warmed(&["main_task"]); + let (bytes, _) = encode_one(&mut enc, &span_start("main_task", 0)); + assert!( + !bytes.windows(9).any(|w| w == b"main_task"), + "the name must appear only in the dictionary frame" + ); } #[test] - fn round_trip_marker_preserves_fields() { - let decoded = round_trip(&make_marker(), 0); - let TraceEvent::Marker { - name, marker_value, .. - } = decoded - else { - panic!("expected Marker"); - }; - assert_eq!(name.as_str(), "ukf_predict"); - assert_eq!(marker_value, None); + fn events_carry_neither_priority_nor_deadline() { + let mut enc = warmed(&["gyro_isr"]); + let (bytes, _) = encode_one(&mut enc, &span_start_with_deadline("gyro_isr", 0)); + let frame = decode_all(&bytes).remove(0); + assert_eq!(frame.priority, 0); + assert_eq!(frame.relative_deadline_ms, None); + assert_eq!(frame.source_type, None); + } + + // ── Size budget (§18.1, AC 5) ───────────────────────────────────────────── + + /// Steady-state frame size for each event class at a representative delta. + fn steady_state_sizes(delta: u64) -> [usize; 4] { + // From a known counter: the sequence is a varint, so its magnitude is + // part of the frame size being measured. + crate::reset_sequence(); + let mut enc = warmed(&["main_task", "ukf_predict"]); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + let mut t = 1_000_000_000u64; + let cases = [ + span_start("main_task", 0), + span_end("main_task", 0), + marker("ukf_predict", 0, Some(42)), + marker("ukf_predict", 0, None), + ]; + for _ in 0..200 { + t += delta; + enc.encode(&span_end("main_task", t), &mut buf).unwrap(); + } + let mut sizes = [0usize; 4]; + for (i, case) in cases.iter().enumerate() { + t += delta; + let mut ev = case.clone(); + match &mut ev { + TraceEvent::SpanStart { timestamp_ns, .. } + | TraceEvent::SpanEnd { timestamp_ns, .. } + | TraceEvent::Marker { timestamp_ns, .. } => *timestamp_ns = t, + } + // A mid-range sequence, which is what a running device carries: the + // number is a varint, and only the 128 values below the first + // boundary — 0.8 % of the 16 384-wide space — cost a single byte. + ev.set_sequence(8_000); + sizes[i] = enc.encode(&ev, &mut buf).unwrap().len; + } + sizes + } + + #[test] + fn steady_state_frames_stay_within_the_size_budget() { + // §18.1 predicted 13 / 12 / 15 / 12 for SpanStart / SpanEnd / Marker with + // a value / bare Marker. At 1300-3800 events/s the mean spacing is + // 260-770 us and bursts are far tighter, so deltas up to 1 ms are the + // operating range; the implementation is at or under budget across it. + for delta in [1_000u64, 10_000, 100_000, 1_000_000] { + let sizes = steady_state_sizes(delta); + for (size, budget) in sizes.iter().zip([13usize, 12, 15, 12]) { + assert!( + *size <= budget, + "delta {delta} ns: frame of {size} B exceeds the {budget} B budget" + ); + } + } + } + + #[test] + fn a_delta_past_the_operating_range_costs_one_more_byte_and_no_more() { + // A 10 ms delta — an idle gap, not a traced workload — pushes the varint + // to three bytes. Recorded rather than hidden: it is where §18.1's + // per-class figures stop holding, and the tail is bounded at one byte. + let wide = steady_state_sizes(10_000_000); + let operating = steady_state_sizes(1_000_000); + for (w, o) in wide.iter().zip(operating.iter()) { + assert_eq!(*w, *o + 1); + } + } + + #[test] + fn frame_sizes_across_the_delta_range_snapshot() { + let table: Vec<(u64, [usize; 4])> = [1_000u64, 10_000, 100_000, 1_000_000, 10_000_000] + .into_iter() + .map(|d| (d, steady_state_sizes(d))) + .collect(); + assert_debug_snapshot!(table); + } + + #[test] + fn v2_more_than_halves_the_mean_event_size_against_v1() { + // v1 measured 33 / 24 / 25 / 27 B for the same four classes (§18.1), a + // mean of 27.25. The saving is in the mean, which is what the bandwidth + // budget is spent from: per class it ranges from a 1.8x cut on a bare + // SpanEnd to a 2.75x cut on a SpanStart, which no longer repeats the + // name, the priority and the deadline on every occurrence. + let sizes = steady_state_sizes(100_000); + let v2_mean = sizes.iter().sum::() as f64 / 4.0; + let v1_mean = (33.0 + 24.0 + 25.0 + 27.0) / 4.0; + assert!( + v2_mean * 2.0 < v1_mean, + "v2 mean {v2_mean} B is not less than half of v1 mean {v1_mean} B" + ); } #[test] - fn round_trip_marker_with_value_preserves_value() { - let decoded = round_trip(&make_marker_with_value(), 0); - let TraceEvent::Marker { marker_value, .. } = decoded else { - panic!("expected Marker"); + fn span_start_wire_format_snapshot() { + crate::reset_sequence(); + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + let n = enc + .encode(&span_start_with_deadline("gyro_isr", 1_000_000), &mut buf) + .unwrap() + .len; + assert_debug_snapshot!(&buf[..n]); + } + + // ── Framing ─────────────────────────────────────────────────────────────── + + #[test] + fn each_frame_declares_its_own_length() { + let mut enc = TraceEncoder::new(); + let (bytes, _) = encode_one(&mut enc, &span_start_with_deadline("gyro_isr", 1_000)); + // decode_all asserts the frames tile the buffer exactly. + assert_eq!(decode_all(&bytes).len(), 2); + } + + #[test] + fn a_buffer_too_small_for_the_event_returns_buffer_full() { + let mut enc = warmed(&["a"]); + let mut buf = [0u8; 2]; + assert_eq!( + enc.encode(&span_end("a", 0), &mut buf), + Err(TracingEncodeError::BufferFull) + ); + } + + #[test] + fn a_buffer_holding_only_the_dictionary_frame_returns_buffer_full() { + let mut enc = TraceEncoder::new(); + let mut probe = [0u8; MAX_TRACE_BURST_SIZE]; + let dictionary_len = { + let mut e = TraceEncoder::new(); + let n = e + .encode(&span_start("main_task", 0), &mut probe) + .unwrap() + .len; + n - 1 // everything but the trailing event frame }; - assert_eq!(marker_value, Some(42_u32)); + let mut buf = vec![0u8; dictionary_len]; + assert_eq!( + enc.encode(&span_start("main_task", 0), &mut buf), + Err(TracingEncodeError::BufferFull) + ); } + #[test] + fn a_maximum_length_name_still_fits_one_frame() { + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + let longest = "x".repeat(32); + let outcome = enc + .encode(&span_start(&longest, u64::MAX / 2), &mut buf) + .unwrap(); + let frames = decode_all(&buf[..outcome.len]); + assert_eq!(frames[0].name.as_str(), longest); + assert!(outcome.len <= MAX_TRACE_BURST_SIZE); + } + + // ── Decoding failures ───────────────────────────────────────────────────── + #[test] fn decode_truncated_frame_returns_error() { - let (buf, n) = encode(&make_span_start(), 0); + let mut enc = warmed(&["a"]); + let (bytes, _) = encode_one(&mut enc, &span_end("a", 0)); assert_eq!( - decode_trace_frame(&buf[..n - 1]), + decode_trace_frame(&bytes[..bytes.len() - 1]), Err(TracingDecodeError::Truncated) ); } @@ -604,15 +1481,8 @@ mod tests { #[test] fn decode_varint_overflow_returns_malformed_varint() { - // 10 bytes each with the continuation bit set — shift reaches 70, exceeding - // the 64-bit limit and hitting the `shift >= 64` guard in decode_varint. let overlong: Vec = (0..10).map(|_| 0xFF).collect(); - assert_eq!( - decode_varint(&overlong), - None, - "varint with shift >= 64 must return None" - ); - // Confirm this surfaces as MalformedVarint when used through the public API. + assert_eq!(decode_varint(&overlong), None); let frame: Vec = overlong.into_iter().chain(std::iter::once(0x00)).collect(); assert_eq!( decode_trace_frame(&frame), @@ -621,9 +1491,92 @@ mod tests { } #[test] - fn decode_returns_correct_consumed_byte_count() { - let (buf, n) = encode(&make_marker_with_value(), 5); - let (_, consumed) = decode_trace_frame(&buf[..n]).unwrap(); - assert_eq!(consumed, n); + fn decode_rejects_an_unknown_event_type() { + // event_type is field 3, varint: tag 0x18, value 9 — past TRACE_START. + let payload = [0x18u8, 0x09]; + let frame = [&[payload.len() as u8][..], &payload[..]].concat(); + assert_eq!( + decode_trace_frame(&frame), + Err(TracingDecodeError::DecodeError) + ); + } + + #[test] + fn decode_returns_the_consumed_byte_count() { + let mut enc = warmed(&["a"]); + let (bytes, _) = encode_one(&mut enc, &marker("a", 0, Some(5))); + let (_, consumed) = decode_trace_frame(&bytes).unwrap(); + assert_eq!(consumed, bytes.len()); + } + + // ── A whole stream ──────────────────────────────────────────────────────── + + #[test] + fn a_full_stream_round_trips_through_a_host_style_decoder() { + let mut enc = TraceEncoder::new(); + let mut buf = [0u8; MAX_TRACE_BURST_SIZE]; + let mut wire = Vec::new(); + + let n = enc.encode_trace_start(1_000, 0x1F, &mut buf).unwrap(); + wire.extend_from_slice(&buf[..n]); + + let events = [ + span_start_with_deadline("gyro_isr", 1_100), + marker("ukf_predict", 1_150, Some(7)), + span_end("gyro_isr", 1_400), + span_start_with_deadline("gyro_isr", 2_100), + span_end("gyro_isr", 2_380), + ]; + for ev in &events { + let outcome = enc.encode(ev, &mut buf).unwrap(); + wire.extend_from_slice(&buf[..outcome.len]); + } + + // Host side: resolve ids through the dictionary, accumulate the deltas. + let mut dictionary: std::collections::HashMap = + std::collections::HashMap::new(); + let mut clock = 0i64; + let mut seen_sequences: Vec = Vec::new(); + let mut resolved: Vec<(std::string::String, i64, FrameKind)> = Vec::new(); + + for frame in decode_all(&wire) { + seen_sequences.push(frame.sequence); + clock = match frame.kind { + FrameKind::NameRegistered | FrameKind::TraceStart => frame.timestamp_ticks, + _ => clock + frame.timestamp_ticks, + }; + match frame.kind { + FrameKind::NameRegistered => { + dictionary.insert(frame.name_id, frame.name.as_str().into()); + } + FrameKind::TraceStart => assert_eq!(frame.source_mask, 0x1F), + kind => resolved.push((dictionary[&frame.name_id].clone(), clock, kind)), + } + } + + assert_eq!( + resolved, + vec![ + ("gyro_isr".into(), 1_100, FrameKind::SpanStart), + ("ukf_predict".into(), 1_150, FrameKind::Marker), + ("gyro_isr".into(), 1_400, FrameKind::SpanEnd), + ("gyro_isr".into(), 2_100, FrameKind::SpanStart), + ("gyro_isr".into(), 2_380, FrameKind::SpanEnd), + ] + ); + assert_eq!(dictionary.len(), 2, "each name registered exactly once"); + + // Every number in the range is present exactly once — a clean stream has + // no gaps. They are *not* in order on the wire: a dictionary frame is + // written ahead of the event that triggered it but numbered after it, + // because the event was numbered by its producer (§5.7, §19.12). + let mut sorted = seen_sequences.clone(); + sorted.sort_unstable(); + let expected: Vec = (0..u32::try_from(seen_sequences.len()).unwrap()).collect(); + assert_eq!(sorted, expected, "no gaps in a clean stream"); + assert_ne!( + seen_sequences, expected, + "and the wire is not in sequence order" + ); } } diff --git a/src/lib.rs b/src/lib.rs index 7395fd2..ec54f10 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -8,6 +8,91 @@ #[cfg(feature = "enabled")] pub mod encode; + +/// The producer-side sequence counter. +/// +/// Numbering at record time rather than in the transport is what makes loss at +/// the producer queue visible: a frame dropped there has already burned a +/// number, so the host sees a gap instead of a contiguous stream with events +/// simply missing (§2.6). +#[cfg(feature = "enabled")] +mod sequence { + /// Folds a freely running counter into the wire's sequence range. + /// + /// Applied on read rather than by keeping the stored counter in range: + /// `fetch_add` cannot wrap at a non-power-of-two bound atomically, and 2³² is + /// an exact multiple of 16 384, so taking the modulus of a wrapping `u32` + /// yields the same sequence either way. + fn wrap(raw: u32) -> u32 { + raw % crate::encode::SEQUENCE_MODULUS + } + + /// Takes the next sequence number. + /// + /// One `fetch_add` — on Cortex-M4 an `LDREX`/`STREX` pair, so no critical + /// section and nothing for a preempting ISR to block on. The counter is + /// process-global because every producer and the transport itself must draw + /// from one space for a gap to mean anything. + #[cfg(not(test))] + pub fn next_sequence() -> u32 { + use core::sync::atomic::{AtomicU32, Ordering}; + static SEQUENCE: AtomicU32 = AtomicU32::new(0); + wrap(SEQUENCE.fetch_add(1, Ordering::Relaxed)) + } + + // Under test the counter is per-thread. The harness runs each test on its own + // thread, so a shared global would make every test that asserts an absolute + // number depend on whichever others happened to run first. The production + // path above is the one §5.7 specifies; `wrap`, which is where the only + // arithmetic lives, is shared by both and tested directly. + #[cfg(test)] + std::thread_local! { + static SEQUENCE: core::cell::Cell = const { core::cell::Cell::new(0) }; + } + + #[cfg(test)] + pub fn next_sequence() -> u32 { + SEQUENCE.with(|c| { + let taken = c.get(); + c.set(taken.wrapping_add(1)); + wrap(taken) + }) + } + + /// Restarts this thread's counter. Tests only. + #[cfg(test)] + pub fn reset_sequence() { + SEQUENCE.with(|c| c.set(0)); + } + + #[cfg(test)] + mod tests { + use super::wrap; + use crate::encode::SEQUENCE_MODULUS; + + #[test] + fn wrap_folds_into_the_sequence_range() { + assert_eq!(wrap(0), 0); + assert_eq!(wrap(SEQUENCE_MODULUS - 1), SEQUENCE_MODULUS - 1); + assert_eq!(wrap(SEQUENCE_MODULUS), 0, "wraps to zero, not to 16384"); + assert_eq!(wrap(SEQUENCE_MODULUS + 1), 1); + } + + #[test] + fn wrap_is_continuous_across_the_u32_boundary() { + // 2^32 is an exact multiple of the modulus, so a counter rolling over + // u32::MAX stays continuous in sequence space — which is what lets the + // stored counter run free instead of being masked on every increment. + assert_eq!(wrap(u32::MAX), SEQUENCE_MODULUS - 1); + assert_eq!(wrap(u32::MAX.wrapping_add(1)), 0); + } + } +} + +#[cfg(feature = "enabled")] +pub use sequence::next_sequence; +#[cfg(all(test, feature = "enabled"))] +pub(crate) use sequence::reset_sequence; mod sink; mod types; @@ -38,7 +123,7 @@ mod proto { } #[cfg(feature = "enabled")] -pub use encode::SequenceEncoder; +pub use encode::{FrameKind, RawTraceFrame, TimeBase, TraceEncoder}; #[cfg(feature = "enabled")] pub use sink::TraceTransport; pub use sink::{NoopSink, TraceSink, TracingError}; diff --git a/src/sink.rs b/src/sink.rs index d93d541..e937610 100644 --- a/src/sink.rs +++ b/src/sink.rs @@ -52,21 +52,56 @@ pub trait TraceTransport { /// `TraceSink` operates in two layers: /// /// 1. **Recording layer** — `record_span_start`, `record_span_end`, and `record_marker` -/// read the hardware clock via `get_elapsed_nanoseconds`, construct [`TraceEvent`]s -/// (sequence left at zero), and hand them to [`TraceTransport::write_event`]. -/// 2. **Transport layer** — code that owns the wire (e.g. [`crate::SequenceEncoder`]) injects a -/// monotonic sequence counter before writing bytes to RTT, UART, etc. The sequence -/// allows the host decoder to detect dropped frames. +/// read the hardware clock via `now_ticks`, construct [`TraceEvent`]s, stamp each +/// with [`next_sequence`](crate::next_sequence), and hand them to +/// [`TraceTransport::write_event`]. Numbering happens here rather than at the wire +/// so that an event dropped on the way to the transport still leaves a gap the host +/// can see. +/// 2. **Transport layer** — code that owns the wire (e.g. [`TraceEncoder`](crate::TraceEncoder)) +/// turns each event into frames and writes the bytes to RTT, UART, etc., carrying the +/// sequence through unchanged. /// /// For tests or placeholders, use [`NoopSink`], which discards all events at zero cost. #[cfg(feature = "enabled")] pub trait TraceSink: TraceTransport { - /// Returns the current monotonic time in nanoseconds. + /// Returns the current time as a tick count. + /// + /// The unit is whatever the encoder for this stream declares on its header + /// — nanoseconds by default, or raw core cycles for a sink using + /// [`TraceEncoder::with_cycle_counter`]. A cycle source may be a + /// free-running 32-bit counter returned widened: the encoder extends it, so + /// that this can be a single volatile load with no critical section and no + /// division on the path an ISR takes. /// /// This method has no default — every `TraceSink` implementor must wire up a real clock /// source. Returning a constant `0` is valid for stubs, but must be done explicitly to /// avoid silent zero timestamps in production code. - fn get_elapsed_nanoseconds(&self) -> u64; + /// + /// [`TraceEncoder::with_cycle_counter`]: crate::TraceEncoder::with_cycle_counter + fn now_ticks(&self) -> u64; + + /// How many ticks make a microsecond in this sink's timebase. + /// + /// Defaults to a nanosecond tick. A sink returning core cycles reports its + /// core clock in MHz — 72 on this target. Used to turn a measured interval + /// into the microseconds a marker payload carries. + fn ticks_per_us(&self) -> u32 { + 1_000 + } + + /// The significant bits of [`now_ticks`](TraceSink::now_ticks). + /// + /// Defaults to the full 64 bits. A sink returning a free-running 32-bit + /// counter reports `u32::MAX`, so that an interval measured across the + /// counter's wrap still comes out right. + fn tick_mask(&self) -> u64 { + u64::MAX + } + + /// Ticks elapsed from `started` to now, correct across a counter wrap. + fn ticks_since(&self, started: u64) -> u64 { + self.now_ticks().wrapping_sub(started) & self.tick_mask() + } /// Records the start of a named execution span. /// @@ -93,14 +128,20 @@ pub trait TraceSink: TraceTransport { let mut name: String<32> = String::new(); name.push_str(source_name) .map_err(|_| TracingError::MessageDropped)?; - self.write_event(TraceEvent::SpanStart { - timestamp_ns: self.get_elapsed_nanoseconds(), + let mut event = TraceEvent::SpanStart { + timestamp_ns: self.now_ticks(), name, source_type, sequence: 0, priority: u32::from(priority), relative_deadline_ms, - }) + }; + // Numbered here, not in the transport, so that an event lost at the + // producer queue still leaves a host-visible gap (§5.7). Taken as late + // as possible: everything between this and the enqueue is a window in + // which a preempting ISR can take a later number and arrive first. + event.set_sequence(crate::next_sequence()); + self.write_event(event) } /// Records the end of a named execution span previously started with [`record_span_start`]. @@ -117,11 +158,13 @@ pub trait TraceSink: TraceTransport { let mut name: String<32> = String::new(); name.push_str(source_name) .map_err(|_| TracingError::MessageDropped)?; - self.write_event(TraceEvent::SpanEnd { - timestamp_ns: self.get_elapsed_nanoseconds(), + let mut event = TraceEvent::SpanEnd { + timestamp_ns: self.now_ticks(), name, sequence: 0, - }) + }; + event.set_sequence(crate::next_sequence()); + self.write_event(event) } /// Records a point-in-time annotation. No matching `record_span_end` is needed. @@ -143,12 +186,14 @@ pub trait TraceSink: TraceTransport { let mut name: String<32> = String::new(); name.push_str(label) .map_err(|_| TracingError::MessageDropped)?; - self.write_event(TraceEvent::Marker { - timestamp_ns: self.get_elapsed_nanoseconds(), + let mut event = TraceEvent::Marker { + timestamp_ns: self.now_ticks(), name, sequence: 0, marker_value: value, - }) + }; + event.set_sequence(crate::next_sequence()); + self.write_event(event) } } @@ -203,7 +248,7 @@ impl TraceTransport for NoopSink { #[cfg(feature = "enabled")] impl TraceSink for NoopSink { - fn get_elapsed_nanoseconds(&self) -> u64 { + fn now_ticks(&self) -> u64 { 0 } } @@ -211,7 +256,10 @@ impl TraceSink for NoopSink { #[cfg(not(feature = "enabled"))] impl TraceSink for NoopSink {} +// `unwrap` and `panic!` are how a test asserts. The crate denies both because a +// firmware panic is a hard fault, which is not a risk a test harness runs. #[cfg(all(test, feature = "std", feature = "enabled"))] +#[allow(clippy::unwrap_used, clippy::panic)] mod tests { use super::*; @@ -244,7 +292,7 @@ mod tests { } impl TraceSink for CaptureSink { - fn get_elapsed_nanoseconds(&self) -> u64 { + fn now_ticks(&self) -> u64 { self.timestamp_ns } } @@ -258,7 +306,7 @@ mod tests { } impl TraceSink for ErrorSink { - fn get_elapsed_nanoseconds(&self) -> u64 { + fn now_ticks(&self) -> u64 { 0 } } diff --git a/src/snapshots/execution_trace__encode__tests__frame_sizes_across_the_delta_range_snapshot.snap b/src/snapshots/execution_trace__encode__tests__frame_sizes_across_the_delta_range_snapshot.snap new file mode 100644 index 0000000..2488342 --- /dev/null +++ b/src/snapshots/execution_trace__encode__tests__frame_sizes_across_the_delta_range_snapshot.snap @@ -0,0 +1,51 @@ +--- +source: src/encode.rs +expression: table +--- +[ + ( + 1000, + [ + 11, + 11, + 13, + 11, + ], + ), + ( + 10000, + [ + 12, + 12, + 14, + 12, + ], + ), + ( + 100000, + [ + 12, + 12, + 14, + 12, + ], + ), + ( + 1000000, + [ + 12, + 12, + 14, + 12, + ], + ), + ( + 10000000, + [ + 13, + 13, + 15, + 13, + ], + ), +] diff --git a/src/snapshots/execution_trace__encode__tests__span_start_wire_format_snapshot.snap b/src/snapshots/execution_trace__encode__tests__span_start_wire_format_snapshot.snap index df5d8bc..e66a962 100644 --- a/src/snapshots/execution_trace__encode__tests__span_start_wire_format_snapshot.snap +++ b/src/snapshots/execution_trace__encode__tests__span_start_wire_format_snapshot.snap @@ -1,34 +1,41 @@ --- -source: execution-trace/src/encode.rs +source: src/encode.rs expression: "&buf[..n]" --- [ - 27, + 29, 8, - 192, - 132, - 61, - 18, - 8, - 108, - 101, - 100, - 95, - 116, - 97, - 115, - 107, + 128, + 137, + 122, + 16, + 1, 24, - 2, + 4, 32, 1, - 40, + 50, + 8, + 103, + 121, + 114, + 111, + 95, + 105, + 115, + 114, + 56, 1, - 48, - 2, - 61, + 64, + 8, + 77, 0, 0, 0, 63, + 4, + 16, + 1, + 24, + 1, ] diff --git a/src/types.rs b/src/types.rs index b9f96dc..16507f6 100644 --- a/src/types.rs +++ b/src/types.rs @@ -42,3 +42,35 @@ pub enum TraceEvent { marker_value: Option, }, } + +#[cfg(feature = "enabled")] +impl TraceEvent { + /// The sequence number assigned when this event was recorded. + /// + /// Zero until [`set_sequence`] is called; the transport forwards whatever is + /// here rather than numbering the event itself, so that a frame lost between + /// the recording layer and the wire still leaves a gap. + /// + /// [`set_sequence`]: TraceEvent::set_sequence + #[must_use] + pub fn sequence(&self) -> u32 { + match self { + TraceEvent::SpanStart { sequence, .. } + | TraceEvent::SpanEnd { sequence, .. } + | TraceEvent::Marker { sequence, .. } => *sequence, + } + } + + /// Stamps this event with its record-time sequence number. + /// + /// Called by the recording layer immediately before handing the event to the + /// transport, so that the window in which a preempting ISR can take a later + /// number and reach the queue first is as narrow as possible. + pub fn set_sequence(&mut self, value: u32) { + match self { + TraceEvent::SpanStart { sequence, .. } + | TraceEvent::SpanEnd { sequence, .. } + | TraceEvent::Marker { sequence, .. } => *sequence = value, + } + } +}