Add extra telemetry to get a GC's shape - #22
Open
r41k0u wants to merge 10 commits into
Open
Conversation
MMTK_VERBOSE reports one number for stop-the-world: the total. A total cannot
tell many small pauses from a few large ones, which is the distinction the GC
space-time shape comparison rests on — two collectors can share a total and
have opposite latency profiles. The per-pause value was already being computed
in resume_mutators (start.elapsed()) and thrown straight into the running sum.
MMTK_PAUSE_LOG=<path> now keeps each (start, duration, full?) and writes them as
NDJSON at exit. Records accumulate in memory rather than being written as they
happen: a mutator is parked waiting on that path, so it must not do I/O. A
record is 24 bytes, so a million collections costs 24 MB. Disabled by default,
where the cost is one relaxed atomic load per pause.
Times are emitted in seconds relative to the first pause so the stream aligns
with the in-mutator probe's timeline without either side knowing the other's
units.
Cross-validation, binarytrees on six pinned P-cores — the logged pauses sum to
the independently accumulated total:
plan pauses sum of records MMTK_VERBOSE total
GenImmix 259 2280 ms 2279 ms
Bactrian 233 1554 ms 1554 ms
And the distribution the total was hiding:
plan p50 p99 max full-GC p50
GenImmix 1.17ms 95.0ms 119.3ms 12.5 ms
Bactrian 0.99ms 88.2ms 111.9ms 1.1 ms
Bactrian cuts the median FULL-GC pause 11x, which is concurrent marking doing
what it is for. The tail does not move (112 vs 119 ms) because in both plans
the worst pauses are nursery collections, not marking — so "concurrent marking
cuts pauses" is true of the median and false of the tail. That is exactly the
kind of claim a summed total cannot support or refute.
…arison
BACTRIAN.md establishes that Bactrian is architecture-matched but not
implementation-matched to stock OCaml 5. Per KC, closing that mechanism gap is
not the goal: dedicated GC workers are fine, and what has to match is the
space-time shape — carried by aggregate CPU doing work against aggregate CPU
doing GC, a ratio invariant to where the GC work runs.
SHAPE.md records the five dimensions, the instruments, and — the part that
matters for trusting any later number — what each instrument was validated
against, including the traps found on the way:
- the probe must read the odometer from the mutator's own domain, because
cross-domain alloc stats refresh only inside GC stop-the-world sections
- the tick path allocates 0 words/tick native, 10 under bytecode (no float
unboxing), so it refuses to arm there
- the probe's BUFFERS, not its tick path, were the real hazard: 16 MiB of
live gap arrays moved vanilla binarytrees from a byte-deterministic 61
major collections to 42, because both collectors size the heap from the
live set
- Gc.minor_words is exactly equivalent across runtimes, but excludes large
allocations on both, and Gc.major_words is broken under MMTk (reads 0)
- pause records sum to MMTk_VERBOSE's independent total to the millisecond,
and the probe's largest gaps track the GC's largest pauses at ratios
0.85-1.34
It also fixes the protocol the measurements have to follow. Chiefly: pin the
heap. Under a dynamic heap MMTk's GC count is bistable — five identical runs
gave 259-265 while a perturbed one latched a different trajectory at 163 —
whereas a pinned 512 MiB heap is deterministic to the object. D2 is not
reproducible otherwise.
Acceptance tolerances are deliberately absent. They are KC's to set once the
shape is measured, and guessing them before seeing data would be backwards.
The probe cannot separate a GC stall from a long unit of ordinary work unless the inter-tick work is far below the pause scale, which is a property of the call site rather than of the probe. Measured both ways on binarytrees and recorded, along with the consequence: probe serves D2, while D3's pause distribution comes from MMTK_PAUSE_LOG and runtime_events, which are zero-overhead and authoritative on their respective sides.
…f_memory Found while establishing the left edge of the D5 heap sweep. Below some heap the program must fail; it should fail as Out_of_memory, not as a segfault. In a band just above the true OOM point it segfaults, and nondeterministically: the same configuration gives SEGV or a clean Out_of_memory run to run, which points at a race or at partially-completed collection state rather than a bad size. binarytrees-20, single domain, native, no probe, two reps per cell: 32M is a clean OOM; 36-52M gives SEGV on GenImmix (4 of 10 reps clean) and one SEGV on Bactrian at 44M; 56M and up are fine. The crash is on a GC WORKER, in ScanMutatorRoots for a MATURE GenImmix collection: scan_stack_frames (fiber.c:305) <- caml_scan_stack <- caml_do_local_roots <- caml_do_roots <- scanning.rs:260. caml_do_roots is called with fflags=0 and caml_do_local_roots records fflags@entry=0, yet the call into caml_scan_stack reads SCANNING_ONLY_YOUNG_VALUES | unknown: 0x5554 — garbage high bits on what should be a small enum bitmask. Neighbouring parameters print <optimized out>, so this may be a gdb artifact rather than real corruption and needs confirming at -O0 or under rr before being believed. Recorded rather than chased so the sweep can floor at 64 MiB and avoid mixing a crash bug into the curve. Worth an rr session (rr record -c <N>, varying N) — the nondeterminism is exactly what rr is for.
…s 0-13 church is the 2-socket Xeon Gold 5120 PERFORMANCE.md section 5 was written against: 56 threads = 2 sockets x 14 cores x 2 SMT, NUMA 0-13,28-41 and 14-27,42-55, Ubuntu 26.04 / gcc 15.2 / glibc 2.43 (an exact toolchain match with the dev laptop), and uniform cores — no hybrid split, which is why it is the reference host. Its cpu0 thread_siblings_list is 0,28, so the doc's taskset -c 0-13 is one thread per PHYSICAL core of socket 0 rather than an arbitrary 14 CPUs. Recorded alongside the note that --cpu-set auto now derives that constraint instead of copying the number, since the previous default would have pinned 0-55 across both sockets.
D1 — aggregate CPU doing work against aggregate CPU doing GC — is the headline dimension, and its proper instrument is perf symbol attribution. perf needs perf_event_paranoid lowered, which needs root, and root is not available on every host we measure on (church, currently). There is a privilege-free route, because on this binding GC work runs on threads the mutator never uses: per-thread utime+stime from /proc/<pid>/task/<tid>/stat separates GC CPU from mutator CPU directly. It only needs the threads to be identifiable, and they were spawned with a bare std::thread::spawn, so /proc/<pid>/task/<tid>/comm inherited the process name and told them apart from nothing. Naming them "mmtk-gc-worker" (14 bytes; Linux truncates comm at 15) makes the attribution possible with no privileges and no perf. This is weaker than the perf split and does not replace it: thread attribution cannot separate the C (coordination-spin) bucket from real GC work, since a worker spinning for work and a worker tracing are both GC-thread CPU. Whether that matters is measurable rather than assumed — if MMTk's idle workers park rather than spin, worker CPU should be roughly invariant to MMTK_THREADS at fixed work, and if they spin it will scale with worker count. That test is worth running early, since it also probes KC's invariance claim directly.
The fork would not link on church: runtime/ocamlrun died with undefined references to Rust internals — core::fmt::write, std::process::abort, core::panicking::panic_fmt, <Mutex>::lock_contended, and "hidden symbol __rdl_alloc isn't defined". Vanilla built fine on the same host. The cause is neither ours nor the archive's. rustc leaves .llvmbc/.llvmcmd in every object; binutils ld/nm auto-load an LLVM gold plugin when they see them, and church carries a stale LLVM-14 one that cannot parse rustc-1.96's LLVM-22 bitcode: bfd plugin: LLVM gold plugin has failed to create LTO module: Opaque pointers are only supported in -opaque-pointers mode (Producer: 'LLVM22.1.2-rust-1.96.0-stable' Reader: 'LLVM 14.0.6') When the plugin fails the member is reported as having NO SYMBOLS AT ALL, so the entire Rust runtime disappears and the link fails naming Rust internals rather than the plugin. It is a nasty failure to diagnose: the object is BYTE-IDENTICAL to one that links elsewhere (same md5, same 11,599,800 bytes), rustc / binutils / gcc / Makefile.config / archive structure / glob order all match, and an archive-wide nm under-reports without an obvious error — the plugin message only reaches stderr, and only when nm runs on a single extracted member. Fix: objcopy --remove-section=.llvmbc --remove-section=.llvmcmd on the extracted objects before bundling. We never LTO across the C/Rust boundary, so the bitcode is dead weight; native code and .symtab are untouched. The same object goes from "no symbols" to its full 1778, matching the working host exactly, and church then builds world.opt clean with GenImmix / Bactrian / ConcurrentImmix / Immix all producing byte-identical output. Best-effort (- prefix, OBJCOPY ?= objcopy): only needed where the stale plugin exists, and objcopy may be absent.
…t in the variable
The previous commit's strip silently did nothing. MMTK_STRIP_BITCODE was defined
as `-$(OBJCOPY) ...`, so it expanded to the literal command `-objcopy`, which
does not exist; make's `-` error-ignore prefix only applies at the start of a
recipe LINE, not inside a variable expansion. The trailing `2>/dev/null || true`
then hid the "command not found", so the build looked like it had stripped and
had not — church still failed with 12573 undefined references.
Now the variable holds a real command and the recipe line carries the `-`, so a
missing objcopy still cannot fail the build. Verified by expansion:
objcopy --remove-section=.llvmbc --remove-section=.llvmcmd <objs>
…g objects The previous two attempts both failed, the second worse than the first. objcopy's signature is `objcopy [opts] infile [outfile]`. Handing it a glob of 505 objects therefore does not strip 505 objects: it strips the FIRST onto the SECOND — destroying it — and silently ignores the other 503. Measured directly: an 844,952-byte object came back as a 6,684,632-byte stripped copy of its neighbour, exit status 0. So church kept failing with the same 12573 undefined references while the build reported success at the strip step. My manual fix had worked only because it fell back to a shell for-loop after the glob form failed; I then wrote the glob form into the Makefile and reported it as verified, having actually verified the loop. Now a per-file loop, verified end to end: three objects strip to three distinct sizes with none cloned, and the std object reports its full 1778 symbols rather than none.
…TIME) The D1 CPU-budget comparison against vanilla needs GC work attributed by the same rule on both sides. Vanilla runs ALL of its GC on the mutator and its runtime_events spans capture it there. Under MMTk, per-thread attribution sees only the worker pool — the GC work the MUTATOR does (write barriers, TLAB refills, LOS allocations) lands in the mutator bucket and flatters MMTk. Measured on church: the identical program's "mutator" CPU reads 2.5 s under MMTk against 1.65 s under vanilla. MMTK_MUTATOR_GC_TIME=1 arms TSC accounting of every mutator-side GC entry point. All such work funnels through this file's helpers — native code makes no other GC-related C calls — so wrapping caml_mmtk_region_barrier, caml_mmtk_satb_barrier, caml_mmtk_refill_tlab and the alloc_shr pair is complete. Per-domain plain u64 accumulators (a domain writes only its own slot), one predictable branch per call when disarmed, calibrated against CLOCK_MONOTONIC at exit. x86-64 only; armed elsewhere it reports zero and says so. The park subtraction is the subtle part and it is load-bearing. A TLAB refill or LOS allocation can BLOCK FOR AN ENTIRE COLLECTION (block acquisition polls, which can trigger a GC and park the mutator), and TSC measures wall cycles — without the subtraction one blocking refill books a whole multi-ms pause as mutator GC *CPU*. The alloc wrappers subtract whatever caml_mmtk_park accumulated inside their window; parked time burns no CPU and belongs to D3's pause log, not D1. It cross-validates immediately: on a binarytrees run the excluded parked time reads 1212.9 ms against MMTK_VERBOSE's independently-accumulated GC time of 1205 ms — two instruments, one phenomenon, 0.7% apart. First measurement is itself a result: mutator-side GC work on binarytrees-20 is ~52 ms (barrier 0.035 ms — the init-write-dominated profile RQ1 predicts — alloc ~52 ms). That is far too small to explain the ~0.9 s mutator-CPU gap vs vanilla, which therefore is NOT misattributed GC work: it is the mutator's own instructions running slower under a different allocation geometry. What no attribution can move into G, only cache counters can explain.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
No description provided.