Skip to main content

moqtap_proxy/
instrument.rs

1//! Slow-path counters, so `Interest::NONE` is a falsifiable claim.
2//!
3//! The framed path is byte-identical to the byte pump, which
4//! means no assertion on forwarded bytes can distinguish `Interest::NONE`
5//! from `Interest::OBJECTS`. These counters can: they are incremented only
6//! *inside* code the fast path never reaches, so they are free on the fast
7//! path, need no feature gate, and the binary under test is the binary that
8//! ships.
9//!
10//! **Counters are scoped to a session, not to the process.** Making them
11//! process-wide with no reset is not merely flaky —
12//! `tests/actions_objects.rs::a_matching_rule_on_a_draft19_fetch_stream_reports_a_bypass`
13//! asserts `objects_elided == 0` while sharing a binary with five tests
14//! whose whole purpose is to elide, and `cargo test` runs a binary's test
15//! functions on a thread pool. That assertion is near-certain to fail, and
16//! a counter suite that goes red for scheduling reasons gets weakened or
17//! `#[ignore]`d within a week — at which point the `Interest::NONE` proof
18//! is back to being an assertion.
19//!
20//! There is deliberately **no process-global `snapshot()`**. Counters are
21//! read through `ProxySession::counters()`, which returns the [`Counters`]
22//! of one session's [`Recorder`]. (Named in plain text rather than as an
23//! intra-doc link, so this module's documentation builds under
24//! `RUSTDOCFLAGS="-D warnings"` whether or not that method is in scope
25//! here.)
26//!
27//! The one thing that does stay process-global is the release thread's
28//! existence and backend ([`release_timer_started`],
29//! [`release_timer_backend`]) — a process-wide *resource*, not a counter,
30//! whose value is monotonic (`false → true`, `None → Some`).
31
32use std::sync::atomic::{AtomicBool, AtomicU32, AtomicU64, AtomicU8, Ordering};
33use std::time::Duration;
34
35// ── the snapshot types ─────────────────────────────────────────────────
36
37/// A snapshot of one session's slow-path counters.
38#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)]
39#[non_exhaustive]
40pub struct Counters {
41    /// `ObjectFramer` instances created.
42    pub framers_created: u64,
43    /// `ObjectFramer::poll_header` calls.
44    pub framer_header_polls: u64,
45    /// `ObjectFramer::poll_object` calls.
46    pub framer_object_polls: u64,
47    /// `ControlStreamParser` constructions.
48    pub control_parsers_created: u64,
49    /// `AnyDatagramHeader::decode` call sites entered.
50    pub datagram_headers_decoded: u64,
51    /// Units pushed onto a per-stream pending queue.
52    pub egress_items_queued: u64,
53    /// Objects removed by `DropMode::Elide`.
54    pub objects_elided: u64,
55    /// Elide fix-ups written: one leading Object ID varint on a subgroup
56    /// stream, one re-encoded framing on a fetch stream. Counted only where
57    /// the bytes actually moved — a survivor that already said the right
58    /// thing is forwarded untouched and counted nowhere.
59    pub object_ids_rewritten: u64,
60    /// Units deferred by [`Action::Delay`](crate::action::Action::Delay),
61    /// counted once each at the decision.
62    ///
63    /// **Units, not objects**, and the name is the whole statement of the
64    /// difference: a delay is honoured at the control site as well as the
65    /// object site, so a deferred SUBSCRIBE is one of these. The field below
66    /// is named for objects because a truncation is refused on a control
67    /// stream and can only ever land on one.
68    ///
69    /// Counted where the decision was taken rather than where the unit came
70    /// back out, so one still sitting in a queue when the session ends is
71    /// already here. [`Self::release_errors`] is the other half — what was
72    /// released, and how late.
73    ///
74    /// Not [`Self::egress_items_queued`], which counts every push, stream
75    /// headers and elided ordering slots included; that figure is larger
76    /// than this one on any session that forwards at all.
77    pub units_delayed: u64,
78    /// Objects cut short by
79    /// [`Action::Truncate`](crate::action::Action::Truncate), counted once
80    /// each.
81    ///
82    /// Applied truncations only. An attempt refused for an out-of-range
83    /// error code, or made at a site that carries no truncation, moves
84    /// [`Self::actions_refused`] and never this.
85    pub objects_truncated: u64,
86    /// Actions refused, counted per attempt.
87    pub actions_refused: u64,
88    /// Streams the framer stopped parsing.
89    pub streams_not_shapeable: u64,
90    /// Objects streamed through without being addressable. The running
91    /// total behind `ImpairmentKind::ObjectNotAddressable`, which is
92    /// emitted only once per stream.
93    pub objects_not_addressable: u64,
94    /// Control frames the decoder refused, which the proxy forwarded
95    /// without being able to read. The running total behind
96    /// `ImpairmentKind::ControlFrameNotDecodable`, which is emitted only
97    /// once per control stream direction.
98    ///
99    /// Zero on a session with no observer and no control interest, which
100    /// builds no parser and reads no frame — the same byte-pump case
101    /// `control_parsers_created` reports.
102    pub control_frames_not_decodable: u64,
103    /// Accumulated `actual_release - release_at`, in nanoseconds.
104    /// The raw sum, kept for callers that want it;
105    /// [`Self::release_errors`] is the useful form.
106    pub release_error_ns: u64,
107    /// Distribution of the above: p50, p95 and max lateness.
108    pub release_errors: ReleaseErrors,
109}
110
111/// Observed lateness of deferred releases, in one session.
112///
113/// Measured **end to end** — from the unit's `release_at` to the instant
114/// its bytes were handed to the destination stream — so it includes the
115/// wheel, the runtime wake and the engine, which is what a scenario
116/// actually cares about. A sample taken inside the release thread would
117/// have reported 0.55 ms while the object went out at 0.9 ms.
118///
119/// Values are bucketed with two significant bits per octave, so each
120/// quantile is the upper bound of its bucket and is accurate to within
121/// 25%; `max_ns` is exact.
122#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)]
123#[non_exhaustive]
124pub struct ReleaseErrors {
125    /// Deferred units released. Units written inline (never queued) and
126    /// units flushed by a drain that ignores release times are excluded,
127    /// so this is the number of units that actually waited.
128    pub count: u64,
129    /// Median lateness, nanoseconds (bucket upper bound).
130    pub p50_ns: u64,
131    /// 95th-percentile lateness, nanoseconds (bucket upper bound).
132    pub p95_ns: u64,
133    /// Worst lateness, nanoseconds. Exact.
134    pub max_ns: u64,
135}
136
137// ── the histogram ──────────────────────────────────────────────────────
138
139/// Histogram slots. `[AtomicU32; 128]` is 512 bytes per session.
140const HIST_BUCKETS: usize = 128;
141
142/// Which bucket `ns` falls in: two significant bits per octave.
143///
144/// Buckets 0-3 are the exact values 0-3; from there each octave is split
145/// into four, so a bucket is at most 25% wider than its lower bound.
146/// Bucket 127 covers everything from 2^32 ns (4.29 s) upward — lateness
147/// past that saturates, and [`ReleaseErrors::max_ns`] stays exact.
148const fn bucket_of(ns: u64) -> usize {
149    if ns < 4 {
150        return ns as usize;
151    }
152    // `ns >= 4`, so `leading_zeros() <= 61` and `oct >= 2`.
153    let oct = (63 - ns.leading_zeros()) as usize;
154    let sub = ((ns >> (oct - 2)) & 0b11) as usize;
155    let idx = (oct - 1) * 4 + sub;
156    if idx >= HIST_BUCKETS {
157        HIST_BUCKETS - 1
158    } else {
159        idx
160    }
161}
162
163/// The largest lateness that lands in bucket `idx`, in nanoseconds.
164///
165/// Reported as the quantile value, which is why quantiles are upper
166/// bounds rather than estimates: a reported `p95_ns` is a number the run
167/// provably did not exceed 95% of the time.
168const fn bucket_upper_ns(idx: usize) -> u64 {
169    if idx < 4 {
170        return idx as u64;
171    }
172    let oct = idx / 4 + 1;
173    let sub = (idx % 4) as u64;
174    // lower = (4 + sub) << (oct - 2), width = 1 << (oct - 2).
175    ((5 + sub) << (oct - 2)) - 1
176}
177
178/// The upper bound of the first bucket whose cumulative count reaches
179/// `pct`% of `total`. `0` when nothing was sampled.
180fn quantile(hist: &[u64; HIST_BUCKETS], total: u64, pct: u64) -> u64 {
181    if total == 0 {
182        return 0;
183    }
184    let target = total.saturating_mul(pct).div_ceil(100).max(1);
185    let mut cum: u64 = 0;
186    for (idx, &count) in hist.iter().enumerate() {
187        cum = cum.saturating_add(count);
188        if cum >= target {
189            return bucket_upper_ns(idx);
190        }
191    }
192    bucket_upper_ns(HIST_BUCKETS - 1)
193}
194
195// ── the recorder ───────────────────────────────────────────────────────
196
197/// Session-scoped counter storage.
198///
199/// One per `ProxySession`, shared by that session's forwarding tasks
200/// through `Arc` (`ForwardCtx` is `#[derive(Clone)]` and cloned per task,
201/// `session.rs:191-229`), so concurrently running sessions in one test
202/// binary cannot see each other's increments. That is what makes
203/// `objects_elided == 0` assertable at all.
204///
205/// Storage is atomics plus a `[AtomicU32; 128]` histogram — 512 bytes per
206/// session. A release sample costs four relaxed atomic operations (sum,
207/// count, max, one bucket) on a path that already did a `write_all`;
208/// every other counter costs one.
209pub struct Recorder {
210    framers_created: AtomicU64,
211    framer_header_polls: AtomicU64,
212    framer_object_polls: AtomicU64,
213    control_parsers_created: AtomicU64,
214    datagram_headers_decoded: AtomicU64,
215    egress_items_queued: AtomicU64,
216    objects_elided: AtomicU64,
217    object_ids_rewritten: AtomicU64,
218    units_delayed: AtomicU64,
219    objects_truncated: AtomicU64,
220    actions_refused: AtomicU64,
221    streams_not_shapeable: AtomicU64,
222    objects_not_addressable: AtomicU64,
223    control_frames_not_decodable: AtomicU64,
224    release_error_ns: AtomicU64,
225    release_count: AtomicU64,
226    release_max_ns: AtomicU64,
227    release_hist: [AtomicU32; HIST_BUCKETS],
228    coarse_timer_reported: AtomicBool,
229}
230
231impl Default for Recorder {
232    fn default() -> Self {
233        Self {
234            framers_created: AtomicU64::new(0),
235            framer_header_polls: AtomicU64::new(0),
236            framer_object_polls: AtomicU64::new(0),
237            control_parsers_created: AtomicU64::new(0),
238            datagram_headers_decoded: AtomicU64::new(0),
239            egress_items_queued: AtomicU64::new(0),
240            objects_elided: AtomicU64::new(0),
241            object_ids_rewritten: AtomicU64::new(0),
242            units_delayed: AtomicU64::new(0),
243            objects_truncated: AtomicU64::new(0),
244            actions_refused: AtomicU64::new(0),
245            streams_not_shapeable: AtomicU64::new(0),
246            objects_not_addressable: AtomicU64::new(0),
247            control_frames_not_decodable: AtomicU64::new(0),
248            release_error_ns: AtomicU64::new(0),
249            release_count: AtomicU64::new(0),
250            release_max_ns: AtomicU64::new(0),
251            release_hist: std::array::from_fn(|_| AtomicU32::new(0)),
252            coarse_timer_reported: AtomicBool::new(false),
253        }
254    }
255}
256
257impl std::fmt::Debug for Recorder {
258    /// Prints the snapshot, not 128 histogram slots.
259    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
260        f.debug_tuple("Recorder").field(&self.snapshot()).finish()
261    }
262}
263
264/// One relaxed `+= 1` on a `u64` counter.
265macro_rules! bump {
266    ($doc:expr, $name:ident, $field:ident) => {
267        #[doc = $doc]
268        pub(crate) fn $name(&self) {
269            self.$field.fetch_add(1, Ordering::Relaxed);
270        }
271    };
272}
273
274impl Recorder {
275    /// A recorder with every counter at zero.
276    pub fn new() -> Self {
277        Self::default()
278    }
279
280    /// Snapshot every counter for this session.
281    pub fn snapshot(&self) -> Counters {
282        let mut hist = [0u64; HIST_BUCKETS];
283        let mut hist_total: u64 = 0;
284        for (slot, out) in self.release_hist.iter().zip(hist.iter_mut()) {
285            *out = u64::from(slot.load(Ordering::Relaxed));
286            hist_total = hist_total.saturating_add(*out);
287        }
288        Counters {
289            framers_created: self.framers_created.load(Ordering::Relaxed),
290            framer_header_polls: self.framer_header_polls.load(Ordering::Relaxed),
291            framer_object_polls: self.framer_object_polls.load(Ordering::Relaxed),
292            control_parsers_created: self.control_parsers_created.load(Ordering::Relaxed),
293            datagram_headers_decoded: self.datagram_headers_decoded.load(Ordering::Relaxed),
294            egress_items_queued: self.egress_items_queued.load(Ordering::Relaxed),
295            objects_elided: self.objects_elided.load(Ordering::Relaxed),
296            object_ids_rewritten: self.object_ids_rewritten.load(Ordering::Relaxed),
297            units_delayed: self.units_delayed.load(Ordering::Relaxed),
298            objects_truncated: self.objects_truncated.load(Ordering::Relaxed),
299            actions_refused: self.actions_refused.load(Ordering::Relaxed),
300            streams_not_shapeable: self.streams_not_shapeable.load(Ordering::Relaxed),
301            objects_not_addressable: self.objects_not_addressable.load(Ordering::Relaxed),
302            control_frames_not_decodable: self.control_frames_not_decodable.load(Ordering::Relaxed),
303            release_error_ns: self.release_error_ns.load(Ordering::Relaxed),
304            release_errors: ReleaseErrors {
305                count: self.release_count.load(Ordering::Relaxed),
306                p50_ns: quantile(&hist, hist_total, 50),
307                p95_ns: quantile(&hist, hist_total, 95),
308                max_ns: self.release_max_ns.load(Ordering::Relaxed),
309            },
310        }
311    }
312
313    /// Record one deferred release's lateness.
314    ///
315    /// Call sites: the release arm of the egress `select!`, once per unit
316    /// `pop_due` yields, with `now.saturating_duration_since(release_at)`.
317    /// Units written inline and units flushed by a drain that ignores
318    /// release times are **not** samples — recording them would dilute
319    /// the distribution with zeros and report teardown as a timing
320    /// failure.
321    pub(crate) fn record_release(&self, late: Duration) {
322        let ns = u64::try_from(late.as_nanos()).unwrap_or(u64::MAX);
323        self.release_error_ns.fetch_add(ns, Ordering::Relaxed);
324        self.release_count.fetch_add(1, Ordering::Relaxed);
325        self.release_max_ns.fetch_max(ns, Ordering::Relaxed);
326        self.release_hist[bucket_of(ns)].fetch_add(1, Ordering::Relaxed);
327    }
328
329    /// `true` the first time it is called, `false` after — a `swap(true)`
330    /// on an `AtomicBool`, so "once per session" holds across the
331    /// session's five concurrent forwarding tasks without a lock.
332    pub(crate) fn claim_coarse_timer_report(&self) -> bool {
333        !self.coarse_timer_reported.swap(true, Ordering::Relaxed)
334    }
335
336    bump!(
337        "One `ObjectFramer` was constructed. `framer.rs`, both constructors.",
338        note_framer_created,
339        framers_created
340    );
341    bump!("`ObjectFramer::poll_header` was entered.", note_framer_header_poll, framer_header_polls);
342    bump!("`ObjectFramer::poll_object` was entered.", note_framer_object_poll, framer_object_polls);
343    bump!(
344        "A `ControlStreamParser` was constructed. `session.rs`, behind `control_parse`.",
345        note_control_parser_created,
346        control_parsers_created
347    );
348    bump!(
349        "An `AnyDatagramHeader::decode` call site was entered.",
350        note_datagram_header_decoded,
351        datagram_headers_decoded
352    );
353    bump!(
354        "One unit was pushed onto a per-stream pending queue. `egress.rs`.",
355        note_egress_item_queued,
356        egress_items_queued
357    );
358    bump!("One object was removed by `DropMode::Elide`.", note_object_elided, objects_elided);
359    bump!(
360        "One elide fix-up was written: a leading Object ID varint on a          subgroup stream, a re-encoded framing on a fetch stream.",
361        note_object_id_rewritten,
362        object_ids_rewritten
363    );
364    bump!(
365        "One unit was deferred by `Action::Delay`. Counted at the decision, \
366         so a unit still queued when the session ends is already in it.",
367        note_unit_delayed,
368        units_delayed
369    );
370    bump!(
371        "One object was cut short by `Action::Truncate`. Applied \
372         truncations only — a refused attempt is `actions_refused`.",
373        note_object_truncated,
374        objects_truncated
375    );
376    bump!(
377        "One action attempt was refused. Counted per attempt, not per stream.",
378        note_action_refused,
379        actions_refused
380    );
381    bump!(
382        "The framer stopped parsing one stream — one latched bypass.",
383        note_stream_not_shapeable,
384        streams_not_shapeable
385    );
386    bump!(
387        "One object was streamed through without being addressable. The \
388         running total behind `ImpairmentKind::ObjectNotAddressable`, which \
389         is emitted once per stream — so this counter and that event count \
390         different things on purpose.",
391        note_object_not_addressable,
392        objects_not_addressable
393    );
394
395    /// `n` control frames were stepped over because the decoder refused
396    /// them. `session.rs`, after any feed that raised the parser's running
397    /// count.
398    ///
399    /// Takes a count where every neighbour takes none. `ControlStreamParser`
400    /// reports a cumulative figure rather than an edge, and one feed can
401    /// refuse several frames, so the caller passes the difference: three
402    /// refusals in one chunk are three here and one
403    /// `ImpairmentKind::ControlFrameNotDecodable`. A `+= 1` per call would
404    /// have made the counter agree with the event and disagree with the
405    /// traffic, which is the wrong one of the two to match.
406    pub(crate) fn note_control_frames_not_decodable(&self, n: u64) {
407        self.control_frames_not_decodable.fetch_add(n, Ordering::Relaxed);
408    }
409}
410
411// ── the release thread, which is process-wide on purpose ───────────────
412
413/// Which primitive the process-wide release thread waits on.
414///
415/// Descriptive, not a knob: the wheel picks the best available backend and
416/// records what it got. `MOQTAP_RELEASE_TIMER` overrides it only to
417/// diagnose a host.
418#[derive(Debug, Clone, Copy, PartialEq, Eq)]
419#[non_exhaustive]
420pub enum TimerBackend {
421    /// One dedicated OS thread sleeping in `SLICE`-bounded
422    /// `std::thread::sleep` steps and parking on an untimed `Condvar`
423    /// when no deadline is armed. The backend on **every** platform, and
424    /// sub-millisecond on all of them: measured p50 lateness
425    /// 0.11-0.17 ms, p95 0.52-0.57 ms on Windows 11.
426    SleepSlice,
427    /// `std::sync::Condvar::wait_timeout`, reachable only by setting
428    /// `MOQTAP_RELEASE_TIMER=condvar`. Precise on Unix, where it is
429    /// backed by a `CLOCK_MONOTONIC` hrtimer; on Windows it is bounded
430    /// below by the ~15.6 ms system tick (measured p50 lateness
431    /// 12.26 ms for a 3 ms deadline) and is the forced-diagnosis backend
432    /// rather than a fallback.
433    Condvar,
434}
435
436impl TimerBackend {
437    /// Whether this backend can resolve delays below the ~15.6 ms Windows
438    /// system tick.
439    ///
440    /// `SleepSlice => true` on every platform. `Condvar => cfg!(unix)` —
441    /// platform-dependent, because it is the good primitive on Unix and
442    /// the degraded one on Windows, and the type says so rather than the
443    /// reader having to know.
444    pub const fn is_high_resolution(self) -> bool {
445        match self {
446            Self::SleepSlice => true,
447            Self::Condvar => cfg!(unix),
448        }
449    }
450
451    /// A stable, lowercase, machine-readable name for reports:
452    /// `"sleep-slice"` / `"condvar"`.
453    pub const fn as_str(self) -> &'static str {
454        match self {
455            Self::SleepSlice => "sleep-slice",
456            Self::Condvar => "condvar",
457        }
458    }
459}
460
461/// No release thread has been constructed.
462const BACKEND_NONE: u8 = 0;
463/// [`TimerBackend::SleepSlice`].
464const BACKEND_SLEEP_SLICE: u8 = 1;
465/// [`TimerBackend::Condvar`].
466const BACKEND_CONDVAR: u8 = 2;
467
468/// The process-wide release thread's backend, or [`BACKEND_NONE`].
469///
470/// Monotonic: written exactly once, by the construction of the
471/// process-wide wheel, and never cleared. That monotonicity is what makes
472/// [`release_timer_started`] sound to assert on from a test that shares a
473/// binary with other tests — in the `true` direction. The tests that assert
474/// `false` are isolated into a test binary of their own, because
475/// `false → true` is the direction that *can* be spoiled.
476static RELEASE_TIMER_BACKEND: AtomicU8 = AtomicU8::new(BACKEND_NONE);
477
478/// Whether the process-wide release thread exists.
479///
480/// `false` until some session issues a `Delay` with a future release time
481/// or a `Hold`. This is the falsifiable form of "an `Interest::NONE`
482/// session starts no threads": assert it, do not assume it.
483pub fn release_timer_started() -> bool {
484    RELEASE_TIMER_BACKEND.load(Ordering::Acquire) != BACKEND_NONE
485}
486
487/// Which backend the process-wide release thread resolved to, or `None`
488/// if it has not started.
489pub fn release_timer_backend() -> Option<TimerBackend> {
490    match RELEASE_TIMER_BACKEND.load(Ordering::Acquire) {
491        BACKEND_SLEEP_SLICE => Some(TimerBackend::SleepSlice),
492        BACKEND_CONDVAR => Some(TimerBackend::Condvar),
493        _ => None,
494    }
495}
496
497/// Publish the fact that the **process-wide** release thread now exists.
498///
499/// `release_timer.rs` is the only caller, and must call it from inside
500/// `shared()`'s one-time initialiser — after `ReleaseTimer::new()` has
501/// resolved a backend, and *not* from `ReleaseTimer::new()` itself, which
502/// also runs for the owned wheels this module's tests and any per-socket
503/// owner construct. Publishing from `new()` would make
504/// [`release_timer_started`] report a process-wide thread that does not
505/// exist.
506///
507/// The state lives here rather than in `release_timer.rs` so that
508/// `instrument.rs` compiles standing alone, depending on nothing else in
509/// the crate, and so there is exactly one source of truth for a value two
510/// modules expose. `release_timer::started()` / `release_timer::backend()`
511/// read it back through the two public functions above.
512///
513/// First writer wins; later calls are ignored, which keeps the value
514/// monotonic even if a future caller gets the "once" wrong.
515///
516/// This function is `pub(crate)` and has no `#[allow(dead_code)]` on
517/// purpose: if `release_timer.rs` never calls it, `-D warnings` fails the
518/// build rather than leaving `release_timer_started()` silently stuck at
519/// `false` — which is the direction that would make the tests asserting
520/// that no release thread was started pass for the wrong reason.
521pub(crate) fn note_release_timer_started(backend: TimerBackend) {
522    let code = match backend {
523        TimerBackend::SleepSlice => BACKEND_SLEEP_SLICE,
524        TimerBackend::Condvar => BACKEND_CONDVAR,
525    };
526    let _ = RELEASE_TIMER_BACKEND.compare_exchange(
527        BACKEND_NONE,
528        code,
529        Ordering::Release,
530        Ordering::Relaxed,
531    );
532}
533
534#[cfg(test)]
535mod tests {
536    use super::*;
537    use std::sync::Arc;
538
539    #[test]
540    fn a_fresh_recorder_snapshots_as_default() {
541        assert_eq!(Recorder::new().snapshot(), Counters::default());
542    }
543
544    #[test]
545    fn every_counter_moves_independently() {
546        let r = Recorder::new();
547        r.note_framer_created();
548        r.note_framer_header_poll();
549        r.note_framer_header_poll();
550        r.note_framer_object_poll();
551        r.note_control_parser_created();
552        r.note_datagram_header_decoded();
553        r.note_egress_item_queued();
554        r.note_object_elided();
555        r.note_object_id_rewritten();
556        r.note_action_refused();
557        r.note_stream_not_shapeable();
558        r.note_object_not_addressable();
559        r.note_control_frames_not_decodable(1);
560
561        let c = r.snapshot();
562        assert_eq!(c.framers_created, 1);
563        assert_eq!(c.framer_header_polls, 2);
564        assert_eq!(c.framer_object_polls, 1);
565        assert_eq!(c.control_parsers_created, 1);
566        assert_eq!(c.datagram_headers_decoded, 1);
567        assert_eq!(c.egress_items_queued, 1);
568        assert_eq!(c.objects_elided, 1);
569        assert_eq!(c.object_ids_rewritten, 1);
570        assert_eq!(c.actions_refused, 1);
571        assert_eq!(c.streams_not_shapeable, 1);
572        assert_eq!(c.objects_not_addressable, 1);
573        assert_eq!(c.control_frames_not_decodable, 1);
574        // Nothing was released, so the release fields stay at their
575        // defaults — a counter suite whose fields bled into each other
576        // would make every counter assertion meaningless.
577        assert_eq!(c.release_error_ns, 0);
578        assert_eq!(c.release_errors, ReleaseErrors::default());
579    }
580
581    /// Two sessions, one process, no interference — the property that lets
582    /// a test assert `objects_elided == 0` while sharing a binary with
583    /// tests whose whole purpose is to elide.
584    #[test]
585    fn two_recorders_do_not_see_each_others_increments() {
586        let a = Arc::new(Recorder::new());
587        let b = Arc::new(Recorder::new());
588        for _ in 0..5 {
589            a.note_object_elided();
590        }
591        assert_eq!(a.snapshot().objects_elided, 5);
592        assert_eq!(b.snapshot().objects_elided, 0);
593    }
594
595    /// The `Arc` clone a `ForwardCtx` hands to each forwarding task must
596    /// reach the same counters, or the session's totals are per-task.
597    #[test]
598    fn arc_clones_share_one_recorder() {
599        let a = Arc::new(Recorder::new());
600        let b = Arc::clone(&a);
601        std::thread::scope(|s| {
602            for _ in 0..4 {
603                let r = Arc::clone(&b);
604                s.spawn(move || {
605                    for _ in 0..250 {
606                        r.note_framer_object_poll();
607                    }
608                });
609            }
610        });
611        assert_eq!(a.snapshot().framer_object_polls, 1000);
612    }
613
614    #[test]
615    fn the_coarse_timer_report_is_claimed_exactly_once() {
616        let r = Arc::new(Recorder::new());
617        let claims: usize = std::thread::scope(|s| {
618            let handles: Vec<_> = (0..8)
619                .map(|_| {
620                    let r = Arc::clone(&r);
621                    s.spawn(move || usize::from(r.claim_coarse_timer_report()))
622                })
623                .collect();
624            handles.into_iter().map(|h| h.join().unwrap()).sum()
625        });
626        assert_eq!(claims, 1);
627        assert!(!r.claim_coarse_timer_report());
628    }
629
630    #[test]
631    fn buckets_are_monotonic_and_bounded_by_their_upper_bound() {
632        let mut previous = 0usize;
633        // Every power of two and its neighbours, plus the exact small
634        // values: a swapped shift or an off-by-one in `bucket_of` shows
635        // up as a non-monotonic index rather than as a wrong quantile
636        // nobody can trace.
637        let mut probes: Vec<u64> = (0..16).collect();
638        for shift in 2..63u32 {
639            let base = 1u64 << shift;
640            probes.extend([base - 1, base, base + 1, base + base / 2]);
641        }
642        probes.sort_unstable();
643        for ns in probes {
644            let idx = bucket_of(ns);
645            assert!(idx >= previous, "bucket_of({ns}) went backwards");
646            assert!(idx < HIST_BUCKETS);
647            previous = idx;
648            if idx < HIST_BUCKETS - 1 {
649                assert!(ns <= bucket_upper_ns(idx), "{ns} exceeds the upper bound of bucket {idx}");
650            }
651        }
652    }
653
654    #[test]
655    fn a_bucket_is_never_more_than_25_percent_wide() {
656        for idx in 4..HIST_BUCKETS {
657            let upper = bucket_upper_ns(idx);
658            let lower = bucket_upper_ns(idx - 1) + 1;
659            assert!(lower <= upper, "bucket {idx} is empty or inverted");
660            assert!(
661                (upper - lower + 1) * 4 <= upper + 1,
662                "bucket {idx} ({lower}..={upper}) is wider than 25%"
663            );
664        }
665    }
666
667    #[test]
668    fn quantiles_bound_the_samples_they_summarise() {
669        let r = Recorder::new();
670        // 100 samples: 1 µs ×95, 40 ms ×5. p50 is a microsecond-ish
671        // bucket, p95 is still one, max is exact.
672        for _ in 0..95 {
673            r.record_release(Duration::from_micros(1));
674        }
675        for _ in 0..5 {
676            r.record_release(Duration::from_millis(40));
677        }
678        let c = r.snapshot();
679        assert_eq!(c.release_errors.count, 100);
680        assert_eq!(c.release_errors.max_ns, 40_000_000);
681        assert_eq!(c.release_error_ns, 95 * 1_000 + 5 * 40_000_000);
682        assert!(c.release_errors.p50_ns >= 1_000);
683        assert!(c.release_errors.p50_ns < 1_250, "p50 too coarse");
684        assert!(c.release_errors.p95_ns >= 1_000);
685        assert!(c.release_errors.p95_ns < 40_000_000, "p95 must not be dragged up by the 5% tail");
686    }
687
688    #[test]
689    fn a_single_sample_is_its_own_p50_and_p95() {
690        let r = Recorder::new();
691        r.record_release(Duration::from_micros(300));
692        let e = r.snapshot().release_errors;
693        assert_eq!(e.count, 1);
694        assert_eq!(e.max_ns, 300_000);
695        assert!(e.p50_ns >= 300_000 && e.p50_ns < 375_000);
696        assert_eq!(e.p50_ns, e.p95_ns);
697    }
698
699    #[test]
700    fn a_zero_lateness_release_is_still_a_release() {
701        let r = Recorder::new();
702        r.record_release(Duration::ZERO);
703        let e = r.snapshot().release_errors;
704        assert_eq!(e.count, 1);
705        assert_eq!(e.max_ns, 0);
706        assert_eq!(e.p50_ns, 0);
707    }
708
709    #[test]
710    fn an_absurd_lateness_saturates_the_last_bucket_but_not_the_max() {
711        let r = Recorder::new();
712        r.record_release(Duration::from_secs(3600));
713        let e = r.snapshot().release_errors;
714        assert_eq!(e.max_ns, 3_600_000_000_000);
715        assert_eq!(e.p50_ns, bucket_upper_ns(HIST_BUCKETS - 1));
716    }
717
718    #[test]
719    fn the_backend_names_and_resolutions_are_pinned() {
720        assert_eq!(TimerBackend::SleepSlice.as_str(), "sleep-slice");
721        assert_eq!(TimerBackend::Condvar.as_str(), "condvar");
722        assert!(TimerBackend::SleepSlice.is_high_resolution());
723        assert_eq!(TimerBackend::Condvar.is_high_resolution(), cfg!(unix));
724    }
725
726    /// The codes `note_release_timer_started` stores must decode back to
727    /// the backend that was stored, and `BACKEND_NONE` must decode to
728    /// `None`. Asserted without touching the static: setting it would
729    /// make this test binary's `release_timer_started()` `true` for every
730    /// other test in it — the hazard that keeps the tests asserting `false`
731    /// in a binary of their own.
732    #[test]
733    fn the_backend_encoding_round_trips() {
734        for (code, backend) in [
735            (BACKEND_SLEEP_SLICE, TimerBackend::SleepSlice),
736            (BACKEND_CONDVAR, TimerBackend::Condvar),
737        ] {
738            let decoded = match code {
739                BACKEND_SLEEP_SLICE => Some(TimerBackend::SleepSlice),
740                BACKEND_CONDVAR => Some(TimerBackend::Condvar),
741                _ => None,
742            };
743            assert_eq!(decoded, Some(backend));
744            assert_ne!(code, BACKEND_NONE);
745        }
746    }
747}