Markk116/smarm
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat(causal): ledger audit — decompose the @50 injection deficit (RFC 007)

Browse Source 
Measure-only counters for the deficit hunt (~23ms short per 700ms window
at 50% on the bottleneck site; superlinear vs 25%). Nothing here changes
injection or absorption; the sweep decides the fix.

Buckets, windowed per cell into new ExperimentResult fields (audit
snapshot taken at end() — spin/attribution freeze there, forgiveness
does not):
- spin_absorbed / park_forgiven: where owed delay actually went. Spin
  during a 0% cell is the baseline-contamination signature — leftover
  debt from a prior window being paid in a later one (checks gate on
  the experiment word, so cooldowns pay nothing and debt carries over).
- drop_park / drop_yield (+counts): the deschedule path flushes no
  sample tail — an in-target-site park or yield silently loses
  [last sample -> now]; on_resume re-arms before the actor runs again.
  New on_deschedule hook in all three intent arms (real park; explicit/
  slice-expiry yield; requeued park counts as yield — it never blocked).
  Slice-expiry yields sample at the descheduling checkpoint, so a fat
  yield bucket points at explicit yield_now or requeued parks.
- discard_overmax (+count, in would-be delta terms so columns compare
  against injected_cycles) / discard_unarmed: the attribute() clamps,
  previously silent.

LedgerCounters + ledger_counters() expose cumulative totals (tests,
run-level prints); render_ledger_audit() is the per-cell companion to
render_summary, which stays byte-identical (pinned). ExperimentResult
now derives Default so literals survive future audit-field growth.

