diff --git a/changelog.d/9823-for-in-deferred-shadow-set.md b/changelog.d/9823-for-in-deferred-shadow-set.md new file mode 100644 index 0000000000..81cb3cd4ac --- /dev/null +++ b/changelog.d/9823-for-in-deferred-shadow-set.md @@ -0,0 +1,28 @@ +**`for-in` no longer allocates a heap string and a hash entry for every own +name at every prototype level** (#9823). + +`js_for_in_keys_value` kept a `HashSet` of every own name — enumerable +or not — at every level of the prototype chain, so that a name owned closer to +the receiver hides the same name further along it (ECMA-262 14.7.5, 12.6.4-2). +It built that set unconditionally, which meant materialising a second key array +per level (all own names, on top of the enumerable ones) and turning every name +at every level into an owned `String` purely so it could be hashed. + +That set can only filter a level at or below the first prototype, and a level +that contributes no enumerable keys of its own never consults it. It is now +built on demand — at the moment a prototype level actually has an enumerable +key to filter — from exactly the levels already walked, so the emitted key +sequence is unchanged. + +On the compiled claude-code TUI, one 400-character reply: **159,947 `String` +allocations and 159,947 hash inserts become zero**, and the key arrays +materialised per call halve from 4.00 to 2.00. Across 17,281 `for-in` loops in +that reply, **no key was emitted from a prototype level at all**, so the set +that cost all of that filtered nothing. The strings totalled 1.91 MB, which is +why an allocation-byte ranking never surfaced this: the cost was 160,000 +mallocs, memcpys, hashes and frees, not the bytes they held. The collection +schedule is unchanged (41 vs 43 copying minors, 46 vs 48 budgeted full-cycle +steps). + +`PERRY_ENUM_DIAG=` reports the counters above. `PERRY_FORIN_LAZY_SHADOW=0` +restores the eager set. diff --git a/changelog.d/9828-buffer-registry-addr-filter.md b/changelog.d/9828-buffer-registry-addr-filter.md new file mode 100644 index 0000000000..2792840957 --- /dev/null +++ b/changelog.d/9828-buffer-registry-addr-filter.md @@ -0,0 +1,32 @@ +**The buffer-registry probe stops answering "maybe" to three quarters of the +addresses it is asked about** (#9828). + +`is_registered_buffer` guards its three registries with +`BUFFER_LIKE_ADDR_WINDOW`, a process-global min/max span, and the 98.0 % +rejection rate in its doc comment is measured on `claude-code --help` — a run +that registers **10** buffers. A streaming turn registers **213**, scattered +across a **527 MB** span, so `[lo, hi]` covers half a gigabyte of ordinary heap +and stops discriminating: on one 400-character reply, 34.6 million probes, of +which the window admits **73.63 %** to the out-of-line lookup, and **99.79 % of +those find nothing**. + +The probe now consults `RegistryAddrFilter` behind the window — the set filter +added after #9272 for exactly this failure, where a registry's entries are +ordinary heap objects interleaved with everything else. Rejection goes from +26.37 % to **96.46 %**, removing **24.25 million out-of-line calls per reply**, +each of which cost a thread-local resolution and a hash. True positives are +unchanged. + +The saturation question that structure demands was answered before adopting it: +`RegistryAddrFilter` accrues bits per admission and never clears them, so a +high-churn set would degrade it into the state #9807 documented for the +per-object layout filter. Buffers are the opposite case — probing is hot, +registration is rare — and 213 cumulative admissions against 1,024 bits gives a +10.0 % false-positive rate. `PERRY_BUFFER_DIAG` reports the occupancy, the +window bounds and the rejection rate so the question stays answerable. + +In the profile, `is_registered_buffer_slow` falls from 169 to 25 leaf samples +(−85 %); its inline caller rises 96 to 123 as the filter's hashes move there, +so the pair falls 44 % overall. That is roughly half of the 3.19 % the profile +attributed to the slow path, and it is below the streaming rig's resolution, so +turn CPU is unchanged. diff --git a/crates/perry-runtime/src/buffer/header.rs b/crates/perry-runtime/src/buffer/header.rs index d3f380ef67..d1224faefc 100644 --- a/crates/perry-runtime/src/buffer/header.rs +++ b/crates/perry-runtime/src/buffer/header.rs @@ -217,6 +217,56 @@ static BUFFER_LIKE_EVER_REGISTERED: RegistryLatch = RegistryLatch::new(); /// [`RegistryAddrWindow`] for the ordering rule that makes it so. static BUFFER_LIKE_ADDR_WINDOW: RegistryAddrWindow = RegistryAddrWindow::new(); +/// The set filter behind the window, for the addresses `[lo, hi]` cannot +/// discriminate. +/// +/// The window's 98.0 % rejection rate above is measured on `claude-code +/// --help`, which registers **10** buffers. On a streaming turn cc registers +/// **213**, scattered across a **527 MB** span — so `[lo, hi]` covers half a +/// gigabyte of ordinary heap and stops rejecting. `PERRY_BUFFER_DIAG`, one +/// 400-character reply: +/// +/// ```text +/// probes=34,603,009 admits=25,627,160 (74.06 %) rejected=8,975,849 (25.94 %) +/// true_positives=53,109 (0.207 % of admits) +/// window [0x5b718eb73e8, 0x5b739e1c0b8] span 527.4 MB +/// registrations=213 unregistrations=12 live_max=201 +/// ``` +/// +/// 25.6 million out-of-line probes per reply, 99.79 % of which find nothing. +/// That is the failure [`RegistryAddrFilter`] was built for after #9272 +/// (`is_registered_symbol`: a window rejects 38.3 %, the filter 99.58 %) — its +/// entries are ordinary heap objects interleaved with everything else, which +/// its doc comment names as the case a window cannot serve. +/// +/// **The capacity question this structure demands was asked before adopting +/// it.** `RegistryAddrFilter` accrues bits per ADMISSION and never clears them, +/// so a high-churn set saturates it — the trap #9807 documented for the +/// per-object layout filter, which held 162,258 keys against 4,096 bits and +/// answered "may hold" to every probe. Buffers are not that case: probing is +/// hot but registration is rare, and **213 cumulative admissions against 1,024 +/// bits and 3 hashes is a 10.0 % false-positive rate**, so the filter rejects +/// about nine of every ten addresses the window admits. The counter that says +/// so ships with it. +/// +/// The window stays in front: two static loads reject 25.94 % for less than +/// the filter's three hashes cost. +static BUFFER_LIKE_ADDR_FILTER: crate::registry_latch::RegistryAddrFilter = + crate::registry_latch::RegistryAddrFilter::new(); + +/// `PERRY_BUFFER_ADDR_FILTER=0` restores the window-only probe, so one binary +/// carries both and the A/B is one environment variable. +fn buffer_addr_filter_enabled() -> bool { + use std::sync::OnceLock; + static CACHED: OnceLock = OnceLock::new(); + *CACHED.get_or_init(|| { + !matches!( + std::env::var("PERRY_BUFFER_ADDR_FILTER").as_deref(), + Ok("0") | Ok("off") | Ok("false") + ) + }) +} + #[cfg(test)] thread_local! { /// Test-only count of `is_registered_buffer` calls that got past the address @@ -256,6 +306,7 @@ pub(crate) fn note_buffer_like_registered(addr: usize) { // checks the latch and then the window, so both must already cover this // address by the time it becomes findable. BUFFER_LIKE_ADDR_WINDOW.admit(addr); + BUFFER_LIKE_ADDR_FILTER.admit(addr); BUFFER_LIKE_EVER_REGISTERED.arm(); } @@ -405,12 +456,17 @@ pub fn register_buffer(ptr: *const BufferHeader) { // the idle fast path and denies it. See `crate::registry_latch`. let addr = ptr as usize; BUFFER_LIKE_ADDR_WINDOW.admit(addr); + BUFFER_LIKE_ADDR_FILTER.admit(addr); BUFFER_LIKE_EVER_REGISTERED.arm(); BUFFER_ADDR_RANGE.with(|r| { let (lo, hi) = r.get(); r.set((lo.min(addr), hi.max(addr))); }); BUFFER_REGISTRY.with(|r| r.borrow_mut().insert(addr)); + if crate::hot_diag::buffer_on() { + let live = BUFFER_REGISTRY.with(|r| r.borrow().len()); + crate::hot_diag::buffer_note_registration(live); + } } /// Historical tier boundary, retained for callers that size test fixtures @@ -442,7 +498,12 @@ pub fn is_registered_buffer(addr: usize) -> bool { // call, the thread-local resolution, the `RefCell` borrow or the hash. // Every writer widens the window before it publishes, which is what makes // rejecting sound; see `BUFFER_LIKE_ADDR_WINDOW`. - if !BUFFER_LIKE_ADDR_WINDOW.may_contain(addr) { + let admitted = BUFFER_LIKE_ADDR_WINDOW.may_contain(addr) + && (!buffer_addr_filter_enabled() || BUFFER_LIKE_ADDR_FILTER.may_contain(addr)); + if crate::hot_diag::buffer_on() { + crate::hot_diag::buffer_note_probe(addr, admitted, BUFFER_LIKE_ADDR_WINDOW.bounds()); + } + if !admitted { // Machine-check the completeness of the writer set instead of trusting // an enumeration of it. The window is only sound if EVERY route into // the three tables below calls `admit` first; an enumeration of those @@ -468,7 +529,11 @@ pub fn is_registered_buffer(addr: usize) -> bool { } #[cfg(test)] TEST_BUFFER_REGISTRY_PROBES.with(|c| c.set(c.get().wrapping_add(1))); - is_registered_buffer_slow(addr) + let found = is_registered_buffer_slow(addr); + if found && crate::hot_diag::buffer_on() { + crate::hot_diag::buffer_note_true_positive(); + } + found } /// `PERRY_BUFFER_RANGE_FILTER=0` restores the unconditional hash lookup. @@ -1081,6 +1146,9 @@ pub(crate) fn finalize_collected_dead_buffer(addr: usize) { BUFFER_REGISTRY.with(|r| { r.borrow_mut().remove(&addr); }); + if crate::hot_diag::buffer_on() { + crate::hot_diag::buffer_note_unregistration(); + } FOREIGN_BACKING_REGISTRY.with(|r| { r.borrow_mut().remove(&addr); }); diff --git a/crates/perry-runtime/src/hot_diag.rs b/crates/perry-runtime/src/hot_diag.rs index faa49fba65..631f14512c 100644 --- a/crates/perry-runtime/src/hot_diag.rs +++ b/crates/perry-runtime/src/hot_diag.rs @@ -624,3 +624,307 @@ impl IcDiag { out } } + +// --------------------------------------------------------------------------- +// Enumeration and concatenation: EXECUTIONS per site, not bytes +// --------------------------------------------------------------------------- + +static ENUM_SINK: OnceLock> = OnceLock::new(); +static ENUM_ON: AtomicBool = AtomicBool::new(false); + +fn enum_sink() -> &'static Option { + ENUM_SINK.get_or_init(|| { + let sink = sink_from_env("PERRY_ENUM_DIAG"); + ENUM_ON.store(sink.is_some(), Ordering::Relaxed); + sink + }) +} + +/// Is the enumeration/concat execution counter armed? +#[inline] +pub fn enum_on() -> bool { + if ENUM_SINK.get().is_none() { + enum_sink(); + } + ENUM_ON.load(Ordering::Relaxed) +} + +/// What actually runs at the two allocation sites the byte-share ranking put +/// at 7.8 % (`for-in` key arrays) and 6.9 % (string concat). +/// +/// The campaign's 19:30 correction is the reason this counts executions rather +/// than bytes: a category's byte share bounds the collection *schedule* it can +/// move, and nothing else. The cost that a small category can still carry is +/// whatever runs per allocation — here, for `for-in`, a heap `String` and a +/// SipHash insert for **every key at every prototype level**, allocated only to +/// be hashed for shadowing and dropped. Those `String`s are native-heap, so +/// they are not even in the 7.8 %. +#[derive(Default)] +pub struct EnumDiag { + started: Option, + last_dump: Option, + events: u32, + /// Entries to `js_for_in_keys_value`. + pub for_in_calls: u64, + /// `for-in` calls that took the non-pointer (primitive receiver) path. + pub for_in_primitive: u64, + /// Prototype levels walked, summed over all calls. + pub for_in_levels: u64, + /// Key arrays materialised by the walk: one `js_object_keys_value` plus one + /// `js_object_get_own_property_names` per level. + pub for_in_key_arrays: u64, + /// Keys seen at any level — each one costs a `String` and a hash. + pub for_in_keys_seen: u64, + /// `String` allocations made by `key_string`. + pub for_in_key_strings: u64, + /// Bytes in those `String`s. + pub for_in_key_string_bytes: u64, + /// `seen.insert` calls (SipHash of the whole key each time). + pub for_in_seen_inserts: u64, + /// Of those, inserts that found the name already present — pure waste, the + /// name was already shadowed. + pub for_in_seen_dupes: u64, + /// Keys actually emitted into the result array. + pub for_in_keys_emitted: u64, + /// Of those, keys emitted at prototype level >= 1 — the only ones for which + /// the shadow set is load-bearing. If this is ~0, every `String` and every + /// hash spent building that set was spent for nothing. + pub for_in_keys_emitted_deep: u64, + /// Times the deferred shadow set was actually materialised. + pub for_in_shadow_built: u64, + /// String concatenations, by entry point. + pub concat_calls: u64, + pub concat_site_calls: u64, + pub concat_chain_calls: u64, + /// Bytes produced by concatenation. + pub concat_out_bytes: u64, +} + +crate::perry_thread_local! { + static ENUM_DIAG: RefCell = RefCell::new(EnumDiag::default()); +} + +/// Run `f` against this thread's enumeration counters, then maybe dump. +#[inline] +pub fn enum_with(f: impl FnOnce(&mut EnumDiag)) { + ENUM_DIAG.with(|d| { + let mut d = d.borrow_mut(); + if d.started.is_none() { + d.started = Some(Instant::now()); + d.last_dump = d.started; + } + f(&mut d); + d.events = d.events.wrapping_add(1); + if d.events % TICK_EVERY == 0 { + let due = d + .last_dump + .is_some_and(|t| t.elapsed().as_millis() >= DUMP_INTERVAL_MS); + if due { + d.last_dump = Some(Instant::now()); + if let Some(sink) = enum_sink() { + write_sink(sink, &d.render()); + } + } + } + }); +} + +impl EnumDiag { + fn render(&self) -> String { + use std::fmt::Write as _; + let mut out = String::with_capacity(1024); + let per = |n: u64, d: u64| if d == 0 { 0.0 } else { n as f64 / d as f64 }; + let _ = writeln!( + out, + "[enum-diag] for_in calls={} (primitive={}) levels={} ({:.2}/call)", + self.for_in_calls, + self.for_in_primitive, + self.for_in_levels, + per(self.for_in_levels, self.for_in_calls) + ); + let _ = writeln!( + out, + " key arrays materialised={} ({:.2}/call) keys seen={} ({:.1}/call) emitted={} ({:.1}/call)", + self.for_in_key_arrays, + per(self.for_in_key_arrays, self.for_in_calls), + self.for_in_keys_seen, + per(self.for_in_keys_seen, self.for_in_calls), + self.for_in_keys_emitted, + per(self.for_in_keys_emitted, self.for_in_calls) + ); + let _ = writeln!( + out, + " PER-KEY WORK: String allocs={} ({:.2} MB) seen.insert={} of which duplicate={} ({:.1} %)", + self.for_in_key_strings, + self.for_in_key_string_bytes as f64 / (1024.0 * 1024.0), + self.for_in_seen_inserts, + self.for_in_seen_dupes, + 100.0 * per(self.for_in_seen_dupes, self.for_in_seen_inserts) + ); + let _ = writeln!( + out, + " emitted/String ratio = {:.3} (1.0 would mean every String earned a key)", + per(self.for_in_keys_emitted, self.for_in_key_strings) + ); + let _ = writeln!( + out, + " LOAD-BEARING: keys emitted at proto level >=1 = {} ({:.2} % of emitted); shadow set built {} times ({:.2}/call)", + self.for_in_keys_emitted_deep, + 100.0 * per(self.for_in_keys_emitted_deep, self.for_in_keys_emitted), + self.for_in_shadow_built, + per(self.for_in_shadow_built, self.for_in_calls) + ); + let _ = writeln!( + out, + "[enum-diag] concat calls={} site={} chain={} out_bytes={:.2} MB ({:.1} B/call)", + self.concat_calls, + self.concat_site_calls, + self.concat_chain_calls, + self.concat_out_bytes as f64 / (1024.0 * 1024.0), + per( + self.concat_out_bytes, + self.concat_calls + self.concat_site_calls + self.concat_chain_calls + ) + ); + out + } +} + +// --------------------------------------------------------------------------- +// `is_registered_buffer`: is the min/max window still rejecting? +// --------------------------------------------------------------------------- + +use std::sync::atomic::{AtomicU64, AtomicUsize}; + +static BUFFER_SINK: OnceLock> = OnceLock::new(); +static BUFFER_ON: AtomicBool = AtomicBool::new(false); + +fn buffer_sink() -> &'static Option { + BUFFER_SINK.get_or_init(|| { + let sink = sink_from_env("PERRY_BUFFER_DIAG"); + BUFFER_ON.store(sink.is_some(), Ordering::Relaxed); + sink + }) +} + +/// Is the buffer-probe instrument armed? One relaxed load once initialised. +#[inline] +pub fn buffer_on() -> bool { + if BUFFER_SINK.get().is_none() { + buffer_sink(); + } + BUFFER_ON.load(Ordering::Relaxed) +} + +// Plain relaxed atomics rather than the thread-local `RefCell` the other +// instruments use: this probe runs millions of times per turn, and a borrow +// per probe would dominate the thing being measured. +static BUF_PROBES: AtomicU64 = AtomicU64::new(0); +static BUF_ADMITS: AtomicU64 = AtomicU64::new(0); +static BUF_TRUE_POS: AtomicU64 = AtomicU64::new(0); +static BUF_ADDR_MIN: AtomicUsize = AtomicUsize::new(usize::MAX); +static BUF_ADDR_MAX: AtomicUsize = AtomicUsize::new(0); +static BUF_WIN_LO: AtomicUsize = AtomicUsize::new(usize::MAX); +static BUF_WIN_HI: AtomicUsize = AtomicUsize::new(0); +static BUF_REGS: AtomicU64 = AtomicU64::new(0); +static BUF_UNREGS: AtomicU64 = AtomicU64::new(0); +static BUF_LIVE_MAX: AtomicUsize = AtomicUsize::new(0); + +/// One `is_registered_buffer` probe that got past the "ever registered" latch. +/// `admitted` is what the inline min/max window answered — the whole question, +/// because only an admitted address pays the out-of-line call. +#[inline] +pub fn buffer_note_probe(addr: usize, admitted: bool, window: Option<(usize, usize)>) { + let n = BUF_PROBES.fetch_add(1, Ordering::Relaxed); + if admitted { + BUF_ADMITS.fetch_add(1, Ordering::Relaxed); + } + BUF_ADDR_MIN.fetch_min(addr, Ordering::Relaxed); + BUF_ADDR_MAX.fetch_max(addr, Ordering::Relaxed); + if let Some((lo, hi)) = window { + BUF_WIN_LO.store(lo, Ordering::Relaxed); + BUF_WIN_HI.store(hi, Ordering::Relaxed); + } + // Dump roughly every million probes; the rig SIGKILLs, so an exit hook + // would never fire. + if n & 0xF_FFFF == 0 { + buffer_dump(); + } +} + +/// The slow path found a real registered buffer. +#[inline] +pub fn buffer_note_true_positive() { + BUF_TRUE_POS.fetch_add(1, Ordering::Relaxed); +} + +/// One buffer registration, with the registry's size after it. Registrations +/// are what a Bloom filter would have to hold, and `RegistryAddrFilter` accrues +/// bits **per admission, not per live entry** — so for a high-churn set the +/// number that decides whether that structure can work is the CUMULATIVE +/// count, not the live one. Both are recorded. +pub fn buffer_note_registration(live_now: usize) { + BUF_REGS.fetch_add(1, Ordering::Relaxed); + BUF_LIVE_MAX.fetch_max(live_now, Ordering::Relaxed); +} + +/// One buffer leaving the registry. +pub fn buffer_note_unregistration() { + BUF_UNREGS.fetch_add(1, Ordering::Relaxed); +} + +#[cold] +fn buffer_dump() { + let probes = BUF_PROBES.load(Ordering::Relaxed); + let admits = BUF_ADMITS.load(Ordering::Relaxed); + let tp = BUF_TRUE_POS.load(Ordering::Relaxed); + let amin = BUF_ADDR_MIN.load(Ordering::Relaxed); + let amax = BUF_ADDR_MAX.load(Ordering::Relaxed); + let wlo = BUF_WIN_LO.load(Ordering::Relaxed); + let whi = BUF_WIN_HI.load(Ordering::Relaxed); + let pct = |a: u64, b: u64| if b == 0 { 0.0 } else { 100.0 * a as f64 / b as f64 }; + let mb = |n: usize| n as f64 / (1024.0 * 1024.0); + let win_span = whi.saturating_sub(wlo); + let probe_span = amax.saturating_sub(amin); + let mut out = String::with_capacity(768); + use std::fmt::Write as _; + let _ = writeln!( + out, + "[buffer-diag] probes={probes} admits={admits} ({:.2} %) rejected={} ({:.2} %) \ + true_positives={tp} ({:.6} % of admits)", + pct(admits, probes), + probes - admits, + pct(probes - admits, probes), + pct(tp, admits) + ); + let _ = writeln!( + out, + " window [{wlo:#x}, {whi:#x}] span {:.1} MB", + mb(win_span) + ); + let _ = writeln!( + out, + " probed [{amin:#x}, {amax:#x}] span {:.1} MB -- window covers {:.1} % of the probed range", + mb(probe_span), + if probe_span == 0 { 0.0 } else { 100.0 * win_span as f64 / probe_span as f64 } + ); + let regs = BUF_REGS.load(Ordering::Relaxed); + let unregs = BUF_UNREGS.load(Ordering::Relaxed); + let live_max = BUF_LIVE_MAX.load(Ordering::Relaxed); + // A 1,024-bit, 3-hash Bloom filter (`RegistryAddrFilter`) accrues bits per + // ADMISSION and never clears them, so `regs` — not `live_max` — is what it + // would have to hold. (1 - e^(-3n/1024))^3 at that n: + let fp = |n: f64| { + let x = 1.0 - (-3.0 * n / 1024.0).exp(); + 100.0 * x * x * x + }; + let _ = writeln!( + out, + " registrations={regs} unregistrations={unregs} live_max={live_max} => a 1024-bit/3-hash Bloom holding all admissions would be {:.1} % false-positive (and {:.1} % if it could hold only the live set)", + fp(regs as f64), + fp(live_max as f64) + ); + if let Some(sink) = buffer_sink() { + write_sink(sink, &out); + } +} diff --git a/crates/perry-runtime/src/object/field_get_set/enumeration.rs b/crates/perry-runtime/src/object/field_get_set/enumeration.rs index d5a60122ab..053bd9fe66 100644 --- a/crates/perry-runtime/src/object/field_get_set/enumeration.rs +++ b/crates/perry-runtime/src/object/field_get_set/enumeration.rs @@ -318,7 +318,18 @@ pub extern "C" fn js_object_keys_value(value: f64) -> *mut ArrayHeader { /// non-enumerable) as "seen" after emitting that level's enumerable subset. #[no_mangle] pub extern "C" fn js_for_in_keys_value(value: f64) -> *mut ArrayHeader { + for_in_keys_with(value, lazy_shadow_enabled()) +} + +/// The walk itself, with the shadow-set strategy as a parameter so a test can +/// run BOTH and assert they agree. `js_for_in_keys_value` reads the env once +/// and delegates here. +pub(crate) fn for_in_keys_with(value: f64, lazy_shadow: bool) -> *mut ArrayHeader { let jv = JSValue::from_bits(value.to_bits()); + let diag = crate::hot_diag::enum_on(); + if diag { + crate::hot_diag::enum_with(|d| d.for_in_calls += 1); + } if jv.is_null() || jv.is_undefined() { return crate::array::js_array_alloc(0); } @@ -326,6 +337,9 @@ pub extern "C" fn js_for_in_keys_value(value: f64) -> *mut ArrayHeader { // Non-pointer primitives (number/boolean, boxed string) have only their own // enumerable keys; every prototype property they inherit is non-enumerable. if !jv.is_pointer() { + if diag { + crate::hot_diag::enum_with(|d| d.for_in_primitive += 1); + } let own = js_object_keys_value(value); let n = crate::array::js_array_length(own); for i in 0..n { @@ -335,12 +349,53 @@ pub extern "C" fn js_for_in_keys_value(value: f64) -> *mut ArrayHeader { return out; } let key_string = |kv: JSValue, scratch: &mut [u8; crate::value::SHORT_STRING_MAX_LEN]| { - unsafe { crate::string::js_string_key_bytes(kv, scratch) } - .and_then(|b| std::str::from_utf8(b).ok().map(|s| s.to_string())) + let made = unsafe { crate::string::js_string_key_bytes(kv, scratch) } + .and_then(|b| std::str::from_utf8(b).ok().map(|s| s.to_string())); + if diag { + if let Some(ref s) = made { + let n = s.len() as u64; + crate::hot_diag::enum_with(|d| { + d.for_in_key_strings += 1; + d.for_in_key_string_bytes += n; + }); + } + } + made }; let mut seen: std::collections::HashSet = std::collections::HashSet::new(); let mut scratch = [0u8; crate::value::SHORT_STRING_MAX_LEN]; let mut current = value; + + // #9792 follow-up: the shadow set is DEFERRED. + // + // `seen` exists for one purpose — a name owned at a closer level hides the + // same name further along the chain (§14.7.5 / 12.6.4-2). That filter can + // only ever apply to a level >= 1, so nothing at level 0 needs it, and a + // level that contributes no enumerable keys of its own never consults it. + // + // The old shape paid for it unconditionally: at EVERY level it materialised + // the all-own-names array (a second key array, including non-enumerable + // names) and turned every name at every level into a heap `String` so it + // could be hashed into the set. Measured on the compiled claude-code TUI, + // one 400-character reply: 17,272 `for-in` calls, 4.00 key arrays per call, + // and **159,752 `String` allocations and SipHash inserts to emit 11,276 + // keys** — an emitted/String ratio of 0.071, for 1.90 MB of bytes. The + // bytes are why no allocation-share ranking could see this; the executions + // are the cost. + // + // So: remember the levels walked, and build the set only at the moment a + // level >= 1 actually has an enumerable key to filter. When it is built it + // is built from exactly the levels already visited, which is the same + // content the eager version would have had at that point, so the emitted + // key sequence is unchanged. + // The levels walked so far, for the rebuild that almost never happens. + // Inline: the measurement says 2.00 prototype levels per call, so a spill + // to the heap is the pathological case, not the common one — and a `Vec` + // here would just reintroduce one malloc per `for-in` in place of the + // 159,947 this change removes. + let mut visited = VisitedLevels::default(); + let mut shadow_live = !lazy_shadow; + let mut level: u32 = 0; // Depth cap guards against pathological / cyclic prototype graphs. for _ in 0..1000 { let cv = JSValue::from_bits(current.to_bits()); @@ -351,34 +406,204 @@ pub extern "C" fn js_for_in_keys_value(value: f64) -> *mut ArrayHeader { // skipping any name already shadowed by a closer level. let enum_arr = js_object_keys_value(current); let en = crate::array::js_array_length(enum_arr); - for i in 0..en { - let kv = crate::array::js_array_get(enum_arr, i); - let name = match key_string(kv, &mut scratch) { - Some(s) => s, - None => continue, - }; - if seen.insert(name) { + if diag { + let en64 = en as u64; + crate::hot_diag::enum_with(|d| { + d.for_in_levels += 1; + d.for_in_key_arrays += 1; + d.for_in_keys_seen += en64; + }); + } + // Level 0 can be shadowed by nothing, so its own enumerable names go + // straight out — own property names are unique within one object, which + // is the only thing the set was doing for this level. + if lazy_shadow && level == 0 && !shadow_live { + for i in 0..en { + let kv = crate::array::js_array_get(enum_arr, i); out = crate::array::js_array_push_f64(out, f64::from_bits(kv.bits())); } - } - // Mark ALL own names (incl non-enumerable) seen so they shadow the - // remainder of the chain. - let all_f64 = super::super::descriptors::js_object_get_own_property_names(current); - let all_arr = (all_f64.to_bits() & crate::value::POINTER_MASK) as *mut ArrayHeader; - if !all_arr.is_null() { - let an = crate::array::js_array_length(all_arr); - for i in 0..an { - let kv = crate::array::js_array_get(all_arr, i); - if let Some(name) = key_string(kv, &mut scratch) { - seen.insert(name); + if diag { + let en64 = en as u64; + crate::hot_diag::enum_with(|d| d.for_in_keys_emitted += en64); + } + } else { + if en > 0 && !shadow_live { + // First level >= 1 with something to filter: pay for the set + // now, over exactly the levels already walked. + build_shadow_set(visited.as_slice(), &mut seen, &mut scratch, diag); + shadow_live = true; + if diag { + crate::hot_diag::enum_with(|d| d.for_in_shadow_built += 1); + } + } + for i in 0..en { + let kv = crate::array::js_array_get(enum_arr, i); + let name = match key_string(kv, &mut scratch) { + Some(s) => s, + None => continue, + }; + let fresh = seen.insert(name); + if diag { + let deep = level > 0; + crate::hot_diag::enum_with(|d| { + d.for_in_seen_inserts += 1; + if !fresh { + d.for_in_seen_dupes += 1; + } else { + d.for_in_keys_emitted += 1; + if deep { + d.for_in_keys_emitted_deep += 1; + } + } + }); + } + if fresh { + out = crate::array::js_array_push_f64(out, f64::from_bits(kv.bits())); } } } + // Mark ALL own names (incl non-enumerable) so they shadow the remainder + // of the chain — but only once the set is live. Until then the level is + // recorded and the array is not materialised at all: this is the second + // of the four key arrays per call that the measurement found. + if shadow_live { + mark_own_names(current, &mut seen, &mut scratch, diag); + } else { + visited.push(current); + } current = super::super::object_ops::js_object_get_prototype_of(current); + level += 1; } out } +/// Prototype levels recorded for a possible shadow-set rebuild, inline for the +/// depths that actually occur. +/// +/// `INLINE` is 8 against a measured 2.00 levels per `for-in` call on the +/// compiled claude-code TUI, so the heap arm is for prototype chains an order +/// of magnitude deeper than anything the workload produces. It exists because +/// the depth cap is 1000, not because it is expected. +struct VisitedLevels { + inline: [f64; Self::INLINE], + len: usize, + spill: Vec, +} + +impl Default for VisitedLevels { + fn default() -> Self { + Self { + inline: [0.0; Self::INLINE], + len: 0, + spill: Vec::new(), + } + } +} + +impl VisitedLevels { + const INLINE: usize = 8; + + fn push(&mut self, v: f64) { + if self.len < Self::INLINE { + self.inline[self.len] = v; + self.len += 1; + } else { + self.spill.push(v); + } + } + + /// The recorded levels in walk order. Borrows rather than copies, and the + /// spill arm concatenates only when it is non-empty. + fn as_slice(&self) -> VisitedSlice<'_> { + VisitedSlice { + head: &self.inline[..self.len], + tail: &self.spill, + } + } +} + +struct VisitedSlice<'a> { + head: &'a [f64], + tail: &'a [f64], +} + +impl VisitedSlice<'_> { + fn iter(&self) -> impl Iterator { + self.head.iter().chain(self.tail.iter()) + } +} + +/// `PERRY_FORIN_LAZY_SHADOW=0` restores the eager shadow set, so one binary +/// carries both paths and an A/B is one environment variable. +fn lazy_shadow_enabled() -> bool { + static ON: std::sync::OnceLock = std::sync::OnceLock::new(); + *ON.get_or_init(|| { + !matches!( + std::env::var("PERRY_FORIN_LAZY_SHADOW").ok().as_deref(), + Some("0") | Some("off") | Some("false") | Some("no") + ) + }) +} + +/// Add every own name of `recv` — enumerable or not — to the shadow set. +fn mark_own_names( + recv: f64, + seen: &mut std::collections::HashSet, + scratch: &mut [u8; crate::value::SHORT_STRING_MAX_LEN], + diag: bool, +) { + let all_f64 = super::super::descriptors::js_object_get_own_property_names(recv); + let all_arr = (all_f64.to_bits() & crate::value::POINTER_MASK) as *mut ArrayHeader; + if all_arr.is_null() { + return; + } + let an = crate::array::js_array_length(all_arr); + if diag { + let an64 = an as u64; + crate::hot_diag::enum_with(|d| { + d.for_in_key_arrays += 1; + d.for_in_keys_seen += an64; + }); + } + for i in 0..an { + let kv = crate::array::js_array_get(all_arr, i); + let name = unsafe { crate::string::js_string_key_bytes(kv, scratch) } + .and_then(|b| std::str::from_utf8(b).ok().map(|s| s.to_string())); + if let Some(name) = name { + if diag { + let n = name.len() as u64; + crate::hot_diag::enum_with(|d| { + d.for_in_key_strings += 1; + d.for_in_key_string_bytes += n; + }); + } + let fresh = seen.insert(name); + if diag { + crate::hot_diag::enum_with(|d| { + d.for_in_seen_inserts += 1; + if !fresh { + d.for_in_seen_dupes += 1; + } + }); + } + } + } +} + +/// Materialise the shadow set for the levels already walked, in order. Called +/// at most once per `for-in`, and only when a level >= 1 has an enumerable key +/// that something closer might hide. +fn build_shadow_set( + visited: VisitedSlice<'_>, + seen: &mut std::collections::HashSet, + scratch: &mut [u8; crate::value::SHORT_STRING_MAX_LEN], + diag: bool, +) { + for recv in visited.iter() { + mark_own_names(*recv, seen, scratch, diag); + } +} + fn closure_dynamic_enumerable_props(ptr: usize) -> Vec<(String, f64)> { let mut props: Vec<(String, f64)> = Vec::new(); @@ -1859,3 +2084,189 @@ fn js_object_entries_shape(obj: *const ObjectHeader) -> *mut ArrayHeader { result } } + +#[cfg(test)] +mod lazy_shadow_tests { + use super::*; + + fn s(bytes: &str) -> *mut crate::StringHeader { + crate::string::js_string_from_bytes(bytes.as_ptr(), bytes.len() as u32) + } + + fn obj_value(o: *mut ObjectHeader) -> f64 { + f64::from_bits(JSValue::object_ptr(o as *mut u8).bits()) + } + + /// Read a key array back as owned strings, in order. + fn keys_of(arr: *mut ArrayHeader) -> Vec { + let mut out = Vec::new(); + let n = crate::array::js_array_length(arr); + let mut scratch = [0u8; crate::value::SHORT_STRING_MAX_LEN]; + for i in 0..n { + let kv = crate::array::js_array_get(arr, i); + if let Some(b) = unsafe { crate::string::js_string_key_bytes(kv, &mut scratch) } { + if let Ok(t) = std::str::from_utf8(b) { + out.push(t.to_string()); + } + } + } + out + } + + /// The deferred shadow set must produce the SAME key sequence as the eager + /// one, including the case the deferral exists to skip and the case it + /// cannot skip. + /// + /// This is the assertion the optimisation lives or dies on: `for_in_keys_with` + /// is run both ways over the same object graph and the two key sequences are + /// compared element by element. Deleting the `build_shadow_set` call, or + /// emitting level 0 through the set instead of directly, makes the + /// shadowing case below disagree and fails this test by name. + #[test] + fn deferring_the_shadow_set_does_not_change_the_key_sequence() { + // 1. Flat object, prototype contributes nothing enumerable — the case + // the deferral is FOR. Both paths must agree. + let flat = crate::object::js_object_alloc(0, 0); + crate::object::js_object_set_field_by_name(flat, s("alpha"), 1.0); + crate::object::js_object_set_field_by_name(flat, s("beta"), 2.0); + let flat_v = obj_value(flat); + let lazy = keys_of(for_in_keys_with(flat_v, true)); + let eager = keys_of(for_in_keys_with(flat_v, false)); + assert_eq!( + lazy, eager, + "a flat object's for-in keys must not depend on when the shadow set is built" + ); + assert_eq!(lazy, vec!["alpha".to_string(), "beta".to_string()]); + + // 2. Prototype WITH enumerable keys, one of them shadowed by an own + // property. This is the case the shadow set exists for, so the + // deferred build must fire and produce the same answer. + let proto = crate::object::js_object_alloc(0, 0); + crate::object::js_object_set_field_by_name(proto, s("beta"), 20.0); + crate::object::js_object_set_field_by_name(proto, s("gamma"), 30.0); + let child = crate::object::js_object_alloc(0, 0); + crate::object::js_object_set_field_by_name(child, s("alpha"), 1.0); + crate::object::js_object_set_field_by_name(child, s("beta"), 2.0); + let child_v = obj_value(child); + crate::object::object_ops::js_object_set_prototype_of(child_v, obj_value(proto)); + + let lazy = keys_of(for_in_keys_with(child_v, true)); + let eager = keys_of(for_in_keys_with(child_v, false)); + assert_eq!( + lazy, eager, + "an inherited enumerable key, and an own key shadowing one on the \ + prototype, must come out identically whether the shadow set was \ + built eagerly or on demand" + ); + // `beta` is owned by the child, so it appears once, at the child's + // position — never again from the prototype. + assert_eq!( + lazy, + vec![ + "alpha".to_string(), + "beta".to_string(), + "gamma".to_string() + ], + "own keys first in insertion order, then unshadowed inherited ones" + ); + } + + /// A prototype chain deeper than `VisitedLevels::INLINE` where the ONLY + /// level that shadows the name lives PAST the inline array. + /// + /// This arm never runs on the measured workload (the shadow set was built 0 + /// times in 17,266 `for-in` calls), so a test is its only coverage. + /// + /// # Why this test is shaped the way it is — do not "simplify" it + /// + /// The obvious way to write it is to give EVERY level the shadowing + /// property, which reads as a stronger test and is not one. The first + /// version of this test did exactly that: `marker` was owned + /// non-enumerably at every level *including the leaf*. Deleting + /// `VisitedLevels`' spill arm — so a rebuild cannot see any level past + /// `INLINE` — left that test still passing, because the LEAF's own + /// `marker` was already in the set and shadowed the root's copy on its + /// own. The assertion was true no matter what the spill did, so it could + /// not fail, and it certified nothing. + /// + /// The fix is not more levels or more assertions, it is making the + /// spilled level the *only* thing that can produce the expected answer: + /// levels `0..INLINE` own nothing at all, exactly one level past the + /// inline array (`INLINE + 2`) owns `marker` non-enumerably, and only the + /// root owns it enumerably. Now dropping the spill leaks `marker` into the + /// result and the test fails by name — verified by making that edit. + /// + /// The general rule this is an instance of: after writing a test for a + /// rarely-taken path, delete the code it covers and check the test + /// actually fails. A test whose expected value is reachable by a second + /// route is measuring the second route. + #[test] + fn only_a_spilled_level_shadows_the_root_and_the_rebuild_must_see_it() { + let shadow_level = VisitedLevels::INLINE + 2; + let depth = shadow_level + 2; + + // Root (deepest): the enumerable `marker` that must stay hidden. + let root = crate::object::js_object_alloc(0, 0); + crate::object::js_object_set_field_by_name(root, s("marker"), 1.0); + crate::object::js_object_set_field_by_name(root, s("deep_only"), 2.0); + + // Build downwards from the root; `chain[i]` is at prototype level + // `depth - 1 - i` when walked from the leaf. + let mut chain = vec![root]; + for _ in 1..depth { + let o = crate::object::js_object_alloc(0, 0); + let ov = obj_value(o); + crate::object::object_ops::js_object_set_prototype_of( + ov, + obj_value(*chain.last().unwrap()), + ); + chain.push(o); + } + // Exactly one level shadows `marker`, and it is past the inline array. + let shadower = chain[depth - 1 - shadow_level]; + crate::object::js_object_set_field_by_name_nonenum(shadower, s("marker"), 0.0); + + let leaf_v = obj_value(*chain.last().unwrap()); + let lazy = keys_of(for_in_keys_with(leaf_v, true)); + let eager = keys_of(for_in_keys_with(leaf_v, false)); + assert_eq!( + lazy, eager, + "a chain whose only shadowing level spilled past the inline array \ + must give the same keys eagerly and on demand" + ); + assert!( + !lazy.contains(&"marker".to_string()), + "the only level owning `marker` sits past VisitedLevels::INLINE, so \ + a rebuild that cannot see the spilled levels would leak the root's \ + enumerable `marker` — got {lazy:?}" + ); + assert_eq!(lazy, vec!["deep_only".to_string()]); + } + + /// A NON-enumerable own property still shadows the same name on the + /// prototype (12.6.4-2). The deferred set only marks all-own-names for a + /// level once it goes live, so this is exactly where a wrong deferral would + /// leak the prototype's copy through. + #[test] + fn a_non_enumerable_own_name_still_shadows_the_prototype_under_deferral() { + let proto = crate::object::js_object_alloc(0, 0); + crate::object::js_object_set_field_by_name(proto, s("hidden"), 9.0); + crate::object::js_object_set_field_by_name(proto, s("shown"), 8.0); + + let child = crate::object::js_object_alloc(0, 0); + // Own but NOT enumerable: must not be emitted, must still shadow. + crate::object::js_object_set_field_by_name_nonenum(child, s("hidden"), 1.0); + let child_v = obj_value(child); + crate::object::object_ops::js_object_set_prototype_of(child_v, obj_value(proto)); + + let lazy = keys_of(for_in_keys_with(child_v, true)); + let eager = keys_of(for_in_keys_with(child_v, false)); + assert_eq!(lazy, eager, "deferral must not change shadowing by a non-enumerable own name"); + assert!( + !lazy.contains(&"hidden".to_string()), + "a non-enumerable own `hidden` must hide the prototype's enumerable \ + `hidden` rather than letting it through — got {lazy:?}" + ); + assert_eq!(lazy, vec!["shown".to_string()]); + } +} diff --git a/crates/perry-runtime/src/registry_latch.rs b/crates/perry-runtime/src/registry_latch.rs index dd6adcadcc..8e64271625 100644 --- a/crates/perry-runtime/src/registry_latch.rs +++ b/crates/perry-runtime/src/registry_latch.rs @@ -225,13 +225,21 @@ impl RegistryAddrWindow { self.hi.fetch_max(addr, Ordering::AcqRel); } - /// Test hook: the current `[lo, hi]` pair, or `None` while empty. - #[cfg(test)] - pub(crate) fn bounds_for_tests(&self) -> Option<(usize, usize)> { + /// The live `[lo, hi]` pair, or `None` while the window is still empty. + /// + /// Diagnostic use: `PERRY_BUFFER_DIAG` reports it, so a window that has + /// widened until it covers the heap is visible rather than inferred. + pub(crate) fn bounds(&self) -> Option<(usize, usize)> { let lo = self.lo.load(Ordering::Acquire); let hi = self.hi.load(Ordering::Acquire); (lo <= hi).then_some((lo, hi)) } + + /// Test hook: the current `[lo, hi]` pair, or `None` while empty. + #[cfg(test)] + pub(crate) fn bounds_for_tests(&self) -> Option<(usize, usize)> { + self.bounds() + } } /// A monotone "which addresses have ever been registered?" **set filter** — diff --git a/crates/perry-runtime/src/string/concat.rs b/crates/perry-runtime/src/string/concat.rs index 77d58367b2..800d942489 100644 --- a/crates/perry-runtime/src/string/concat.rs +++ b/crates/perry-runtime/src/string/concat.rs @@ -624,6 +624,9 @@ pub extern "C" fn js_string_concat( a: *const StringHeader, b: *const StringHeader, ) -> *mut StringHeader { + if crate::hot_diag::enum_on() { + crate::hot_diag::enum_with(|d| d.concat_calls += 1); + } let scope = crate::gc::RuntimeHandleScope::new(); let a_handle = scope.root_string_ptr(a); let b_handle = scope.root_string_ptr(b); @@ -980,6 +983,9 @@ const CONCAT_CHAIN_MAX_PARTS: usize = 32; /// with STRING_TAG via the standard `nanbox_string_inline` helper. #[no_mangle] pub extern "C" fn js_string_concat_chain(parts: *const f64, n: i32) -> *mut StringHeader { + if crate::hot_diag::enum_on() { + crate::hot_diag::enum_with(|d| d.concat_chain_calls += 1); + } let n = (n as usize).min(CONCAT_CHAIN_MAX_PARTS); if n == 0 || parts.is_null() { return crate::string::js_string_from_bytes(b"".as_ptr(), 0); diff --git a/crates/perry-runtime/src/string/concat_site.rs b/crates/perry-runtime/src/string/concat_site.rs index 239eb923b2..1679d6b9a6 100644 --- a/crates/perry-runtime/src/string/concat_site.rs +++ b/crates/perry-runtime/src/string/concat_site.rs @@ -76,6 +76,9 @@ pub extern "C" fn js_string_concat_site_value( prefix: *const StringHeader, value: f64, ) -> f64 { + if crate::hot_diag::enum_on() { + crate::hot_diag::enum_with(|d| d.concat_site_calls += 1); + } let slot = concat_site_slot(value); if let Some(k) = slot { let cached = unsafe { *table.add(k) };