crates/gunnar-stage/tests/attribution.rs
//! What the attribution has to get right, proved against a **fake clock**.
//!
//! # Why a fake clock and not a `sleep`
//!
//! oden's load average ran 8–135 across the session this was written in, and a
//! test that asserts "the child got most of the time" against a real clock on a
//! loaded box either flakes or is loose enough to pass while broken. The three
//! properties under test — that a child's cost is *subtracted* from its parent,
//! that two threads are told apart, and that a stage's own name is what a
//! reader can ask for — are arithmetic, not timing, so they are asserted
//! exactly.
//!
//! # Seen red (2026-08-04)
//!
//! Each assertion below was watched fail before it was trusted, by the edit
//! named beside it:
//!
//! | assertion | broken by | what it then reported |
//! |---|---|---|
//! | exclusive subtraction | deleting the parent-suspend block in `enter` | `outer` 1050 instead of 150 — the parent charged the whole of its child |
//! | per-thread routing | making `ALLOC_B` a `static AtomicU64` | `walk` 1 000 003 on the thread that allocated 3 bytes |
//! | the fractions summing | charging `incl` where `excl` is charged | 133% of a request |
//!
//! # One test function, deliberately
//!
//! [`enable`](gunnar_stage::enable), the installed clock and the process-wide
//! table are all global, and `cargo test` runs test *cases* concurrently on
//! threads. Four `#[test]` functions here would race on the switch and the
//! failure would look like a bug in the thing under test. So the whole file is
//! one case, run in order.
use std::cell::Cell;
thread_local! {
static FAKE_USER: Cell<u64> = const { Cell::new(0) };
static FAKE_SYS: Cell<u64> = const { Cell::new(0) };
}
/// A per-thread CPU clock that only moves when the test says so.
fn fake_clock() -> (u64, u64) {
(FAKE_USER.with(|c| c.get()), FAKE_SYS.with(|c| c.get()))
}
fn burn_user(ns: u64) {
FAKE_USER.with(|c| c.set(c.get() + ns));
}
fn burn_sys(ns: u64) {
FAKE_SYS.with(|c| c.set(c.get() + ns));
}
#[test]
fn stage_attribution() {
gunnar_stage::set_cpu_clock(fake_clock);
exclusive_subtraction();
user_and_sys_stay_apart();
allocation_is_per_thread();
churn_is_not_residency();
current_names_the_innermost_stage();
disabled_costs_and_records_nothing();
}
/// A child's cost is taken off its parent, and the exclusive columns sum to the
/// whole.
fn exclusive_subtraction() {
gunnar_stage::reset();
gunnar_stage::reset_global();
gunnar_stage::enable();
{
let _outer = gunnar_stage::enter("outer");
burn_user(100);
gunnar_stage::note_alloc(100);
{
let _inner = gunnar_stage::enter("inner");
burn_user(900);
gunnar_stage::note_alloc(900);
}
burn_user(50);
gunnar_stage::note_alloc(50);
}
let report = gunnar_stage::thread_report();
gunnar_stage::disable();
let outer = report["outer"];
let inner = report["inner"];
assert_eq!(
outer.excl_user_ns, 150,
"the parent was charged its child's 900 ns; exclusive accounting is what makes a \
fraction mean anything, and this is the shape where a stage that only *calls* the \
expensive one looks like the expensive one"
);
assert_eq!(inner.excl_user_ns, 900);
assert_eq!(outer.calls, 1);
assert_eq!(
report.values().map(|t| t.excl_user_ns).sum::<u64>(),
1050,
"the exclusive columns must sum to the whole request, or the percentages a report \
prints add up to something that is not 100"
);
// **Memory is exclusive too, and this is the case that says so.** Charged
// inclusively, `peak_growth_bytes` double-counts through every nesting
// level: MEASURED 2026-08-04 on a real 12 181-object clone, `select` was
// credited with 14.48% of a peak that belonged entirely to its children and
// the column summed to 114% of the request. Every other assertion in this
// file is on a stage with no children and could not have seen it.
assert_eq!(
outer.peak_growth_bytes, 150,
"the parent was charged its child's 900 bytes of peak growth"
);
assert_eq!(inner.peak_growth_bytes, 900);
assert_eq!(outer.retained_bytes, 150);
assert_eq!(
report.values().map(|t| t.peak_growth_bytes).sum::<u64>(),
1050,
"the peak column must sum to the request's own peak growth"
);
// The inclusive column is the other half of the pair, and it must NOT have
// the child subtracted: "select_objects is 71% of the fetch" and "the tree
// walk inside it is 64%" are both true and both wanted.
assert!(
outer.incl_wall_ns >= inner.incl_wall_ns,
"an inclusive parent cannot be shorter than its own child"
);
}
/// User and system time are separate columns, because a stage that is 90%
/// `sys` is a syscall problem and a stage that is 90% `user` is a code problem,
/// and they get different next weeks.
fn user_and_sys_stay_apart() {
gunnar_stage::reset();
gunnar_stage::enable();
{
let _s = gunnar_stage::enter("reads");
burn_sys(4_000);
burn_user(1_000);
}
let report = gunnar_stage::thread_report();
gunnar_stage::disable();
assert_eq!(report["reads"].excl_sys_ns, 4_000);
assert_eq!(report["reads"].excl_user_ns, 1_000);
}
/// **The one this repository has already got wrong.** A counting
/// `#[global_allocator]` written here before counted per *process* while
/// `cargo test` ran cases on threads, so every byte landed on whichever case
/// happened to be running.
///
/// Two threads, a deliberately lopsided workload, and the attribution has to
/// follow the right one.
///
/// # The barriers are the whole test
///
/// Written first without them, this case **passed against a deliberately
/// process-wide byte counter** — the exact bug it exists to catch. Two short
/// threads spawned back to back do not overlap, so each one's global delta
/// happened to be its own work and the sum came out right. It proved
/// *summation* and called it isolation. That is the same shape as the
/// `pack_stats` probe that reported 0 packs through `cat` and exited 0: an
/// instrument whose green is indistinguishable from a real result.
///
/// With the barriers both threads are inside their `walk` stage at the same
/// time and the heavy one allocates *while the light one is watching*. A
/// per-thread counter still reports 1 000 000 and 3. A process-wide one reports
/// 1 000 003 **twice**, because each thread's interval now spans the other's
/// work, and the sum comes out at 2 000 006. Verified red 2026-08-04 by
/// swapping `ALLOC_B` for an `AtomicU64`.
fn allocation_is_per_thread() {
use std::sync::Barrier;
gunnar_stage::reset();
gunnar_stage::reset_global();
gunnar_stage::enable();
let gate = std::sync::Arc::new(Barrier::new(2));
let heavy_gate = std::sync::Arc::clone(&gate);
let heavy = std::thread::spawn(move || {
gunnar_stage::reset();
let _s = gunnar_stage::enter("walk");
heavy_gate.wait(); // both threads are now inside `walk`
gunnar_stage::note_alloc(1_000_000);
heavy_gate.wait(); // the light thread allocates after this, still inside
heavy_gate.wait();
drop(_s);
gunnar_stage::flush_thread();
});
let light_gate = std::sync::Arc::clone(&gate);
let light = std::thread::spawn(move || {
gunnar_stage::reset();
{
let _s = gunnar_stage::enter("walk");
light_gate.wait();
light_gate.wait(); // the heavy thread's million has landed by here
gunnar_stage::note_alloc(3);
light_gate.wait();
}
{
let _s = gunnar_stage::enter("write");
gunnar_stage::note_alloc(5_000);
gunnar_stage::note_dealloc(5_000);
}
gunnar_stage::flush_thread();
});
heavy.join().expect("heavy thread");
light.join().expect("light thread");
let report = gunnar_stage::global_report();
gunnar_stage::disable();
assert_eq!(
report["walk"].excl_alloc_bytes, 1_000_003,
"the two threads' `walk` stages did not add up; a per-process counter reports one \
thread's million against the other thread's three"
);
assert_eq!(report["walk"].excl_alloc_count, 2);
assert_eq!(report["write"].excl_alloc_bytes, 5_000);
assert_eq!(report["walk"].peak_growth_bytes, 1_000_003);
// `write` took 5 000 bytes and gave them back, so it retains nothing — but
// it did raise the high-water mark while it held them, and that is what an
// RSS figure would have seen. Both facts are reported and they are not the
// same fact.
assert_eq!(report["write"].retained_bytes, 0);
assert_eq!(report["write"].peak_growth_bytes, 5_000);
}
/// Churn is not residency and residency is not the peak.
///
/// A stage that allocates a megabyte a page at a time and frees each page has
/// enormous `excl_alloc_bytes` and may own none of the memory; a stage that
/// takes 5 000 bytes under an earlier stage's high-water mark owns none of the
/// peak however long it holds them. A single "memory" column cannot say either,
/// which is why there are three.
fn churn_is_not_residency() {
gunnar_stage::reset();
gunnar_stage::enable();
{
let _s = gunnar_stage::enter("big");
gunnar_stage::note_alloc(1_000_000);
gunnar_stage::note_dealloc(1_000_000);
}
{
let _s = gunnar_stage::enter("small");
gunnar_stage::note_alloc(5_000);
}
let report = gunnar_stage::thread_report();
gunnar_stage::disable();
assert_eq!(report["big"].excl_alloc_bytes, 1_000_000);
assert_eq!(report["big"].retained_bytes, 0);
assert_eq!(report["big"].peak_growth_bytes, 1_000_000);
assert_eq!(report["small"].excl_alloc_bytes, 5_000);
assert_eq!(report["small"].retained_bytes, 5_000);
assert_eq!(
report["small"].peak_growth_bytes, 0,
"`small` sat entirely under `big`'s high-water mark, so it owns none of the peak; a \
report that charged it 5 000 would point the next week's work at the wrong stage"
);
}
/// A read has to be chargeable to the stage that issued it, which is the fact
/// that separates "the fetch read 12 000 objects" from "the tree walk read
/// 11 400 of them and the pack writer re-read 600".
fn current_names_the_innermost_stage() {
gunnar_stage::reset();
gunnar_stage::enable();
assert_eq!(gunnar_stage::current(), None);
let _a = gunnar_stage::enter("select");
assert_eq!(gunnar_stage::current(), Some("select"));
{
let _b = gunnar_stage::enter("select.tree_closure");
assert_eq!(gunnar_stage::current(), Some("select.tree_closure"));
}
assert_eq!(
gunnar_stage::current(),
Some("select"),
"leaving a child must restore the parent, or every read after the first nested stage \
is charged to a stage that has already returned"
);
drop(_a);
gunnar_stage::disable();
}
/// Off is off. The default state of a production server records nothing, and a
/// report taken from it is empty rather than plausible.
fn disabled_costs_and_records_nothing() {
gunnar_stage::reset();
gunnar_stage::disable();
{
let _s = gunnar_stage::enter("ghost");
burn_user(10_000);
gunnar_stage::note_alloc(999);
}
let report = gunnar_stage::thread_report();
assert!(
report.is_empty(),
"a disabled probe recorded {} stages; the feature-off path is the one production runs \
and it must be provably inert",
report.len()
);
}