Tests: +7 (spin counted, forgiveness counted, in-site park drop, in-site
yield drop, overmax discard, 0%-window leftover absorption — synthesized
deterministically via inject_delay_cycles_for_test with no experiment
active — and the audit render). 22/22 causal.
This commit is contained in:
Claude (sandbox)
2026-07-13 12:07:19 +00:00
parent a2d0b7af18
commit a3be8f0977
3 changed files with 482 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/causal.rs
+211 -7
View File
@@ -79,6 +79,31 @@ mod inner {
/// ~3ms at 3 GHz.
const MAX_SPIN_PER_VISIT: u64 = 10_000_000;
// -----------------------------------------------------------------------
// Ledger audit (RFC 007 deficit hunt): where injected delay is born,
// paid, and forgiven — and where would-be attribution is silently lost
// (deschedule tails, clamp discards). Monotone Relaxed totals, read via
// `ledger_counters()`; `run_experiments` windows them into
// `ExperimentResult`. Measure-only: nothing here changes injection or
// absorption behaviour.
// -----------------------------------------------------------------------
/// Cycles bystanders actually spun to pay down the global ledger.
static SPIN_ABSORBED_CYCLES: AtomicU64 = AtomicU64::new(0);
/// Cycles waived at wake after a real park (the blocked-thread rule).
static PARK_FORGIVEN_CYCLES: AtomicU64 = AtomicU64::new(0);
/// Would-be attribution lost when the target-site actor parks mid-site.
static DROP_PARK_CYCLES: AtomicU64 = AtomicU64::new(0);
static DROP_PARK_N: AtomicU64 = AtomicU64::new(0);
/// Same loss at yields (explicit, slice-expiry, or a park that requeued).
static DROP_YIELD_CYCLES: AtomicU64 = AtomicU64::new(0);
static DROP_YIELD_N: AtomicU64 = AtomicU64::new(0);
/// Samples discarded by the TSC-weirdness clamp, in would-be delta terms.
static DISCARD_OVERMAX_CYCLES: AtomicU64 = AtomicU64::new(0);
static DISCARD_OVERMAX_N: AtomicU64 = AtomicU64::new(0);
/// In-site samples dropped because the thread's clock was unarmed.
static DISCARD_UNARMED_N: AtomicU64 = AtomicU64::new(0);
fn sites() -> &'static Mutex<Vec<&'static str>> {
SITES.get_or_init(|| Mutex::new(Vec::new()))
}
@@ -256,7 +281,9 @@ mod inner {
// and credit ourselves the same amount — the credited gap *is*
// the virtual speedup.
if last == 0 {
return; // unarmed clock: no interval to attribute
// Unarmed clock: no interval to attribute — count the loss.
DISCARD_UNARMED_N.fetch_add(1, Ordering::Relaxed);
return;
}
// SAFETY: `slot` is the on-CPU actor's slot (checked non-null
// above); see `check_cancelled` for the lifetime argument.
@@ -276,6 +303,7 @@ mod inner {
while preempt::rdtsc().saturating_sub(start) < spin {
core::hint::spin_loop();
}
SPIN_ABSORBED_CYCLES.fetch_add(spin, Ordering::Relaxed);
unsafe { (*slot).set_causal_delay(mine.wrapping_add(spin)) };
preempt::extend_timeslice(spin);
// The spin is not part of the next sample interval either.
@@ -293,7 +321,16 @@ mod inner {
/// SAFETY: `slot` must point at the on-CPU actor's slot (the
/// `check_cancelled` lifetime argument).
unsafe fn attribute(slot: *const crate::runtime::Slot, interval: u64, pct: u64) {
if interval == 0 || interval > MAX_SAMPLE_CYCLES {
if interval == 0 {
return; // now == last: nothing to attribute, nothing lost
}
if interval > MAX_SAMPLE_CYCLES {
// TSC-weirdness clamp: the sample is discarded, not the run.
// Count the loss in would-be delta terms so the audit's columns
// compare directly against `injected_cycles`.
DISCARD_OVERMAX_N.fetch_add(1, Ordering::Relaxed);
DISCARD_OVERMAX_CYCLES
.fetch_add(interval.saturating_mul(pct) / 100, Ordering::Relaxed);
return;
}
let delta = interval.saturating_mul(pct) / 100;
@@ -327,10 +364,14 @@ mod inner {
if old == target && new != target {
let now = preempt::rdtsc();
let last = LAST_SAMPLE_TSC.with(|c| c.replace(now));
if last != 0 && pct > 0 {
// SAFETY: forwarded from the guard, which holds the on-CPU
// actor's slot for its whole life (see `SiteGuard::slot`).
unsafe { attribute(slot, now.saturating_sub(last), pct) };
if pct > 0 {
if last != 0 {
// SAFETY: forwarded from the guard, which holds the on-CPU
// actor's slot for its whole life (see `SiteGuard::slot`).
unsafe { attribute(slot, now.saturating_sub(last), pct) };
} else {
DISCARD_UNARMED_N.fetch_add(1, Ordering::Relaxed);
}
}
} else if new == target && old != target {
LAST_SAMPLE_TSC.with(|c| c.set(preempt::rdtsc()));
@@ -352,13 +393,55 @@ mod inner {
pub(crate) fn on_resume(slot: &crate::runtime::Slot) {
if slot.take_causal_parked() {
let global = GLOBAL_DELAY.load(Ordering::Relaxed);
if slot.causal_delay() < global {
let mine = slot.causal_delay();
if mine < global {
PARK_FORGIVEN_CYCLES.fetch_add(global - mine, Ordering::Relaxed);
slot.set_causal_delay(global);
}
}
LAST_SAMPLE_TSC.with(|c| c.set(preempt::rdtsc()));
}
/// Deschedule-path hook (scheduler side, same OS thread the actor just
/// ran on). If an experiment is live and the departing actor sits in the
/// target site, the sample tail `[last sample -> now]` is about to be
/// lost: nothing flushes it here, and `on_resume` re-arms the clock
/// before the actor runs again. Measure-only (RFC 007 deficit hunt) —
/// tally the would-be attribution into the park/yield drop buckets and
/// leave behaviour untouched. The interval is capped at
/// MAX_SAMPLE_CYCLES: past that the flush would have discarded it anyway
/// (counted separately). `now` includes the few hundred ns of scheduler
/// bookkeeping since the actor actually stopped — an acceptable
/// overcount for a diagnostic.
///
/// Slice-expiry yields sample at the same checkpoint that deschedules
/// them, so their tails are ~zero by construction; a fat yield bucket
/// therefore points at explicit `yield_now` calls or requeued parks.
pub(crate) fn on_deschedule(slot: &crate::runtime::Slot, real_park: bool) {
let exp = EXPERIMENT.load(Ordering::Relaxed);
if exp == 0 {
return;
}
let target = (exp >> 32) as u32;
let pct = exp & 0xffff_ffff;
if pct == 0 || slot.causal_site() != target {
return;
}
let last = LAST_SAMPLE_TSC.with(|c| c.get());
if last == 0 {
return;
}
let interval = preempt::rdtsc().saturating_sub(last).min(MAX_SAMPLE_CYCLES);
let would_be = interval.saturating_mul(pct) / 100;
if real_park {
DROP_PARK_N.fetch_add(1, Ordering::Relaxed);
DROP_PARK_CYCLES.fetch_add(would_be, Ordering::Relaxed);
} else {
DROP_YIELD_N.fetch_add(1, Ordering::Relaxed);
DROP_YIELD_CYCLES.fetch_add(would_be, Ordering::Relaxed);
}
}
// -----------------------------------------------------------------------
// Experiments
// -----------------------------------------------------------------------
@@ -376,6 +459,63 @@ mod inner {
GLOBAL_DELAY.load(Ordering::Relaxed)
}
/// Cumulative ledger-audit totals since startup (RFC 007 deficit hunt).
/// All monotone; window a span by snapshotting before/after and taking
/// `delta_since`. Cycle fields are in would-be-injected delta terms so
/// they compare directly against `injected_cycles`.
#[derive(Clone, Copy, Debug, Default)]
pub struct LedgerCounters {
pub spin_absorbed_cycles: u64,
pub park_forgiven_cycles: u64,
pub drop_park_cycles: u64,
pub drop_park_n: u64,
pub drop_yield_cycles: u64,
pub drop_yield_n: u64,
pub discard_overmax_cycles: u64,
pub discard_overmax_n: u64,
pub discard_unarmed_n: u64,
}
impl LedgerCounters {
/// Field-wise difference against an earlier snapshot.
pub fn delta_since(&self, before: &LedgerCounters) -> LedgerCounters {
LedgerCounters {
spin_absorbed_cycles: self
.spin_absorbed_cycles
.saturating_sub(before.spin_absorbed_cycles),
park_forgiven_cycles: self
.park_forgiven_cycles
.saturating_sub(before.park_forgiven_cycles),
drop_park_cycles: self.drop_park_cycles.saturating_sub(before.drop_park_cycles),
drop_park_n: self.drop_park_n.saturating_sub(before.drop_park_n),
drop_yield_cycles: self
.drop_yield_cycles
.saturating_sub(before.drop_yield_cycles),
drop_yield_n: self.drop_yield_n.saturating_sub(before.drop_yield_n),
discard_overmax_cycles: self
.discard_overmax_cycles
.saturating_sub(before.discard_overmax_cycles),
discard_overmax_n: self.discard_overmax_n.saturating_sub(before.discard_overmax_n),
discard_unarmed_n: self.discard_unarmed_n.saturating_sub(before.discard_unarmed_n),
}
}
}
/// Snapshot the cumulative audit counters.
pub fn ledger_counters() -> LedgerCounters {
LedgerCounters {
spin_absorbed_cycles: SPIN_ABSORBED_CYCLES.load(Ordering::Relaxed),
park_forgiven_cycles: PARK_FORGIVEN_CYCLES.load(Ordering::Relaxed),
drop_park_cycles: DROP_PARK_CYCLES.load(Ordering::Relaxed),
drop_park_n: DROP_PARK_N.load(Ordering::Relaxed),
drop_yield_cycles: DROP_YIELD_CYCLES.load(Ordering::Relaxed),
drop_yield_n: DROP_YIELD_N.load(Ordering::Relaxed),
discard_overmax_cycles: DISCARD_OVERMAX_CYCLES.load(Ordering::Relaxed),
discard_overmax_n: DISCARD_OVERMAX_N.load(Ordering::Relaxed),
discard_unarmed_n: DISCARD_UNARMED_N.load(Ordering::Relaxed),
}
}
/// Absorbed-delay ledger of the on-CPU actor (testing/introspection).
pub fn my_absorbed_delay_cycles() -> u64 {
let slot = preempt::current_slot_ptr();
@@ -430,6 +570,7 @@ mod inner {
}
/// One completed experiment cell.
#[derive(Default)]
pub struct ExperimentResult {
pub site: String,
pub speedup_pct: u32,
@@ -438,6 +579,19 @@ mod inner {
pub deltas: Vec<(String, u64)>,
/// Virtual delay injected during the window (cycles).
pub injected_cycles: u64,
// Ledger-audit deltas over the window (RFC 007 deficit hunt); see
// `LedgerCounters` for field semantics. `spin_absorbed_cycles > 0`
// in a 0% cell means the window paid debt left over from an earlier
// one — the baseline-contamination signature.
pub spin_absorbed_cycles: u64,
pub park_forgiven_cycles: u64,
pub drop_park_cycles: u64,
pub drop_park_n: u64,
pub drop_yield_cycles: u64,
pub drop_yield_n: u64,
pub discard_overmax_cycles: u64,
pub discard_overmax_n: u64,
pub discard_unarmed_n: u64,
}
/// Run the plan synchronously on the calling (OS) thread: for every
@@ -479,10 +633,16 @@ mod inner {
for &pct in &plan.speedups_pct {
let before = progress_snapshot();
let injected_before = global_delay_cycles();
let audit_before = ledger_counters();
let t0 = Instant::now();
begin(*sid, pct);
controller_sleep(plan.experiment);
end();
// Snapshot immediately: injection and spin freeze at `end()`
// (checks gate on the experiment word), but forgiveness does
// not — a later snapshot would leak cooldown wakes into the
// window.
let audit = ledger_counters().delta_since(&audit_before);
let elapsed = t0.elapsed();
let after = progress_snapshot();
let deltas = after
@@ -502,6 +662,15 @@ mod inner {
duration: elapsed,
deltas,
injected_cycles: global_delay_cycles() - injected_before,
spin_absorbed_cycles: audit.spin_absorbed_cycles,
park_forgiven_cycles: audit.park_forgiven_cycles,
drop_park_cycles: audit.drop_park_cycles,
drop_park_n: audit.drop_park_n,
drop_yield_cycles: audit.drop_yield_cycles,
drop_yield_n: audit.drop_yield_n,
discard_overmax_cycles: audit.discard_overmax_cycles,
discard_overmax_n: audit.discard_overmax_n,
discard_unarmed_n: audit.discard_unarmed_n,
});
controller_sleep(plan.cooldown);
}
@@ -626,6 +795,41 @@ mod inner {
s
}
/// Ledger-audit companion to `render_summary` (RFC 007 deficit hunt):
/// per cell, where the window's virtual delay went — born (injected),
/// paid (absorbed), waived (forgiven at wake) — and the attribution the
/// sampler lost: tails dropped at parks/yields inside the target site,
/// plus clamp discards. Cycle columns in ms at the calibrated TSC rate.
/// `absorbed` above `injected` in a cell (0% especially) means it paid
/// debt left over from earlier windows.
pub fn render_ledger_audit(results: &[ExperimentResult]) -> String {
use std::fmt::Write;
let hz = tsc_hz();
let ms = |c: u64| c as f64 / hz * 1e3;
let mut s = String::new();
let _ = writeln!(s, "== smarm causal ledger audit ==");
for r in results {
let _ = writeln!(
s,
"site {:<22} @{:>2}% injected {:>7.1}ms absorbed {:>7.1}ms forgiven {:>7.1}ms \
drop park {:>6.2}ms/{:<4} yield {:>6.2}ms/{:<4} discard >max {:>6.2}ms/{:<3} unarmed {}",
r.site,
r.speedup_pct,
ms(r.injected_cycles),
ms(r.spin_absorbed_cycles),
ms(r.park_forgiven_cycles),
ms(r.drop_park_cycles),
r.drop_park_n,
ms(r.drop_yield_cycles),
r.drop_yield_n,
ms(r.discard_overmax_cycles),
r.discard_overmax_n,
r.discard_unarmed_n
);
}
s
}
/// Coz-compatible profile text (`profile.coz`), so Coz's existing plot
/// tooling renders our experiments — the RFC's "don't build a UI" call.
pub fn render_coz(results: &[ExperimentResult]) -> String {