Repository navigation
prof: cut BEX tracing producer + consumer overhead - #3765
Conversation
ProfileWriter::write_message allocated a fresh Vec (and paid an extra encoded_len walk to pre-size it) for every event the consumer transcoded — a malloc/free per traced event on the consumer's hot path. Reuse one scratch buffer on the writer: encode_length_delimited writes its own length prefix and grows the buffer as needed, so after the first events capacity is stable and no allocation happens. Bytes written are byte-identical. Measured (speedtest, tracing on, tmpfs sink vs the same before this change): record-dense workloads -13 to -16% end-to-end (fib32 -15.6, closure-apply -14.6, pure-call -13.4, binary-tree -13.2, call-chain -12.6); loop-heavy workloads ~0 (they emit few records). bex_events 51/51 green.
The VM producer encoded each raw record into a zeroed 41-byte stack buffer and then memcpy'd that into the ring segment — two writes of the same bytes plus a dead memset per traced event. Add Ring::push_with(len, |slot| ...) which reserves the slot and lets the producer serialize straight into it (Buf::with_slice_mut), so encode_to writes once, into the ring. push() now delegates to push_with; the now-unused Buf::write is removed. The loom build keeps per-byte tracked stores via a temp, so the data-race model is unchanged. Also folds in two producer micro-fixes: the clock anchor is split into an inline OnceLock fast path + #[cold] init, and the per-emit ring gate is deduped (the helper takes the resolved &Ring instead of re-checking Option). Measured (divan, opt-level="s" as shipped, off-vs-discard ns/pair, fastest sample): call-chain ~19.6 -> ~15.5 ns/pair (-21% of the producer overhead); pure-call ~neutral within its run-to-run variance, no regression. Output is byte-identical (record roundtrip + consumer e2e tests green); bex_events 51/51, bex_vm green. NOTE: a stub-clock experiment showed the rdtsc reads cost only ~1-6 ns/pair (they pipeline in-situ) -- the dominant producer cost is record encode + the ring write, which this targets, not the clock.
…m_slice The record Writer routed every u16/u32/u64 through bytes() -> copy_from_slice with a runtime length, which does not inline at opt-level="s" (the shipped profile) — ~78 instructions per 38-byte CallFunction. Write each fixed field with a single ptr::write_unaligned (to_le for portability): one `mov` each, ~15 instructions, no out-of-line call. Byte-identical wire (record roundtrip + e2e consumer tests green, 51/51 bex_events). This is the producer-encode lever from the consumer/producer research. An earlier const-offset fixed-array attempt regressed (~6 ns) because it added a zeroing + a final copy; a copy_nonoverlapping<N> form likely kept a memcpy libcall at opt-s. write_unaligned is a direct store with neither. The ~5-8 ns/ pair it removes sits at the divan run-to-run noise floor on the call-storm microbenches, so it is committed on codegen merit (provably fewer instructions, no libcall), like the write-in-place change.
…rd divide TickConverter::to_ns ran a u128 multiply then a u128 DIVIDE by denom on every record the consumer transcodes — a variable 128-bit divide is ~20-40 non-pipelined cycles. The rate is fixed for a run (after the one-time TSC refine), so precompute scale = numer<<48 / denom once at each rate install and convert on the hot path via (dt * scale) >> 48 — a multiply-shift, no divide. The cold prev-segment branch (late-draining pre-refine ticks) keeps the exact divide. Exact for rate (1,1): scale = 2^48 so ns == dt (the identity converter used by the e2e oracle is bit-unchanged). For measured TSC/CNTVCT rates the rounding is <=1 ns (below tracing-timestamp resolution) and monotonic, so per-thread ordering is preserved; new test reciprocal_matches_exact_divide pins this for 125/3, 5/16, 1e9/24e6. bex_events 52/52. Measured: prof_drain_throughput 4M events 518ms -> ~493ms median (~7.7M -> ~8.0-8.7M ev/s/core), consistent with removing the divide.
…tion) The consumer transcoded every record by building a prost DiskEventV1 and calling encode_length_delimited, which walks the nested-oneof message ~3x (encoded_len, encode_raw, and the embedded-message path recomputes the inner length again) before writing a byte — ~half the consumer's per-record cost. Encode the two hot events (CallFunction/EndFunction = the per-call pair, ~all event volume) directly in one pass with back-patched single-byte length prefixes (both messages are < 128 B). Cold/rare records (header, StartThread, SetFunctionId, EndThread, Heartbeat) stay on prost. This mirrors Perfetto's "protozero" streaming protobuf encoder, used there for the same reason. Measured: prof_drain_throughput 4M events ~493ms -> ~234ms (8.1M -> 17.0M ev/s/core, 2.1x); with the reciprocal to_ns change the consumer is 7.7M -> 17.0M overall (2.2x). The consumer is no longer the per-record bottleneck for record-dense workloads. Correctness: to_disk_event still builds the prost structs, so a proto field add/remove/rename/type-change is a COMPILE error (exhaustive struct literal + the encoders' field reads). New differential test hand_encoder_matches_prost asserts byte-for-byte equality with prost over a range of inputs, covering even a field renumber. bex_events 53/53; e2e roundtrip + prof_gate decode the hand-written bytes unchanged.
|
The latest updates on your projects. Learn more about Vercel for GitHub.
|
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Repository UI Review profile: CHILL Plan: Pro Run ID: 📒 Files selected for processing (1)
🚧 Files skipped from review as they are similar to previous changes (1)
📝 WalkthroughWalkthroughThis PR introduces a set of hot-path encoding optimizations in the ChangesProfiling hot-path encoding optimizations
Estimated code review effort🎯 4 (Complex) | ⏱️ ~60 minutes Possibly related PRs
Poem
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✏️ Tip: You can configure your own custom pre-merge checks in the settings. ✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
There was a problem hiding this comment.
🧹 Nitpick comments (2)
baml_language/crates/bex_events/src/prof/record.rs (1)
197-200: 💤 Low valueMinor: Docstring claim about panic behavior is now approximate.
The doc says "Panics (slice indexing) if
bufis shorter" but with the newu16/u32/u64implementations, an undersized buffer could cause UB before hitting a safe slice index. In practice this is mitigated because:
- All records start with a
u8(TAG_...)which panics on empty buffer- The primary callers (
encode()withMAX_RECORD_LEN,Ring::push_withwithencoded_len()) always provide correctly-sized buffersThis is acceptable for internal hot-path code, just noting the doc is no longer strictly precise.
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@baml_language/crates/bex_events/src/prof/record.rs` around lines 197 - 200, Update the docstring for the encode method in RawRecord to be more precise about the actual panic and undefined behavior. The current documentation states "Panics (slice indexing) if `buf` is shorter" but with the new u16/u32/u64 implementations, an undersized buffer can trigger undefined behavior before reaching safe slice indexing. Revise the docstring to clarify that undefined behavior may occur with insufficient buffer size due to unsafe operations on integral types, while noting that in practice this is mitigated by the initial u8 TAG check and correct buffer sizing from the primary callers.baml_language/crates/bex_vm/src/vm.rs (1)
2943-2947: ⚡ Quick winRefresh this helper doc to match the new ring-slot path.
This comment still describes the removed stack-buffer implementation and says the helper no-ops when profiling is off, but the new helper requires callers to pass an already-unwrapped
Ringand writes directly into the reserved slot.Proposed doc update
- /// Encodes and pushes one profiling record into the per-resume ring - /// snapshot. No-op when profiling is off. The buffer is sized by - /// `SET_FUNCTION_ID_LEN` (41 B — the largest fixed record the VM emits: - /// `CallFunction` 38, `EndFunction` 26, `SetFunctionId` 41) — the 292-byte - /// `MAX_RECORD_LEN` zeroing is measurable at per-call rates. + /// Encodes and pushes one profiling record into the supplied per-resume + /// ring snapshot. Callers perform the profiling-off gate before calling + /// this helper. The ring slot is sized from `RawRecord::encoded_len()` and + /// initialized in place via `RawRecord::encode_to()`.🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@baml_language/crates/bex_vm/src/vm.rs` around lines 2943 - 2947, Update the documentation comment for the helper function (around line 2943-2947) to reflect the new implementation. Remove references to the removed stack-buffer implementation and the stack-buffer sizing details (SET_FUNCTION_ID_LEN, MAX_RECORD_LEN, CallFunction, EndFunction, SetFunctionId). Update the documentation to accurately describe the new behavior: that the helper takes an already-unwrapped Ring as a parameter from the caller, writes directly into a reserved slot, and is no longer a no-op when profiling is off. Ensure the updated comment clearly documents the new signature and behavior instead of the old stack-buffer approach.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Nitpick comments:
In `@baml_language/crates/bex_events/src/prof/record.rs`:
- Around line 197-200: Update the docstring for the encode method in RawRecord
to be more precise about the actual panic and undefined behavior. The current
documentation states "Panics (slice indexing) if `buf` is shorter" but with the
new u16/u32/u64 implementations, an undersized buffer can trigger undefined
behavior before reaching safe slice indexing. Revise the docstring to clarify
that undefined behavior may occur with insufficient buffer size due to unsafe
operations on integral types, while noting that in practice this is mitigated by
the initial u8 TAG check and correct buffer sizing from the primary callers.
In `@baml_language/crates/bex_vm/src/vm.rs`:
- Around line 2943-2947: Update the documentation comment for the helper
function (around line 2943-2947) to reflect the new implementation. Remove
references to the removed stack-buffer implementation and the stack-buffer
sizing details (SET_FUNCTION_ID_LEN, MAX_RECORD_LEN, CallFunction, EndFunction,
SetFunctionId). Update the documentation to accurately describe the new
behavior: that the helper takes an already-unwrapped Ring as a parameter from
the caller, writes directly into a reserved slot, and is no longer a no-op when
profiling is off. Ensure the updated comment clearly documents the new signature
and behavior instead of the old stack-buffer approach.
ℹ️ Review info
⚙️ Run configuration
Configuration used: Repository UI
Review profile: CHILL
Plan: Pro
Run ID: 28139e04-b8ef-4a44-ab74-b6b8a5739de8
📒 Files selected for processing (6)
baml_language/crates/bex_events/src/prof/clock.rsbaml_language/crates/bex_events/src/prof/file.rsbaml_language/crates/bex_events/src/prof/record.rsbaml_language/crates/bex_events/src/prof/ring.rsbaml_language/crates/bex_events/src/prof/sync.rsbaml_language/crates/bex_vm/src/vm.rs
⏭️ Performance benchmarks were skippedPerf benchmarks (CodSpeed) are opt-in on pull requests — they no longer run on every push. They always run automatically after merge to To run them on this PR, do any of the following, then push a commit (or re-run CI):
|
|
No description provided. |
The consumer transcoded the events of a drained range (one contiguous slice, up to a 256 KiB segment) but issued a write_all per event into an 8 KiB BufWriter — a syscall every ~460 events (~4,300 per 2M-event run). Accumulate the whole range into the writer's reused buffer (encode_event appends; no per-event clear), then a single flush_buffered per range. The BufWriter is removed entirely: the range buffer is the buffer, so each range is one write straight to the File (~135 writes per 2M-event run). flush()/sync() now flush that buffer (sync still fsyncs). No format change; bytes byte-identical (e2e_fake_producer_roundtrip + the hand_encoder differential test green, bex_events 53/53). prof_drain_throughput 4M events ~234ms -> ~210-225ms (~17.0M -> ~17.7-19.0M ev/s/core). This is also the structural carrier for optional per-segment compression (lz4) — deferred; the binding constraint on record-dense full-IO is disk byte volume, and compression is the lever, but it is a format-version bump kept out of this no-format-change PR.
There was a problem hiding this comment.
🧹 Nitpick comments (1)
baml_language/crates/bex_events/src/prof/consumer.rs (1)
377-388: ⚡ Quick winPreserve the heartbeat flush error.
flush_buffered()already returns the concreteio::Error; carrying it through keeps disk-full/permission/interruption diagnostics instead of reporting only"heartbeat write failed".♻️ Proposed fix
- let mut failed = Vec::new(); + let mut failed: Vec<(u64, io::Error)> = Vec::new(); for (&engine_id, slot) in &mut self.writers { if let Some(writer) = slot { writer.encode_event(&event); - if writer.flush_buffered().is_err() { - failed.push(engine_id); + if let Err(err) = writer.flush_buffered() { + failed.push((engine_id, err)); } } } - for engine_id in failed { - self.fail_writer(engine_id, &io::Error::other("heartbeat write failed")); + for (engine_id, err) in failed { + self.fail_writer(engine_id, &err); }🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@baml_language/crates/bex_events/src/prof/consumer.rs` around lines 377 - 388, The code in the writers loop is discarding the actual error returned by flush_buffered() and replacing it with a generic error message. Capture the concrete io::Error from the flush_buffered() call instead of just checking is_err(), and pass that actual error to self.fail_writer() to preserve diagnostic details like disk-full, permission, or interruption errors instead of reporting only the generic "heartbeat write failed" message.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Nitpick comments:
In `@baml_language/crates/bex_events/src/prof/consumer.rs`:
- Around line 377-388: The code in the writers loop is discarding the actual
error returned by flush_buffered() and replacing it with a generic error
message. Capture the concrete io::Error from the flush_buffered() call instead
of just checking is_err(), and pass that actual error to self.fail_writer() to
preserve diagnostic details like disk-full, permission, or interruption errors
instead of reporting only the generic "heartbeat write failed" message.
ℹ️ Review info
⚙️ Run configuration
Configuration used: Repository UI
Review profile: CHILL
Plan: Pro
Run ID: 7a6ae25d-6564-4ac0-858e-b7158dc389d9
📒 Files selected for processing (2)
baml_language/crates/bex_events/src/prof/consumer.rsbaml_language/crates/bex_events/src/prof/file.rs
🚧 Files skipped from review as they are similar to previous changes (1)
- baml_language/crates/bex_events/src/prof/file.rs
Two docstrings drifted from the code in this PR's earlier commits: - RawRecord::encode_to said "Panics if buf is shorter", but the write_unaligned field writes (commit d8ce1f2) are unchecked, so an undersized buf is UB in release, not a panic. Restate it as a safety precondition (buf.len() >= encoded_len()), noting both callers satisfy it. - prof_push_record still described the removed stack buffer + 41-byte zeroing + profiling-off no-op; it now takes an already-unwrapped &Ring and encodes into the reserved ring slot (commit 85bf08b). Doc-only.
|
Addressed both CodeRabbit nitpicks in 6906347 (doc-only): |
Bare [`push`] in push_with's doc resolves against module scope, where no item named `push` exists — it is a method, so the link needs Self::push. Caught only by CI's RUSTDOCFLAGS=-D warnings (rustdoc::broken_intra_doc_links); local clippy/test passes do not run rustdoc.
Summary
Reduces the runtime overhead of the BEX tracing system on both sides of the ring: the producer (the VM encoding/pushing a raw record per call into a lock-free SPSC ring) and the consumer (the background thread transcoding to protobuf and writing per-engine
.bamlprof). Profiling is default-on, so this is paid by every run.Six commits, each measured and committed on its own merit. No
.bamlprofformat change; byte-identical wire output (guarded by a differential test). Allbex_eventsunit tests,bex_engine'sprof_gate, the loom/miri concurrency suites, and clippy--all-featuresare green.Commits
e7daa17Vec::with_capacityper event (was a malloc + a redundantencoded_lenwalk per record).85bf08bRing::push_with/Buf::with_slice_mut) — drops the intermediate stack buffer, the 41-byte zeroing, and one of two copies. Loom keeps per-byte tracked stores.d8ce1f2ptr::write_unalignedinstead ofcopy_from_slice— the latter did not inline atopt-level="s"(the shipped profile): ~78 instructions/record → ~15, no libcall.d4eb542d55970CallFunction/EndFunction) in one pass with back-patched 1-byte length prefixes, instead of prost (which walks this nested-oneof message 3×). Cold records stay on prost. Same technique as Perfetto's protozero.905d6a7writeper drained range instead of one per event: accumulate the whole range (one ~256 KiB segment slice) into the writer's buffer, then a single write straight to theFile. Drops the 8 KiBBufWriter(~4,300 → ~135 write syscalls / 2M-event run).Results (Linux x86 dev box)
Consumer — ~2.4× throughput
prof_drain_throughput: 7.7M → ~18M events/s/core. The reciprocal removes the per-record divide; the hand-rolled encoder removes ~2/3 of the prost cost (prost was size-walking the message twice and byte-walking once); the batched range write removes the per-event syscall churn.End-to-end, single process (clean isolation)
Same binary,
BAML_PROFILEtoggled, real disk IO, profile dir wiped before each run so there is no cross-run accumulation. Medians, ms:off(tracing disabled)discard(producer floor, no IO)full(real IO)Decomposition on these adversarial call-storm microbenches: producer ring-emit ~+18-24%, consumer transcode+write+fsync ~+30%. The producer cost is at the encode/push floor (the clock read itself is only ~1-6 ns/pair — verified by a stub experiment; the rest is encoding + the ring commit, both irreducible without dropping records). The consumer (~18M ev/s) nearly matches the producer's ~18-20M ev/s burst, leaving a small drain tail plus the one-file write/fsync.
Corpus medians
Across the full speedtest corpus, the same-binary tracing-on producer cost is +3.6% median; total full-pipeline +8.2% median. Real-shaped workloads (loops, strings, classes) are well under +10% — only the call-storm microbenches (millions of trivial calls, which no LLM-bound BAML program emits) are high.
Follow-ups (not in this PR)
.bamlprofbyte volume; per-segment lz4 (~1.8-3× smaller files) is the lever, viable now that the consumer has CPU headroom. It's a format-version bump, so it's kept out of this no-format-change PR (separate branch/PR). The batched-range write here (905d6a7) is its structural carrier.opt-level=3— evaluated and reverted (speeds the VM ~17% but not the tracing delta; risks the wasm size budget).Verification
cargo test -p bex_events(53, incl.hand_encoder_matches_prostdifferential byte-equality andreciprocal_matches_exact_divide)cargo test -p bex_engine --test prof_gate(decodes the written bytes unchanged throughread_bamlprof)--cfg baml_loom) 34/34 + miri 33/33 on the ring/push_withchange--all-targets --all-featuresclean; CI mirror underrustup run 1.93.0Summary by CodeRabbit