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}